/ Performance,Windows / 43浏览

【译】Wait Analysis – 寻找空闲时间

原文:https://randomascii.wordpress.com/2012/05/05/xperf-wait-analysisfinding-idle-time/

Windows 性能工具包(Windows Performance Toolkit),也称为 xperf,是一个强大且免费的系统级别 Windows 性能分析工具。在过去的文章中,我曾谈到使用 xperf 内置的采样分析器来定位 PowerPoint 的性能瓶颈(其教程版本在这里),但这其实并没有完全展示出 xperf 的真正价值。尽管我认为 xperf 作为一个采样分析器要优于大多数替代方案(它的采样频率更高、开销更低,且能分析内核与用户模式),xperf 的真正强大之处在于它能揭示其他分析器根本无法测量的信息。

本文在 2015 年 9 月进行了更新,以兼容 WPA 10 和 UIforETW

简而言之,许多分析器可以告诉你「程序正在做什么」,但很少有分析器可以非常精准地告诉你「程序为什么什么都不做」。

更多关于此类调查的细节可参见这篇博文中提到的 第二个 ETW 培训视频


故事背景

xperf 的学习曲线很陡峭。因此,我强烈建议你先阅读本系列之前的文章。最好的起点是 ETW Central,其中提供了一个结构化良好的资源列表。

阅读完这些基础内容,并且在你安装了 UIforETW 并熟悉了部分 WPA 跟踪分析基础操作之后,就可以继续看这篇文章。


Wait Analysis 的成功案例

我在使用 Wait Analysis 时,解决了许多性能问题。这其中的一些延迟虽然很短,不易察觉,但依然影响体验。另一些则是对使用产生了严重影响。而无论是哪一种,几乎都无法只用 CPU 采样或其他「常规」CPU 分析工具进行诊断。例如:

  • 找到导致 Internet Explorer 和各种游戏启动时出现短暂卡顿的原因
  • 分析 Luke Stackwalker(一个探查器)为什么在被使用时会导致游戏帧率出现抖动
  • 发现某些情况下,从旧版 Windows 升级到新版后性能下降 10 倍的原因
  • 查明为什么在使用 fraps 录制时会出现帧率卡顿
  • 发现某些高负载系统中,一连串锁竞争导致帧率卡顿
  • 发现并解决 Visual Studio 输出窗口反复出现 2~6 秒卡死的原因

最后这项调查就是我今天想重点讲述的。它足够简单且独立,可以在一篇(虽然有点长)的文章中完整地描述从头到尾的分析过程。


如何定位卡顿

要分析诸如帧率抖动或暂时性卡顿等瞬时问题,第一个挑战就是在跟踪数据(trace)中找到这段卡顿。因为一个跟踪可能覆盖了 60 秒的时间范围,而卡顿可能只持续 2 秒甚至更短,所以知道该在何处查看是至关重要的。下面是一些可行的方法:

  • 通过对输入事件进行记录来查找触发卡顿的按键,因为输入事件通常和卡顿的出现时间紧密相关
  • 在感兴趣的函数中使用自定义埋点(instrumentation)
  • 观察 CPU 使用率或其他数据中是否有异常模式
  • Window in Focus 图表中寻找线索
  • 利用操作系统本身的卡顿检测事件
  • 记录下卡顿发生在「开始或停止」跟踪的相对时间位置

我自己就用过所有这些技巧。针对第一个方法,UIforETW 内置了一个输入事件记录器,它会将所有键盘和鼠标输入写入到跟踪文件里。如果你的卡顿恰好是在按下某个键或点击鼠标后触发的,那么通过查找该按键或鼠标事件就可以很容易地定位卡顿发生的时间点。

自定义埋点(即在程序的关键点发出 ETW 事件,例如在游戏中每帧或在执行某个慢操作时使用 CETWScope)也很常见。如果你可以给自己的游戏或应用加上埋点,出现问题时就能通过可视化事件很直观地看到「卡顿」或「延迟」究竟发生在哪里。不过,如果你要分析的是别人的程序,比如 Visual Studio,那就没法用这种方法。

有些时候,卡顿会显现在 CPU 使用率图表上。例如,我之前遇到的一个卡顿就因为 CPU 使用非常稳定,唯独中间出现了一个大缺口,一眼就能看出来。

