WPA入门（一） —— 到底为什么这么慢？

本文链接地址： 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)。

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执行，线程切换和读写磁盘，这样我们就可以利用这些信息来进行分析了。

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。下图中，System Keywords就是Provider，而System Stacks就是开启抓取堆栈的开关了。

1	`wpr -profiledetails CPU`

选好了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`

由于我们可以把组当作普通的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: SRV*d:\symbols*http://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进行简单的性能分析，这次就先介绍到这里，之后我们再来尝试分析更加复杂的问题。