.NET 性能测试工具 -- 事件跟踪器（ETW）

内容预告：

• Windows内置工具（性能计数器）
• 事件跟踪器（WPT，PerfMoniter，PerfView，自定义ETW）
• 时间分析
• 内存分配分析
• 内存使用量分析
• 其他分析

---

Event Tracing for Windows(ETW)可以查看很多内核和CLR的性能数据，如下表所示，有几个工具都是基于ETW开发的，后面会详细介绍：

Kernel	PROC_THREAD	Creation and destruction of processes and threads
Kernel	LOADER	Load and unload of images (DLLs, drivers, EXEs)
Kernel	SYSCALL	System calls
Kernel	DISK_IO	Disk I/O reads and writes (including head location)
Kernel	HARD_FAULTS	Page faults that resulted in disk I/O (not satisfied from memory)
Kernel	PROFILE	Sampling event—a stack trace of all processors collected every 1ms
CLR	GCKeyword	Garbage collection statistics and information	Collection started, collection ended, finalizers run, ~100KB of memory have been allocated
CLR	ContentionKeyword	Threads contend for a managed lock	Contention starts (a thread begins waiting), contention ends
CLR	JITTracingKeyword	Just in time compiler (JIT) information	Method inlining succeeded, method inlining failed
CLR	ExceptionKeyword	Exceptions that are thrown

 

 

 

 

 

 

 

Windows Performance Toolkit (WPT)是ETW的工具集，捕获ETW事件到日志文件。可以在http://msdn.microsoft.com/en-us/performance/cc752957.aspx 下载。

使用步骤如下：

1. 在环境变量里将_NT_SYMBOL_PATH的值设置到微软的公开符号服务器和本地符号缓存，如C:\Temp\Symbols*http://msdl.microsoft.com/download/symbols
2. 在环境变量里_NT_SYMCACHE_PATH的值设置到一个自定义目录。
3. 打开管理员权限的cmd窗口定位到安装文件夹（如C:\Program Files\Windows Kits\8.0\Windows Performance Toolkit）。
4. 运行xperf -on Base开始跟踪内核数据
5. 随便运行一些程序
6. 停止跟踪，输出日志。xperf -d KernelTrace.etl
7. 打开图形分析器 xperfview KernelTrace.etl

WPT的运用场景是：

• 捕获硬盘IO操作

• 提供所有CPU的活动

• 显示IO，内存，CPU等的叠加图

• 显示调用栈

最新的Windows SDK8.0包含一些新工具，叫做Windows Performance Recorder (wpr.exe) 和Windows Performance Analyzer (wpa.exe), 是为了替代XPerf 和XPerfView的。wpr -start和xperf -on相同，wpr -stop和xperf -d 一样。WPA分析UI和XPerfView的功能一样，更多信息可以参考 http://msdn.microsoft.com/en-us/library/hh162962.aspx.

 XPerfView可以看GC事件的数据：

 

---

PerfMonitor是一个开源的控制台工具 http://bcl.codeplex.com/releases/view/49601.

PerfMonitor的优点是可以更细节地分析CLR和JIT。

使用方法如下：

C:\PerfMonitor > perfmonitor runAnalyze JackCompiler.exe
Starting kernel tracing. Output file: PerfMonitorOutput.kernel.etl
Starting user model tracing. Output file: PerfMonitorOutput.etl
Starting at 4/7/2012 12:33:40 PM
Current Directory C:\PerfMonitor
Executing: JackCompiler.exe {
} Stopping at 4/7/2012 12:33:42 PM = 1.724 sec
Stopping tracing for sessions 'NT Kernel Logger' and 'PerfMonitorSession'.
Analyzing data in C:\PerfMonitor\PerfMonitorOutput.etlx
GC Time HTML Report in C:\PerfMonitor\PerfMonitorOutput.GCTime.html
JIT Time HTML Report in C:\PerfMonitor\PerfMonitorOutput.jitTime.html
Filtering to process JackCompiler (1372). Started at 1372.000 msec.
Filtering to Time region [0.000, 1391.346] msec
CPU Time HTML report in C:\PerfMonitor\PerfMonitorOutput.cpuTime.html
Filtering to process JackCompiler (1372). Started at 1372.000 msec.
Perf Analysis HTML report in C:\PerfMonitor\PerfMonitorOutput.analyze.html
PerfMonitor processing time: 7.172 secs.

