一個好的程序員能夠在系統出現問題之后馬上定位錯誤的根源並找到正確的解決方案,一個更好的程序員能夠根據當前的運行狀態預知未來可能發生的問題,並將問題扼殺在搖籃中。診斷跟蹤能夠幫助我們有效地糾錯和排錯《幾種基本診斷跟蹤編程方式》提供了7個實例演示了針對TraceSource、EventSource和DiagnosticSource的基本用法,其實它們還具有一個更“高級”的使用方式。(本篇提供的實例已經匯總到《ASP.NET Core 6框架揭秘-實例演示版》)
[S708]DefaultTraceListener針對文件的日志輸出(源代碼)
[S709]利用DelimitedListTraceListener將日志輸出到CSV文件(源代碼)
[S710]更加完整的EventListener類型定義(源代碼)
[S711]利用EventSource的事件日志輸出調用鏈(源代碼)
[S712]AnonymousObserver<T>的應用(源代碼)
[S713]強類型診斷事件訂閱(源代碼)
[S708]DefaultTraceListener針對文件的日志輸出
在跟蹤日志框架中,我們利用注冊的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)的形式寫入指定的文件而已。
[S709]利用DelimitedListTraceListener將日志輸出到CSV文件
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輸出的日志文件
[S710]更加完整的EventListener類型定義
上一篇已經演示了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屬性返回的依然是沒有做任何格式化的原始信息,筆者認為這是值得改進的地方。
[S711]利用EventSource的事件日志輸出調用鏈
我們接下來通過一個簡單的實例來演示如何利用自定義的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所示。
我們在演示程序中調用了FooAsync方法,並在這之前創建了一個FoobarListener對象來訂閱日志事件,進而將格式化的事件信息寫入指定的.csv文件中。程序運行之后,我們會在.csv文件中看到8條對應的日志事件記錄。如圖5所示,Start事件和Stop事件分別記錄了活動的開始時間戳與耗時,而ActivityId和RelatedActivityId可以清晰地反映整個調用鏈的流轉。
[S712]AnonymousObserver<T>的應用
不論是代表發布者的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所示。
[S713]強類型診斷事件訂閱
為了降低日志事件發布者和訂閱者之間的耦合度,日志事件的內容荷載在很多情況下都會采用匿名類型對象來表示。正因為如此,在本章開篇和前面演示的實例中,我們只能采用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()); } }); ...