Window in Focus 图表会追踪你切换窗口的情况,也能提供重要线索。

而一个能直接显示卡顿时间和时长的事件更是理想之选。其实在 Windows 7 及更新版本中,Win32k ETW 用户提供程序在检测到线程长时间没有处理消息、然后恢复时,就会发出相应事件。对于 Windows 7 及后续系统,这通常就够了,而 UIforETW 也默认启用了这个提供程序。Vista 或者更早版本就没有这么方便了。


实践开始

我上传了一份示例跟踪文件(2015-09-25_20-56-25 VS F8 short hang.zip)到我的 github bigfiles 仓库。如果你将这个 zip 文件下载并解压到 UIforETW 的跟踪目录(默认是 Documents\\\\etwtraces),然后在 UIforETW 中双击该文件,就可以用 WPA 10 打开它了。最好的学习方式就是跟我一起动手做。另外,你也应该下载同名的 .txt 文件,并将其复制到同一个 etwtraces 目录。这样当你在 UIforETW 中选中该跟踪文件时,UIforETW 会显示这个 .txt 文件的内容,你也可以在 Trace information 区域记录自己的分析笔记。

加载好跟踪之后,记得在 Trace 菜单中点击 Load Symbols,除非你已经在 UIforETW 的设置里启用了「Load symbols automatically after trace load」。

这次的示例捕获了我在 Visual Studio 中查看编译警告时遇到的卡顿。过程是:我反复按 F8 浏览编译警告,结果按到第三次 F8 后,就遭遇了一次大约六秒的停顿。我们在 Trace information 中记录了这些信息,以便后续分析。这样的信息在诊断性能问题时非常宝贵。


找到卡顿的起始点

当用 WPA 10 打开这个跟踪时,你应该会看到名为「Generic Events Randomascii Chrome and Multi Events」的图表和表格在最上面。如果没有看到,可以去 UIforETW 的设置对话框中点击「Copy startup profiles」,然后重新加载跟踪。使用合适的启动配置文件会让分析过程简单很多。

Generic Events 表格中,你可以依次展开:UIforETW、Multi-Input、Keyboard、Keydown,就能看到 20 个键盘事件。按 F7 键是用来编译项目,而那三个 F8 键分别对应了跳转到不同的警告信息。我们知道卡顿是从第三次按 F8(下图选中的那条记录)开始,因此可知卡顿从跟踪的第 6.5 秒开始(对应蓝色竖线处):

我们已经估计这次卡顿大约持续了 6 秒,但还可以更精确地确定其结束时间点。


确定卡顿持续时间

在 WPA 的 Graph Explorer 窗口中,打开 System Activity 下的 UI Delays 图表,就能看到更准确的信息。只要线程长时间没有处理消息(大于 200 毫秒),Microsoft-Windows-Win32k 提供程序就会发出一条事件,这些事件会在 UI Delays 图表中展示出来。下图所示,devenv.exe 有一次连续 5,469 毫秒没有处理消息,其中 3,172 毫秒时间里消息队列里明明有输入消息却被忽略了。

表格中还会展示进程 ID(9104)和 UI 线程的线程 ID(10364)。要分析一次空闲卡顿(idle hang)就必须知道是哪个进程、哪个线程在等,这些信息就显得至关重要。


缩小范围,找到根因

分析空闲卡顿时,需要选中整段卡顿的时间区间,尤其要包含卡顿结束的时间点。多选一些时间总比少选要好,万一遗漏到结束时的关键事件就很麻烦。这个区间可以用鼠标拖选或者在 UI Delays 图表上直接右键点击相应的 MsgCheck Delay 条,再选择 Zoom 进行放大。


谁唤醒了谁?

如果一个线程没有在运行,而后来又开始运行,那一定有一次上下文切换(context switch)让它重新获得执行权。这个上下文切换会记录在 ETW 跟踪文件中,并且还带有一堆有用的信息。其中包括:

  • 新进程名和线程 ID
  • 线程恢复时的调用栈(实际上就是线程进入等待时的那条栈)
  • 线程本次未运行的持续时长
  • 如果线程在等待某个同步原语,还会记录哪个线程将其唤醒

