记一次 .NET 某电子病历 CPU 爆高分析

乎语百科 236 0

一：背景

1.讲故事

前段时间有位朋友微信找到我，说他的程序出现了 CPU 爆高，帮忙看下程序到底出了什么情况？图就不上了，我们直接进入主题。

二：WinDbg 分析

1. CPU 真的爆高吗？

要确认是否真的爆高，可以使用 !tp 观察。


0:000> !tp
CPU utilization: 96%
Worker Thread: Total: 36 Running: 36 Idle: 0 MaxLimit: 32767 MinLimit: 16
Work Request in Queue: 61
    Unknown Function: 00007ffc5c461750  Context: 00000187da7a9788
    Unknown Function: 00007ffc5c461750  Context: 0000017fcdd36e88
    ...
    Unknown Function: 00007ffc5c461750  Context: 00000187da5e87d8
    Unknown Function: 00007ffc5c461750  Context: 00000187da872788
--------------------------------------
Number of Timers: 2
--------------------------------------
Completion Port Thread:Total: 1 Free: 1 MaxFree: 32 CurrentLimit: 1 MaxLimit: 1000 MinLimit: 16

从卦中可以看到 CPU=96%，果然是 CPU 爆高，而且 Work Request 也累积了 61 个任务未处理，看样子下游不给力哈？ 不给力有可能是因为 GC 触发导致线程频繁停顿，也可能真的是处理太慢。

2. 是 GC 触发了吗？

要查看是否真的 GC 触发，可以用 !t -special 观察下是否有 SuspendEE 字样。


0:000> !t -special
ThreadCount:      83
UnstartedThread:  0
BackgroundThread: 74
PendingThread:    0
DeadThread:       9
Hosted Runtime:   no
                                                                                                        Lock
       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
  19    1 1c84 0000017abe10cf60    28220 Preemptive  0000000000000000:0000000000000000 0000017abe103f70 0     Ukn
  ...
          OSID Special thread type
       26 1c78 DbgHelper
       27 1328 GC SuspendEE
       28 1e78 GC
       29 1ffc GC
       30 1de0 GC

果不其然 27 号线程带了 SuspendEE ,说明当前 GC 是触发状态，接下来看下 27 号线程的非托管栈, 到底发生了什么。


0:027> k
 # Child-SP          RetAddr               Call Site
00 00000074`11aff348 00007ffc`66624abf     ntdll!NtWaitForSingleObject+0x14
01 00000074`11aff350 00007ffc`591aa747     KERNELBASE!WaitForSingleObjectEx+0x8f
02 00000074`11aff3f0 00007ffc`591aa6ff     clr!CLREventWaitHelper2+0x3c
03 00000074`11aff430 00007ffc`591aa67c     clr!CLREventWaitHelper+0x1f
04 00000074`11aff490 00007ffc`59048ef5     clr!CLREventBase::WaitEx+0x7c
05 00000074`11aff520 00007ffc`5905370e     clr!SVR::t_join::join+0x10f
06 00000074`11aff580 00007ffc`59049278     clr!SVR::gc_heap::plan_phase+0x11f4
07 00000074`11aff900 00007ffc`590494d6     clr!SVR::gc_heap::gc1+0xb8
08 00000074`11aff950 00007ffc`59048c64     clr!SVR::gc_heap::garbage_collect+0x870
09 00000074`11aff9f0 00007ffc`59192487     clr!SVR::gc_heap::gc_thread_function+0x74
0a 00000074`11affa20 00007ffc`59194194     clr!SVR::gc_heap::gc_thread_stub+0x7e
0b 00000074`11affa60 00007ffc`694184d4     clr!GCThreadStub+0x24
0c 00000074`11affa90 00007ffc`69dee8b1     kernel32!BaseThreadInitThunk+0x14
0d 00000074`11affac0 00000000`00000000     ntdll!RtlUserThreadStart+0x21

从栈方法 gc_thread_function() 来看，这是一个专有的 GC 线程，熟悉 server GC 的朋友应该知道，用户线程分配 引发GC后，会通过 event 唤醒GC线程，言外之意就是还没有找到这个用户线程触发的导火索，要想找到答案有很多方法，查看当前的 GCSettings 观察 GC 触发的诱因及代数，截图如下：

我去，居然是一个诱导式FullGC，言外之意就是有代码会调用 GC.Collect() ，接下来我们用 ~*e !clrstack 导出所有的线程栈，观察 GC.Collect() 字样，还真给找到了。。。


0:117> !clrstack
OS Thread Id: 0x170c (117)
        Child SP               IP Call Site
