使用 Windows 事件跟踪 (ETW) 进行应用程序分析

• 下载演示项目 - 562 KB
• 下载源代码 - 3.17 MB

引言

这是关于 ETW 事件的系列文章的第一篇。第一篇文章介绍了如何使用它们，第二篇文章将介绍 EtwDataViewer 如何以分层树状结构显示事件并进行分析，以揭示上下文并支持搜索。

当应用程序出现问题时，我们总是希望有更多的日志，甚至有日志。使用 printfs 或其他技术将大量日志数据写入文件会减慢性能并填满磁盘。因此，调试版本通常包含比发布版本更多的日志功能，因为为了提高性能，这些日志已被手动或由编译器移除。然而，当生产环境出现问题需要进行故障排除时，您就希望能有那些日志。能否在生产系统中按需开启日志，且对性能影响几乎为零，这不是很棒吗？调试版本的一个缺点是，一些开发人员让调试版本运行另一个实现。我理解这样做的原因，运行时检查和更安全的内存处理，但在最坏的情况下，一个问题在调试版本中是无法重现的。

调试器和性能分析器都是用于故障排除、优化和改进软件的不可或缺的工具。但对于处理大数据，这些工具的作用有限。假设处理 10000 张发票的批处理性能非常差。如果我逐个单步调试 10 或 20 张发票，可能检测不到明显的问。如果我们使用数据库，CPU 几乎不会饱和，这使得检测瓶颈更加困难。问题通常发生在更高层面。我们做的事情对吗？我们是否在执行冗余的数据库查询？我们执行的查询是否真的像我们想的那样被内部缓存了？如果没有从代码本身构建的高级数据点，可能很难回答这些问题。

Event Tracing for Windows (ETW) 可用于插入永久性的、几乎零影响的数据点。这些数据点可以在生产环境中启用和禁用，然后在完全不同的机器上进行分析。我们将了解如何插入这些数据点并生成一份精美的报告。

背景

日志记录和诊断可以使用各种不同的工具进行。来自 sysinternals 的 Process Monitor 收集系统范围的事件。非常适合查找丢失的注册表项、锁定的文件和干扰进程。Process Monitor 同时使用钩子和 ETW 来收集信息。

然后是 xprof.exe 和 Windows Performance Recorder (wpr.exe 和 wprgui.exe)，它们来自 Windows Performance Toolkit，该工具也包含在 Windows SDK 8.0 中。xprof.exe 只使用 ETW，但具有更详细的级别。您可以将磁盘访问图与线程调度图进行比较，或者查看软件如何影响分页。非常强大，而且最重要的是，所有这些都是免费的。

我同时使用这两个工具，但为了显示应用程序特定的事件，我一直依赖 debugview.exe（也来自 sysinternals）。不幸的是，日志打印通常无法显示上下文，而且普通打印更难分析，因为每个开发人员都倾向于以自己的方式编写日志。

一种标准化的方法是按照 ETW 格式编写日志。

场景

让我们回到订单系统示例。在订单系统中，我们经常谈论订单和订单行。通常，一个订单可以包含一到一千个不同的产品，每种产品类型都放在单独的订单行中。当订单被接单时，产品在仓库中被预留，当它被打包和发货时，库存就会减少。此外，一张发票可能包含多个订单，有时需要处理数千张发票，例如在月底。需要处理的数据量是巨大的，并且有许多敏感的步骤需要数据锁定和数据重取。我们拥有的数据越多，使用调试来单步执行程序就越不可行。性能分析也有其弱点。当订单中的订单行数量不均匀时，我无法轻松使用性能分析器提供的统计信息。当然，我可以优化一些低级别的调用，如 ToString 或其他方法，这最初会带来良好的性能提升，但在成熟的软件中，这些优化大多已经完成了。必须在更高层面进行优化。问问自己，我们是否真的在做正确的事情，而不是在以最快的速度做我们正在做的事情。

我们需要的是高质量的数据点。

• 订单行数量
• SQL 查询数量
• 执行的查询
• SQL 数据缓存的效率（自定义实现）
• SQL 数据缓存被刷新的原因
• 锁的数量
• 嵌套事务的数量
• 我们锁定的对象
• 时间度量
• 内存消耗
• 我们创建某些对象的耗时