这点非常关键。一次上下文切换告诉我们:线程是怎么被唤醒的,等待了多长时间,又是谁把它唤醒的。这也是为什么要确保我们在选区内包含「卡顿结束」的部分。只有这样,才能抓住那个真正令线程「复活」的上下文切换事件。

CPU Usage (Precise) 表格里就包含上下文切换的信息。用 UIforETW 的启动配置文件打开跟踪时,默认只显示图表。要做 Wait Analysis,我们需要在对应图表上点击「Display Graph and Table」,把表格也显示出来:

接下来,在表格里展开 New Process 下的 devenv.exe (9104),并找到「New Thread Id 10364」。可以看见该线程在 5.469 秒的时间窗口里只消耗了 111.7 毫秒的 CPU 时间,这一下我们就知道这是一次「空闲导致的卡顿」,而不是线程在执行大量计算导致的卡顿。

分清什么时候应该用 Wait Analysis(分析线程空闲导致的卡顿)和什么时候用 CPU Usage 分析(分析线程繁忙导致的卡顿)非常关键。如果你试图用 CPU 使用率分析一个空闲线程,就会得到毫无意义的结果。

注意,大多数情况下线程处于空闲状态是完全正常的。大多数线程就应该空闲。之所以这一次空闲「不正常」,是因为它是 Visual Studio 的 UI 线程,而且在这 5.469 秒里都没有处理任何消息,导致用户界面失去响应。

devenv.exe 的 UI 线程在这个区间总共发生了 47 次上下文切换,我们要找的是那次让它重新从最长空闲中醒来的上下文切换,所以需要对表格按「Time Since Last」进行排序。正如我在 这篇文章里解释过的,「Time Since Last」代表了线程再次获得 CPU 前已经被挂起了多长时间。UIforETW 的配置文件默认会列出两个「Time Since Last」列:一个用 Sum 聚合,一个用 Max 聚合。当你想找某个调用栈的所有上下文切换总共花了多长空闲时间时,可以用 Sum;当你想找一次单独的、时长最长的上下文切换时,可以用 Max。对于我们的例子,用哪个都行;不过我建议大家平时多尝试一下这两种。

如果用右箭头逐级展开(从第一项开始一直右键或右箭头钻取),我们会看到只有一次上下文切换(Count=1)对应了线程「空闲 5.341 秒后」重新获得 CPU 的时刻——这就是我们的卡顿。表中的「NewThreadStack」信息显示线程是从 _RtlUserThreadStart 一直传到若干 VS 的内部函数,这些函数调用顺序都显示在调用栈里。Microsoft 为 Visual Studio 的大部分代码都提供了符号表,所以我们能看到大约五十行之后才进入一些「更有价值的细节」:

这里清晰可见:就是这一次上下文切换(Count=1)导致 Visual Studio 的 UI 线程整整等待了 5.202 秒,真是一目了然。

往调用栈更底层看,我们会发现 ntoskrnl.exe 调用了 FLTMGR.SYS,紧接着是 mup.sys!MupiCallUncProvider(以及最终出现的 WaitForSingleObject 调用)——仔细想想这意味着什么?

如果在最底部继续往右滚动,展开 Readying Process/Thread Id/Stack,就能看到是哪个线程把该线程唤醒的:

Readying Process/Thread Id/Stack 表示「使等待线程进入就绪状态的线程」,也就是满足了等待条件的线程。也可能是锁、事件、另一个线程或者其他同步操作。不过,如果线程是因为定时器超时被唤醒,那么 Readying Process/Thread Id 就没有意义。定时器超时是通过硬件中断实现的,中断服务例程(ISR)会调度一个延迟过程调用(DPC),而那个 DPC 会在某个现有线程的上下文里执行,就像寄生体一样,它利用宿主线程去唤醒其他线程,所以此时显示的 Readying Process/Thread 并不是「真正」的唤醒者。进行 Wait Analysis 时,如果你看到 Ready Thread in DPC 为 True,就要忽略 Readying Process/Thread,正如我在这个 Twitter 线程里讨论过的那样。

我们可以看到是 System 进程下的线程(ID 5880)在 IopfCompleteRequest 中调用了 MUP.SYS 里的代码。要是你知道 MUP.SYS 是干什么的,这会进一步提示卡顿和网络 I/O 有关。不过即使不知道,你也能看到在 Visual Studio 调用了 CreateFileW 之后,花了很长时间才返回。


