调试 IIS 进程上的高 CPU 使用率

Posted 2023-03-06

【中文标题】调试 IIS 进程上的高 CPU 使用率

【英文标题】：Debugging high CPU ussage on IIS process

【发布时间】：2015-06-23 11:58:08

【问题描述】：

IIS 进程的 CPU 使用率高

我目前正在调查我们的一台生产服务器上的高 CPU 使用率，我遇到了困难，希望这里的人能够提供帮助。将 CPU 使用率与入站 Web 服务调用（WCF 和 REST）的数量进行比较告诉我，它们是不相关的，只要调用增加或减少，CPU 使用率似乎就会攀升。

设置

Windows 2012 R2 服务器 x64 IIS 8.5 .NET 4.5 运行我们的应用程序的单个应用程序池 00:00 自动回收应用程序池

问题

最近我们的 CPU 使用率急剧增加，模式似乎是 CPU 使用率从午夜（我回收池的地方）开始攀升，并不断攀升，直到池再次被回收。

数据

通过分析 taskmanager 和使用性能计数器，我已经能够确认确实是我们的 W3WP 进程消耗了 CPU。

当 CPU 消耗超过 50% 的阈值超过 10 秒时，我将 DebugDiag 2.1 配置为间隔 10 秒进行 3 次内存转储。 （出现此问题之前的正常 CPU 使用率为 5-10%）

使用 ntsd 查看转储文件，我看到几个线程消耗大量 CPU：

0:047> !runaway
 User Mode Time
  Thread       Time
  47:2920      0 days 0:24:42.921
  49:1f1c      0 days 0:23:07.796
  52:2ed8      0 days 0:21:38.218
  54:1560      0 days 0:21:37.937
  48:273c      0 days 0:21:19.140
  59:2110      0 days 0:20:56.078
  45:2d90      0 days 0:20:35.906
...
  19:1c88      0 days 0:00:00.000

（这里只显示一些线程） 因此，我尝试查看这些线程中发生了什么，因为这不是预期的行为。所有具有长时间运行任务的线程似乎都得到了管理，但是当我尝试 !clrstack 时，我得到了：

0:047> !clrstack
OS Thread Id: 0x2920 (47)
        Child SP               IP Call Site
GetFrameContext failed: 1
0000000000000000 0000000000000000 <unknown>

这让我感到困惑，因为我期待的是托管堆栈。当我查看本机堆栈时，我得到了一些不同的东西：

