练习 3 - 了解关键路径和等待时间量分析

  • 项目

场景和活动可能会意外延迟。 例如，在 Microsoft Edge 中打开选项卡所需的时间可能比预期的要长。

活动被定义为从开始事件流向结束事件的一系列操作，一些操作顺序执行，一些操作并行执行。 跟踪中的任何开始/结束事件对都可以被视为一个活动。 通过这一系列操作的最长路径被称为“关键路径”。 减少关键路径上任何操作的持续时间会直接减少整个活动的持续时间。

建议确定完成活动的进程和线程，并从活动完成的时间开始向后工作。 首先分析完成该活动的线程，以确定该线程如何花费其大部分时间以及处于什么状态：“正在运行”、“就绪”或“正在等待”。

大量运行时间表明直接 CPU 使用率可能影响关键路径的持续时间。 在“就绪”状态下花费的时间表明其他线程通过阻止关键路径上的线程执行来影响关键路径的持续时间。 在“正在等待”状态下花费的时间指向 I/O、计时器或当前线程正在等待的关键路径上的其他线程和进程。

准备好当前线程的每个线程都可能是关键路径中的另一个环节，并且还可以进行分析，直到考虑到关键路径的持续时间。

所有必需的信息都记录在“WPA”中的“CPU 使用率(精确)”图表和表格中。 调度程序记录的 CPU 使用事件与上下文切换相关联。 此表重点描述了被换入线程 NewThread，每一行代表一个上下文切换。 针对以下事件序列收集数据：

显示数据收集工作流程的图表。

  1. 由于阻止函数调用，“NewThread”被换出。

  2. “NewThread”已准备好由就绪线程运行。

  3. “NewThread”被换入，从而换出旧线程。

  4. “NewThread”再次换出。

下面是“CPU 使用率(精确)”表中相关的列。

列 详细信息
% CPU Usage 切换新线程后的 CPU 使用率。 此值表示为当前可见时间段内总 CPU 时间的百分比。
计数 行表示的上下文切换数。 对于单个行，此值始终为 1。
CPU Usage (ms) 上下文切换后新线程的 CPU 使用率。
NewProcess 新线程的进程。
NewThreadId 新线程的线程 ID。
NewThreadStack 新线程换入时的堆栈。 通常表明线程被什么阻止或正在等待什么。
Ready(s) 线程在就绪队列中花费的时间（由于抢占或 CPU 不足）。
ReadyingThreadId 就绪线程的线程 ID。
ReadyingProcess 拥有就绪线程的进程。
ReadyThreadStack 就绪线程的堆栈。
ReadyTime (s) 新线程就绪的时间。
SwitchInTime(s) 新线程换入的时间。
Waits (s) 线程在逻辑或物理资源上等待的时间。 当“ReadyingThreadId”发出“NewThreadId”信号时，等待结束。

步骤 1：捕获并打开 UI 延迟问题的跟踪

本练习将侧重于具有无响应 UI 的虚拟进程。 该进程是一个具有按钮和文本框的简单的 Windows 窗体应用程序。 单击按钮时，UI 将停止响应 20 秒，直到文本框更新。 你将分析此操作的关键路径。

UIDelage 示例对话框的屏幕截图。

  1. 从此处下载“UIDelay.exe”。

  2. 启动“UIDelay.exe”。

  3. 从“开始”菜单打开“WPR”。

  4. 修改跟踪配置。

    1. 选择“一级会审”和“CPU 使用率”。

    2. 选择“常规”作为“性能方案”。

    3. 选择“详细”作为“详细级别”。

      WPR 对话框的屏幕截图。

  5. 单击“开始”。

  6. 在“UIDelay.exe”中，单击“单击”按钮。

    • 等到文本框显示“完成!”

  7. 在“WPR”中，保存跟踪，然后使用“WPA”将其打开。

  8. 打开“跟踪”菜单，然后选择“配置符号路径”。

    • 指定符号缓存的路径。 有关符号详细信息，请参阅 MSDN 上的符号支持页面。

  9. 打开“跟踪”菜单，然后选择“负载符号”。

步骤 2：标识延迟的 UI 线程

