VS2010与Win7共舞：ETW自定义程序日志

IT168.com

2009.09.1411:15

关注

文本Tag：微软 .NET .NET Framework windows 7

【IT168 专稿】在Visual Studio 2010中，我们可以利用性能计数器对应用程序的性能进行实时的监视，以发现应用程序的性能瓶颈的所在。当我们发现问题后，如果想解决问题，就需要更多的信息。这个时候，就该ETW上场了。

Event Tracing for Windows (ETW)

Event Tracing for Windows (ETW)是由操作系统提供的一种通用的，系统开销较低(与性能日志和警报相比)的事件追踪手段，用以监控具有负载的系统的性能。ETW主要用于必须频繁记录事件、错误、警告或审核的服务器应用程序。ETW提供用户模式的应用程序和内核模式的设备驱动程序所触发的事件追踪机制。此外，ETW还能够动态地启用或者禁用日志记录，便于进行详细的追踪，而无需重新启动操作系统或者应用程序。

ETW最先在Windows 2000中被引入。自那时以后，各种Windows操作系统核心和服务组件都通过ETW记录其活动，它现在是Windows平台上的关键系统仪表技术之一。在Windows 7中，ETW得到了进一步的增强。首先是更强的功能，可伸缩性和鲁棒性，增加了多个新的Windows事件和事件提供者。在ETW的开发方面，增加了设计时严重，从XML自动生成代码等。正是基于ETW的优秀性能和强大功能，越来越多的第三方应用程序开始放弃自己的日志系统，逐渐开始使用ETW来追踪和记录其状态和活动。在这里，我们就利用ETW来记录我们自己开发的应用程序的各种事件活动，从而进行性能调优或者是进行应用程序的日常维护。

ETW的架构

图1 ETW的架构

整个ETW系统由Provider，Customer和Controller三个部分构成：

• Provider

所谓的Provider，就是事件的提供者，它可以是系统组件，驱动程序或者是我们开发的应用程序。首先，它需要向系统进行注册一个Event Trace，然后当这个Provider被Controller启动(Enable)后，它就可以开始向相应的Event Trace Session发送事件了。

• Controller

顾名思义，Controller就是一个控制器。它的主要任务有两个：一是Event Trace Session的控制管理。它利用StartTrace在内存中创建一个Event Trace session，这样Provider就知道该往哪里发生事件。而Controller也会负责将Session里记录的事件送到Consumer。Controller的第二个任务就是对Provider进行管理，启动或是停止Provider。为了避免额外的开销，Provider不会一直都在工作，只有当被Enable的时候，才开始工作。

• Consumer

Consumer实时地从Event Trace Session或者是日志文件中订阅事件。Consumer主要的作用是提供Event Trace Callback。我们可以设计一个通用的callback来处理所有的事件，也可以为特定的我们感兴趣的事件设计callback。对于通用事件的callback，我们可以在OpenTrace的时候通过参数指定，而对于特定时间的callback，则可以通过SetTraceCallback指定。

内容导航

使用Event Log记录简单日志

为了便于在我们开发的应用程序中使用ETW，在Visual Studio 2010中，.NET Framework 在 System.Diagnosis 下提供了EventLog类来进行简单的事件输出，我们可以利用这个类来记录简单的应用程序日志，以代替应用程序的日志系统。

我们还是以上一篇文章中的文件复制程序作为例子，利用Event Log输出复制文件所花费的时间以帮助我们找到程序性能低下的原因。

首先我们在类中添加一个EventLog的成员变量：

Code highlighting produced by Actipro CodeHighlighter (freeware)
http://www.CodeHighlighter.com/

// EventLog成员变量
private static EventLog copyLog;

然后，我们需要在类的初始化函数中对其进行初始化：

Code highlighting produced by Actipro CodeHighlighter (freeware)
http://www.CodeHighlighter.com/

   public MainForm()
        {
            this.InitializeComponent();
            //
            // …
            // 创建并初始化EventLog对象
            copyLog = new EventLog();
            copyLog.Source = "FileCopyApp";
            ///
            // …
       }

默认情况下，我们通过这种方式输出的EventLog会出现在Event Viewer(事件查看器)的Application(应用程序)分类下，如果我们想让日志出现在其他分类或者自定义的分类，可以使用CreateEventSource方法将事件源添加到当前事件中。例如：

Code highlighting produced by Actipro CodeHighlighter (freeware)
http://www.CodeHighlighter.com/

