使用 ETW 对 .NET 应用程序进行性能诊断

下载代码示例

您编写一个托管应用程序来亲身体验一下 – 您会觉得其速度较慢。您的应用程序在功能上是正常的，但其性能有很多不足。您想诊断出性能问题并解决这些问题，但您的应用程序正在生产环境中运行，导致您无法安装探查器或中断它。或者，您应用程序的使用范围可能不够广泛，无法证明购买 Visual Studio 探查器来进行 CPU 分析是合理的。

幸运的是，Windows 事件跟踪 (ETW) 可以缓解这些问题。此强大的日志记录技术内置在 Windows 基础结构的多个部分中，并且 Microsoft .NET Framework 4 CLR 中利用此技术使分析您的托管应用程序变得更加简单。ETW 收集系统范围的数据并分析所有资源（CPU、磁盘、网络和内存），使其对获取整体视图很有用。此外，可对 ETW 生态系统进行调整以减少其开销，使该系统适用于生产诊断。

本文旨在使您了解使用 ETW 分析托管应用程序的好处。我不会介绍所有内容 - 有几个可用于诊断的 OS 事件和 CLR ETW 事件在本文中不会提到。但您将了解如何使用 ETW 生态系统大大提高托管应用程序的性能和功能。为了开始向您介绍针对托管代码的基于 ETW 的诊断，我将使用可从 bcl.codeplex.com/releases/view/49601 下载的免费 ETW 工具 (PerfMonitor) 来演示示例调查。

PerfMonitor

利用 PerfMonitor，您可以方便快捷地收集 ETW 性能数据并生成有用报告。此工具不是为了替代深层分析工具（如 Visual Studio 探查器），而是为了向您提供应用程序性能特征的概述，并让您执行一些快速分析。

还有一种称作 XPerf 的 ETW 诊断工具，可通过 Windows 性能工具包免费获得此工具。虽然 XPerf 很适合用来在 Windows 上进行本机代码分析，但它尚无法深入支持托管代码分析。另一方面，PerfMonitor 公开了使用 ETW 分析托管代码的范围和能力。PerfMonitor 能够收集与 .NET Framework 运行时代码关联的符号信息，从而使它对 .NET Framework 性能调查很有价值，尽管它不支持 XPerf 可提供的深层分析。

PerfMonitor 是一个完全独立的工具，您只需使用它即可开始对托管应用程序进行分析和诊断。唯一的要求是，您至少必须运行 Windows Vista 或 Windows Server 2008。PerfMonitor 是一个命令行工具，从其位置键入 PerfMonitor.exe usersGuide 将显示一个概述。如果您想在操作环境下（如在生产服务器上）诊断您客户的程序，则您需要做的是将相应文件复制到该计算机上，并准备开始收集配置文件。如果需要，可脱机分析配置文件。

在任何性能调查过程中，通常会检查四个因素：CPU、磁盘 I/O、内存和可伸缩性。大多数调查都将从 CPU 开始，CPU 将影响应用程序的启动和执行时间。在诊断较长的启动时间时，检查磁盘 I/O 是最有用的（磁盘 I/O 是冷启动时间的主要因素，冷启动时间是指内存中没有某个应用程序时（如重启后）启动此应用程序所花的时间），而过多的内存消耗（或泄露）可能会导致应用程序随时间的流逝变得更慢。如果您希望您的应用程序的吞吐量与处理器数成比例，则可伸缩性很关键。

PerfMonitor 可帮助您获取除可伸缩性以外的所有这些因素的快照，并且可为您提供足够多的信息以便您使用其他专业工具进行进一步的探究。例如，若要诊断与 CLR .NET 垃圾收集 (GC) 堆相关的问题，使用 CLRProfiler 将是更好的选择。但是，PerfMonitor 很快会告知您是否存在问题，以及您是否需要使用其他工具进行进一步的探究。在某些情况下，PerfMonitor 自身会指出该问题，并包含您解决性能 Bug 所需的所有信息，很快将向您介绍这一点。请查看“CLR 全面透析”专栏“.NET 应用程序的内存使用量审核”(msdn.microsoft.com/magazine/dd882521)，其中讨论了审核程序内存使用量并规划性能的重要性。将这个原理扩展一下，您可利用 PerfMonitor 快速审核托管程序的多个方面的性能，而不仅仅是内存。

示例调查：CsvToXml

