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" });
