2013年10月20日,WPT终于迎来了新一轮的更新,在这次更新之后,我们在WPT的目录下已经找不到xperfview的身影了,而WPA则添加了多项新的功能。由于平时用WPA还算用的比较多,而且这工具实在相当好用,所以在这里打算写一些文章介绍一下它。
1. WPT简介
WPT的全名是Windows Performance Toolkit,是Windows下用来进行性能分析的一套工具,它的功能非常强大,你可以使用它来监控CPU,内存,磁盘和网络等等的活动,从而来确定当前系统的性能瓶颈。虽然它功能强大,但是却完全免费。它包含在Windows Assessment and Deployment Kit (Windows ADK)中,最新的版本是8.1,你可以通过MSDN来下载并随意使用它:http://www.microsoft.com/en-US/download/details.aspx?id=39982。
WPT主要包含两个部分:Windows Performance Recorder (WPR)和Windows Performance Analyzer (WPA)。从名字我们就很容易看出来,前者是用来记录性能数据的,后者是用来分析性能数据的了,后面我们会更加详细的介绍这两个工具。
2. 这东西怎么做到的?
原理,我们喜欢原理。和其他的性能分析工具不同,它是由Windows本身的事件机制来提供支持的——Event Tracing for Windows (ETW)。
ETW是从Windows 2000开始就引入的一种高速的事件记录机制,而在Vista之后,Windows又对其进行了完善,使其可以记录比之前多的多的信息,比如系统CPU上正在运行的堆栈,而现在它已经成为Windows中最主要的一种分析性能问题的方法了。
下面这张图来自MSDN,展现了ETW的主要基本架构,主要分成4个部分:Session,Controller,Provider和Consumer。
- Provider:ETW的事件提供者,我们在最后的记录文件中看到的事件就是来自于他们。
- Consumer:ETW的事件接收者,比如我们实现一个实时的Consumer来查看系统中当前有那些事件正在发生。
- Controller:用于开关ETW的事件。
- Session:它存在在内核中,用于表示一个ETW事件记录会话。系统中可以存在多个Session,每个Session都可以接收来自于多个Provider的事件,最后我们可以将多个Session中的事件写入一个日志文件中,这个日志文件就叫做Trace。
![etw-overview](https://i-blog.csdnimg.cn/blog_migrate/d9acba70bc0b5678201d658102e2a39e.png)
通过ETW,我们可以将系统所有关键的地方都加入事件,记录其行为和堆栈,比如CPU执行,线程切换和读写磁盘,这样我们就可以利用这些信息来进行分析了。
3. 老板,来点栗子吧,都饿了
好了,让我们来看个例子吧,我们都知道notepad打开大文件的时候非常的慢,到底为什么呢?首先我们生成一个180M的文本文件,如下图所示,然后让我们来抓个Trace试一试吧。
![wpt-test-txt](https://i-blog.csdnimg.cn/blog_migrate/36522854a9b6ad114c1ba3eea5e998ed.png)
3.1. 生成Trace文件
3.1.1. 使用WPRUI生成Trace文件
我们打开Windows Performance Recorder (WPRUI.exe),然后将我们关心的数据选中:CPU Usage, Disk I/O activity和File I/O activity,然后按Start,这样我们开始录制了。
![wpt-wpr](https://i-blog.csdnimg.cn/blog_migrate/e75ca1b1c8ece78c10c8c9e940a3bf0b.png)
让我们用记事本打开test.txt,很快记事本就失去响应了,现在我们大概等上半分钟左右,文件打开完之后,我们就可以停止记录并生成Trace了。
3.1.2. 使用WPR生成Trace文件
当然我们也可以使用命令行来是抓取Trace。在命令行下主要有两种抓Trace的方法:xperf和wpr,由于后者比较简单,所以我们先来看看后者:Windows Performance Recorder (WPR.exe)。
在WPR中,我们通过如下命令便可以查看到所有的Profile列表。
1
|
wpr -profiles
|
![wpr-cmd-profiles](https://i-blog.csdnimg.cn/blog_migrate/446d64e471cb575c5951e2b3fa938152.png)
如果我们想知道每个Profile都开启了那些Provider,那么我们可以使用profiledetails来查看,比如CPU Usage。下图中,System Keywords就是Provider,而System Stacks就是开启抓取堆栈的开关了。
1
|
wpr -profiledetails CPU
|
![wpr-cmd-profiledetails](https://i-blog.csdnimg.cn/blog_migrate/1282995211da061db365797366427d8f.png)
选好了Profile,我们便可以通过如下命令启动和生成Trace了。这里需要注意:启动和停止Trace是需要管理员权限的。
1
2
|
wpr -start CPU
wpr -stop 1.etl
|
3.1.3. 使用xperf生成Trace文件
最后,我们来看看xperf。由于使用它,你可以对每个Provider和Stackwalk进行单独的控制,所以它的能力是最强的,当然使用起来也最难。我们可以通过如下的语句来查看当前都支持那些Provider和Stackwalk。
1
2
|
xperf -providers
xperf -help stackwalk
|
选择好需要的Provider和Stackwalk,我们就可以通过如下基本语法来启动和生成Trace:
1
2
|
xperf -start -on [provider1+provider2+…+providern] -stackwalk [stackwalk1+stackwalk2+…+stackwalkn]
xperf -stop -d [
file
.etl]
|
不过我们刚刚看到wpr中CPU Usage的Profile里面包含着这么多Provider,难道我们要一个一个的填?xperf为了简化我们的操作,提出了一个叫做组(Group)的概念,我们可以通过如下命令来查看所有的组。
1
|
xperf -providers -KG
|
![xperf-cmd-providers-kg](https://i-blog.csdnimg.cn/blog_migrate/cff96f1c33fbba4801afdff604198da8.png)
由于我们可以把组当作普通的Provider一样的用,所以有了这个,我们启动Trace就方便多了,一般我们都可以使用Base和Diag来简化我们的命令,比如,我们可以使用如下命令来记录一些基本的CPU和Disk信息。
1
|
xperf -start -on Diag+FileIO -stackwalk CSwitch+ReadyThread+Profile
|
另外,你还可以通过帮助来了解更多的命令。
1
|
xperf -help
|
3.2. 使用WPA分析Trace文件
现在终于轮到我们祭出大杀器——WPA了!让我们用WPA打开这个Trace文件吧。
![wpt-wpa](https://i-blog.csdnimg.cn/blog_migrate/d7917f756b195f189f83d408eceb439b.png)
打开之后我们会发现WPA的左侧有很多的图,并且他们被分为几类:
- System Activity:系统活动,里面主要是进程线程的生命周期,原始事件等等内容。
- Computation:记录了CPU的各项活动。
- Storage:记录了磁盘的活动和文件的操作。
- Memory:记录了系统内存的变化。
- Power:记录了电源相关的各种信息。
3.2.1. UI Delay Graph
我们知道打开这个文本文件的时候记事本失去响应了一段时间,所以让我们先查看System Activity下的UI Delay图,通过双击我们可以在右侧的Analysis中查看这个图中的具体内容。
![wpa-ui-delay](https://i-blog.csdnimg.cn/blog_migrate/e6f04007ab0c73dd3388c8960ad70540.png)
通过名字,我们很容易猜出来,UI Delay Graph记录着UI上的卡顿。通过上图,我们可以看到在notepad.exe上存在着一个28s长的MsgCheck Delay,这个应该就是我们当时观察到的记事本失去响应的那段时间了。我们选中这一个Delay,WPA会自动选中左侧所有的图中的同一个时间区域,让我们对这段时间系统都在做什么有一个最直观的感觉。从上图中,我们可以看到这段时间内,前10%的时间磁盘非常的忙,但是CPU相对空闲,而后90%的时间CPU则很忙,而磁盘的消耗却近乎为0,看来这个问题很可能主要是由于CPU消耗过高导致的。为了更清楚的查看这段时间发生的事情,我们可以在UI Delay的图上点击右键,使用Zoom功能,只查看这一段时间内发生的事件。
3.2.2. Disk IO Graph
Disk IO Graph中记录了系统在这段时间内所有的磁盘操作,我们现在先打开它,看看磁盘在这次Delay中到底做了什么事情。打开这个图之后,我们需要重新调整一下列的位置,对当前所有的IO重新分组,如下图所示。
![wpa-diskio](https://i-blog.csdnimg.cn/blog_migrate/2c3115953516ba43489e96cfb02ae1b1.png)
我们可以看到notepad在这段时间之内发起了173个1M的IO,这些IO总共花费了2.5s的时间。这应该就是前10%的时间所主要做的事情了,接下来让我们来看看CPU在这段时间内做了什么吧。
3.2.3. 加载符号文件
对了,在查看更详细的内容之前,我们需要加载系统文件的符号文件,这样能更好的帮助我们理解系统内部到底在执行哪些东西。我们可以通过Trace -> Configurate Symbol Paths可以设置好符号文件的地址,如下图:
- Symbol Path: SRV*d:\symbols*http://msdl.microsoft.com/download/symbols
- SymCache Path: d:\symcache
![wpa-symbol](https://i-blog.csdnimg.cn/blog_migrate/107b5abd2820aec3c4d1fabe352c6201.png)
这里需要提到的问题有两个:
- 第一次符号文件的加载通常需要非常长的时间,因为系统中有很多的可执行文件,每个文件都需要去尝试加载一次。
- Symbol Path就是我们平常看到的pdb文件,而SymCache Path存放的SymCache文件是WPA中用于缓存pdb文件中对WPA有用的信息的文件,所以很明显,他的大小肯定比pdb要小很多,加载起来也会更快。
3.2.4. CPU Usage (Sampled) Graph
为了查看这段时间内CPU上都执行了什么指令,让我们来打开CPU Usage (Sampled) Graph吧。CPU Sampled Graph内展示的数据,是每隔一毫秒在CPU上采集到的正在执行的线程信息和相关堆栈。从下面这张图里,我们可以从堆栈上看到主要的问题在Edit控件的操作上,Edit控件会按行来建立文件内容,从而导致了相当多的内存操作,最后导致了非常缓慢的文件加载。
![wpa-cpu](https://i-blog.csdnimg.cn/blog_migrate/c7e505fdf98f938a1f631d63577e61af.png)
3.2.5. 多图查看
为了让我们更加直观的了解这个问题,我们还可以同时打开多个图,比如我们现在同时打开UI Delay,CPU Usage (Sampled)和Disk IO,我们就能更加直观的看到其从IO为主的消耗转到CPU为主的消耗的过程。
![wpa-multi-graph](https://i-blog.csdnimg.cn/blog_migrate/ddb9380fe91309a12741996a072a56bd.png)
TADA,这样经过简单几步操作,我们就找到问题了。
4. 总结
好了,我们现在已经知道了WPT的基本原理,如何使用WPR抓取Trace文件,并且还知道了如何使用WPA进行简单的性能分析,这次就先介绍到这里,之后我们再来尝试分析更加复杂的问题。