WPA入门（二） —— 分析线程上的等待
上回我们说道记事本怒开大文件，WPA奋勇显神威。通过CPU Sampling Graph和Disk IO Graph，我们很快的定位到了记事本打开大文件缓慢的真正原因。但是就和硬盘里和生活中的女神们一样，现实往往都是残酷的。很多时候不是程序本身消耗了很多的CPU和磁盘资源，最后导致了程序运行的缓慢，甚至我们通过任务管理器查看，会发现CPU，硬盘的使用其实都不高，似乎整个系统是空闲的，但是却就是不干活，这又是为什么呢？这一次，让我们来看一个稍稍复杂一点点的问题吧。
1. 线程状态
为了让我们更加好的理解接下来的内容，首先，我们需要先补充一点和Windows下线程调度相关的背景知识，当然如果你已经知道了，可以跳过这一节。
Windows下线程在被调度的过程中，如性能相关的状态主要有三个：
- 运行中（Running）：该线程正在运行中。
- 就绪中（Ready）：该线程已经可以运行了，但是暂时还没有得到CPU。
- 等待中（Waiting）：该线程正在等待某个资源，暂时还无法运行。
他们之间可以相互转化，其状态转化图和转化原因如下：
-
运行中 -> 就绪中：
正在运行的线程还可以继续运行，但是却放弃了CPU。这种情况主要有三种原因：- 被更高优先级的线程抢占了CPU
- 主动放弃了CPU，比如调用了Sleep(0)
- 时间片结束
-
就绪中 -> 运行中：
由于现在正在运行的线程放弃了CPU，线程调度器会将该CPU分配给正在就绪队列中等待的线程中的另外一个线程，使其开始运行。 -
运行中 -> 等待中：
正在运行的线程由于需要等待某一个资源而无法继续运行，这时其会进入等待状态，比如调用了WaitForSingleObject，或者Sleep函数。 -
等待中 -> 就绪中 / 运行中：
一个在等待中的线程，由于其等待的资源被激活，从而变成了可以运行的状态，比如一个事件被SetEvent激活了，这个时候该线程会被线程调度器根据当前是否有可以让其使用的CPU而变更为就绪中或者运行中。
通过这三个关键的线程状态，我们就可以开始尝试着通过Trace来理解这一段时间内系统里都发生了什么，并且为什么会发生这些事情了。
2. 使用WPA分析线程上的等待
现在我们来看看怎么通过WPA来分析这些线程的运行状态吧。
2.1. CPU Usage (Precise) graph
在WPA中，有一个叫做CPU Usage (Precise) graph的图，所有的线程调度的信息都被记录了在这个图里面。为了理解这个图，我们需要先知道几个非常重要的概念，并且为了统一，后面出现这几种概念，我们就都用英文原文来表示了，因为这样似乎更方便理解这个图中的字段：
- New Thread：切换至CPU上进行工作的线程。
- Readying Thread：唤醒New Thread的线程，也就是导致New Thread从其他状态转换到运行中的线程。
- Old Thread：本来在当前CPU上执行的，而在New Thread切入之后被换出的线程。
- New Process / Readying Process / Old Process：New Thread / Readying Thread / Old Thread所属的进程。
现在我们再来看CPU Usage (Precise) graph中的字段，应该就很好理解了。
- NewProcessName / ReadyingProcessName：New Process / Readying Process的进程名。
- NewThreadId / ReadyingThreadId：New Thread / Readying Thread的进程名。
- NewThreadStack：New Thread被切入时的堆栈。
- ReadyThreadStack：Readying Thread唤醒New Thread的堆栈。
- LastSwitchOutTime (s)：New Thread上次从运行中切换出去的时间。
- ReadyTime (s)：New Thread被Readying Thread唤醒，从等待中变为就绪中的时间。
- SwitchInTime (s)：New Thread被切入CPU上执行的时间。
- NextSwitchOutTime (s)：New Thread下一次被切换出CPU的时间。
- Waits (s)：该线程在“等待中”状态下停留的时间，= ReadyTime (s) – LastSwitchOutTime (s)。
- Ready (s)：该线程在“就绪中”状态下停留的时间，= SwitchInTime (s) – ReadyTime (s)。
下图来自MSDN，用来解释这几个字段，表述非常的清楚。
2.2. 关键路径（Critical Path）和等待分析（Wait Analysis）
在使用上述知识开始分析之前，我们还需要了解另外一个概念：关键路径。比如，你为了完成事情A，你需要顺序完成B，C，D和E四件事情，而且只有C和D可以并行，但是D要花更长的时间。那么对于A来说，完成A需要的时间就取决于：完成B、E的时间和完成C和D中更慢的那一件的时间，也就是完成B，D和E的时间，那么B+D+E就是A的关键路径。所以我们只要分析一件事情的关键路径，就能分析出瓶颈在哪里了。
为了分析关键路径，我们可以通过分析线程上的等待，来将关键路径还原，主要的步骤分为这么几步：
- 找到当前线程上的等待，记录下开始和结束的时间。
- 通过当前等待的信息找到其ReadyThread。
- 分析这一段时间内ReadyThread上在做什么，如果发现等待，就重复第2步，直到没有更多的线程可以分析。
这样，我们就通过分析等待将关键路径建立出来了，所有在关键路径上发生的事情，也就是我们最关注的事情了。
3. 趁热再来个栗子
经常使用Spy++的人应该都遇到过这个问题：如果一个窗口失去了响应，那么使用Spy++查看这个窗口的属性就会变得非常的慢。这是为什么呢？我们使用WPA结合上面提到的知识来找到这个问题的原因所在吧。
3.1. 构造现场
首先，我们需要构造一个现场，让我们打开记事本，然后使用windbg把记事本断下来。现在我们就拥有了一个失去响应的窗口了。
然后，让我们打开Spy++，查看一下这个窗口的属性，大家会明显感觉到打开属性窗口和点Refresh按钮刷新窗口属性的时候特别的慢。
3.2. 初步分析
好了，既然我们已经有了必现的现场，那就让我们来抓个Trace分析一下吧。上一篇中我们已经介绍了使用WPR抓Trace的方法，这里就不再赘述了，过程是一样的。
得到Trace之后，我们用WPA来打开它。我们已经知道spy++的UI卡了一段时间，那么我们就可以先打开UI Delays Graph来查看这段时间内发生的所有卡顿。果不其然在里面我们看到notepad.exe和spyxx_amd64.exe上都有长时间的卡顿，Notepad.exe卡的原因就不用说了，而选中spy++上的卡顿后，我们发现当前系统里面CPU和磁盘都基本处于空闲的状态。看来这个卡顿的原因很有可能是在等待一个资源，比如锁或者事件，所以我们只有祭出上面提到的分析线程等待的方法来分析这个卡顿了。
3.3. 等待分析
我们在UI Delay Graph里面可以看到，这个spy++的2992这个线程上卡了1.1s的，为什么呢？为了弄明白这个问题，让我们双击打开左侧Graph Explorer中的CPU Usage (Precise)图，并使用Zoom功能只看这1.1s内spy++上发生的事情。
其实这个默认图表对我们的分析来说并没有那么的有用，因为其中我们并看不到线程状态转换时的堆栈，也就是NewThreadStack和ReadyThreadStack。这个时候，我们可以通过点击图表上方的齿轮按钮来打开View Editor，从而按照我们的意愿来任意调整当前的图表。这里，我们打开了NewThreadStack和ReadyThreadStack，把LastSwitchOutTime (s)，ReadyTime (s)和SwitchInTime (s)三个字段移动到了ReadyingProcess的前面，并且按照线程等待时间Wait (us)降序排序。如下图所示。
接下来，让我们来展开spyxx_amd64.exe中2992线程下的所有记录。通过NewThreadStack，我们可以推测出当我们点击刷新按钮时，Spy++会重新获取窗口信息，而其中函数GetOtherProcessData造成了一个1s的等待，另外GetFullWindowText造成了一个100ms的等待，这应该就是造成其界面延迟的主要原因了，继续展开堆栈，我们便可以通过ReadyingThread的信息推断出到底是什么唤醒了该线程，结束了这两个的等待。以GetOtherProcessData为例，通过下图，可以看到ReadyThreadStack上是一个Timer，也就是说，Spy++在获取其他进程的数据时，等待某个资源一直没有返回，直到1s后超时结束（堆栈太长，屏幕太小，所以只截了一半…… =.=|||）。当然如果大家对另外一个也感兴趣，可以自己动手试一试。
超时，嗯。。。。。。这不和没说一样么？它到底在等什么其他进程的数据呢？不了解最终的原因，我们是很难想明白解决这个问题的方法的，只是可惜这个信息在这个Trace里面并没有记录下来，有什么办法可以解决么？其实超时这个问题还是很常见的，解决方法也很简单，再抓一个Trace看看正常情况下是什么唤醒这个线程就好了。这里，我们Detach Windbg让记事本正常运行起来，然后用WPR再抓一个相同的Trace，就可以了。
打开新抓的Trace，我们在UI Delay Graph里面已经看不到spy++在这段时间内卡过了。那我们怎么找到刚刚我们发现的等待呢？搜索一下NewThreadStack。我们先打开CPU Usage (Precise) Graph，调整成同样的图表，然后选中NewThreadStack，按Ctrl+F打开查找对话框，输入GetOtherProcessData，点Search，很快我们便可以找到对应的堆栈了。展开堆栈，我们可以看到在记事本的3784线程上，spy++的模块spyxxhk_amd64.dll通过消息钩子接管了一个窗口消息，并且通过SetEvent在37.543915610s唤醒了spy++，使其被切回CPU上执行，如下图所示。
那么这个消息又是谁发送给记事本的呢？我们知道记事本是在37.543915610s时将spy++唤醒的，那么肯定有另外的线程在这个时间点之前将记事本唤醒使其执行这个窗口消息，而且如果有多个消息将记事本唤醒，当前处理的消息的来源肯定发生在离当前时间点更近的位置，所以我们可以通过从后向前遍历线程3784上该时间点前所有的将该线程唤醒的堆栈，来找到这个消息的来源。这里，我们找到了一个非常可疑的堆栈，如下图所示。
原来，这个消息是Spy++自己发送的，并且就是由GetOtherProcessData来发送的，看上去应该就是我们要找的原因了。而且现在我们还得到了两个时间点：记事本得到消息的时间37.543715224s，和spy++得到返回的时间：37.543915610s。我们来看看这段时间内记事本3784线程都在做些什么？
继续使用Zoom功能，并观察线程3784上的NewThreadStack，如下图。原来spy++会hook这个消息，并且在其中调用GetClassNameW来获取窗口类名。到此为止，分析应该算是结束了，当然如果这个线程上还有其他可疑的等待，我们可以用同样的方法对其递归的进行分析，直到找到最后的原因。
这样通过分析Spy++和记事本中各个线程的等待，我们终于还原了GetOtherProcessData的整个工作流程，也就是其关键路径：
- 用户点击Spy++上的刷新窗口信息按钮，触发Spy++调用GetOtherProcessData来在目标窗口所在进程内获取窗口的相关数据。
- GetOtherProcessData使用PostMessage给记事本中的目标窗口所在线程发送特定的窗口消息，并开始等待相关数据返回。
- Spy++全局钩子模块在记事本中截获消息，并在其中调用GetClassNameW来获取窗口类名。
- Spy++全局钩子模块调用SetEvent唤醒Spy++，结束。
那怎么来解决这个问题呢？可能大家已经想到了，如果目标窗口所在的线程卡住了，那么我们还可以尝试使用CreateRemoteThread来在目标进程中创建一个新的线程来获取对应的数据，这样也能避免一些数据获取不到的问题。
4. 你……在说些啥？
好的，这次的文章比上次稍稍难一点，希望我把这个分析方法说明白了。现在我们了解了Windows中一个线程可能处在的几种状态，知道了如何通过这些状态去解释一个线程的行为，并且还知道了使用WPA来进行等待分析并建立起某个特定问题的关键路径。如果大家发现其中有什么错误，还请大家多多指正，感谢不已。
原创文章，转载请标明出处：Soul Orbit本文链接地址：WPA入门（二） —— 分析线程上的等待