.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