如何利用ETW（Event Tracing for Windows）记录日志

jxwjq

　　ETW是Event Tracing for Windows的简称，它是Windows提供的原生的事件跟踪日志系统。由于采用内核（Kernel）层面的缓冲和日志记录机制，所以ETW提供了一种非常高效的事件跟踪日志解决方案。
一、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自身是一个非常强大的事件跟踪日志系统，有兴趣的朋友可以参阅相关的文档进行系统学习。
二、针对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:     protected void WriteEvent(int eventId, params object[] args);      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的工具，这是一款免费的性能分析工具，下载地址为http://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="李四"