EventLog copyLog = new EventLog("MyLog");
            // 首先应判断日志来源是否存在
            // 如果存在，则删除已有的日志来源
            // 一个日志来源只能同时与一个事件绑定
            if ( EventLog.SourceExists("FileCopyApp") )
            {
                EventLog.DeleteEventSource("FileCopyApp");
            }
            EventLog.CreateEventSource("FileCopyApp", "MyLog");
            // 指定日志来源
            copyLog.Source = "FileCopyApp";

这样，我们所记录的日志就会出现在自定义的日志分类下，更加便于我们对日志进行分析整理。

完成EventLog对象的创建后，我们就可以开始在文件复制过程中进行日志的记录了，在这里，我们记录每个被复制的文件的名字以及复制这个文件的耗时。

Code highlighting produced by Actipro CodeHighlighter (freeware)
http://www.CodeHighlighter.com/

            // 创建后台复制线程
            this.worker = new BackgroundWorker();
            // 执行复制
            this.worker.DoWork += (o, e) =>
            {
                string[] files = Directory.GetFiles(source);
                for (int i = 0; i < files.Length; ++i)
                {
                    // 记录文件复制开始时间
                    DateTime startTime = DateTime.Now;

                    Thread.Sleep(1000);
                    // 执行复制
                    File.Copy(files[i], Path.Combine(dest, Path.GetFileName(files[i])));
                    // 计算复制过程耗时
                    TimeSpan timeDiff = ( DateTime.Now - startTime );
                    Int32 dDiff = (Int32)timeDiff.TotalSeconds ;
                    // 输出日志
                    copyLog.WriteEntry("复制:" + files[i] +
                                      " 耗时：" + dDiff.ToString(),
                                      EventLogEntryType.Information);

                    this.worker.ReportProgress((int)((100.0f * i) / files.Length));
                }
            };

现在，我们以管理员身份编译和运行这个程序，在文件复制过程中，EventLog就会将复制的文件名和耗时作为事件的内容记录到日志中。通过分析日志，我们可以知道在复制哪一个文件时耗时最多，从而可以进行更加有针对性的诊断和调试。

图2 利用EventLog记录的事件

内容导航

自定义日志

在上面我们利用EventLog输出的事件中，我们以一个字符串的形式输出了文件名和耗时。为了更加便于我们对日志进行进一步的筛选，我们希望将其输出成一个字符串和一个整数值的形式：字符串记录复制的文件名，而相应的整数值则记录复制操作的耗时。针对这种情况，我们就需要对事件进行自定义了。

在Visual Studio 2010中，自定义ETW事件按照如下的5个设计步骤进行：

图3 自定义ETW事件的步骤

1. 设计

所谓设计，就是定义我们需要在事件中输出哪些信息，比如事件的类型，等级，通道以及事件模板等等。在这里，我们需要输出的是被复制的文件的名字和复制操作耗时，所以我们决定采用事件模板，其中包含一个字符串值和一个整数值，分别用于记录文件名和操作耗时。

2. 定义事件XML文件

在ETW中，我们使用一个XML文件来描述和定义一个事件。在这个XML文件中，我们定义了Provider的GUID，事件，事件模板，以及通道等等事件属性。虽然我们可以用文本编辑器手动地编写这个XML文件，但是更简单地是使用Windows SDK中的Manifest Generator(ecmangen.exe)工具创建事件的XML文件。

图4 用Manifest_Generator创建事件的XML文件

在这里，我们简单地定义了一个Provider，其中它提供了一个事件模板(Template)，包含一个字符串项目和整数项目，可以供我们填充文件名和复制耗时。最后，我们可以得到这样一个定义事件的XML文件FileCopier.Manifest.xml：

Code highlighting produced by Actipro CodeHighlighter (freeware)
http://www.CodeHighlighter.com/