我使用 ETW 诊断的示例程序可将一个 CSV 文件转换成一个 XML 文件。可从 code.msdn.microsoft.com/mag201012ETW 获得源代码和解决方案包（以及示例输入 CSV 文件 data.csv）。若要执行程序，请运行命令 CsvToXml.exe data.csv output.xml。

与许多程序类似，CsvToXml 已迅速连在一起，开发人员从未期望将它用于大型 CSV 文件。当我开始在现实领域中使用该程序时，我发现它太慢了。它处理一个 750K 的文件所花的时间竟然超过了 15 秒！我知道出现了问题，但没有分析工具，我也只能猜测此情况是因为运行速度慢导致的。（您能否只看一下源代码就找出问题呢？）幸运地是，PerfMonitor 可以帮助您找出该问题。

生成和查看程序跟踪

第一步是，通过在管理员命令提示符窗口中执行以下命令来快速审核应用程序（ETW 将收集计算机范围内的数据，因此需要管理权限）：

PerfMonitor runAnalyze CsvToXml.exe data.csv out.xml

这将开始 ETW 日志记录、启动 CsvToXml.exe、等待 CsvToXml 完成、停止日志记录，并最终呈现一个显示对 CsvToXml 的分析信息的网页。通过一个简单步骤，您便能够拥有大量数据，这些数据可帮助您揭示 CsvToXml 中的性能瓶颈。

图 1 中捕获了该命令的结果。此页包含进程 ID、使用的命令行和高级性能数据的细目（其中包括 CPU 统计信息、GC 统计信息和实时 (JIT) 统计信息），以及其他数据。PerfMonitor 还通过指向信息性文章或其他工具的有用链接，来提供对开始诊断的位置的第一级分析。

图 1 针对 CsvToXml 的性能分析

此报告说明，格式转换所花费的时间将近 14 秒，在平均利用率为 99% 的 CPU 中花费的时间为 13.6 秒。因此，该方案与 CPU 性能联系紧密。

GC 中的时间总量和 GC 暂停时间量较少，这很好；但最大 GC 分配速率为 105.1MB/秒，这个速率过快了 - 这需要进一步的调查。

CPU 分析

详细的 CPU 分析可提供 CPU 时间的细目，如图 2 所示，还可以通过三种方式来读取 CPU 配置文件数据。可以通过自下而上的视图快速获知，哪些方法占用的 CPU 时间最多，应先对此进行诊断。自上而下的视图可用于确定您的代码是需要体系结构更改还是结构更改，并帮助您了解程序的整体性能。调用方-被调用方视图指示了各个方法之间的关系 - 例如，调用方法与被调用方法之间的对应关系。

图 2 针对 CsvToXml.exe 的自下而上的分析

与其他 CPU 探查器类似，PerfMonitor 视图为您提供了包含时间（特定方法使用的时间，包括其被调用方使用的时间）和排除时间（特定方法使用的时间，不包括其被调用方使用的时间）。当包含时间与排除时间相等时，将在特定方法内完成工作。PerfMonitor 还提供了 CPU 利用率图，该图对特定方法随时间变化的 CPU 使用率进行了细分。通过将鼠标指针悬停在报告中的列标题上方，可为您提供有关其含义的更多详细信息。

大多数性能调查都将从自下而上的视图开始，该视图是一个按排除时间划分的方法列表（图 2 中显示了该视图）。通过选择自下而上的视图，您会看到 mscorlib 方法 System.IO.File.OpenText 是占用 CPU 最多的方法。单击该链接将显示 OpenText 方法的调用方/被调用方视图，该视图揭示了 CsvToXml.CsvFile.get_ColumnNames 方法正在从程序中调用 OpenText，而 get_ColumnNames 占用的 CPU 时间约为 10 秒（图 3）。此外，将在一个循环内从 CsvToXml.CsvFile.XmlElementForRow 调用该方法（XmlElementForRow 本身调用自 Main 方法）。

图 3 get_ColumnNames 的调用方-被调用方视图

因而，有些内容在这些方法中似乎是错误的。从这些方法中拉出代码会导致出现问题，如图 4 中突出显示的部分所示：此文件在一个循环内反复打开和分析！

图 4 方法 ColumnNames 由方法 XmlElementForRow 调用

          public string[] ColumnNames
{
  get
  {
    using (var reader = File.OpenText(Filename))
      return Parse(reader.ReadLine());
  }
}
 
public string XmlElementForRow(string elementName, string[] row)
{
  string ret = "<" + elementName;
  for (int i = 0; i < row.Length; i++)
    ret += " " + ToValidXmlName(ColumnNames[i]) + "=\"" + EscapeXml(row[i]) + "\"";
  ret += "/>";
  return ret;
}

