调试高 CPU 使用率答案

【问题标题】：Debug High CPU Usage调试高 CPU 使用率
【发布时间】：2015-06-03 21:26:16
【问题描述】：

我有一个使用 UCMA（统一通信托管 API）4.0 SDK 的托管应用程序。我正在尝试调试应用程序使用 100% 的 CPU 并且系统挂起的问题。我已经使用 SOS 扩展来尝试调试根本原因。我目前被卡住了。我设法找到了占用 CPU 时间的线程 ID，但它们大多是非托管线程。我真的需要这方面的帮助。

线程 15、18、16、17、19、20 都是非托管线程，具有相同的调用堆栈。线程 9、10、11、12、13、14 都是非托管线程，并且也具有相同的调用堆栈。另一个问题是线程 21 和 22 似乎正在等待一个事件，那么为什么它们被认为是消耗 CPU 时间的失控线程？

有人知道 ZwRemoveIoCompletionEx 在做什么吗？这是像 NtWaitForMultipleObjects 一样处于休眠状态的东西，还是会占用 CPU 时间？在此应用程序的情况下，一旦达到 100%，它就永远不会下降，直到应用程序重新启动。

0:000> !loadby sos clr
0:009> .time
Debug session time: Wed May 27 15:47:52.000 2015 (UTC - 4:00)
System Uptime: 31 days 1:05:59.329
Process Uptime: 31 days 1:01:27.000
  Kernel time: 0 days 21:44:58.000
  User time: 1 days 16:51:40.000
0:000> !runaway
 User Mode Time
  Thread       Time
  15:113c      0 days 3:46:30.510
  18:1418      0 days 3:18:07.135
  16:1404      0 days 3:08:01.009
  17:140c      0 days 3:07:19.310
  19:1428      0 days 3:04:56.943
  20:1434      0 days 2:52:51.664
  22:1450      0 days 0:47:50.153
   9:11dc      0 days 0:45:02.904
  21:1440      0 days 0:43:34.623
  12:13cc      0 days 0:33:35.298
  11:1250      0 days 0:32:50.386
  14:fbc       0 days 0:31:57.018
  10:1178      0 days 0:29:12.920
  13:13c4      0 days 0:28:42.048
   2:fa8       0 days 0:03:11.678
   4:1164      0 days 0:02:45.080