<?xml version="1.0" encoding="UTF-16"?>
<instrumentationManifest xsi:schemaLocation="http://schemas.microsoft.com/win/2004/08/events eventman.xsd" xmlns="http://schemas.microsoft.com/win/2004/08/events" xmlns:win="http://manifests.microsoft.com/win/2004/08/windows/events" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xs="http://www.w3.org/2001/XMLSchema" xmlns:trace="http://schemas.microsoft.com/win/2004/08/events/trace">
    <instrumentation>
        <events>
            <provider name="SimpleEtwProvider" guid="{D9B453B9-6230-486C-8DEC-C7C5A2230D04}" symbol="SimpleEtwProvider" resourceFileName="D:\Programs\FileCopier.exe" messageFileName="D:\Programs\FileCopier.exe" message="$(string.ProviderMessage)">
                <events>
                    <event symbol="SimpleEvent" value="1001" version="1" channel="SimpleOperationalChannel" level="win:Informational" task="SimpleTask" opcode="SimpleOpcode" template="SimpleTemplate" keywords="SimpleKeyword " message="$(string.SimpleEtwProvider.SimpleEvent.message)">
                    </event>
                </events>
                <levels>
                </levels>
                <tasks>
                    <task name="SimpleTask" symbol="SimpleTask" value="1" eventGUID="{9B0655BE-219F-439E-9439-B604BD822E22}">
                    </task>
                </tasks>
                <opcodes>
                    <opcode name="SimpleOpcode" symbol="SimpleOpcode" value="10">
                    </opcode>
                </opcodes>
                <channels>
                    <channel name="SimpleOperationalChannel" chid="SimpleOperationalChannel" symbol="SimpleOperationalChannel" type="Operational" enabled="true">
                    </channel>
                </channels>
                <keywords>
                    <keyword name="SimpleKeyword" symbol="SimpleKeyword" mask="0x1">
                    </keyword>
                </keywords>
                <templates>
                    <template tid="SimpleTemplate">
                        <data name="StringData" inType="win:UnicodeString" outType="xs:string">
                        </data>
                        <data name="IntegerData" inType="win:Int32" outType="xs:int">
                        </data>
                    </template>
                </templates>
            </provider>
        </events>
    </instrumentation>
    <localization>
        <resources culture="en-US">
            <stringTable>
                <string id="level.Informational" value="Information">
                </string>
                <string id="SimpleEtwProvider.SimpleEvent.message" value="A simple event to demo ETW...">
                </string>
                <string id="ProviderMessage" value="Simple Event Trace for Windows Provider">
                </string>
            </stringTable>
        </resources>
    </localization>
</instrumentationManifest>

图4 用Manifest_Generator创建事件的XML文件内容导航

3. 产生代码

在Visual Studio 2010中，我们并不能直接使用上面产生的XML文件来创建Provider。所以我们还需要对这个XML文件进行进一步的处理，利用Windows SDK提供的编译器来编译XML文件以产生相应的代码。

首先，我们需要利用Windows Message Compiler (mc.exe)将XML文件编译成相应的头文件和资源描述文件，在Windows SDK的命令行工具中执行：

Code highlighting produced by Actipro CodeHighlighter (freeware)
http://www.CodeHighlighter.com/

MC FileCopier.Manifest.xml

编译成功后，我们会得到四个文件：MSG00001.bin, FileCopier.Manifest.h, FileCopier.Manifest.rc和FileCopier.ManifestTEMP.BIN。对于非托管代码，我们可以直接使用编译产生的头文件来创建Provider，而对于托管代码，我们还需要做进一步的处理，利用Resource Compiler (rc.exe)将.rc资源描述文件编译成编译后资源文件.res：

Code highlighting produced by Actipro CodeHighlighter (freeware)
http://www.CodeHighlighter.com/

RC FileCopier.Manifest.rc

编译后我们得到FileCopy.Manifest.res文件，在Visual Studio 2010中，我们通过项目属性将这个资源文件添加到项目中：

图5 在项目中使用编译后的资源文件

4. 构造Provider并输出事件

通过前面三个步骤，我们就完成了事件资源的准备工作，现在我们就可以在应用程序代码中创建Provider，利用代码创建事件并进行事件的输出了。

