WinDbg 失控命令输出解释

Question

我有一个生产 CPU 问题，经过几天的常规活动后，CPU 突然开始达到峰值。我已保存转储文件并运行 !runaway 命令以获取 CPU 耗时最高的线程列表。输出如下：

用户模式时间
线程时间
21:110 0 天 10:51:39.781
19:f84 0 天 10:41:59.671
5:cc4 0 天 0:53:25.343
48:74 0 天 0:34:20.140
47:1670 0 天 0:34:09.812
13:460 0 天 0:32:57.640
8:14d4 0 天 0:19:30.546
7:d90 0 天 0:03:15.000
23:1520 0 天 0:02:21.984
22:ca0 0 天 0:02:08.375
24:72c 0 天 0:02:01.640
29:10ac 0 天 0:01:58.671
27:1088 0 天 0:01:44.390

如您所见，输出显示我有 2 个线程：21 和 19，它们总共消耗了 20 多个小时的 CPU 时间，我能够像这样跟踪其中 1 个线程的调用堆栈：

~21s
!CLRStack

此时的输出无关紧要，我们称它为“X callstack”

我想要的是关于 !runaway 命令输出的解释。据我了解，转储文件是应用程序当前状态的快照。所以我的问题是：

1. 当转储过程只用了几秒钟时，runaway 命令如何显示线程 21 的 10:51 小时值？
2. 这是否意味着我使用 !CLRStack 命令找到的 X 调用堆栈的特定“实例”已挂起超过 10 小时？或者这是 21 个线程执行他的整个 X 调用堆栈执行的总时间？如果是这样，那么负责执行这么多 X 调用堆栈的 21 个线程似乎很奇怪。据我所知，起源是一个网络请求（运行时应该为每个调用分配一个随机线程）

我有一个推测可以回答这两个问题：

也许windbg通过获取线程调用堆栈的实际时间并将其除以转储过程的范围来计算时间，因此，例如，如果X调用堆栈的具体执行耗时1秒，整个转储过程耗时3秒（ 33%），当进程运行总共 24 小时时，输出将显示：

8 小时（24 小时的 33%）

我是对的，还是完全弄错了？

Answer 1

这个答案旨在让 OP 能够理解。它并不打算对所有位和字节都正确。

[...] 并将其除以倾销过程的范围 [...]

这种理解可能是万恶之源：转储进程只会让您及时了解进程在某个点的状态。转储进程的持续时间为 0.0 秒，因为在操作期间所有线程都被挂起。 （因此，您的过程的相对时间没有改变，时间静止不动；当然挂钟时间会改变）

您正在考虑将进程转储为在较长时间内对其进行监视，但事实并非如此。转储进程只需要时间，因为它涉及磁盘活动等。

所以不，没有“范围”，因此您不能（这真的很难）衡量故障转储的性能问题。

runaway 命令如何显示线程 21 的 10:51 小时值，[...]

如果您只有一个每秒触发的计时器事件，您的 C# 程序如何知道程序运行了多长时间？答案是：它使用一个变量并增加值。

Windows 大致就是这样处理的。 Windows 负责线程调度，每次重新调度线程时，都会更新一个包含线程时间的变量。

在编写故障转储时，操作系统早已收集到的信息已包含在故障转储中。

[...] 转储过程只需要几秒钟？

由于崩溃转储是由 WinDbg 的一个线程进行的，因此该线程所占用的时间。您需要调试 WinDbg 并在 WinDbg 线程上执行 !runaway 以查看花费了多少 CPU 时间。可能是一个不错的练习，.dbgdbg（调试调试器）命令对您来说可能是新的；除此之外，这种特殊情况并没有真正的帮助。

这是否意味着我使用 !CLRStack 命令找到的 X 调用堆栈的特定“实例”已挂起超过 10 小时？

没有。这意味着在您创建故障转储的时间点，执行了该特定方法。不多也不少。

此信息与!runaway 无关，因为该线程可能在很长一段时间内一直在做一些完全不同的事情，但刚刚结束。

或者这是 21 个线程执行他的整个 X 调用堆栈执行的总时间？

没有。故障转储不包含如此详细的性能数据。您需要像 JetBrains dotTrace 这样的性能分析器来获取该信息。分析器会经常查看调用堆栈，然后聚合相同的调用堆栈并得出每个调用堆栈的 CPU 时间。