类似情况的发生频率远远超出您的想象。在最初编写此方法时，开发人员可能认为此方法只会在极少数情况下被调用（与 ColumnNames 的情况相同），因此可能不会太多关注此方法的性能。但是，以后经常会出现在循环中停止调用此方法的情况，导致应用程序的性能下降。

在 CSV 文件中，由于所有行的格式都相同，因此没有必要每次都这样做。您可以将 ColumnNames 功能提升至构造函数中（如图 5 所示），保留此属性以提供缓存列名。这可确保只读取此文件一次。

图 5 缓存列名以获取更好的性能

          public CsvFile(string csvFileName)
{
  Filename = csvFileName;
 
    using (var reader = File.OpenText(Filename))
      ColumnNames = Parse(reader.ReadLine());
        
}
 
public string Filename { get; private set; }
 
public string[] ColumnNames { get; private set;}

我们在重新生成后再次执行了上一个命令，发现应用程序的速度快多了；现在的持续时间仅为 2.5 秒。

但在使用修补程序审阅数据时，您会发现 CPU 时间仍占主导地位。通过重新深入了解 CPU 时间并查看自下而上的分析，您会发现 Regex.Replace 现在是开销最大的方法，并且此方法调用自 EscapeXml 和 ToValidXmlName。由于 EscapeXml 是开销最大的方法（排除时间为 330 毫秒），因此请检查其源代码：

          private static string EscapeXml(string str)
{
  str = Regex.Replace(str, "\"", "&quote;");
  str = Regex.Replace(str, "<", "&lt;");
  str = Regex.Replace(str, ">", "&gt;");
  str = Regex.Replace(str, "&", "&amp;");
  return str;
}

由于还会在 XmlElementForRow 中的循环内调用 EscapeXml，因此此方法有可能会成为一个瓶颈。正则表达式对这些替换有点多余，而使用字符串 Replace 方法应该会更高效。将 EscapeXml 替换为以下内容：

          private static string EscapeXml(string str)
{
  str = str.Replace("\"", "&quote;");
  str = str.Replace("<", "&lt;");
  str = str.Replace(">", "&gt;");
  str = str.Replace("&", "&amp;");
  return str;
}

利用此转换后，时间总量已减少约 2 秒，且 CPU 时间仍占主导地位。这是可接受的性能 - 您几乎将执行速度加快了七倍。

为了便于读者进行练习，我已在示例程序中保留了几个性能 Bug，可使用 ETW 事件标识这些 Bug。

探究 GC 统计信息

PerfMonitor GC 统计信息提供了内存配置文件的简要概述。您可能记得，我强烈建议执行内存使用率审核，而通过 GC ETW 事件提供的信息提供了有关 .NET GC 堆的任何问题的快照。您可通过快速摘要视图获知 GC 聚合堆的大小、分配速率和 GC 暂停时间。通过在 PerfMonitor 结果选项卡上选择“GC 时间分析”链接，可显示 GC 的详细信息、GC 发生的时间、GC 占用的时间量等。

您可通过这些信息来确定是否需要使用 CLRProfiler 或其他内存探查器进一步分析任何内存问题。“.NET 垃圾回收堆透析”一文 (msdn.microsoft.com/magazine/ee309515) 对使用 CLRProfiler 调试 .NET GC 堆进行了深入的探讨。

对于此特定程序而言，不存在任何令人不安的 GC 统计信息。分配速率较高；一个有效的经验法则是让分配速率低于 10MB/s。但暂停时间非常短。高的分配速率出现在 CPU 时间下面，多数情况下这表示将获得 CPU 增益 – 这与您发现的情况一样。但修复后的分配速率仍比较高，这表示进行了大量分配（您能纠正此问题吗？）。几毫秒的 GC 暂停时间是对 .NET Framework 运行时提供的自调节和高效 GC 有力证明。因此，.NET Framework GC 将自动负责内存管理。

探究 JIT 统计信息

若要缩短启动时间，要探究的第一批项目中的一个项目是对方法进行 JIT 编译所需的时间。如果花费的时间很长（例如，启动应用程序所需的大部分时间都由 JIT 编译所占用），则应用程序可以从本机映像生成 (NGen) 中受益，它可通过对程序集进行预编译并将其保存到磁盘上来消除 JIT 编译时间。也就是说，对程序集进行 JIT 编译并将其保存到磁盘上，这样便无需对后续执行进行 JIT 编译。在选择采用 NGen 之前，您可能还需要考虑将要进行 JIT 编译的一些方法推迟到程序中的某个时点执行，以便 JIT 编译时间不会影响启动。有关详细信息，请参阅“NGen 的性能优势”一文 (msdn.microsoft.com/magazine/cc163610)。

