一个好的程序员能够在系统出现问题之后马上定位错误的根源并找到正确的解决方案，一个更好的程序员能够根据当前的运行状态预知未来可能发生的问题，并将问题扼杀在摇篮中。诊断跟踪能够帮助我们有效地纠错和排错《几种基本诊断跟踪编程方式》提供了7个实例演示了针对TraceSource、EventSource和DiagnosticSource的基本用法，其实它们还具有一个更“高级”的使用方式。(
一个好的程序员能够在系统出现问题之后马上定位错误的根源并找到正确的解决方案，一个更好的程序员能够根据当前的运行状态预知未来可能发生的问题，并将问题扼杀在摇篮中。诊断跟踪能够帮助我们有效地纠错和排错《几种基本诊断跟踪编程方式》提供了7个实例演示了针对TraceSource、EventSource和DiagnosticSource的基本用法，其实它们还具有一个更“高级”的使用方式。(本篇提供的实例已经汇总到《ASP.NET Core 6框架揭秘-实例演示版》）
[S708]DefaultTraceListener针对文件的日志输出[S708]DefaultTraceListener针对文件的日志输出（源代码）
[S709]利用DelimitedListTraceListener将日志输出到CSV文件（源代码）
[S710]更加完整的EventListener类型定义（源代码）
[S711]利用EventSource的事件日志输出调用链（源代码）
[S712]AnonymousObserver<T>的应用（源代码）
[S713]强类型诊断事件订阅（源代码）
在跟踪日志框架中，我们利用注册的TraceListener对象对跟踪日志消息进行持久化存储（如将格式化的日志消息保存在文件或者数据库中）或者可视化显示（如输出到控制台上），又或者是将它们发送到远程服务做进一步处理。跟踪日志系统定义了几个原生的TraceListener类型。默认使用的是如下这个DefaultTraceListener类型。创建的TraceSource对象会自动注册具有如下定义的DefaultTraceListener对象，后者会将日志消息作为调试信息发送给调试器。DefaultTraceListener对象还可以帮助我们将日志内容写入指定的文件，文件的路径可以通过LogFileName属性来指定。
public class DefaultTraceListener: TraceListener { public string LogFileName { get; set; } public override void Write(string message); public override void WriteLine(string message); ... }
我们通过一个简单的程序来演示DefaultTraceListener针对文件的日志输出。如代码片段所示，在创建一个TraceSource对象之后，我们将默认注册的TraceListener清除，然后注册了根据指定的日志文件（trace.log）创建的DefaultTraceListener对象，然后针对每种事件类型输出了一条日志。
using System.Diagnostics; var source = new TraceSource("Foobar", SourceLevels.All); source.Listeners.Clear(); source.Listeners.Add(new DefaultTraceListener { LogFileName = "trace.log" }); var eventTypes = (TraceEventType[])Enum.GetValues(typeof(TraceEventType)); var eventId = 1; Array.ForEach(eventTypes, it => source.TraceEvent(it, eventId++, $"This is a {it} message."));
运行程序后我们会发现编译输出目录下会生成一个trace.log文件，程序中生成的10条跟踪日志会逐条写入该文件中（见图1）。DefaultTraceListener在进行针对文件的日志输出的时候，仅仅是将格式化的日志消息以追加（Append）的形式写入指定的文件而已。
图1 针对静态类型Trace的跟踪事件分发处理机制
DelimitedListTraceListener是TextWriterTraceListener的子类，它在对跟踪日志信息进行格式化的时候会采用指定的分隔符。默认情况下采用分号（“；”）作为分隔符。由于跟踪日志的内容荷载最终都会格式化成一个字符串，字符串的输出可以由一个TextWriter对象来完成。一个TextWriterTraceListener对象利用封装的TextWriter对象完成针对跟踪日志内容的输出工作。如下面的代码片段所示，这个TextWriter对象体现在TextWriterTraceListener的Writer属性上。
public class DelimitedListTraceListener : TextWriterTraceListener { public string Delimiter { get; set; } public DelimitedListTraceListener(Stream stream); public DelimitedListTraceListener(TextWriter writer); public DelimitedListTraceListener(string fileName); public DelimitedListTraceListener(Stream stream, string name); public DelimitedListTraceListener(TextWriter writer, string name); public DelimitedListTraceListener(string fileName, string name); public override void TraceData(TraceEventCache eventCache, string source, TraceEventType eventType, int id, object data); public override void TraceData(TraceEventCache eventCache, string source, TraceEventType eventType, int id, params object[] data); public override void TraceEvent(TraceEventCache eventCache, string source, TraceEventType eventType, int id, string message); public override void TraceEvent(TraceEventCache eventCache, string source, TraceEventType eventType, int id, string format, params object[] args); }
基于分隔符的格式化实现在重写的TraceData方法和TraceEvent方法中，所以调用TraceSource对象的Write或者WriteLine方法时输出的内容不会采用分隔符进行分隔。对于第二个TraceData方法重载，如果传入的内容荷载对象是一个数组，那么每个元素之间同样会采用分隔符进行分隔。在默认情况下采用的分隔符为逗号（“，”），但是如果Delimiter属性表示的主分隔符为逗号，此分隔符就会选择分号（“；”）。如下所示的代码片段展示了在选用默认分隔符的情况下分别通过TraceData方法和TraceEvent方法输出的文本格式。
TraceData 1：
{SourceName};{EventType};{EventId};{Data};{ProcessId};{LogicalOperationStack};{ThreadId};{DateTime};{Timestamp};TraceData 2：
{SourceName};{EventType};{EventId};{Data1},{Data2},...,{DataN};{ProcessId};{LogicalOperationStack};{ThreadId};{DateTime};{Timestamp};TraceEvent
{SourceName};{EventType};{EventId};{Message};;{ProcessId};{LogicalOperationStack};{ThreadId};{DateTime};{Timestamp};上面展示的跟踪日志输出格式中的占位符“{LogicalOperationStack}”表示当前逻辑操作的调用堆栈。上述代码片段还揭示了另一个细节，那就是对TraceEvent方法的输出格式来说，在表示日志消息主体内容的“{Message}”和表示进程ID的“{ProcessId}”之间会出现两个分隔符，这可能是一个漏洞（Bug）。如果我们采用逗号（“，”）作为分隔符，那么最终输出的就是一个CSV（Comma Separated Value）文件。例如在如下所示的实例演示中，我们将当前目录下一个名为trace.csv的文件作为日志文件，然后根据这个文件的FileStream创建了一个DelimitedListTraceListener对象并将其注册到TraceSource对象上，最后针对每种事件类型输出了10条日志。
using System.Diagnostics; var fileName = "trace.csv"; File.AppendAllText(fileName, @$"SourceName,EventType,EventId,Message,N/A,ProcessId,LogicalOperationStack, hreadId, DateTime, Timestamp,{ Environment.NewLine}"); using (var fileStream = new FileStream(fileName, FileMode.Append)) { var options = TraceOptions.Callstack | TraceOptions.DateTime |TraceOptions.LogicalOperationStack | TraceOptions.ThreadId | TraceOptions.Timestamp; var listener = new DelimitedListTraceListener(fileStream){ TraceOutputOptions = options, Delimiter = "," }; var source = new TraceSource("Foobar", SourceLevels.All); source.Listeners.Add(listener); var eventTypes = (TraceEventType[])Enum.GetValues(typeof(TraceEventType)); for (int index = 0; index < eventTypes.Length; index++) { var enventType = eventTypes[index]; var eventId = index + 1; Trace.CorrelationManager.StartLogicalOperation($"Op{eventId}"); source.TraceEvent(enventType, eventId, $"This is a {enventType} message."); } source.Flush(); }
为了演示上面提到的逻辑操作的调用堆栈，我们利用Trace类型得到一个CorrelationManager对象，并调用其StartLogicalOperation方法启动一个以“Op{EventId}”格式命名的逻辑操作。由于DelimitedListTraceListener对象内部采用了缓冲机制，所以我们人为地调用了TraceSource对象的Flush方法强制输出缓冲区中的跟踪日志。程序运行之后输出的10条跟踪日志将全部记录在trace.csv文件中，如果直接利用Excel打开这个文件，就会看到图2所示的内容。
图2 通过DelimitedListTraceListener输出的日志文件
上一篇已经演示了EventSource和EventListener的简单用法，我们接下来做一个更加完整的演示。我们先以常量的形式预定义几个EventTask和EventTags对象，前者表示操作执行所在的应用层次，后者表示三种典型的关系数据库类型。
public class Tasks { public const EventTask UI = (EventTask)1; public const EventTask Business = (EventTask)2; public const EventTask DA = (EventTask)3; } public class Tags { public const EventTags MSSQL = (EventTags)1; public const EventTags Oracle = (EventTags)2; public const EventTags Db2 = (EventTags)3; }
我们依然沿用执行SQL命令的应用场景，为此我们对之前定义的DatabaseSource类型作一些简单的修改。如代码片段所示，我们在日志方法OnCommandExecute上标注了EventAttribute特性对它的所有属性都做了相应的设置，其中Task和Tags属性使用的是上面定义的常量。值得注意的是，我们为Message属性设置了一个包含占位符的模板。OnCommandExecute方法在调用WriteEvent方法发送日志事件之前，先利用IsEnabled方法确认EventSource对象针对指定的等级和输出渠道已经被订阅。
[EventSource(Name = "Artech-Data-SqlClient")] public sealed class DatabaseSource : EventSource { public static DatabaseSource Instance = new DatabaseSource(); private DatabaseSource() {} [Event(1, Level = EventLevel.Informational, Keywords = EventKeywords.None, Opcode = EventOpcode.Info, Task = Tasks.DA, Tags = Tags.MSSQL, Version = 1, Message = "Execute SQL command. Type: {0}, Command Text: {1}")] public void OnCommandExecute(CommandType commandType, string commandText) { if (IsEnabled(EventLevel.Informational, EventKeywords.All, EventChannel.Debug)) { WriteEvent(1, (int)commandType, commandText); } } }
我们采用如下的代码对作为日志事件订阅者的DatabaseSourceListener类型的进行了重新定义。为了验证接收的日志事件是否与OnCommandExecute方法中的订阅一致，我们在重写的OnEventWritten方法中输出了EventWrittenEventArgs对象的所有属性。
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($"Channel: {eventData.Channel}"); Console.WriteLine($"Keywords: {eventData.Keywords}"); Console.WriteLine($"Level: {eventData.Level}"); Console.WriteLine($"Message: {eventData.Message}"); Console.WriteLine($"Opcode: {eventData.Opcode}"); Console.WriteLine($"Tags: {eventData.Tags}"); Console.WriteLine($"Task: {eventData.Task}"); Console.WriteLine($"Version: {eventData.Version}"); Console.WriteLine($"Payload"); var index = 0; if (eventData.PayloadNames != null) { foreach (var payloadName in eventData.PayloadNames) { Console.WriteLine($"\t{payloadName}:{eventData.Payload?[index++]}"); } } } }
在如上所示的演示程序中，我们创建了一个DatabaseSourceListener对象。在提取出单例形式的DatabaseSource对象后，我们调用了它的OnCommandExecute发送了一个关于SQL命令执行的日志事件。
using App; using System.Data; _ = new DatabaseSourceListener(); DatabaseSource.Instance.OnCommandExecute(CommandType.Text, "SELECT * FROM T_USER");
程序运行之后，日志事件的详细信息会以图3所示的形式输出到控制台上。我们从输出结果可以发现EventWrittenEventArgs的Message属性返回的依然是没有做任何格式化的原始信息，笔者认为这是值得改进的地方。
图3 针对静态类型Trace的跟踪事件分发处理机制
我们接下来通过一个简单的实例来演示如何利用自定义的EventSource和EventListener来完成针对活动的跟踪。假设一个完整的调用链由Foo、Bar、Baz和Qux这四个活动组成，为此我们定义如下这个FoobarSource，并针对四个活动分别定义了四组对应的事件方法，其中“{Op}Start”和“{Op}Stop”方法分别对应活动的开始与结束事件，前者的荷载信息包含活动开始的时间戳，后者的荷载信息包含操作耗时。
[EventSource(Name = "Foobar")] public sealed class FoobarSource : EventSource { public static readonly FoobarSource Instance = new(); [Event(1)] public void FooStart(long timestamp) => WriteEvent(1, timestamp); [Event(2)] public void FooStop(double elapsed) => WriteEvent(2, elapsed); [Event(3)] public void BarStart(long timestamp) => WriteEvent(3, timestamp); [Event(4)] public void BarStop(double elapsed) => WriteEvent(4, elapsed); [Event(5)] public void BazStart(long timestamp) => WriteEvent(5, timestamp); [Event(6)] public void BazStop(double elapsed) => WriteEvent(6, elapsed); [Event(7)] public void QuxStart(long timestamp) => WriteEvent(7, timestamp); [Event(8)] public void QuxStop(double elapsed) => WriteEvent(8, elapsed); }
如下所示的FoobarListener会订阅上面的这些事件，并将接收的调用链信息保存到一个.csv文件中（log.csv）。在重写的OnEventSourceCreated方法中，我们除了根据EventSource的名称订阅由FoobarSource发出的八个事件外，还需要订阅TplEtwProvider发出的用于保存活动流转信息的事件。本着尽量缩小订阅范围的原则，我们在调用EnableEvents方法时采用日志等级和关键字对订阅事件进行了过滤。在重写的OnEventWritten方法中，我们将捕捉到的事件信息（名称、活动开始时间戳和耗时、ActivityId和RelatedActivityId）进行格式化后写入指定的.csv文件中。
public sealed class FoobarListener : EventListener { protected override void OnEventSourceCreated(EventSource eventSource) { if (eventSource.Name == "System.Threading.Tasks.TplEventSource") { EnableEvents(eventSource, EventLevel.Informational, (EventKeywords)0x80); } if (eventSource.Name == "Foobar") { EnableEvents(eventSource, EventLevel.LogAlways); } } protected override void OnEventWritten(EventWrittenEventArgs eventData) { if (eventData.EventSource.Name == "Foobar") { var timestamp = eventData.PayloadNames?[0] == "timestamp"? eventData.Payload?[0]: ""; var elapsed = eventData.PayloadNames?[0] == "elapsed"? eventData.Payload?[0]: ""; var relatedActivityId = eventData.RelatedActivityId == default? "": eventData.RelatedActivityId.ToString(); var line = @$"{eventData.EventName},{timestamp},{elapsed},{ eventData.ActivityId},{ relatedActivityId}"; File.AppendAllLines("log.csv", new string[] { line }); } } }
如下所示的代码片段可以模拟由Foo、Bar、Baz和Qux这四个活动组成的调用链。针对这些活动的控制实现在InvokeAsync方法中，该方法的参数start和stop提供的委托对象分别用来发送活动的开始事件与结束事件，至于参数body返回的Task对象则代表了活动自身的操作。为了模拟活动耗时，我们人为地等待了一个随机的时间。
using App; using System.Diagnostics; var random = new Random(); File.AppendAllLines("log.csv", new string[] { @"EventName,StartTime,Elapsed,ActivityId,RelatedActivityId" }); var listener = new FoobarListener(); await FooAsync(); Task FooAsync() => InvokeAsync(FoobarSource.Instance.FooStart, FoobarSource.Instance.FooStop, async () => { await BarAsync(); await QuxAsync(); }); Task BarAsync() => InvokeAsync(FoobarSource.Instance.BarStart, FoobarSource.Instance.BarStop, BazAsync); Task BazAsync() => InvokeAsync(FoobarSource.Instance.BazStart,FoobarSource.Instance.BazStop, () => Task.CompletedTask); Task QuxAsync() => InvokeAsync(FoobarSource.Instance.QuxStart, FoobarSource.Instance.QuxStop, () => Task.CompletedTask); async Task InvokeAsync(Action<long> start, Action<double> stop, Func<Task> body) { start(Stopwatch.GetTimestamp()); var sw = Stopwatch.StartNew(); await Task.Delay(random.Next(10, 100)); await body(); stop(sw.ElapsedMilliseconds); }
四个活动分别实现在四个对应的方法中（FooAsync、BarAsync、BazAsync和QuxAsync），为了模拟基于Task的异步编程，我们让这四个方法统一返回一个Task对象。从这四个方法的定义可以看出，它们体现的调用链如图4所示。
图4 由相关活动构建的调用链
我们在演示程序中调用了FooAsync方法，并在这之前创建了一个FoobarListener对象来订阅日志事件，进而将格式化的事件信息写入指定的.csv文件中。程序运行之后，我们会在.csv文件中看到8条对应的日志事件记录。如图5所示，Start事件和Stop事件分别记录了活动的开始时间戳与耗时，而ActivityId和RelatedActivityId可以清晰地反映整个调用链的流转。
图5 记录在.csv文件中的调用链信息
不论是代表发布者的DiagnosticListener对象，还是定义在该类型上代表所有DiagnosticListener对象的静态属性AllListeners，它们都体现为一个IObservable<T>对象。要完成针对它们的订阅，我们需要创建一个对应的IObserver<T>对象，AnonymousObserver<T>就是对IObserver<T>接口的一个简单的实现。AnonymousObserver<T>定义在NuGet包“System.Reactive.Core”中，它采用与开篇演示实例提供的Observer<T>一样的实现方式，即通过指定的委托对象（Action<T>和Action<Exception>）来实现IObservable<T>接口的三个方法。如下所示的代码片段体现了Web服务器针对一次HTTP请求处理的日志输出，服务器在接收请求后以日志的方式输出请求上下文信息和当前时间戳，在成功发送响应之后输出响应消息和整个请求处理的耗时。
using System.Diagnostics; using System.Net; DiagnosticListener.AllListeners.Subscribe(listener => { if (listener.Name == "Web") { listener.Subscribe(eventData => { if (eventData.Key == "ReceiveRequest" && eventData.Value != null) { dynamic payload = eventData.Value; var request = (HttpRequestMessage)(payload.Request); var timestamp = (long)payload.Timestamp; Console.WriteLine(@$"Receive request. Url: {request.RequestUri};Timstamp:{ timestamp}"); } if (eventData.Key == "SendReply" && eventData.Value != null) { dynamic payload = eventData.Value; var response = (HttpResponseMessage)(payload.Response); var elaped = (TimeSpan)payload.Elaped; Console.WriteLine($"Send reply. Status code: {response.StatusCode}; Elaped: {elaped}"); } }); } }); var source = new DiagnosticListener("Web"); var stopwatch = Stopwatch.StartNew(); if (source.IsEnabled("ReceiveRequest")) { var request = new HttpRequestMessage(HttpMethod.Get, "https://www.artech.top"); source.Write("ReceiveRequest", new { Request = request, Timestamp = Stopwatch.GetTimestamp() }); } await Task.Delay(100); if (source.IsEnabled("SendReply")) { var response = new HttpResponseMessage(HttpStatusCode.OK); source.Write("SendReply", new { Response = response, Elaped = stopwatch.Elapsed }); }
对于诊断日志发布的部分，我们需要先创建一个名为Web的DiagnosticListener对象，并利用开启的Stopwatch来计算请求处理耗时。我们利用手动创建的HttpRequestMessage对象来模拟接收到的请求，在调用Write方法发送一个名为“ReceiveRequest”的日志事件时，该HttpRequestMessage对象连同当前时间戳以一个匿名对象的形式作为日志的内容荷载对象。在人为地等待100毫秒以模拟请求处理耗时之后，我们调用DiagnosticListener对象的Write方法发出名为“SendReply”的日志事件，标志着针对当前请求的处理已经结束，作为内容荷载的匿名对象包含手动创建的一个HttpResponseMessage对象和模拟耗时。
程序前半段针对日志事件的订阅是通过调用Subscribe扩展方法实现的，在指定的Action<DiagnosticListener>委托对象中，我们根据名称过滤出作为订阅目标的DiagnosticListener对象，然后订阅它的ReceiveRequest和SendReply事件。对于订阅的ReceiveRequest事件，我们采用动态类型（dynamic）的方式得到了代表当前请求的HttpRequestMessage对象和时间戳，并将请求URL和时间戳打印出来。SendReply事件以用相同的方法提取代表响应消息的HttpResponseMessage对象和耗时，并将响应状态码和耗时打印出来。程序运行之后，在控制台上看到的输出结果如图6所示。
图6 针对请求的跟踪
为了降低日志事件发布者和订阅者之间的耦合度，日志事件的内容荷载在很多情况下都会采用匿名类型对象来表示。正因为如此，在本章开篇和前面演示的实例中，我们只能采用dynamic关键字将荷载对象转换成动态类型后才能提取出所需的成员。由于匿名类型并非公共类型，所以上述方式仅限于发布程序和订阅程序都在同一个程序集中才使用。在不能使用动态类型提取数据成员的情况下，我们不得不采用反射或者表达式树的方式来解决这个问题，虽然可行但会变得很烦琐。
强类型日志事件订阅以一种很“优雅”的方式解决了这个问题。简单来说，所谓的强类型日志事件订阅就是将日志订阅处理逻辑定义在某个类型对应的方法中，这个方法可以按照日志内容荷载对象的成员结构来定义对应的参数。实现强类型的日志事件订阅需要实现两个“绑定”，即日志事件与方法之间的绑定，以及荷载的数据成员与订阅方法参数之间的绑定。
参数绑定利用荷载成员的属性名与参数名之间的映射来实现，所以订阅方法只需要根据荷载对象的属性成员来决定对应的参数的类型和名称。日志事件与方法之间的映射则可以利用下面的DiagnosticNameAttribute特性来实现，我们只需要在订阅方法上标注这个方法并指定映射的日志事件的名称即可。
public class DiagnosticNameAttribute : Attribute { public string Name { get; } public DiagnosticNameAttribute(string name); }
强类型诊断日志事件的订阅对象可以通过DiagnosticListener的如下几个扩展方法来完成，它们定义在NuGet包“Microsoft.Extensions.DiagnosticAdapter”中。这些SubscribeWithAdapter方法重载在指定对象和标准订阅对象之间做了适配，将指定对象转换成一个IObserver<KeyValuePair<string, object>>对象。
public static class DiagnosticListenerExtensions { public static IDisposable SubscribeWithAdapter(this DiagnosticListener diagnostic, object target); public static IDisposable SubscribeWithAdapter(this DiagnosticListener diagnostic, object target, Func<string, bool> isEnabled); public static IDisposable SubscribeWithAdapter(this DiagnosticListener diagnostic, object target, Func<string, object, object, bool> isEnabled); }
我们接下来将前面演示的实例改造成强类型日志事件订阅的方式。首先定义如下这个DiagnosticCollector作为日志事件订阅类型。可以看出这仅仅是一个没有实现任何接口或者继承任何基类的普通POCO类型。我们定义了OnReceiveRequest和OnSendReply两个日志事件方法，应用在它们上面的DiagnosticNameAttribute特性设置了对应的事件名称。为了自动获取日志内容荷载，可以根据荷载对象的数据结构为这两个方法定义参数。
public sealed class DiagnosticCollector { [DiagnosticName("ReceiveRequest")] public void OnReceiveRequest(HttpRequestMessage request, long timestamp) => Console.WriteLine($"Receive request. Url: {request.RequestUri}; Timstamp:{timestamp}"); [DiagnosticName("SendReply")] public void OnSendReply(HttpResponseMessage response, TimeSpan elaped) => Console.WriteLine($"Send reply. Status code: {response.StatusCode}; Elaped: {elaped}"); }
我们接下来只需要改变之前的日志事件订阅方式即可。如下面的代码片段所示，在根据名称找到作为订阅目标的DiagnosticListener对象之后，我们直接创建DiagnosticCollector对象，并将其作为参数调用SubscribeWithAdapter扩展方法进行注册。改动后的程序运行之后，同样会在控制台上输出图6所示的结果。
using App; using System.Diagnostics; using System.Net; DiagnosticListener.AllListeners.Subscribe(listener => { if (listener.Name == "Web") { listener.SubscribeWithAdapter(new DiagnosticCollector()); } }); ...