0000007419f1d580 00007ffc69e25ac4 [InlinedCallFrame: 0000007419f1d580] System.GC._Collect(Int32, Int32)
0000007419f1d580 00007ffbfba0fbf2 [InlinedCallFrame: 0000007419f1d580] System.GC._Collect(Int32, Int32)
0000007419f1d550 00007ffbfba0fbf2 Spire.Pdf.PdfDocument.Dispose()
...
0000007419f1e2f0 00007ffc504b1092 System.Web.Mvc.MvcHandler.EndProcessRequest(System.IAsyncResult)

从代码看居然是一个商业组件 Spire.Pdf 在 Dispose 时手工释放触发的，一般这么做的目的是想通过此方法间接释放非托管资源。

其实一个 FullGC 不代表什么，如果频繁的 FullGC 肯定是有问题的，那如何观察是否频繁呢？在 CLR 源码中有一个 full_gc_counts 的全局变量，记录着FullGC 的次数，代码如下：


size_t gc_heap::full_gc_counts[gc_type_max];

enum gc_type
{
    gc_type_compacting = 0,
    gc_type_blocking = 1,
#ifdef BACKGROUND_GC
    gc_type_background = 2,
#endif //BACKGROUND_GC
    gc_type_max = 3
};

接下来可以用 x 命令去检索这个变量，观察各自的布局。

因为 gc_type_compacting 和 gc_type_blocking 有重叠，而且观察进程运行了 17min，所以 17min 触发了至少 113 =90+23 次 FullGC。


0:117> .time
Debug session time: Tue Sep  6 15:56:08.000 2022 (UTC + 8:00)
System Uptime: 0 days 21:59:52.396
Process Uptime: 0 days 0:17:10.000
  Kernel time: 0 days 0:34:34.000
  User time: 0 days 0:39:05.000

这个算频繁吗？触发点是否集中？ 在DUMP这种照片下是不得而知的，为了稳一点再看看可有其他的线索。

3. 还有其他线索吗？

既然线程池堆积了很多任务，除了受到一些诸如 GC 的外因影响，内因肯定是最主要的，既然都是 http 请求，可以用 !whttp 观察各自的 HttpContext。


0:117> !whttp
HttpContext    Thread Time Out Running  Status Verb     Url
0000017b406b6f80  102 00:05:00 00:08:56    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017b46797110  107 00:05:00 00:07:35    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017b814572f8   97 00:05:00 00:08:49    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017b84634490  104 00:05:00 00:07:46    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017bc04767b0   90 00:05:00 00:08:43    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017e3e79cbb8   96 00:05:00 00:09:45    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017e7ee10b80   88 00:05:00 00:09:40    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017e89b2cfb0  109 00:05:00 00:04:37    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017e8adb6b80  106 00:05:00 00:02:53    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017d41e90f28  103 00:05:00 00:08:04    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017d4385d528  101 00:05:00 00:07:39    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017d471b7d58   98 00:05:00 00:06:50    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017bc8283c48  117 00:05:00 00:00:32    200 GET      /xxx/xxx/xxxMedTags
...

从卦中看，有两点信息：

  1. 高达 17 个 Excel 导出请求，一般来说导出操作都是 CPU 密集型的, 17 个请求可能刚好把 CPU 全部打满，可以通过 !cpuid 验证下。

0:117> !cpuid
CP  F/M/S  Manufacturer     MHz
 0  6,79,1  <unavailable>   1995
 1  6,79,1  <unavailable>   1995
 2  6,79,1  <unavailable>   1995
 3  6,79,1  <unavailable>   1995
 4  6,79,1  <unavailable>   1995
 5  6,79,1  <unavailable>   1995
 6  6,79,1  <unavailable>   1995
 7  6,79,1  <unavailable>   1995
 8  6,79,1  <unavailable>   1995
 9  6,79,1  <unavailable>   1995
10  6,79,1  <unavailable>   1995
11  6,79,1  <unavailable>   1995
12  6,79,1  <unavailable>   1995
13  6,79,1  <unavailable>   1995
14  6,79,1  <unavailable>   1995
15  6,79,1  <unavailable>   1995
  1. 触发 GC 的请求是 /xxx/xxx/xxxMedTags 也高达 32s ，说明程序此时整体变慢。

接下来就是把挖到的这两点信息告诉朋友，重点是 xxxLogOutputExcel 导出，一定要限定频次。

三：总结

总体来说这次生产事故诱发的因素有两个：

  • 主因是客户高频次的点击 Excel 导出，越着急越点，越点越着急，导致系统的雪崩。

  • 高频的Excel点击操作，间接导致 Spire.Pdf 在某一时段为了释放非托管资源频发的诱导 GC.Collect，进而雪上加霜。

解决方案就简单了，抑制高频点击。

多一点耐心，少一点急躁，也许我们相处的会更好。

标签：

留言评论

  • 这篇文章还没有收到评论，赶紧来抢沙发吧~