示例应用程序 CsvToXml.exe 的启动成本并不高，因此允许它每次对所有方法进行 JIT 编译是可行的。JIT 编译统计信息还指明，已进行 JIT 编译的方法的数目为 17（建议调用的所有方法都已进行 JIT 编译），JIT 编译时间的总量为 23 毫秒。这些都不是与此应用程序相关的性能问题，但对于受 JIT 编译时间影响的大型应用程序，使用 NGen 应会消除任何问题。通常，当应用程序开始对数以百计或数以千计的方法进行 JIT 编译时，JIT 编译时间就会成为影响因素。在此类情况下，NGen 是消除 JIT 编译成本的解决方案。

MSDN 杂志 中的其他文章中包含了有关改进启动的更多指导信息，而 ETW 事件可帮助标识和解决瓶颈。还提供了其他几个 JIT 事件（包括 JIT 内联事件），它们能提供对方法无法内联的原因的深入分析。

.NET Framework 4 中的 CLR ETW 事件

CLR 团队撰写了一篇有关跟踪 DLL 加载并确定启动期间是否需要加载特定 DLL 的博客文章。通过使用 ETW 事件，可使确定是否需要在启动期间进行 DLL 加载的过程变得更加简单。通过使用 .NET Framework 4 中提供的 ETW 模块加载事件，我们可了解加载了哪些模块以及加载原因。还有一些针对模块卸载等情况的事件。

.NET Framework 4 中还提供了几个事件，利用这些事件可更轻松地诊断托管应用程序。图 6 总结了这些事件。可使用 PerfMonitor runPrint 命令对执行期间触发的所有事件进行转储。CLR 团队还会运行允许您连接和分离 ETW 分析的事件，并且该团队打算继续添加更多的 ETW 事件，以使调试托管应用程序的过程在将来版本中变得更加简单。

图 6 .NET Framework 4 中的 ETW 事件

Event Category Name	Description
Runtime Information ETW Event	捕获有关运行时的信息，包括 SKU、版本号、激活运行时的方式、启动运行时所使用的命令行参数、GUID（如果适用）以及其他相关信息。
Exception Thrown ETW Event	捕获有关引发的异常的信息
Contention ETW Events	捕获有关对运行时使用的监控视器锁或本机锁的争用情况的信息。
Thread Pool ETW Events	捕获有关工作线程池和 I/O 线程池的信息。
Loader ETW Events	捕获有关加载和卸载应用程序域、程序集和模块的信息。
Method ETW Events	捕获有关用于符号解析的 CLR 方法的信息。
GC ETW Events	捕获有关 GC 的信息。
JIT Tracing ETW Events	捕获有关 JIT 内联和尾调用的信息。
Interop ETW Events	捕获有关 Microsoft 中间语言 (MSIL) 存根生成和缓存的信息。
Application Domain Resource Monitoring (ARM) ETW Events	捕获有关应用程序域的状态的详细诊断信息。
Security ETW Events	捕获有关强名称和 Authenticode 验证的信息。
Stack ETW Event	捕获可用于其他事件以在引发事件后生成堆栈跟踪的信息。

您会发现执行目录中有两个后缀为 PerfMonitorOutput 的文件；这两个文件是 ETW 日志文件。您还会发现后缀为 kernel 的文件，这表示它们包含 OS 事件。PerfMonitor 收集的数据与 XPerf 使用的数据相同，因此您可以使用 PerfMonitor 来简化数据收集，并简化报告和 XPerf 以便对相同数据进行更高级的分析。PerfMonitor 合并命令会将 ETW 文件转换为 XPerf 的可读格式。

总结

使用 ETW 进行性能调查不仅简单而且很有效。提供了多种免费的、低开销的基于 ETW 的工具，这些工具允许有效调试托管代码。我刚刚介绍的只是 .NET Framework 运行时中提供的 ETW 事件的皮毛。我的目标是，让您开始使用 ETW 事件和工具调试托管应用程序。通过下载 PerfMonitor、使用 CLR 中的 ETW 事件的 MSDN 文档并阅读 CLR Perf 博客，您可以快速开始对托管应用程序进行性能调查。

原文：http://msdn.microsoft.com/zh-cn/magazine/gg490356.aspx

NTrace - High Performance Tracing for .NET Applications