65.9K
CodeProject 正在变化。 阅读更多。
Home

理解 PerfView 中的线程时间视图

Sebastian Solnica
emptyStarIconemptyStarIconemptyStarIconemptyStarIconemptyStarIcon

0/5 (0投票)

2015年10月4日

MIT

4分钟阅读

viewsIcon

12737

最近，在检查一个缓慢请求问题（我计划在另一篇文章中描述这次调查）时，我意识到每次打开“线程时间”视图时，都需要花点时间来理解这个视图到底包含什么。

最近，在检查一个缓慢请求问题（我计划在另一篇文章中描述这次调查）时，我意识到每次打开“线程时间”视图时，都需要花点时间来理解这个视图到底包含什么。我决定写这篇文章，既为了我自己，也为了任何和我一样有这种感觉的人 :)。

 

“线程时间”视图是 PerfView 中最详细的视图，用于分析 CPU 峰值和线程等待时间。这通常不是你首先打开的视图，因为你会很快被呈现的大量数据弄得不知所措。我通常会从定位应用程序正在运行的有趣时间段开始进行线程时间分析。为此，你可以使用任何特殊视图，例如“服务器请求线程时间堆栈”视图或“ASP.NET 线程时间”视图，或者在“事件”视图中找到你感兴趣的事件。例如，在我的诊断案例中（反汇编请求），我使用了Windows Kernel/TcpIp/Accept 和 Windows Kernel/TcpIp/Disconnect 事件来设置我进一步调查的时间范围。但在本文中，我们将只检查请求时间的 2 毫秒（完整的分析应该很快就会发布）。让我们打开“线程时间”视图，并将“开始”和“结束”输入框分别设置为：9,330.058 和 9,333.001。现在切换到“调用树”选项卡，然后开始展开选定进程下的每个线程节点。其中大多数可能具有BLOCKED状态（如下图所示），这意味着它们在这段时间内什么都没做。

blocked-threads

