225
如何利用ETW（Event Tracing for Windows）記錄日誌
ETW是Event Tracing for Windows的簡稱，它是Windows提供的原生的事件跟蹤日誌係統。由於采用內核（Kernel）層麵的緩衝和日誌記錄機製，所以ETW提供了一種非常高效的事件跟蹤日誌解決方案。
事件監測（Event Instrumentation）總會包含兩個基本的實體，事件的提供者（ETW Provider）和消費者（ETW Consumer），ETW框架可以視為它們的中介。ETW Provider會預先注冊到ETW框架上，提供者程序在某個時刻觸發事件，並將標準化定義的事件提供給ETW框架。Consumer同樣需要注冊到ETW框架上，在注冊的時候可以設置事件的刪選條件和接收處理事件的回掉。對於接收到的事件，如果它滿足某個注冊ETW Consumer的篩選條件，ETW會調用相應的回調來處理該事件。
ETW針對事件的處理是在某個會話（ETW Session）中進行的，ETW Session提供了一個接收、存儲、處理和分發事件的執行上下文。ETW框架可以創建多一個會話來處理由提供者程序發送的事件，但是ETW Session並不會與某個單一的提供者綁定在一起，多個提供者程序可以向同一個ETW Session發送事件。對於接收到的事件，ETW Session可以將它保存在創建的日誌文件中，也可以實時地分發給注冊的消費者應用。ETW會話的開啟和終止是通過 Session的開啟和終止是通過ETW控製器（ETW Controller）進行管理的。除了管理ETW Session之外，ETW Controller還可以禁用（Disable）或者恢複（Enable）注冊到某個ETW Session上的ETW Provider。
綜上所述，整個ETW模型由ETW框架本身和ETW Provider、ETW Consumer以及ETW Controller組成，上圖很好地展示了這四者之間的關係。出於篇幅的限製，我們隻能對ETW作一個粗略的介紹，實際上ETW自身是一個非常強大的事件跟蹤日誌係統，有興趣的朋友可以參閱相關的文檔進行係統學習。
.NET提供了一種比較獨特並且簡單的編程模式編寫針對ETW的事件提供和消費程序。所謂的ETW Provider就是事件的提供者，它體現了事件的來源，對應著一個EventSource對象。EventSource類型定義在“System.Diagnostics.Tracing”這個NuGet包中。如下麵的代碼片段所示，EventSource類型中定義了一係列WriteEvent方法重載，這些方法會觸發一個事件並將其遞交給ETW框架。這些方法具有一個代表事件ID的參數，必須是一個介於[0, 65535] 之間的整數，而其他參數將作為負載（Payload）附加到事件對象上。
1: public class EventSource : IDisposable
2: {
3: ...
4: protected void WriteEvent(int eventId);
5: protected void WriteEvent(int eventId, int arg1);
6: protected void WriteEvent(int eventId, long arg1);
7: protected void WriteEvent(int eventId, string arg1);
8: protected void WriteEvent(int eventId, byte[] arg1);
9:
10: protected void WriteEvent(int eventId, int arg1, int arg2);
11: protected void WriteEvent(int eventId, int arg1, string arg2);
12: protected void WriteEvent(int eventId, long arg1, long arg2);
13: protected void WriteEvent(int eventId, long arg1, string arg2);
14: protected void WriteEvent(int eventId, long arg1, byte[] arg2);
15: protected void WriteEvent(int eventId, string arg1, int arg2);
16: protected void WriteEvent(int eventId, string arg1, long arg2);
17: protected void WriteEvent(int eventId, string arg1, string arg2);
18: protected void WriteEvent(int eventId, int arg1, int arg2, int arg3);
19: protected void WriteEvent(int eventId, long arg1, long arg2, long arg3);
20: protected void WriteEvent(int eventId, string arg1, int arg2, int arg3);
21: protected void WriteEvent(int eventId, string arg1, string arg2, string arg3);
22: }
由於其中一個WriteEvent方法具有一個通過params關鍵字定義的參數，並且參數的類型為對象數組，所以我們可以在編程的時候可以將任意類型和不限數量的對象作為參數，但實際上作為負載的這些參數隻能是原生類型（Primative Type）、字符串、GUID和枚舉這些簡單的類型而已。其實EventSource類型還具有很多其他成員，但是篇幅所限，我們就不對它詳細介紹了。
雖然EventSource並不是一個抽象類，但是我們在具體項目開發中都不會直接創建一個EventSource對象並調用它的WriteEvent方法觸發並向ETW框架一個事件。一般來說，我們會為一組相關的事件定義一個繼承於EventSource的子類，比如我們定義了如下一個SecurityEventSource的類型來寫入與安全相關的事件。
1: [EventSource(Name = "MyApp.Security")]
2: public class SecurityEventSource : EventSource
3: {
4: ...
5: private SecurityEventSource() {}
6: public static readonly SecurityEventSource Instance = new SecurityEventSource();
7: }
一個EventSource對應著注冊到ETW框架上的某一個ETW Provider。每個EventSource對象都具有一個可讀的名稱和一個作為唯一標識的ID，EventSource的名稱和ID實際上就是對應ETW Provider的名稱和ID。EventSource的名稱和ID都派生於自定義EventSource的類型，換句話說，同一類型的多個EventSource具有相同的名稱和ID。如果在應用中使用到了多個具有相同類型的EventSource對象，這必然引起命名衝突和識別上問題，所以我們總是采用Singleton的模式來使用自定義EventSource，這也體現在上麵定義的這個SecurityEventSource類型中。
在默認情況下，自定義EventSource的類型（不含命名空間）將作為對應ETW Provider的名稱。但是在很多情況下，我們希望采用一種路徑話的方式對ETW Provider進行命名以便我們可以看出多個ETW Provider之間的關係，比如我們希望源自當前應用的所有ETW Provider都采用應用的名稱作為前綴，默認的明明策略就滿足不了我們的問題了。在這種情況下，我們可以在自定義的EventSource類型上標注一個EventSourceAttribute特性來指定一個不同的名稱，上麵定義的這個SecurityEventSource正是采用這種方式為對應的ETW Provider起了一個與類型不同的名稱（“MyApp.Security”）。
標注在自定義EventSource類型上的EventSourceAttribute特性除了可以指定名稱之外，還可以通過設置Guid屬性為EventSource指定一個唯一標準。如果沒有顯式指定，EventSource的唯一標識將派生於當前的類型，所以我們其實並不推薦顯式指定這個Guid屬性。從下麵的代碼片段還可以看出這個EventSourceAttribute還具有一個名為LocalizationResources的屬性，我們可以利用這個屬性指定的資源文件實現本地化。
1: [AttributeUsage(AttributeTargets.Class)]
2: public sealed class EventSourceAttribute : Attribute
3: {
4: public string Guid { get; set; }
5: public string Name { get; set; }
6: public string LocalizationResources { get; set; }
7: }
在默認情況下，自定義EventSource類型上每一個返回類型的void的實例方法都將對應一個事件，而且方法名稱就是事件名稱。我們可以在這些方法上應用一個類型為EventAttribute特性來為目標事件定義一些描述信息。如果我們不希望某個方法映射為一個事件，可以方法上標注一個NonEventAttribute特性。
1: [AttributeUsage(AttributeTargets.Method)]
2: public sealed class NonEventAttribute : Attribute
3: {}
4:
5: [AttributeUsage(AttributeTargets.Method)]
6: public sealed class EventAttribute : Attribute
7: {
8: public EventAttribute(int eventId);
9:
10: public int EventId { get; }
11: public EventLevel Level { get; set; }
12: public string Message { get; set; }
13: public EventKeywords Keywords { get; set; }
14: public EventTags Tags { get; set; }
15: public EventOpcode Opcode { get; set; }
16: public EventTask Task { get; set; }
17: public EventChannel Channel { get; set; }
18: public byte Version { get; set; }
19: public EventActivityOptions ActivityOptions { get; set; }
20: }
如上麵的代碼片段所示，我們可以通過設置EventAttribute的屬性為目標事件提供很多額外的描述。比如我們設置事件的ID（EventId）、等級（Level）和消息（Message）。其中事件等級通過具有如下定義的EventLevel枚舉來表示，該枚舉為我們定義了6個事件等級（由高到低依次是LogAlways、Critical、Error、Warning、Informational和Verbose）。至於EventAttribute的Message屬性，除了指定一個完整的描述當前消息的文本之外，我們還可以在其中定義{0}、{1}和{2}這樣的占位符，執行目標方法指定的參數將依次替換這些占位符。
1: public enum EventLevel
2: {
3: LogAlways,
4: Critical,
5: Error,
6: Warning,
7: Informational,
8: Verbose
9: }
EventAttribute的Keywords和EventTags屬性分別代表為事件指定的關鍵字和標簽，它的Opcode和Task屬性幫助我們將事件映射為一個預定義的操作和任務。這四個屬性的返回類型都是枚舉，但是實際上在很多情況下我們都是將它們當作一個整數在用。舉個簡單的例子，表示操作代碼的EventOpcode枚舉中定義了如下11個選項，並且每個選項都具有一個具體的值，但是我們可以完全忽略它們。我們的應用完全可以按照自己的標準來定義操作代碼，我們可以將整數1映射任何一個操作（比如“登錄”），雖然它在EventOpcode中表示“開啟（Start）”。
1: public enum EventOpcode
2: {
3: Info = 0,
4: Start = 1,
5: Stop = 2,
6: DataCollectionStart = 3,
7: DataCollectionStop = 4,
8: Extension = 5,
9: Reply = 6,
10: Resume = 7,
11: Suspend = 8,
12: Send = 9,
13: Receive = 240,
14: }
ETW Provider提供的事件還可以寫入Event Log，EventAttribute的Channel屬性用於設置Event Log通道（Event Log Channel，可以理解為事件從最初的發布到最終被寫入日誌文件所經曆的傳輸通道）的類型，具體的通道類型定義在如下一個EventChannel枚舉中。如果時間具有版本，我們將版本號定義在EventAttribute的Version屬性上。
1: public enum EventChannel : byte
2: {
3: None = 0,
4: Admin = 0x10,
5: Operational = 0x11,
6: Analytic = 0x12,
7: Debug = 0x13
8: }
我們可以利用ETW事件來追蹤（Track）某個活動（Activity）的開始和終止，而活動開始與終止的追蹤行為可以通過EventAttribute的ActivityOptions屬性來設置。這個屬性對應的EventActivityOptions為我們定義了四種活動追蹤行為，其中None表示默認行為，而Disable則意味著禁止追蹤。Recursive表示可以“遞歸”的方式開啟和終止活動，比如“開始A”-“開始B”-“終止B”-“終止A”。另一個選項Detachable表示多個活動之間可以有重疊，比如“開始A”-“開始B”-“終止A”-“終止B”。
1: [Flags]
2: public enum EventActivityOptions
3: {
4: None = 0,
5: Disable = 2,
6: Recursive = 4,
7: Detachable = 8,
8: }
接下來我們通過一個簡單的實例來演示如何利用自定義的EventSource來編寫ETW事件提供程序。如下所示的是上麵介紹的這個用於跟蹤安全相關事件的SecurityEventSource的完整定義，我們在這個類型上應用了一個EventSourceAttribute特性並名稱設置為“MyApp.Security”。SecurityEventSource之中定義了一個內嵌的Keywords類，她定義了兩個表示ETW事件關鍵字（Authentication和Authorization）的常量，我們用它來區分“認證”和“授權”相關的事件。
1: [EventSource(Name ="MyApp.Security")]
2: public class SecurityEventSource : EventSource
3: {
4: public class Keywords
5: {
6: public const EventKeywords Authentication = (EventKeywords)1;
7: public const EventKeywords Authorization = (EventKeywords)2;
8: }
9:
10: private SecurityEventSource()
11: {}
12:
13: public static readonly SecurityEventSource Instance = new SecurityEventSource();
14:
15: [Event(1,Keywords=Keywords.Authentication, Level = EventLevel.Informational, Message ="用戶{0}認證成功")]
16: public void SignInSuccess(string userName)
17: {
18: this.WriteEvent(1, userName);
19: }
20:
21: [Event(2, Keywords = Keywords.Authentication, Level = EventLevel.Warning, Message = "用戶{0}認證失敗")]
22: public void SignInFail(string userName)
23: {
24: this.WriteEvent(2, userName);
25: }
26:
27: [Event(3, Keywords = Keywords.Authorization, Level = EventLevel.Warning, Message = "用戶{0}執行未授權操作{1}")]
28: public void DenyAccess(string userName, string operation)
29: {
30: this.WriteEvent(3, userName, operation);
31: }
32: }
定義在SecurityEventSource中的三個實例方法對應著三個ETW事件，其中方法SignInSuccess和SignInFail與認證相關，表示認證成功和認證失敗。通過標注的EventAttribute特性可以看出，這兩個ETW事件采用的等級分別為Informational和Warning。我們為這個特性的Message屬性設置了一個包含占位符的模板，占位符代表作為參數傳入的用戶名。另一個方法DenyAccess與授權相關，表示某個用戶試圖執行一個未被授權的操作，我們依然通過標注的EventAttribute事件設置了ETW事件的關鍵字、等級和消息。我們最終在Main方法中按照如下的方式調用這三個方法。
1: SecurityEventSource.Instance.SignInSuccess("張三");
2: SecurityEventSource.Instance.SignInFail("李四");
3: SecurityEventSource.Instance.DenyAccess("王五", "修改密碼");
為了查看寫入的事件，我們在這裏需要隆重推薦一款叫做PerfView的工具，這是一款免費的性能分析工具，下載地址為https://www.microsoft.com/download/details.aspx?id=28567。接下來我們就來簡單介紹一下如何利用PerfView來啟動上麵這個程序，並收集運行時的性能數據。開啟PerfView之後，我們選擇菜單“Collect”>“Run”打開ETW數據收集窗口。
假設程序所在項目的根目錄為“c:\app”，我們在“Current Directory”文本框中將這個目錄設置為當前目錄，而“Command”文本框中則直接設置為“dotnet run”，即直接執行dotnet命令來啟動我們的程序。為了讓PerfView能搜集自定義EventSource寫入的事件，我們需要將SecurityEventSource對應的ETW Provider的名稱添加到“Additional Providers”文本框中。在這裏指定的是“*MyApp.Security”，不要忘了前置的“*”。
設置完成之後我們直接點擊“Run Command”，我們的程序將會被啟動，由它產生的ETW相關的性能數據將會被PerfView收集起來，我們利用SecurityEventSource提供的事件信息自然也包括其中。收集的性能數據最終會打包生成一個.etl文件，文件的路徑可以通過“Data File”文本框進行設置。ETW性能數據的收集以及文件的生成大概需要幾十秒的時間。整個過程完成之後，PerfView將會按照如下圖所示的方式自動打開生成的文件。
如果要查看收集的ETW事件，我們隻需要點擊“Events”節點開啟事件窗口。由於具有很多默認注冊的ETW Provider，所以我們會看到左側會顯示非常多的事件，為了查看由SecurityEventSource提供的事件，我們將EventSource的名稱前綴（“MyApp”）設置為過濾條件。我們可以看到一共具有四條相關的事件，其中三條是通過定義在SecurityEventSource中對應三個對應方法寫入的。對於收集的每一個事件，我們可以得到與之相關的時間名稱、執行時間、進程、線程、消息以及其他相關信息，具體的信息如下表所示。
|
Event Name |
Time MSec |
Process Name |
Rest |
|
MyApp.Security/SignInSuccess |
4,818.583 |
dotnet (8660) |
ThreadID="16,088" FormattedMessage="用戶"張三"認證成功 " userName="張三" |
|
MyApp.Security/SignInFail |
4,818.583 |
dotnet (8660) |
ThreadID="16,088" FormattedMessage="用戶"李四"認證失敗 " userName="李四" |
|
MyApp.Security/DenyAccess |
4,818.583 |
dotnet (8660) |
ThreadID="16,088" FormattedMessage="用戶"王五"執行未授權操作"修改密碼"" userName="李四" |
微信公眾賬號：大內老A
微博：www.weibo.com/artech
如果你想及時得到個人撰寫文章以及著作的消息推送，或者想看看個人推薦的技術資料，可以掃描左邊二維碼（或者長按識別二維碼）關注個人公眾號（原來公眾帳號蔣金楠的自媒體將會停用）。
本文版權歸作者和博客園共有，歡迎轉載，但未經作者同意必須保留此段聲明，且在文章頁麵明顯位置給出原文連接，否則保留追究法律責任的權利。
最後更新：2017-10-25 11:05:07