其他线程呢?

在我们的选区范围内,devenv.exe 里还有很多线程在大部分时间里都处于空闲状态。为什么不看看它们?

这里需要明白一点:Sum:Time Since Last 只表示「线程挂起了多长时间」。空闲本身并不可怕,只有当线程本该执行某些任务却一直空闲时,才会导致卡顿。对于一个多线程应用而言,如果机器只有四个核心,那剩余大部分线程大多数时间都应该是空闲的,否则系统就会被彻底占满。

我们之所以关注线程 10364,是因为(根据 MsgCheckDelay 事件)它是 UI 线程,并且它在这 5.469 秒中没有处理任何消息,导致用户界面卡死。这就是我们分析的重点所在。


查看 File I/O Summary

既然我们已经知道卡顿跟文件 I/O 有关,下一步就该看看这段时间内到底发生了哪些文件 I/O。幸运的是,UIforETW 同样记录了这部分信息。

在 WPA 的 Graph Explorer 中,找到 Storage 分类,然后打开 File I/O 图表,并显示汇总表。如果你把 View Preset 切换为 Count by Process, Thread, Type,然后依次展开 Process devenv.exe (9104),Thread 10364,并按持续时间(Duration)排序,用右箭头逐级钻取,就很容易找到那次耗时很长的 I/O 操作。

通过滚动到 File Path 列,你就能看到类似下面的输出(截图内容很多,这里就只能截一部分了),点击图片可以查看大图:

可以看到,有一次「Create file」操作来自于 devenv.exe 的线程 10364,耗时 5.342 秒,试图打开路径 \\\\\\\\Perforce\\\\main,最终报告「网络路径无法找到」。

嗯,就在这里了。

也就是说,Visual Studio 想要去打开一个并不存在的网络文件,结果有时候就会触发 5.342 秒的网络超时,因此造成了界面卡顿。

卡顿剩余的时间花在了其他一些小的上下文切换和 CPU 时间上,总体加起来就得到了那 5.469 秒。真正导致线程长时间挂起的就是这 5.342 秒的 CreateFile 操作。


卡顿真正原因是什么?

这个文件名非常奇怪,完整路径其实是:

\\\\Perforce\\main\\src\\Lib\\Public\\sharedstuff.lib#127 – opened for edit

乍一看就不像是一个正常的文件路径,更像 Perforce 的输出信息——只不过它把原先 Perforce 中的斜杠换成了反斜杠。而事实上,这正是发生的情况。 我当时在 Valve 工作,会将编译结果上传到 Perforce,所以在构建脚本里加了一个预构建步骤去检查这些文件是否已被签出(check out)。Perforce 的命令行输出就包含了这样一句带有「opened for edit」的提示。

而 Visual Studio 又「热心地」把它当作潜在的文件路径来处理,将里面的「/」反转成了「\」并认为这代表了 \\perforce\main 上的文件名。由于这是按下 F8 后发生的事情,所以说明 VS 认为这是一条和警告或错误相关的路径,尝试去跳转过去。

于是就出现了调用栈上的 CResultList::AttemptToNavigate,一切都对上了。


结论

知道原因后,我在预构建脚本中加了一行 sed 命令,把输出内容重新格式化,让 VS 不再识别它为文件路径。这样一来,不仅避免了那次卡顿,也让 F8 可以真正跳转到真正需要关注的错误或警告信息上。sed 的具体用法非常简单,比如把「//」替换掉,把「...」替换成「—」:

sed -e s!//!! -e s!\\.\\.\\.!—! 

这样就把输出从下面这种易引发卡顿的文本(VS 解析为路径,进而触发网络 I/O):

变成了对 VS 来说「安全」的文本(VS 不会当它是路径)

我也把这个问题报告给了 Visual Studio 团队。像这样带上 xperf 跟踪文件的 bug 报告会非常有力,因为我能在报告里非常明确地指出问题所在,并向他们提供跟踪文件以供进一步确认。就像 minidump 文件对报告崩溃问题很有效一样,xperf 跟踪文件对报告性能问题也同样强大。Visual Studio 团队后来在 VS2012 中修复了这个问题:VS 输出窗口的解析器会忽略 UNC 路径,不再因为这些「假路径」阻塞 UI。

