Soul Orbit

WPA入门(一) —— 到底为什么这么慢?

原创文章,转载请标明出处:Soul Orbit
本文链接地址: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-overview

通过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的详情:
windows-kernel-trace

我们在系统里面最常见的Kernel Session有两个:”NT Kernel Logger”和”Circular Kernel Context Logger”,我们可以通过logman来查看当前所有的ETW Session。
kernel-sessions

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-provider-in-trace

这里我们可以看到这些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试一试吧。
wpt-test-txt

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

让我们用记事本打开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

如果我们想知道每个Profile都开启了那些Provider,那么我们可以使用profiledetails来查看,比如CPU Usage。

1
wpr -profiledetails CPU

下图中,System Keywords就是来自内核的Provider,而System Stacks就是开启抓取堆栈的开关了。
wpr-cmd-profiledetails

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

由于我们可以把组当作普通的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

打开之后我们会发现WPA的左侧有很多的图,并且他们被分为几类:

  • System Activity:系统活动,里面主要是进程线程的生命周期,原始事件等等内容。
  • Computation:记录了CPU的各项活动。
  • Storage:记录了磁盘的活动和文件的操作。
  • Memory:记录了系统内存的变化。
  • Power:记录了电源相关的各种信息。

3.2.1. UI Delay Graph

我们知道打开这个文本文件的时候记事本失去响应了一段时间,所以让我们先查看System Activity下的UI Delay图,通过双击我们可以在右侧的Analysis中查看这个图中的具体内容。
wpa-ui-delay

通过名字,我们很容易猜出来,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

我们可以看到notepad在这段时间之内发起了173个1M的IO,这些IO总共花费了2.5s的时间。这应该就是前10%的时间所主要做的事情了,接下来让我们来看看CPU在这段时间内做了什么吧。

3.2.3. 加载符号文件

对了,在查看更详细的内容之前,我们需要加载系统文件的符号文件,这样能更好的帮助我们理解系统内部到底在执行哪些东西。我们可以通过Trace -> Configurate Symbol Paths可以设置好符号文件的地址,如下图:

这里需要提到的问题有两个:

  • 第一次符号文件的加载通常需要非常长的时间,因为系统中有很多的可执行文件,每个文件都需要去尝试加载一次。
  • 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

3.2.5. 多图查看

为了让我们更加直观的了解这个问题,我们还可以同时打开多个图,比如我们现在同时打开UI Delay,CPU Usage (Sampled)和Disk IO,我们就能更加直观的看到其从IO为主的消耗转到CPU为主的消耗的过程。
wpa-multi-graph

Tada,这样经过简单几步操作,我们就找到问题了。

4. 总结

好了,我们现在已经知道了WPT的基本原理,如何使用WPR抓取Trace文件,并且还知道了如何使用WPA进行简单的性能分析,这次就先介绍到这里,之后我们再来尝试分析更加复杂的问题。

同系列文章:
坚持原创技术分享,您的支持将鼓励我继续创作!