上面的统计结果包括：

• CPU统计，CPU利用率。
• GC统计，GC时间，最大GC堆是4.5MB，内存分配速率最高是1496.1MB/秒，平均GC暂停时间是0.1MS。
• JIT编译统计，159个函数在运行时被JIT编译，共30493个机器字节。

下图表明CPU做的最多的工作是这3个函数：System.String.Concat, JackCompiler.Tokenizer.Advance, 和System.Linq.Enumerable.Contains

 84.2%的CPU时间花在了：JackCompiler.Parser.Parse, 调用了ParseClass, ParseSubDecls, ParseSubDecl, ParseSubBody

 

 下图是一些GC事件的细节统计：

 

---

PerfView：一个免费工具，可以分析堆的使用。在http://www.microsoft.com/download/en/details.aspx?id=28567 下载。

 上面的报告包括了：

• 原始的ETW事件列表。
• CPU在栈上使用时间的分组。
• 镜象加载，硬盘IO，GC使用栈的情况。
• GC统计。

PerfView还可以生成堆的快照。

 

---

自定义 ETW Providers：也可以自己开发基于ETW的性能数据统计工具。.NET4.5之前输出ETW数据相当困难，.NET4.5要容易很多了，继承System.Diagnostics.Tracing.EventSource类然后调用 WriteEvent函数就可以输出了。

public class CustomEventSource : EventSource {
public class Keywords {
public const EventKeywords Loop = (EventKeywords)1;
public const EventKeywords Method = (EventKeywords)2;
}
[Event(1, Level = EventLevel.Verbose, Keywords = Keywords.Loop,
Message = "Loop {0} iteration {1}")]
public void LoopIteration(string loopTitle, int iteration) {
WriteEvent(1, loopTitle, iteration);
}
[Event(2, Level = EventLevel.Informational, Keywords = Keywords.Loop,
Message = "Loop {0} done")]
public void LoopDone(string loopTitle) {
WriteEvent(2, loopTitle);
}
[Event(3, Level = EventLevel.Informational, Keywords = Keywords.Method,
Message = "Method {0} done")]
public void MethodDone([CallerMemberName] string methodName = null) {
WriteEvent(3, methodName);
}
}
class Program {
static void Main(string[] args) {
CustomEventSource log = new CustomEventSource();
for (int i = 0; i < 10; ++i) {
Thread.Sleep(50);
log.LoopIteration("MainLoop", i);
}
log.LoopDone("MainLoop");
Thread.Sleep(100);
log.MethodDone();
}
}

PerfMonitor工具可以自动从程序获得ETW的事件数据：

C:\PerfMonitor > perfmonitor monitorDump Ch02.exe
Starting kernel tracing. Output file: PerfMonitorOutput.kernel.etl
Starting user model tracing. Output file: PerfMonitorOutput.etl
Found Provider CustomEventSource Guid ff6a40d2-5116-5555-675b-4468e821162e
Enabling provider ff6a40d2-5116-5555-675b-4468e821162e level: Verbose keywords:
0xffffffffffffffff
Starting at 4/7/2012 1:44:00 PM
Current Directory C:\PerfMonitor
Executing: Ch02.exe {
} Stopping at 4/7/2012 1:44:01 PM = 0.693 sec
Stopping tracing for sessions 'NT Kernel Logger' and 'PerfMonitorSession'.
Converting C:\PerfMonitor\PerfMonitorOutput.etlx to an XML file.
Output in C:\PerfMonitor\PerfMonitorOutput.dump.xml
PerfMonitor processing time: 1.886 secs.

---

 

其实还有一个东西叫做Windows Management Instrumentation (WMI).这里没有提到，它可以获取到系统状态，BIOS固件，等数据。文档见http://msdn.microsoft.com/en-us/library/windows/desktop/aa394582.aspx