0:047> !dumpstack
OS Thread Id: 0x2920 (47)
Current frame: ntdll!NtWaitForSingleObject+0xa
Child-SP         RetAddr          Caller, Callee
0000009c46eae730 00007fff0c131118 KERNELBASE!WaitForSingleObjectEx+0x94, calling ntdll!NtWaitForSingleObject
0000009c46eae7d0 00007fff051f91eb clr!CLREventWaitHelper2+0x38, calling kernel32!WaitForSingleObjectEx
0000009c46eae7e0 00007fff0c13155c KERNELBASE!SetEvent+0xc, calling ntdll!NtSetEvent
0000009c46eae810 00007fff051f9197 clr!CLREventWaitHelper+0x1f, calling clr!CLREventWaitHelper2
0000009c46eae870 00007fff051f9120 clr!CLREventBase::WaitEx+0x70, calling clr!CLREventWaitHelper
0000009c46eae8b0 00007fff052890e6 clr!SVR::t_join::join+0x106, calling clr!CLREventBase::WaitEx
0000009c46eae900 00007fff053d5913 clr!SVR::gc_heap::bgc_thread_function+0x97, calling clr!CLREventBase::WaitEx
0000009c46eae940 00007fff0533fcb6 clr!Thread::intermediateThreadProc+0x7d
0000009c46eaeb10 00007fff0ef4086d ntdll!RtlAllocateHeap+0x17d, calling ntdll!RtlpAllocateHeap
0000009c46eaec20 00007fff0ef40073 ntdll!RtlpSubSegmentInitialize+0x2f3, calling ntdll!RtlpHeapGenerateRandomValue32
0000009c46eaeca0 00007fff0ef40c65 ntdll!RtlpLowFragHeapAllocFromContext+0x355, calling ntdll!memset
0000009c46eaed10 00007fff0ef40c65 ntdll!RtlpLowFragHeapAllocFromContext+0x355, calling ntdll!memset
0000009c46eaed70 00007fff0ef407c7 ntdll!RtlAllocateHeap+0xd7, calling ntdll!RtlpLowFragHeapAllocFromContext
0000009c46eaede0 00007fff0ef407c7 ntdll!RtlAllocateHeap+0xd7, calling ntdll!RtlpLowFragHeapAllocFromContext
0000009c46eaee80 00007fff05f5a89a mscoree!calloc_impl+0x72, calling ntdll!RtlAllocateHeap
0000009c46eaeeb0 00007fff0c135ac4 KERNELBASE!SetTEBLangID+0x2c, calling ntdll!RtlSetLastWin32ErrorAndNtStatusFromNtStatus
0000009c46eaeef0 00007fff05cf15e6 mscoreei!calloc_impl+0x5d, calling ntdll!RtlAllocateHeap
0000009c46eaef20 00007fff05cf145b mscoreei!initptd+0xb7, calling mscoreei!unlock
0000009c46eaef30 00007fff0ef40c65 ntdll!RtlpLowFragHeapAllocFromContext+0x355, calling ntdll!memset
0000009c46eaef50 00007fff05cf138e mscoreei!CRT_INIT+0x135, calling kernel32!GetCurrentThreadId
0000009c46eaef80 00007fff05cf11ee mscoreei!__DllMainCRTStartup+0x8a, calling mscoreei!DllMain
0000009c46eaefe0 00007fff0c3b1387 00007fff0c3b1387
0000009c46eaf030 00007fff04c111d2 00007fff04c111d2, calling 00007fff04c11070
0000009c46eaf0c0 00007fff0ef407c7 ntdll!RtlAllocateHeap+0xd7, calling ntdll!RtlpLowFragHeapAllocFromContext
0000009c46eaf0f0 00007fff0ef2c187 ntdll!RtlDeactivateActivationContextUnsafeFast+0xc7, calling ntdll!_security_check_cookie
0000009c46eaf110 00007fff05085c6e MSVCR120_CLR0400!calloc_impl+0x5d, calling ntdll!RtlAllocateHeap
0000009c46eaf120 00007fff0ef2c2a3 ntdll!RtlActivateActivationContextUnsafeFast+0x93, calling ntdll!_security_check_cookie
0000009c46eaf140 00007fff05085d9b MSVCR120_CLR0400!initptd+0xb7, calling MSVCR120_CLR0400!unlock
0000009c46eaf160 00007fff03064d9c clrjit!__DllMainCRTStartup+0x8d, calling clrjit!DllMain
0000009c46eaf190 00007fff0ef4b9b8 ntdll!LdrpReleaseModuleEnumLock+0x1c, calling ntdll!RtlReleaseSRWLockShared
0000009c46eaf1a0 00007fff0ef2c324 ntdll!LdrpCallInitRoutine+0x4c
0000009c46eaf1c0 00007fff0ef4b96b ntdll!LdrpReleaseLoaderLock+0x27, calling ntdll!LdrpReleaseModuleEnumLock
0000009c46eaf200 00007fff0ef2c083 ntdll!LdrpInitializeThread+0x1f3, calling ntdll!LdrpReleaseLoaderLock
0000009c46eaf270 00007fff0ef2bfc3 ntdll!LdrpInitializeThread+0x133, calling ntdll!RtlActivateActivationContextUnsafeFast
0000009c46eaf278 00007fff0ef2bff6 ntdll!LdrpInitializeThread+0x166, calling ntdll!RtlDeactivateActivationContextUnsafeFast
0000009c46eaf2e0 00007fff0ef28fa3 ntdll!_LdrpInitialize+0x93, calling ntdll!NtTestAlert
0000009c46eaf350 00007fff0ef28ec8 ntdll!LdrInitializeThunk+0x18, calling ntdll!NtContinue
0000009c46eaf7c0 00007fff0533fc9f clr!Thread::intermediateThreadProc+0x66, calling clr!_chkstk
0000009c46eaf800 00007fff0e7713d2 kernel32!BaseThreadInitThunk+0x22
0000009c46eaf830 00007fff0ef25444 ntdll!RtlUserThreadStart+0x34

这让我相信线程正在等待一些资源（这是正确的吗？）这是我真正迷路的地方！ 跟踪中间的那些行发生了什么：

0000009c46eaefe0 00007fff0c3b1387 00007fff0c3b1387
0000009c46eaf030 00007fff04c111d2 00007fff04c111d2, calling 00007fff04c11070

我的猜测是这里发生了一些托管的事情，但是为什么 !clrstack 不工作呢？ 通过查看第一帧，我觉得它正在等待一些资源句柄。我看起来手柄是 0xa，但我不确定这一点。用 !handle 0xa ff 查看句柄，我明白了：

