ASP.NET Core 6框架揭秘实例演示[11]：诊断跟踪的几种基本编程方式
- 2022 年 3 月 1 日
- 筆記
- .NET 6, .NET Core, [02] 编程技巧, Asp.Net, Asp.Net Core, ASP.NET Core 6框架揭秘
在整个软件开发维护生命周期内，最难的不是如何将软件系统开发出来，而是在系统上线之后及时解决遇到的问题。一个好的程序员能够在系统出现问题之后马上定位错误的根源并找到正确的解决方案，一个更好的程序员能够根据当前的运行状态预知未来可能发生的问题，并将问题扼杀在摇篮中。合理地利用诊断手段能够帮助我们有效地纠错和排错。(本篇提供的实例已经汇总到《ASP.NET Core 6框架揭秘-实例演示版》）
[S701]TraceSource跟踪日志（源代码）
[S702]基于等级的日志过滤（源代码）
[S703]自定义面向控制台的TraceListener（源代码）
[S704]EventSource事件日志（源代码）
[S705]自定义EventListener监听事件（源代码）
[S706]DiagnosticListener诊断日志（源代码）
[S707]为DiagnosticListener注册强类型订阅者（源代码）
[S701]TraceSource跟踪日志
在利用TraceSource来记录日志时，我们需要做的就是根据名称和最低日志等级创建一个TraceSource对象，然后将事件ID、事件类型和日志消息作为参数调用它的TraceEvent方法。在如下所示的演示代码中，我们创建了一个TraceSource对象，并将名称和最低日志等级分别设置为Foobar与SourceLevels.All，后者决定了所有等级的日志都会被记录下来。我们针对每种事件类型记录了一条日志消息，而事件ID被设置为一个自增的整数。
using System.Diagnostics; var source = new TraceSource("Foobar", SourceLevels.All); var eventTypes = (TraceEventType[])Enum.GetValues(typeof(TraceEventType)); var eventId = 1; Array.ForEach(eventTypes, it => source.TraceEvent(it, eventId++, $"This is a {it} message.")); Console.Read();
我们说日志框架大都采用订阅发布模式来记录日志，但是上面的程序只涉及作为发布者的TraceSource对象，作为真正完成日志写入的订阅者（监听器）没有出现。如果以Debug的方式执行程序，我们会发现相应的日志以图1所示的形式被输出到Visual Studio的输出窗口中，这是因为日志框架会默认注册一个类型为DefaultTraceListener的监听器，它将日志作为调试信息进行了输出。
图1 通过默认注册的DefaultTraceListener写入的日志
[S702]基于等级的日志过滤
TraceEventType枚举类型共定义了10种事件类型，并且对应的枚举项是从高到低排列的（Critical最高，Transfer最低），所以上面的演示实例会按照等级的高低输出10条日志。如果我们只希望部分事件类型的日志被记录下来应如何做呢？一般来说，等级越高越应该被记录下来。创建TraceSource对象时指定的SourceLevels枚举表示需要被记录下来的最低日志等级。如果只希望记录Warning等级以上的日志，我们可以演示程序进行如下的改写即可。
using System.Diagnostics; var source = new TraceSource("Foobar", SourceLevels.Warning); var eventTypes = (TraceEventType[])Enum.GetValues(typeof(TraceEventType)); var eventId = 1; Array.ForEach(eventTypes, it => source.TraceEvent(it, eventId++, $"This is a {it} message.")); Console.Read();
由于最低日志等级设置成SourceLevels.Warning，当我们以Debug模式启动程序后，只有等级不低于Warning（Warning、Error和Critical）的三条日志消息以图2所示的形式被写入Visual Studio的调试输出窗口。
图2 记录下来的被过滤的日志
[S703]自定义面向控制台的TraceListener
到目前为止，我们都在使用系统默认注册的DefaultTraceListener监听器来完成对日志消息的输出。DefaultTraceListener除了调用Debug的Write方法将指定的消息作为调试信息进行输出外，它还支持针对物理文件的输出方式。如果需要，我们还可以针对期望的输出渠道注册自定义的TraceListener。
public class ConsoleListener : TraceListener { public override void Write(string? message) => Console.Write(message); public override void WriteLine(string? message) => Console.WriteLine(message); }
我们在上面的代码片段中继承抽象类TraceListener定义了一个ConsoleListener类型，它通过重写的Write和WriteLine方法将分发给它的日志输出到控制台上。这个自定义的ConsoleListener可以通过如下的方式来使用。
using App; using System.Diagnostics; var source = new TraceSource("Foobar", SourceLevels.Warning); source.Listeners.Add(new ConsoleListener()); var eventTypes = (TraceEventType[])Enum.GetValues(typeof(TraceEventType)); var eventId = 1; Array.ForEach(eventTypes, it => source.TraceEvent(it, eventId++,$"This is a {it} message."));
如上面的代码片段所示，TraceSource对象的Listeners属性维护了一组注册的TraceListener对象，我们只需要将创建的ConsoleListener对象添加到这个列表中即可。由于这个针对控制台的TraceListener的存在，满足过滤条件的三条日志消息将以图3所示的形式输出到控制台上。
图3 通过注册的ConsoleListener写入的日志
[S704]EventSource事件日志
EventSource最初是微软为Windows操作系统自身的日志框架ETW（Event Tracing for Windows）设计的，目前已经没有平台的限制。这是一种非常高效的记录日志的方式，它提供的强类型的编程方式可以使记录日志变得很“优雅”。EventSource所谓的强类型编程模式主要体现在如下两个方面：其一，我们可以继承抽象类EventSource定义一个具体的派生类型，并将发送日志事件的操作实现在它的某个方法中；其二，日志消息的内容可以通过一个自定义的数据类型来承载。
我们可以将下面演示程序中的DatabaseSource视为某个数据库访问组件拥有的EventSource。我们将其定义成一个封闭（Sealed）的类型，并利用静态只读字段Instance以单例的形式来使用这个对象。我们针对“SQL命令执行”这一事件定义了对应的OnCommandExecute方法，该方法的两个参数分别表示DbCommand的类型（CommandType ）和文本（存储过程名称或者SQL语句）。OnCommandExecute方法最终调用继承的WriteEvent方法来发送日志事件。该方法的第一个参数1代表日志事件的ID。
public sealed class DatabaseSource : EventSource { public static readonly DatabaseSource Instance = new(); private DatabaseSource() {} public void OnCommandExecute(CommandType commandType, string commandText) => WriteEvent(1, commandType, commandText); }
我们在如下所示的演示程序中利用Instance字段得到了对应的DatabaseSource 对象，并以如下的形式调用了它的OnCommandExecute方法。
using App; using System.Data; DatabaseSource.Instance.OnCommandExecute(CommandType.Text, "SELECT * FROM T_USER");
一个EventSource同样具有一个确定的名称。从ETW层面来讲，EventSource的名称就是ETW Provider的名称。自定义的EventSource类型默认会以类型名称来命名，所以演示实例采用的EventSource名称为“DatabaseSource”。日志事件需要有一个具有唯一性的整数作为ID，如果没有显式设置，系统会采用从1开始自增的方式为每个日志方法分配一个ID。由于DatabaseSource中只定义了一个唯一的日志方法OnCommandExecute，那么它被赋予的ID自然是1。事件方法在调用WriteEvent方法发送日志事件时，需要指定与当前方法匹配的事件ID，这就是该方法在调用WriteEvent方法时将第一个参数设置为1的原因。
由于EventSource具有向ETW日志系统发送日志事件的能力，所以我们可以利用一些工具来收集这些事件。笔者习惯使用的是一款叫作PerfView的GUI工具，这是一款可以在网上直接下载的性能分析工具，解压缩后就是一个可执行文件。笔者倾向于将该工具所在的目录添加到环境变量PATH中，这样就可以采用命令行的形式进行启动。我们可以采用Run和Collect这两种模式启动PerfView：前者利用PerfView启动和检测某个指定的应用，后者则独立启动PerfView并检测当前运行的所有应用进程。我们可以将应用所在根目录作为工作目录，并以Run执行命令“PerfView /onlyproviders=*DatabaseSource run dotnet run”启动PerfView。为了将自定义的Trace Provider纳入PerfView的检测范围，我们将命令行开关onlyproviders设置为“*DatabaseSource”。PerfView run命令执行的应用程序为“dotnet run”，这就意味着我们的演示程序将作为监测程序被启动。
PerfView会将捕获到的日志打包到当前目录下一个名为PerfViewData.etl.zip的压缩文件中，它左侧的目录结构会以图7-5所示的形式列出该文件。双击该文件展开其子节点后会看到一个Events节点，PerfView捕捉到的日志就可以通过它来查看。双击Events节点后，图4所示的事件视图将会列出捕获到的所有日志事件，我们可以输入“DatabaseSource”筛选由DatabaseSource发送的事件。从图4中可以看到，DatabaseSource共发送了两个事件，其中一个就是OnCommandExecute。双击事件视图左侧的“OnCommandExecute”可以查看该事件的详细信息，调用对应日志方法时提供的数据会包含在Rest列中，内容如下: ThreadID=”17,608″ commandType=”Text” commandText=”SELECT * FROM T_USER”。
图4 利用PerfView启动并检测应用程序
[S705]自定义EventListener监听事件
虽然系统会根据默认的规则来命名自定义EventSource的名称和日志输出方法的事件ID，但是对它们进行显式设置是更好的选择。如下面的代码片段所示，我们在DatabaseSource类型上通过标注的EventSourceAttribute特性将名称设置为“Artech-Data-SqlClient”，OnCommandExecute方法利用标注的EventAttribute特性将事件ID设置为1。
[EventSource(Name ="Artech-Data-SqlClient")] public sealed class DatabaseSource : EventSource { ... [Event(1)] public void OnCommandExecute(CommandType commandType, string commandText) => WriteEvent(1, commandType, commandText); }
除利用PerfView捕捉EventSource对象触发的事件外，我们还可以通过EventListener对象达到相同的目的。我们定义了如下这个与DatabaseSource 对应的DatabaseSourceListener类型。如的代码片段所示，该类型继承自抽象类EventListener。它的OnEventSourceCreated方法能够感知到当前进程中所有EventSource对象的创建，所以我们重写了该方法对匹配EventSource实施过滤，并最终通过调用EnableEvents方法订阅由目标EventSource发出的全部或者部分等级的事件。针对订阅事件的处理实现在重写的OnEventWritten方法中。
public class DatabaseSourceListener : EventListener { protected override void OnEventSourceCreated(EventSource eventSource) { if (eventSource.Name == "Artech-Data-SqlClient") { EnableEvents(eventSource, EventLevel.LogAlways); } } protected override void OnEventWritten(EventWrittenEventArgs eventData) { Console.WriteLine($"EventId: {eventData.EventId}"); Console.WriteLine($"EventName: {eventData.EventName}"); Console.WriteLine($"Payload"); var index = 0; if (eventData.PayloadNames != null) { foreach (var payloadName in eventData.PayloadNames) { Console.WriteLine($"\t{payloadName}:{eventData.Payload?[index++]}"); } } } }
我们在OnEventSourceCreated方法中通过调用EnableEvents方法对由DatabaseSource发出的所有事件（EventLevel.LogAlways）进行了订阅，所以只有DatabaseSource对象发出的日志事件能够被捕捉到。在重写的OnEventWritten方法中，作为唯一参数的EventWrittenEventArgs对象承载了日志事件的所有信息，我们将事件的ID、名称和荷载数据（Payload）输出到控制台上。
using App; using System.Data; _= new DatabaseSourceListener(); DatabaseSource.Instance.OnCommandExecute(CommandType.Text, "SELECT * FROM T_USER");
EventListener并不需要显式注册，所以只需要按照如上所示的方式在程序启动的时候创建DatabaseSourceListener对象即可。程序运行之后，由DatabaseSourceListener对象捕获的日志事件信息会以图5所示的形式输出到控制台上。
图5 利用自定义的EventListener捕捉日志事件
[S706]DiagnosticListener诊断日志
基于TraceSource和EventSource的日志框架主要关注的是日志荷载内容在进程外的处理，所以被TraceSource对象作为内容荷载的对象必须是一个字符串；虽然EventSource对象可以使用一个对象作为内容荷载，但是最终输出的其实还是序列化后的结果。基于DiagnosticSource的日志框架采用了不一样的设计思路：作为发布者的DiagnosticSource对象将原始的日志荷载对象直接分发给订阅者进行处理，事件的触发和监听处理是同步执行的。同样是采用观察者模式，它做得似乎更加彻底，因为作为发布者和订阅者的类型显式地实现了IObservable<T>与IObserver<T>接口。
IObservable<T>接口代表可被观察的对象，也就是被观察者/发布者。IObserver<T>接口代表观察者/订阅者。IObservable<T>接口定义了用来订阅主题的唯一方法Subscribe。IObserver<T>接口则提供了三个方法，其中核心方法OnNext用于处理发布主题，OnCompleted方法会在所有主题发布结束后被执行，OnError方法则作为发布过程中出现错误时采用的异常处理器。
public interface IObservable<out T> { IDisposable Subscribe(IObserver<T> observer); } public interface IObserver<in T> { void OnCompleted(); void OnError(Exception error); void OnNext(T value); }
为了便于演示，我们预先定义了如下这个通用的观察者类型Observer<T>。如下代码片段所示，它实现了IObserver<T>接口，我们利用初始化时提供的Action<T>对象来实现其OnNext方法，而OnError和OnCompleted方法则不执行任何操作。
public class Observer<T> : IObserver<T> { private readonly Action<T> _onNext; public Observer(Action<T> onNext) => _onNext = onNext; public void OnCompleted() { } public void OnError(Exception error) { } public void OnNext(T value) => _onNext(value); }
我们以如下的形式采用DiagnosticSource诊断日志来实现上面演示的针对数据库命令执行的日志输出场景。DiagnosticSource是一个抽象类型，我们使用的是它的子类DiagnosticListener。也就是说DiagnosticListener的角色是发布者，而不是订阅者，这一点和它的命名不太相符。如下面的代码片段所示，我们创建了一个命名为“Artech-Data-SqlClient”的DiagnosticListener对象，然后调用其Write方法完成日志事件的发送。日志事件被命名为“CommandExecution”，荷载内容是包含CommandType和CommandText两个属性的匿名对象。
using App; using System.Data; using System.Diagnostics; DiagnosticListener.AllListeners.Subscribe(new Observer<DiagnosticListener>( listener => { if (listener.Name == "Artech-Data-SqlClient") { listener.Subscribe(new Observer<KeyValuePair<string, object?>>(eventData => { Console.WriteLine($"Event Name: {eventData.Key}"); if (eventData.Value != null) { dynamic payload = eventData.Value; Console.WriteLine($"CommandType: {payload.CommandType}"); Console.WriteLine($"CommandText: {payload.CommandText}"); } })); } })); var source = new DiagnosticListener("Artech-Data-SqlClient"); if (source.IsEnabled("CommandExecution")) { source.Write("CommandExecution", new {CommandType = CommandType.Text,CommandText = "SELECT * FROM T_USER"}); }
DiagnosticListener类型的静态属性AllListeners以一个IObservable<DiagnosticListener>对象的形式提供当前进程内创建的所有DiagnosticListener对象，我们调用它的Subscribe方法注册了一个Observer<DiagnosticListener>对象。在根据名称筛选出带订阅的目标DiagnosticListener对象之后，我们调用其Subscribe方法注册了一个Observer<KeyValuePair<string, object>>对象，并用它监听发出的日志事件。
日志事件的所有信息体现在作为泛型参数的KeyValuePair<string, object>对象中，它的Key和Value分别表示事件的名称与荷载内容。由于我们已经知道了作为荷载内容的数据结构，所以可以采用动态类型的方式将成员的值提取出来。该程序启动之后，DiagnosticListener对象记录的日志内容会以图6所示的形式输出到控制台上。
图6 捕捉DiagnosticListener发出的日志事件
[S707]为DiagnosticListener注册强类型订阅者
上面演示的实例通过为DiagnosticListener对象显式注册一个IObserver<KeyValuePair<string, object>>对象的方式来捕捉由它发出的日志事件，实际上我们还有一种更加简便的编程方式。由于每个DiagnosticListener对象发出的日志事件都有一个确定的名称，并且总是将提供的荷载对象原封不动地分发给注册的订阅者，如果能够解决事件名称与方法之间以及日内容荷载对象成员与方法参数之间的映射，我们就能够使用一个具体的类型作为DiagnosticListener的订阅者。这种强类型的日志记录方式实现在 “Microsoft.Extensions.DiagnosticAdapter”这个NuGet包中。
在添加了上述NuGet包的引用之后，我们定义了如下这个名为DatabaseSourceCollector订阅类型。如代码片段所示，我们在OnCommandExecute方法上通过标注的DiagnosticNameAttribute特性实现了与订阅事件（“CommandExecution”）的关联。OnCommandExecute方法定义了两个参数（commandType和commandText），它们的类型和名称刚好与日志荷载对象对应的成员相匹配。
public class DatabaseSourceCollector { [DiagnosticName("CommandExecution")] public void OnCommandExecute(CommandType commandType, string commandText) { Console.WriteLine($"Event Name: CommandExecution"); Console.WriteLine($"CommandType: {commandType}"); Console.WriteLine($"CommandText: {commandText}"); } }
为了使用上面的DatabaseSourceCollector 对象来捕捉发出的日志事件，我们对演示程序进行了改写。如下面的代码片段所示，我们不再创建并注册一个IObserver<KeyValuePair<string, object>>对象，而是调用SubscribeWithAdapter扩展方法将DatabaseSourceCollector对象注册为日志订阅者。由于捕捉到的日志事件的相关信息在OnCommandExecute方法中采用与上面完全一致的输出结构，所以应用程序启动之后同样会在控制台上呈现出与图7-7完全一致的内容（S707）。
using App; using System.Data; using System.Diagnostics; DiagnosticListener.AllListeners.Subscribe( new Observer<DiagnosticListener>( listener => { if (listener.Name == "Artech-Data-SqlClient") { listener.SubscribeWithAdapter(new DatabaseSourceCollector()); }})); var source = new DiagnosticListener("Artech-Data-SqlClient"); source.Write("CommandExecution", new { CommandType = CommandType.Text, CommandText = "SELECT * FROM T_USER" });