可以使用 SQL Profiler 来获取执行的查询，但将其与软件当前正在发生的事情关联起来要困难得多。在最好的情况下，您自己构建了一个能够将这些日志与自己的日志合并的工具。

添加 ETW 数据点

添加 ETW 数据点具有陡峭的学习曲线。关于这个主题的完整说明和教程很少。我不得不上网搜索资源，进行一些试错，并自己弄清楚一些事情。我的目的是向您展示 ETW 可以做什么，以播下兴趣的种子。最终，我希望我还能写一篇关于这个的教程。

ETW 事件的生产者称为 Provider。消费者称为 Controller。您有两种编写 Provider 的选择。一种是实现经典 Provider，它也可以用于 XP 等较旧的操作系统，另一种是基于清单的 Provider，它支持最多 8 个并发会话。我选择了基于清单的 Provider，这是推荐的一种。

代码

您需要 Visual Studio 2012 来打开解决方案。我本人使用的是 Express 版本。此外，您还需要 Windows SDK 8.0，以及 Windows Performance Toolkit，这是 SDK 的一个可选包。

我发现编写 ETW Provider 的示例代码一点也不容易理解，或者至少不清楚我该如何编写自己的。我不知道的是，如果您使用清单，您甚至不需要编写任何代码。代码可以从清单本身生成，而清单是在一个名为 ecmangen.exe 的图形化工具中快速完成的。

该工具有一个简短但非常有用的“帮助”文档。我按照第一个示例的步骤进行操作，然后我能够扩展它并根据我的需求调整清单。

完成清单后，您应该通过消息编译器 (mc.exe) 运行它，然后也使用相同的工具从清单生成 .cs 文件。您最终会得到一些开箱即用的静态类。无需初始化。

mc FirstETW.man
mc -css MyProvider.Eventing FirstETW.man

-css 开关会生成 .cs 文件，您可以将这些文件添加到您的项目中。下面是生成类的骨架。我删除了函数体，但您看到的是该类是静态的，并且已准备就绪。

namespace MyProvider.Eventing
{
    public static class FunctionTraceProvider
    {
        public static bool EventWriteFunctionEntry() { }
        public static bool EventWriteFuntionExit(string FunctionName) { }
        public static bool EventWriteCreateDbConnection() { }
        public static bool EventWriteSqlQuery(string query, int rowcount) { }
        public static bool EventWriteNetException(string message) { }
    }
}

将其置于上下文中。例如，我可以记录我的软件执行的查询。

public List<OrderSummary> GetOrderSummary()
{
  const string sql = "select [OrderId], [CustomerId], [OrderlineId], [ProductId], [ProductDescription] from [OrderSummary];";
  var ds = new DataSet();
  var da = new Sql.SQLiteDataAdapter(sql, m_connection);
  da.Fill(ds);
  var list = new List<OrderSummary>();
  // Code for filling the list removed 
  
  // Logging query and the number of rows returned
  MyProvider.Eventing.FunctionTraceProvider.EventWriteSqlQuery(sql, list.Count);
  
  return list;
}

在上面的示例中，我记录了 SQL 查询以及返回的行数。出于效率考虑，请考虑使用映射到查询编号的 SQL 字符串常量，而只记录查询编号。

我还需要运行资源编译器，并将 FirstETW.rc 转换为 FirstETW.res。

rc FirstETW.rc

然后我将其作为资源文件添加到项目属性下。我还没有弄清楚如何直接使用 .rc 文件。

运行演示项目

基于清单的 Provider 必须在您要收集数据的每台计算机上注册，但在执行此操作之前，您必须更新清单中的 2 个文件路径，使其指向正确的文件。

保存清单后，您可以使用 wevtutil.exe 工具注册 Provider。

wevtutil.exe im FirstETW.man  //installs the provider
wevtutil.exe um FirstETW.man  //uninstalls the provider

整合所有内容

ETW 事件的一种记录方式是通过 *xperf.exe*。这将启动对您的 Provider 的日志记录。

xperf.exe -start <SomeName> -on <NameOfYourRegisteredProvider>
xperf.exe -start FirstETW -on Function-Entry-Exit-Provider

您可以通过 WcfTestClient.exe 工具与 WCF 应用进行交互，该工具是 Visual Studio 的一部分。