在执行关键路径分析之前，必须先确定活动开始和停止事件。

  1. 在“Graph 资源管理器”的“系统活动”节点中找到“UI 延迟”图。

    Graph 资源管理器 UI 的屏幕截图。

  2. 将“UI 延迟”图拖放到“分析”选项卡中。

  3. 找到“UIDelay.exe”进程。

    1. 其持续时间应约为 20 秒。 这表明“UIDelay.exe”的 UI 线程有 20 秒的延迟。

    2. UI 线程标识符显示在“Thread Id”列中。 在此示例中为 24174。 在你在计算机上捕获的跟踪中，此值会有所不同。 请务必记下线程 ID。

      示例数据的屏幕截图。

  4. 选择整个“UIDelay.exe”时间间隔，右键单击并放大。

    缩放选项的屏幕截图。

应始终放大尝试分析的区域。 它减少了无关活动引入的干扰量。

步骤 3：分析 UI 延迟关键路径

有了具有线程 ID 和时间戳的分析起点后，便可以开始研究活动关键路径，了解导致 UI 线程延迟 20 秒的事件序列。

此步骤的“NewThreadId”是你在步骤 2 中确定的线程（“UIDelay.exe”进程中的线程 24174）。

  1. 将“CPU 使用率(精确)”图表添加到“分析”选项卡并应用“按进程显示的利用率，线程”预设。

    WPA 中示例数据的屏幕截图，显示具有“按进程显示的利用率，线程”的 Graph 资源管理器

  2. 右键单击列标题，使“NewThreadStack”、“ReadyThreadStack”和“CPU Usage (ms)”列可见。

  3. 删除“Ready (us) [Max]”和“Waits (us) [Max]”列。 该视区现应如下所示。

    WPA 中示例数据的屏幕截图，显示名为“UIDelay.exe”的系列的“按进程显示的 CPU 使用利用率，线程”的放大视图

  4. 在“NewProcess”列中查找并展开“UIDelay.exe”进程，然后单击列标题按“Waits (us) [Sum]”排序。

  5. 在“UIDelay.exe”进程中搜索“NewThreadId”，并分析其处于“正在运行”、“就绪”或“正在等待”状态的时间。

    • 在下面的示例中，可以发现：

      • 线程将消耗 10.025 秒的 CPU 时间。

      • 线程正在等待 5.159 秒。

      • 线程处于就绪状态的时间可以忽略不计（10 毫秒）。

      WPA 中示例数据的屏幕截图，显示通过 New Process UIDelay.exe 刻度尺的双线

    注意 你可以使用练习 2 步骤 4 中描述的同一个方法分析 10 秒的 CPU 活动，同时使用“CPU 使用率(采样)”图表并查看“UIDelay.exe”进程。

  6. 若要了解“NewThreadId”正在等待的内容，请展开“NewThreadId”组以显示“NewThreadStack”。

  7. 展开“[Root]”并确定导致等待的函数调用。

    WPA 中示例表的屏幕截图，显示 UIDelay.exe 单击事件数据

在此示例中，当按钮单击功能被触发时，“UIDelay.exe”线程 ID 24174 将等待基础阻止函数调用 5.073 秒：

  • 5.021 秒是通过“ExecuteWMICall”函数下的操作得来的。

  • 35 毫秒是通过“PingServer”函数下的操作得来的。

步骤 3.1：查看 ExecuteWMICall 代码路径

如果在“ExecuteWMICall”下进一步展开调用堆栈，则会发现 UI 线程通过显式调用“Thread.Sleep”实际上休眠了 5 秒。

WPA 中示例数据的屏幕截图。

应不惜一切代价避免这种行为，因为它直接影响了响应能力。 如果代码需要等待信息，它应该在单独的线程上异步执行，并使用事件驱动的方法。

步骤 3.2：查看 PingServer 代码

如果在“PingServer”下进一步展开调用堆栈，则会发现 UI 线程在通过网络发送“Ping”命令时具有 I/O 依赖性。

WPA 中示例表的屏幕截图，显示 UIDelay.exe 节点扩展到 System.ni.dll 数据

虽然延迟非常小（35 毫秒），但应该在 UI 线程上予以避免。 请记住，普通人都会注意到大于 100 毫秒的 UI 延迟。 此操作可能会将总的活动用时增加 100 毫秒以上，从而导致用户对响应能力的感知不佳。

这些操作应该在单独的线程上异步发生，不会阻止 UI。