0:047> !handle 0xa ff
Handle 000000000000000a
  Type          File
  Attributes    0
  GrantedAccess 0x100020:
         Synch
         Execute/Traverse
  HandleCount   2
  PointerCount  65535
  No object specific information available

告诉我这指向一个文件，但是什么文件，我该如何从这里继续？看看其他***跑道线程给了我同样的画面。

呼救声

我知道这是一项艰巨的任务，但我真的需要帮助才能从这里继续前进。我是在正确的轨道上还是我只是在黑暗中四处闲逛？ 任何帮助将不胜感激！

新闻

在建立我们的 IT 部门之后。用一些我觉得有趣的计数器记录一个 perfMon 数据集给我我得出了一个结论：1）我们正在泄漏线程 2）GC 变得疯狂（可能是因为泄漏）。 关于如何检测导致线程泄漏的任何想法？ 在此处查看计数器：2

在发现我们正在泄漏线程后，我一直在查看我们的代码并发现了一些感兴趣的代码：

// Initialize TimerExecutionEveryMinute timer
const double timeConversion = 60 * 1000; //convert one minute to milliseconds

var timer1 = new System.Timers.Timer  Enabled = true, Interval = timeConversion ;
timer1.Elapsed += TimerExecutionEveryMinute;

然后：

// Execution every minute
public static void TimerExecutionEveryMinute(object sender, EventArgs e)

    var jpsLogger = KernelContainer.Kernel.Get<IJpsLogger>();

    // Initialize MemBag
    MemBag.Log.ActivityIdReset(Guid.NewGuid());
    MemBag.Log.BaseType = "TimerExecution";
    MemBag.Log.BaseClass = "Timer";
    MemBag.Log.BaseMethod = "TimerExecutionEveryMinute";

    // Statistic timer job
    var t1 = jpsLogger.Trace.SpecializedDebug("Analyses.OneMinuteTimer", "One minute timer begin");

        var t2 = jpsLogger.Trace.SpecializedDebug("Analyses.OneMinuteTimer", "    Method.WriteDB begin");
            Method.WriteDB();
        jpsLogger.Trace.SpecializedDebug("Analyses.OneMinuteTimer", "    Method.WriteDB end", t2);

        t2 = jpsLogger.Trace.SpecializedDebug("Analyses.OneMinuteTimer", "    Memory.LogCurrentState begin");
            Memory.LogCurrentState();
        jpsLogger.Trace.SpecializedDebug("Analyses.OneMinuteTimer", "    Memory.LogCurrentState end", t2);


        //Calculates the CPU load based on samples taken at every timer step
        t2 = jpsLogger.Trace.SpecializedDebug("Analyses.OneMinuteTimer", "    CPU load begin");
            CPULogger.LogCpu();
        jpsLogger.Trace.SpecializedDebug("Analyses.OneMinuteTimer", "    CPU load end", t2);

        // Dump log information to file
        t2 = jpsLogger.Trace.SpecializedDebug("Analyses.OneMinuteTimer", "    FileLogger.WriteAsync begin");
            FileLogger.WriteAsync();
        jpsLogger.Trace.SpecializedDebug("Analyses.OneMinuteTimer", "    FileLogger.WriteAsync end", t2);

        jpsLogger.Trace.SpecializedDebug("Analyses.OneMinuteTimer", "One minute timer end", t1);

这可能是泄漏线程的地方吗？我相信 System.Timers.Timer 每次我创建事件时都会启动新线程，并且它是线程安全的，所以我会在执行代码周围创建锁，每分钟执行的代码都会写入日志文件，我的论文如果该访问到文件被阻塞并且线程不断堆积，这可以解释逻辑线程的线性增加数量，如2中所见@

【问题讨论】：

我做了更多研究，似乎!runaway 顶部的所有线程都是 GC 线程，为什么它们会占用所有 cpu 周期？

在那个特定的时刻，这个线程什么也没做。找到一个做某事的线程。你能附上Visual Studio吗？ Process Explorer 还可以显示正在运行的进程的线程堆栈。利用这种能力在生产中采集一些样本。

你如何判断线程没有做任何事情？以及如何找到实际上给 CPU 带来负载的那些？ !runaway 列表顶部的所有踏板似乎都在等待什么..

我们的问题似乎与此类似：serverfault.com/questions/614372/… 不幸的是没有答案。

顺便说一句，我无法将 VS 附加到产品服务器。但也许我可以使用 perfMon 来查看哪些线程在做这项工作。

【参考方案1】：

我没有答案，但让我尝试提供一些提示。

在你提到的问题中

最近我们的 CPU 使用率急剧增加...