Code highlighting produced by Actipro CodeHighlighter (freeware)
http://www.CodeHighlighter.com/

    using Etw = System.Diagnostics.Eventing;

    public partial class MainForm : Form
    {
        private BackgroundWorker worker;

        // 定义Provider和Descriptor
        private Etw.EventProvider provider;
        private Etw.EventDescriptor descriptor;

        public MainForm()
        {
            this.InitializeComponent();

            //…

            // 定义事件的GUID
            // 这里使用跟XML文件中相同的Provider GUID
            Guid etwProviderId = new Guid("{d9b453b9-6230-486c-8dec-c7c5a2230d04}");
            // 利用GUID创建Provider
            provider = new Etw.EventProvider(etwProviderId);

            unchecked
            {
                // 创建Descriptor，描述Provider
                // 这里的属性，使用XML文件中定义的事件属性
                descriptor = new Etw.EventDescriptor
                (
                  0x3e9,                    // Event ID
                  0x1,                      // Event Version
                  0x10,                     // Operation Channel ID
                  0x2,                      // Level
                  0xa,                      // Opcode
                  0x1,                      // Task
                  (long)0x8000000000000001 // Keywords
                );
            }

            // 检查Provider是否启用
            if (provider.IsEnabled())
            {
                // 如果Provider已经启动，输出事件
                object[] msgload = { "FileCopier启动", 0 };
                provider.WriteEvent(ref descriptor, msgload);
            }
        }

在这段代码中，我们首先利用GUID创建了一个EventProvider，这里使用的GUID是我们在创建事件的XML文件时得到的GUID。然后，我们利用在XML文件中定义的事件的各种属性值，我们创建一个EventDescriptor。完成这两个对象的创建后，我们就可以利用Provider的WriteEvent函数进行事件的输出了。在文件复制过程中，我们利用Provider输出复制的文件名和耗时：

Code highlighting produced by Actipro CodeHighlighter (freeware)
http://www.CodeHighlighter.com/

            // 执行复制
            this.worker.DoWork += (o, e) =>
            {
                string[] files = Directory.GetFiles(source);
                for (int i = 0; i < files.Length; ++i)
                {
                    // 记录开始时间
                    DateTime startTime = DateTime.Now;

                    Thread.Sleep(1000);
                    // 执行复制操作
                    File.Copy(files[i], Path.Combine(dest,
                             Path.GetFileName(files[i])));
                    // 计算复制耗时
                    TimeSpan timeDiff = ( DateTime.Now - startTime );
                    Int32 dDiff = (Int32)timeDiff.TotalSeconds ;
                    //copyLog.WriteEntry("复制:" + files[i] +
                                         " 耗时：" + dDiff.ToString(),
                                         EventLogEntryType.Information);
                    // 构造事件消息
                    object[] message = { files[i], dDiff };
                    // 记录事件，填充事件模板
                    provider.WriteEvent(ref descriptor, message);

                    this.worker.ReportProgress((int)((100.0f * i) / files.Length));
                    //…
                }
            };

5. 编译部署

完成代码编辑后，整个Provider的创建过程就完成了。现在我们可以编译整个项目生产应用程序，也就是一个全新的Provider。得到编译生成的应用程序后，我们需要将其部署到目标机器上。这里需要注意的是，首先我们需要修改定义事件的XML文件，将其中的元素的messageFileName和 resourceFileName属性修改为应用程序的执行位置。例如，我们的应用程序安装到了“D:\Programs\”目录下并从这个目录运行，则相应的XML文件应该为：

Code highlighting produced by Actipro CodeHighlighter (freeware)
http://www.CodeHighlighter.com/

<events>
<provider name="SimpleEtwProvider" guid="{D9B453B9-6230-486C-8DEC-C7C5A2230D04}" symbol="SimpleEtwProvider" resourceFileName="D:\Programs\FileCopier.exe" messageFileName="D:\Programs\FileCopier.exe" message="$(string.ProviderMessage)">

然后，我们利用Windows Event Command-line utility (wevtutil.exe)将这个Provider在目标机器上进行注册：

Code highlighting produced by Actipro CodeHighlighter (freeware)
http://www.CodeHighlighter.com/

WEVTUTIL im FileCopier.Manifest.xml

这样，我们的应用程序在执行文件复制的过程中就是一个注册后的消息Provider，就可以进行自定义事件的输出了。当文件复制完成后，我们可以在事件查看器中看到这样更加人性化，更加直观的日志：

图6 更加直观的自定义事件

在这个视图中，我们可以清楚的看到我们输出的文件名和复制操作耗时，当然，我们还可以切换到XML视图查看更加详尽的事件信息，这对于我们利用事件信息进行应用程序的诊断和调试都很有帮助。

通过Performance Counters，我们可以定位应用程序的性能瓶颈;利用ETW，我们可以创建事件和输出丰富的自定义消息以进行进一步的诊断和调试。借助Windows 7所提供的这倚天剑和屠龙刀，配合Visual Studio 2010，发现并解决应用程序的性能问题只在谈笑间!

系列文章索引：

VS与Win7共舞：性能计数器进行性能分析

VS2010与Windows7共舞：对库进行编程

VS与Windows 7共舞：库(Library)

VS2010与Win7共舞:响应Ribbon控件消息

VS与Win7共舞:用XML文件定义Ribbon界面

VS 2010与Windows7共舞：又见Ribbon

VS2010与Win7共舞：任务栏状态提示

VS2010与Win7共舞：任务栏缩略图

VS2010与Windows 7共舞：Jumplist