顺带一提,mup.sys 是处理网络文件 I/O 的驱动程序。如果在调用栈或「Ready Thread Stack」里看到它,就意味着网络 I/O 可能是造成卡顿的罪魁祸首。在 UI 线程上进行文件 I/O 本就危险,而进行网络文件 I/O 更是高风险,这些都容易导致卡顿。

等待链

有些 Wait Analysis 的场景会比这次更复杂。比如,在某些游戏中,主线程可能卡顿几百毫秒,是因为它等待了某个信号量(semaphore)或临界区(critical section),而释放该同步对象的另一个线程又在等待别的东西,可能链式传递好多次。在这种场景下,「Readying Thread」就非常关键,因为它代表了谁释放了同步对象。只要知道是谁阻塞了主线程,你就可以去看看那个线程是在忙(CPU 使用率过高)还是也在等别的锁(空闲等待)。通常排查一两层就能找到根本原因,不过我最近遇到过一次跨四个进程、六次上下文切换才找到操作系统调度问题的案例。

当顺着等待链往下查时,记得一定要关注事件的发生顺序。如果线程 1234 在 10.5 秒时被线程 5678 唤醒,那么 5678 在 10.5 秒之后的其他上下文切换或 CPU 活动就和 1234 的等待链无关了,因为唤醒已经发生了,那之后再发生的事情不会影响这个等待。

对于 CPU 活动,通过选择相应的时间范围就能过滤掉无关内容;对于上下文切换,则需要一直展开查看「SwitchInTime (s)」这一列,该列记录了上下文切换发生的实际时间。

最后要提醒的是,如果你用自旋锁或自己实现的同步原语(如 CSuperFastCriticalSection)来「忙等」,这种 Wait Analysis 就无法帮上忙了。因为操作系统的同步原语都内置了相应的 ETW 事件,可以让我们「完美」跟踪等待链,但自定义锁就没有这种系统级别的跟踪。即使你自定义的锁可能「速度更快」,其实通常也没快多少,而失去 Wait Analysis 带来的洞察力,代价反而更大。能进行可视化分析,往往比小幅提升性能更重要。

难道别的分析器也能做同样的事情?

采样分析器和插桩式分析器也许能告诉你程序在空闲时停留在哪个函数上,但它们通常告诉不了你为何空闲、具体在等谁。只有通过跟踪一条条唤醒线程的线索,并结合其他信息,才能确定导致空闲等待的真正根源。

另外,xperf 还能以「连续捕获(continuous capture)」模式运行,不断地把系统活动记录到一个环形缓冲区里,当你观察到问题时再把缓冲区写到磁盘,之后进行离线分析。这是非常灵活的做法。

Wait Analysis 并不是「照着菜谱做饭」

做菜很多时候要精确按配方来,一旦乱改就容易失败;但 Wait Analysis 更像是解决谜题,需要灵活思考、跳出固有思路,并且对整个系统有深入理解。你要理解上下文切换、思考哪些空闲时间是正常的、哪些是不正常的;要分辨什么时候看 CPU Usage、什么时候看等待链;有时还需要摸索出全新角度的分析手段或表格汇总方式。确实不容易,但一旦掌握了这些技巧,就能解决大多数开发者无法处理的难题。

另一种观点

如果你想了解更多关于 xperf 处理卡顿的案例,可以看看 Trey Nash 的这篇 等待分析文章。如果你想在 Linux 上做类似的分析,请参阅 Brendan Gregg 关于 Off-CPU 分析的文章。

【译】ETW 堆跟踪 – 每个分配都被记录
【译】ETW 堆跟踪 – 每个分配都被记录
如何通过 ETW Provider 来记录应用日志
如何通过 ETW Provider 来记录应用日志
如何通过 C++ 实时监听 ETW 事件
如何通过 C++ 实时监听 ETW 事件
【译】调查并确定 Windows 运行速度变慢问题
【译】调查并确定 Windows 运行速度变慢问题
【译】丢失的 WPA 文档 —— 磁盘使用
【译】丢失的 WPA 文档 —— 磁盘使用
【译】丢失的 WPA 文档 —— CPU 调度
【译】丢失的 WPA 文档 —— CPU 调度

0

  1. This post has no comment yet

发表回复

您的邮箱地址不会被公开。 必填项已用 * 标注