你可以安全地将它们从视图中排除（在线程节点上按 Alt+E）。这样，你就只剩下具有有趣调用堆栈的线程了。在我的案例中，选定的时间段内，进程中只有两个线程处于活动状态：5760 和 7260。我们将重点关注第一个。展开所有调用堆栈后，我得到了以下数据（我已用点替换了无关的行）。

 


  Process32 w3wp (3736)
  + Thread (5760) CPU=7ms (.NET ThreadPool)
  ...
  Name                                                                     First       Last
  + nancy!ModuleExtensions.Bind                                            9,330.057  9,331.099
  | + Nancy!DynamicModelBinderAdapter.TryConvert                           9,330.057  9,331.099
  |  + Nancy!DefaultBinder.Bind                                            9,330.057  9,331.099
  |   + Nancy!DefaultBinder.DeserializeRequestBody                         9,330.057  9,331.099
  |    + Nancy!JsonBodyDeserializer.Deserialize                            9,330.057  9,331.099
  |     + mscorlib.ni!StreamReader.ReadToEnd                               9,330.057  9,331.099
  |      + mscorlib.ni!StreamReader.ReadBuffer                             9,330.057  9,331.099
  |       + Nancy!RequestStream.Read                                       9,330.057  9,331.099
  |        + Microsoft.Owin.Host.SystemWeb!DelegatingStream.Read           9,330.057  9,331.099
  |         + System.Web.ni!HttpBufferlessInputStream.Read                 9,330.057  9,331.099
  |          + System.Web.ni!IIS7WorkerRequest.ReadEntityBody              9,330.057  9,331.099
  |           + System.Web.ni!IIS7WorkerRequest.ReadEntityCoreSync         9,330.057  9,331.099
  |            + System.Web.ni!DomainBoundILStubClass.IL_STUB_PInvoke(...  9,330.057  9,331.099
  |             + webengine4!MgdReadEntityBody                             9,330.057  9,331.099
  |               + ...                                                    9,330.057  9,331.099
  |                 + ntoskrnl!NtWaitForSingleObject                       9,330.057  9,331.099
  |                  + ntoskrnl!KeWaitForSingleObject                      9,330.057  9,331.099
  |                   + ntoskrnl!KiCommitThreadWait                        9,330.057  9,331.099
  |                    + ntoskrnl!KiSwapContext                            9,330.057  9,331.099
  |                     + ntoskrnl!SwapContext_PatchXRstor                 9,330.057  9,331.099
1#|                      + BLOCKED                                         9,330.057  9,330.663
2#|                      + CPU_TIME                                        9,330.663  9,331.099
  + LowLevelDesign.Diagnostics.LogStore.ElasticSearch!ElasticSearchAppC... 9,331.728  9,332.373
  |                    + ...                                               9,331.728  9,332.373
3#|                      + CPU_TIME                                        9,331.728  9,332.373
  + FluentValidation!FluentValidation.AbstractValidator`1[...].Validate    9,331.099  9,331.728
  |                    + ...                                               9,331.099  9,331.728
4#|                      + CPU_TIME                                        9,331.099  9,331.728

 

注意左边距和上面的四个标记——我稍后会引用它们。通过查看右侧的时间范围，我们可以看到一切都始于 9,330.057 毫秒。首先，线程被阻塞（标记 1#），直到 9,330.663 毫秒。BLOCKED 事件的调用堆栈显示了线程在被挂起时正在做什么。。现在，我们有一些CPU_TIME，分为三个时间段。

  • 从 9,330.663 毫秒到 9,331.099 毫秒（标记 2#）
  • 从 9,331.099 毫秒到 9,331.728 毫秒（标记 4#）
  • 从 9,331.728 毫秒到 9,332.373 毫秒（标记 3#）

正如你在代码片段中看到的，行并没有按时间顺序排序——标记 4# 在 3# 之前，你应该检查“时间”列来查看哪个时刻更早，例如。

  |When                                 First	    Last
2#| AAAAAA9AAAA3____________________    9,330.057   9,331.099
3#| __________________8AAAAAA1______    9,331.728   9,332.373
4#| ___________6AAAAAA1_____________    9,331.099   9,331.728

现在的问题是如何解释这些调用堆栈？在我们回答这个问题之前，让我们先了解 PerfView 是如何构建“线程时间”视图的。众所周知，ETW 跟踪只是一个收集不同提供商事件的过程。PerfView（或 WPA）中可用的视图只是显示这些收集事件的便捷方式。“线程时间”视图也不例外，它是基于以下事件构建的。

  • Windows Kernel/Thread/CSwitch – 每次线程获得 CPU 时间时生成的事件（CPU 从一个线程切换到另一个线程）。
  • Windows Kernel/PerfInfo/Sample – 每毫秒生成的事件，用于收集系统中每个处理器上正在运行的进程的堆栈跟踪。

让我们打开“事件”视图，将时间范围设置为 9,330.058 毫秒–9,333.001 毫秒，选择我们的进程，并从事件列表中选择上述事件。我们将收到以下记录（我为了更好的可读性进行了格式化）。

Event#1
Event Name:   Windows Kernel/Thread/CSwitch
Time MSec :   9,331.778
Process Name: w3wp (3736)
Rest:         HasStack="True" ThreadID="5,760" OldThreadID="7,256" OldProcessID="3,736" OldProcessName="w3wp" NewThreadID="5,760" NewProcessID="3,736" NewProcessName="w3wp" ProcessorNumber="0" NewThreadPriority="8" OldThreadPriority="9" NewThreadQuantum="0" OldThreadQuantum="0" OldThreadWaitReason="15" OldThreadWaitMode="Swappable" OldThreadState="Wait" OldThreadWaitIdealProcessor="0" NewThreadWaitTime="0"

Event#2
Event Name:   Windows Kernel/PerfInfo/Sample
Time MSec :   9,332.100
Process Name: w3wp (3736)
Rest:         HasStack="True" ThreadID="5,760" InstructionPointer="0xfffff800019c7bf0" ProcessorNumber="0" Priority="0" ExecutingDPC="False" ExecutingISR="False" Rank="0" Count="1"

Event#3
Event Name:   Windows Kernel/Thread/CSwitch
Time MSec :   9,332.373
Process Name: w3wp (3736)
Rest:         HasStack="True" ThreadID="1,244" OldThreadID="5,760" OldProcessID="3,736" OldProcessName="w3wp" NewThreadID="1,244" NewProcessID="3,736" NewProcessName="w3wp" ProcessorNumber="0" NewThreadPriority="9" OldThreadPriority="8" NewThreadQuantum="0" OldThreadQuantum="0" OldThreadWaitReason="32" OldThreadWaitMode="Swappable" OldThreadState="Ready" OldThreadWaitIdealProcessor="0" NewThreadWaitTime="452"

现在，一切都变得清晰了。我们有两个上下文切换，可以看到第一次切换，在 9,331.778 毫秒（事件 #1），激活了我们的 5760 线程（NewThreadID），直到 9,332.373 毫秒（事件 #3）才停止，那时系统调度程序暂停了它，并将第一个 CPU 切换到了线程 1244（NewThreadID）。在此期间，在 9,332.100 毫秒记录了一个分析事件，这证明该线程正在第一个处理器上运行。

通过所有收集到的数据，我们可以总结 5760 线程生命周期中的 2 毫秒如下表所示。

时间 描述
9,331.778 毫秒 在接收到请求流后，系统唤醒了该线程，并开始执行某些操作（我们不知道是什么）。
9,332.100 毫秒 该线程正在 ElasticSearch 日志存储中执行一些请求（堆栈来自我的代码，所以我知道 :)）。
9,332.373 毫秒 该线程正在执行验证（FluentValidation.AbstractValidator`1.Validate）时，被系统暂停。

正如你所见，你的系统在每一毫秒都在发生很多事情，收集 ETW 跟踪是准确了解是什么让你的 CPU 核心繁忙的最佳方法之一 :)。


Filed under: CodeProject, 诊断线程问题

© . All rights reserved.