注册地址 https://:8080/ordersystem 并从工具中调用方法。

可以使用以下命令保存日志

xperf.exe -stop <SomeName> -d <FilePath>
xperf.exe -stop FirstETW -d "c:/temp/myevents.etl"

之后，您可以在 xperfview.exe 中查看日志

xperfview.exe myevents.etl

结果如下所示

上面的图表仅显示了我们 Provider 在一段时间内的日志事件。如果我们选择一个开始和结束时间段，然后在任何摘要表中右键单击，我们将获得所有事件及其携带数据的详细列表。

使用 ETW 获得了什么？

到目前为止。差别不大。所有事件都只是以长列表的形式呈现。就像我们通常的跟踪或 printfs 一样。它们是线程安全的，并且可能比 prints 快得多。除此之外，优势微乎其微。

利用 ETW

让我们开启更多的 ETW Provider。整个内核中充满了它们。您可以记录磁盘访问、网络、上下文切换、线程调度、分页量，字面意思上是系统做的最小的移动。ETW 非常高效，对您的系统几乎没有影响。

使用 -on DiagEasy 开关来启用最常用的 Provider。

xperf.exe -on DiagEasy -start FirstEtw -on Function-Entry-Exit-Provider
// Do your stuff with your app
// Then stop the logging
xperf.exe -stop FirstETW -d "c:/temp/myevents1.etl"  // stop user defined provider
xperf.exe -stop -d "c:/temp/myevents2.etl"           // stop kernel providers

xperfview.exe myevents1.etl myevents2.etl            // Merge and show everything

如果您放大图表，您就可以看到特定事件如何影响 CPU、磁盘和网络活动。

这真是太棒了！！！

报告

我们可以将记录的事件变成一份真正的摘要报告。为什么不使用 Excel 和数据透视表进行一些数据分析呢？首先，我们需要将事件导出到 csv 文件。在页面上的任意位置右键单击，然后选择“导出完整表格”。然后用 Excel 打开文件并创建数据透视表。

请点击图片以全尺寸查看

在数据透视表中，我可以统计所有包含特定数据的已记录事件的数量。我可以看到一个特殊的 SQL 查询被执行了 6 次，我们有 1 次 .Net 异常，并且创建了 7 次数据库连接。我们还可以看到哪种类型的查询执行得最多。数据透视表可以显示模式并为报告提供结构。旋转数据透视表可以得到一个完全不同的报告视图。

下一步

完整的 ETW 跟踪以及额外的 Provider 和使用数据透视表可能会很有用。

但让我们回到我最初的订单系统软件。为了真正能够查明问题区域。我需要构建一个事件层次结构。要做到这一点，必须提前计划以便实现。自从本文写成以来，我写了一篇关于 EtwDataViewer 的后续文章，该文章介绍了如何创建一个支持事件层次结构的日志查看器。

在我的示例 WCF 应用中。我创建了一个具有已发布接口的 WCF 服务。我记录了已发布方法的进入和退出。此外，我还记录了一些其他数据点。有了进入和退出，我可以假设这两个点之间的事件属于同一个任务。这不能保证，但也许您可以暂时禁用多任务处理以进行日志记录，或者也用任务 ID 标记事件。这可以创建一个上下文，进一步计算孤立任务的影响。如果您真的雄心勃勃，可以考虑使用 -on DiagEasy 开关获得的内核 ETW 数据中的 CSV 日志。

替代方法

读者 Andre Ziegler 告知了我新的 .Net 4.5 类 System.Diagnostics.Tracing.EventSource[^]，它简化了 ETW 编写，并且不需要清单。但是，由于 ETW Provider 没有在系统范围内注册，因此无法再使用 xperf，而是推荐使用 PerfView[^]。这里有一个简短的教程 入门教程：在 C# 中记录您自己的 ETW 事件：System.Diagnostics.Tracing.EventSource[^]。在我看来，.Net 类似乎更容易使用，但清单方法更完整。此外，如果您使用混合模式应用程序，清单方法有一个优势，您可以为 C++ 和 C# 生成代码。

历史

2013 年 4 月 1 日 - 初次发布

2013 年 4 月 3 日 - 添加了使用 .Net 类的替代方法。

2013 年 8 月 6 日 - 添加了指向 后续文章的链接