WPA入门（一） —— 到底为什么这么慢？
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)。
2.1. 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，我们可以将系统所有关键的地方都加入事件，记录其行为和堆栈，比如CPU执行，线程切换和读写磁盘，这样我们就可以利用这些信息来进行分析了。
2.2. System/Kernel vs User
这一小节大家可以选择跳过，因为在实际分析Trace的时候并用不上，只是ETW中有几个概念特别容易混淆，导致有时候交流上可能会产生误解而已。如果你决定跳过，那么就请把System Keywords简单理解成系统内核的Providers，只是用了一个不同的名称而已，这样之后在WPT的配置中看到这个词就不会觉得太奇怪了。
在ETW里面我们经常会看到System/User Provider, System/User Keywords，Kernel/User Session, Kernel/User Event之类的词汇，他们之间到底有什么区别和联系呢？
2.2.1. System Provider, Kernel Session, Kernel Event
System Provider的真名叫做"Windows Kernel Trace"，他被内核非常多的模块公用，他产生的事件被称为Kernel Event，但是这个Provider产生的事件只能被一种Session接收，这种Session也被称作Kernel Session。我们可以通过logman来查看System Provider的详情：
我们在系统里面最常见的Kernel Session有两个：“NT Kernel Logger"和"Circular Kernel Context Logger”，我们可以通过logman来查看当前所有的ETW Session。
2.2.2. User Provider, User Session, User Event
理解了System Provider之后，就好理解User Provider了：除了"Windows Kernel Trace"以外的Provider被统称为User Provider，即便他运行在内核里。这些Provider发出来的事件可以被发送到任何非Kernel Session的Session中，这些Session统称为User Session，而这些事件就被称为User Event。
2.2.3. Keywords, System Keywords
通常一个Provider里面会有很多总不同类型的事件，所以如果我们所有事件都记录在Trace中，Trace会变的非常的大，所以ETW通过Keyword提供一种过滤事件的方法。Keywords本质上就是一个64位的整数，当某个Keyword被启用，那么它对应的位就会被置1。记录事件时如果某个Keyword对应的位不是1，那么ETW就不记录该事件。那为什么我们这里System Keywords要单独拿出来说呢？因为System Keywords在本质上和在Trace中看到的样子是不一样的，而User Event的Keywords看到的是一样的。
我们在上面已经用logman查看过Windows Kernel Trace Provider了，我们可以看到他包括了很多不同的Keywords，覆盖了从进程，线程到磁盘，文件各个不同的方面，那么在Trace里面看这些Keyword是个什么样子的呢？我们去WPA中看一看吧：
这里我们可以看到这些System Keywords在Trace里面的Provider Id并不是Windows Kernel Trace的Provider Id，而他们在Trace里面的Keywords都是0。而且我们可以看到比如DiskIO和FileIO从2个Keyword被转换成了2个Provider，而Thread和Context Switch被放在一个Provider下面，但是变成两个不同的Task。所以System Keywords的行为并没有想象中的那么好理解。而在真正分析Trace的时候，我们只需要把它看成来自内核的Provider，只不过名字不同而已就好了。
3. 老板，来点栗子吧，都饿了
好了，让我们来看个例子吧，我们都知道notepad打开大文件的时候非常的慢，到底为什么呢？首先我们生成一个180M的文本文件，如下图所示，然后让我们来抓个Trace试一试吧。
3.1. 生成Trace文件
3.1.1. 使用WPRUI生成Trace文件
我们打开Windows Performance Recorder (WPRUI.exe)，然后将我们关心的数据选中：CPU Usage, Disk I/O activity和File I/O activity，然后按Start，这样我们开始录制了。
让我们用记事本打开test.txt，很快记事本就失去响应了，现在我们大概等上半分钟左右，文件打开完之后，我们就可以停止记录并生成Trace了。
3.1.2. 使用WPR生成Trace文件
当然我们也可以使用命令行来是抓取Trace。在命令行下主要有两种抓Trace的方法：xperf和wpr，由于后者比较简单，所以我们先来看看后者：Windows Performance Recorder (WPR.exe)。
在WPR中，我们通过如下命令便可以查看到所有的Profile列表。
1 | wpr -profiles |
如果我们想知道每个Profile都开启了那些Provider，那么我们可以使用profiledetails来查看，比如CPU Usage。
1 | wpr -profiledetails CPU |
下图中，System Keywords就是来自内核的Provider，而System Stacks就是开启抓取堆栈的开关了。
选好了Profile，我们便可以通过如下命令启动和生成Trace了。这里需要注意：启动和停止Trace是需要管理员权限的。
1 | wpr -start CPU |
3.1.3. 使用xperf生成Trace文件
最后，我们来看看xperf。由于使用它，你可以对每个Provider和Stackwalk进行单独的控制，所以它的能力是最强的，当然使用起来也最难。我们可以通过如下的语句来查看当前都支持那些Provider和Stackwalk。
1 | xperf -providers |
选择好需要的Provider和Stackwalk，我们就可以通过如下基本语法来启动和生成Trace：
1 | xperf -start -on [provider1+provider2+…+providern] -stackwalk [stackwalk1+stackwalk2+…+stackwalkn] |
不过我们刚刚看到wpr中CPU Usage的Profile里面包含着这么多Provider，难道我们要一个一个的填？xperf为了简化我们的操作，提出了一个叫做组（Group）的概念，我们可以通过如下命令来查看所有的组。
1 | xperf -providers -KG |
由于我们可以把组当作普通的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文件吧。
打开之后我们会发现WPA的左侧有很多的图，并且他们被分为几类：
- System Activity：系统活动，里面主要是进程线程的生命周期，原始事件等等内容。
- Computation：记录了CPU的各项活动。
- Storage：记录了磁盘的活动和文件的操作。
- Memory：记录了系统内存的变化。
- Power：记录了电源相关的各种信息。
3.2.1. UI Delay Graph
我们知道打开这个文本文件的时候记事本失去响应了一段时间，所以让我们先查看System Activity下的UI Delay图，通过双击我们可以在右侧的Analysis中查看这个图中的具体内容。
通过名字，我们很容易猜出来，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重新分组，如下图所示。
我们可以看到notepad在这段时间之内发起了173个1M的IO，这些IO总共花费了2.5s的时间。这应该就是前10%的时间所主要做的事情了，接下来让我们来看看CPU在这段时间内做了什么吧。
3.2.3. 加载符号文件
对了，在查看更详细的内容之前，我们需要加载系统文件的符号文件，这样能更好的帮助我们理解系统内部到底在执行哪些东西。我们可以通过Trace -> Configurate Symbol Paths可以设置好符号文件的地址，如下图：
- Symbol Path: SRVd:\symbolshttp://msdl.microsoft.com/download/symbols
- SymCache Path: d:\symcache
这里需要提到的问题有两个：
- 第一次符号文件的加载通常需要非常长的时间，因为系统中有很多的可执行文件，每个文件都需要去尝试加载一次。
- 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控件会按行来建立文件内容，从而导致了相当多的内存操作，最后导致了非常缓慢的文件加载。
3.2.5. 多图查看
为了让我们更加直观的了解这个问题，我们还可以同时打开多个图，比如我们现在同时打开UI Delay，CPU Usage (Sampled)和Disk IO，我们就能更加直观的看到其从IO为主的消耗转到CPU为主的消耗的过程。
Tada，这样经过简单几步操作，我们就找到问题了。
4. 总结
好了，我们现在已经知道了WPT的基本原理，如何使用WPR抓取Trace文件，并且还知道了如何使用WPA进行简单的性能分析，这次就先介绍到这里，之后我们再来尝试分析更加复杂的问题。
原创文章，转载请标明出处：Soul Orbit本文链接地址：WPA入门（一） —— 到底为什么这么慢？