这是否意味着该应用之前运行良好？是否没有您意识到的异常 CPU 峰值？

如果是这种情况，那么你需要看看最近发生了什么变化：

是否为您的应用部署了任何新代码，特别是分配大量数据的任何代码？

是否在服务器上安装了任何更新，如果是，您能否审核它们并检查任何可能提到您症状的 Microsoft 知识库文章（或简单地谷歌更新名称，看看是否有博客提到它们） '正在相遇。

在您的情况下，垃圾收集器似乎出了问题。我要做的第一件事是查看已部署的任何新代码-可能是代码（或该代码的副作用）正在分配对象，其副作用是 GC 进入超速运行以处理内存压力。

考虑到这一点，为什么不下载 .NET 内存管理工具的 trisl 版本，例如 RedGate's ANTS Memory Profiler，并在峰值期间拍摄一些内存转储快照。使用这样的工具更容易在转储之间进行比较，例如告诉您分配/释放的对象数量、使用的内存量等。它可能会给您一个线索。

【讨论】：

感谢您的意见。我无法确定对我们的代码库的更改是否可能是导致 CPU 负载高的原因，因为我们使用了持续的 delevery，并且当 CPU 一天用完并且入站调用开始直到超时时第一次看到问题，我们通过更改解决了这个问题从 4 个 CPU 到 16 个 CPU 的（虚拟）服务器是一种临时解决方案。关于服务器更新，我们最近从 2008 r2 更改为 2012，这在这里绝对很重要，但我根本不知道如何证明/反驳。

我们有 JetBrains 包（DotTrace 和 DotMemory），但它们似乎有问题，我担心在使用它们时会导致我们的实时服务器崩溃。由于 IT 部门的规则，获得在我们的产品服务器上放置 3. 派对软件的许可也很麻烦。

啊，是的，我忘了这是一个实时服务器问题。在这种情况下，我不会尝试安装任何第三方诊断软件，正如您所解释的那样。

【参考方案2】：

好的，这里是您问题的部分答案。高 CPU 使用率似乎有多种原因，但我设法找到了 GC 发疯的原因之一。

在我们的代码中某处，开发人员插入了一段代码，每分钟记录一次当前的 ram 使用情况（用于监控和调试目的）。这是这样实现的：

GC.GetTotalMemory(true)

在文档中查找此方法告诉我，每次调用此方法时，bool 参数实际上都会强制执行完整的 GC - 每分钟执行一次完整的 GC！难怪我们在 GC 中的 CPU 和时间会飙升。将此更改为 false 将 CPU 使用率减半。我们仍然存在性能/资源问题，但这是一个巨大的进步。

希望这对某人有所帮助。

【参考方案3】：

评论有点长，所以一个社区 wiki 来分享我的经验。

不久前，我们遇到了类似的问题，这是由 Sybase .NET 驱动程序中的不良代码（如 Reflector ;p 所示）导致的，该驱动程序锁定了每个 DB 命令，而不是仅在需要时（事务的 IIRC ）。更新到具有更细粒度锁定的较新驱动程序解决了该问题，并且服务器从那时起一直平稳运行。

查看您的信息，它看起来与我们所经历的非常相似。 DebugDiag 可靠地告诉我锁定是一个问题，并引导我找到解决方案。确保正确配置转储。

如果您有一些登台服务器，您可以为 DebugDiag 加载负载（比如使用 JMeter），这也会有所帮助。

另一种方法虽然乏味，但转储所有已加载的程序集，框架程序集除外。然后在您最喜欢的反编译器中检查它们，寻找在您的应用程序中使用的Monitor.Enter(...) 引用（如果您可以模拟外部生产，则可能运行覆盖，以查看使用了什么）。然后尝试识别过度乐观的锁定。如果您自己的代码，您可以修复它，否则联系供应商。

【讨论】：

谢谢。这里非常有用的信息。实际上，我确实有一个舞台服务器，我一直在使用 jMeter 进行努力，但尽管生产服务器有 16 个核心并且分期只有 4 个，但我一直无法像实时一样高负载 CPU。

@iCediCe：更少的内核意味着它可能会更容易复制:)

是的！你会这么认为吗？但似乎并非如此。在我的 jMeter 负载中，我只点击了端点中最常用的 10 种方法（~每秒点击次数超过 1 次的方法）我可能是我们较少使用的方法之一造成了破坏。查看我添加到原始问题中的新信息。

@iCediCe：向它抛出至少 100 个并发请求。

周一我会更努力地施压，现在我要回家喝冰镇啤酒。顺便说一句，我仍然对如何解析它指向的实际文件的句柄非常感兴趣......