0:015> kb
RetAddr           : Args to Child                                                           : Call Site
000007fe`fd36546f : 00000000`272946f0 000007fe`e5394b29 00000000`27295b18 00000000`27295b18 : ntdll!ZwRemoveIoCompletionEx+0xa
00000000`7700c089 : 00000000`1c4981e0 00000000`00000001 00000000`00000001 00000000`00000000 : KERNELBASE!GetQueuedCompletionStatusEx+0xdf
000007fe`e51b634b : 00000000`000009b0 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!GetQueuedCompletionStatusExStub+0x19
000007fe`e538fc0b : 00000000`1c4981e0 00000000`1c4981e0 000007fe`e5905340 00000000`00000000 : rtmpal!RtcPalTaskQueueDequeue+0x17
000007fe`e538f960 : 00000000`1f55fcf0 00000000`00000000 00000000`1db59eb0 00000000`1f55fcf0 : Microsoft_Rtc_Internal_Media!CStreamingEngineImpl::EngineWorkerThread+0x267
000007fe`e51b33c8 : 00000000`00000000 00000000`1c40a6a0 00000000`1c4a4f80 00000000`00000000 : Microsoft_Rtc_Internal_Media!CStreamingEngineImpl::EngineWorkerThreadProc+0xf0
000007fe`f22a3d67 : 00000000`00000000 00000000`1c40a6a0 00000000`00000000 00000000`00000000 : rtmpal!RtcPalSetSchedulerPolicy+0x194
000007fe`f22a3f0e : 000007fe`f233cdb0 00000000`00000000 00000000`00000000 00000000`00000000 : msvcr110!beginthreadex+0x107
00000000`76fd652d : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : msvcr110!endthreadex+0x192
00000000`7720c541 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0xd
00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d

0:022> !clrstack
OS Thread Id: 0x1450 (22)
        Child SP               IP Call Site
000000001fdcda68 000000007723186a [HelperMethodFrame_1OBJ: 000000001fdcda68] System.Threading.WaitHandle.WaitMultiple(System.Threading.WaitHandle[], Int32, Boolean, Boolean)
000000001fdcdba0 000007fee968c64c System.Threading.WaitHandle.WaitAny(System.Threading.WaitHandle[], Int32, Boolean)
000000001fdcdc00 000007fe8e097a70 Microsoft.Rtc.Internal.Media.RtpEventHandlerThread.EventHandlerThreadProc()
000000001fdce8d0 000007fee973d0b5 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000001fdcea30 000007fee973ce19 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000001fdcea60 000007fee973cdd7 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
000000001fdceab0 000007fee96b0301 System.Threading.ThreadHelper.ThreadStart()
000000001fdcedc8 000007feed44ffe3 [GCFrame: 000000001fdcedc8] 
000000001fdcf0f8 000007feed44ffe3 [DebuggerU2MCatchHandlerFrame: 000000001fdcf0f8]

0:021> kb
RetAddr           : Args to Child                                                           : Call Site
000007fe`fd331430 : 00000000`00190398 00000000`771f3a92 00000000`c0000008 00000000`00000110 : ntdll!NtWaitForMultipleObjects+0xa
00000000`76fd1220 : 00000000`1edefc18 00000000`1edefc00 00000000`00000000 00000000`00da7a64 : KERNELBASE!WaitForMultipleObjectsEx+0xe8
000007fe`e53bc322 : 00000000`0000cae8 00816179`f67cb320 00000000`1c497eb0 00000000`1edefce0 : kernel32!WaitForMultipleObjects+0xb0
000007fe`e51b33c8 : 00000000`00000000 00000000`00000000 00000000`1dad4630 00000000`1c4a5160 : Microsoft_Rtc_Internal_Media!CStreamingEngineImpl::TimerThreadProc+0x37e
000007fe`f22a3d67 : 00000000`00000000 00000000`1dad4630 00000000`00000000 00000000`00000000 : rtmpal!RtcPalSetSchedulerPolicy+0x194
000007fe`f22a3f0e : 000007fe`f233cdb0 00000000`00000000 00000000`00000000 00000000`00000000 : msvcr110!beginthreadex+0x107
00000000`76fd652d : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : msvcr110!endthreadex+0x192
00000000`7720c541 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0xd
00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d

0:013> kb
RetAddr           : Args to Child                                                           : Call Site
000007fe`fd36546f : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!ZwRemoveIoCompletionEx+0xa
00000000`7700c089 : 00000000`00000000 00000000`000000b7 00000000`00000001 00000000`1c4a4a40 : KERNELBASE!GetQueuedCompletionStatusEx+0xdf
000007fe`e51c0fef : 000007fe`e5905340 000007fe`e53eb764 00000000`00000000 00000000`1dac2ab0 : kernel32!GetQueuedCompletionStatusExStub+0x19
000007fe`e53eaf4b : 000007fe`e5905340 00000000`35bdd608 00000000`00000001 00000000`1f17fc20 : rtmpal!RtcPalIOCP::GetQueuedCompletionStatus+0x18f
000007fe`e53eac6d : 00000000`00000510 00000000`0000dddd 00000000`1dad9fe0 00000000`1f17fc80 : Microsoft_Rtc_Internal_Media!CTransportManagerImpl::TransportWorkerThread+0xe7
000007fe`e51b33c8 : 00000000`00000000 00000000`1c409460 00000000`1c4a4e40 00000000`00000000 : Microsoft_Rtc_Internal_Media!CTransportManagerImpl::TransportWorkerThreadProc+0x13d
000007fe`f22a3d67 : 00000000`00000000 00000000`1c409460 00000000`00000000 00000000`00000000 : rtmpal!RtcPalSetSchedulerPolicy+0x194
000007fe`f22a3f0e : 000007fe`f233cdb0 00000000`00000000 00000000`00000000 00000000`00000000 : msvcr110!beginthreadex+0x107
00000000`76fd652d : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : msvcr110!endthreadex+0x192
00000000`7720c541 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0xd
00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d

【问题讨论】：

那么...您的线程实际上在做什么？你的代码是做什么的？
使用 Windbg 是确定正在发生的事情的最佳方式。唯一的问题是它需要天才才能弄清楚，这是因为 MSFT 从来没有真正以记录良好或易于理解的方式公开内部数据结构。那里有一些很好的教程，但是，在互联网上查找 WINDBG 教程和 WINDBG 失控线程。祝你好运，我从来没有发现 WINDBG 很容易破译，而且在 50 次左右我只有大约 5 次能够弄清楚。
@EdS。这就是我似乎无法追踪执行的地方，因为这些是非托管线程，似乎是由 Microsoft UCMA 库分离出来的。如果我可以将它映射回我的应用程序在 Microsoft UCMA SDK 上调用的托管线程 ID，那将会很有帮助。
"为什么它们被认为是失控线程？"他们不是。所有活动线程都按 CPU 时间排序，由您决定“失控”的阈值是多少。请注意，（现在）等待线程的 CPU 使用率大约是主要违规者的 1/4。
如果你有 100% cpu，你可以考虑使用性能分析器。这会让你到达你想去的地方......

标签： c# performance debugging cpu-usage ucma

【解决方案1】：

使用 WinDbg 调试性能问题需要多次转储。一次转储只是时间快照，并不能为您提供完整的画面。

现在（在进行转储时），线程可能都没有做任何事情。您确定转储时它使用了 100% CPU 吗？还是在进行转储前一毫秒从 100% 恢复？

!runaway 显示的值是程序整个生命周期内的累积值。这只是告诉您该线程在过去工作了很多。它不会告诉你它现在正在做什么或将来会做什么。

虽然已经由 Mark Russinovich 和其他一些破解者完成，但这不是初学者的事情。

由于您需要多次转储才能全面了解情况，因此请使用其他工具来分析性能问题。典型的工具称为分析器，例如Redgate 的 ANTS 分析器或 JetBrains 的 dotTrace。

如果你真的想走这条路，至少使用 ProcDump (SysInternals) 和 -ma -c -n -s 选项来收集一些不错的高 CPU 转储。

【讨论】：

没有这个应用程序的问题是它总是卡在 100% 并且不会下降。另一个问题是，这有时会在应用程序运行几天或几周后发生。这些分析器是否需要安装调试版本？在生产环境中部署调试版本是不可行的。
@sgobiraj: 好的，如果它只能在如此困难的情况下在生产环境中重现，分析器可能会放弃（因为它产生了那么多数据）或者只是太慢而无法使用该程序在生产中。在这种情况下，使用 Procdump 获取其中一些转储可能是唯一的选择。
@sgobiraj：看来您已经花了很多时间寻找问题，而解决方案和创建转储的选择很重要。你能告诉我们更多你尝试过的东西，这样我们就不会想出像这样太简单的答案吗？例如。查看内核时间：您的进程有 21 小时内核时间和 40 小时用户时间。这对于 .NET 应用程序来说不太可能，您的应用程序是否执行了除 UCMA 之外可能与内核相关的其他事情？你用的是最新版本吗？ UCMA 需要驱动程序吗？如果是这样，它们是最新的吗？ ...
直接我们没有使用任何内核时间。据我所知，UCMA 不需要驱动程序。我正在尝试设置 Perfmon，但不确定如何设置它，以便我可以查看特定进程的活动并确定哪个线程正在使用 CPU 时间。

【解决方案2】：

一切都很顺利。有一个问题，您使用windbg 获取堆栈跟踪，有一些建议，然后当您说出“生产环境”这个神奇的词时wham世界改变了。

关于你帖子的其余部分，我注意到了这一点：

在此应用程序的情况下，一旦达到 100%，它就永远不会回落，直到应用程序重新启动。

基本上这意味着它坏了，而且坏得很厉害。

我还观察到您有一个多线程应用程序，这使得找出问题所在变得更加困难。

你不应该在生产环境中做的事情

嗯，基本上列表是：

调试
分析
运行单元测试
...这个列表还在继续。

如果您有一个 100% 的 CPU 峰值从未下降，那么查看软件开发过程的其余部分可能也会很有趣。你有自动（功能）测试代码吗？您是否使用代码覆盖率来检查您测试的内容？简而言之：你相信你有一个稳定的环境吗？

目前，这对您没有一点帮助。也就是说，在修复错误之后，我认为从长远来看考虑这些问题很重要。我不确定这是否适用于你的情况 - 但根据我的经验，你有这样的错误通常意味着你还有一些艰苦的工作要做。

已经坏了，不可能坏了

首先，让我们修复它。让我们面对残酷的事实。它已经坏了，所以如果我们暂时打破它，那也没关系。

问题是 100% CPU。您需要知道的是 CPU 使用率在代码中的位置。分析器是最适合的工具。

让自己成为像 Red Gate ANTS 这样的专业性能分析器。安装，开始。此外，您需要将 PDB 和源代码（与您的开发机器相同的文件夹结构）放在生产服务器上，我可能会将调试 DLL 放在那里。这都是暂时的，等我们发现我们的bug之后，这些东西应该又会消失了。正如我所说，您不希望在生产环境中使用它。

不要对您的生产应用程序轻描淡写，只需对您的源代码使用“行级”或“方法级”分析。它不会破坏你的应用程序，只会让它变慢。您还可以“暂停”分析器，这基本上意味着不再收集采样数据——在错误出现之前这样做是个好主意。

当错误出现时，再次继续分析器，并捕获一些数据。

调试器

根据我的经验，对应用程序进行调试和“堆栈跟踪”有时会破坏它们。我不完全确定何时会发生这种情况 - 但在所述生产环境中，您应该在停止调试过程后重新启动正在调试的应用程序。

一个可能的堆栈跟踪应用程序是来自 sysinternals 的process explorer。以管理员身份运行，双击进程，进入“线程”选项卡并单击每个线程的“堆栈跟踪”（或双击），直到发现有趣的东西。

如果您发现 Wait 或 Sleep，那可能还好。

祝你好运！

【讨论】：

【解决方案3】：

从SysInternals 尝试 Process Explorer 和 ProcMon。尽管它可能不会立即给您答案，但它提供了有关该过程的大量上下文，并且可能有助于阐明应用程序正在执行的不同操作。在 ProcMon 中，只需为您感兴趣的 ProcessName 设置一个过滤器。在 Process Explorer 中，找到该进程，右键单击 -> 属性。您会看到诸如线程和 TCP 连接之类的东西以及许多其他东西。

【讨论】：

是的，对不起。我的意思是说 ProcMon。