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

从代码看居然是一个商业组件 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_GCgc_type_background = 2,#endif //BACKGROUND_GCgc_type_max = 3};接下来可以用 x 命令去检索这个变量 , 观察各自的布局 。

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

文章插图
因为 gc_type_compactinggc_type_blocking 有重叠 , 而且观察进程运行了 17min , 所以 17min 触发了至少 113 =90+23 次 FullGC 。
0:117> .timeDebug session time: Tue Sep6 15:56:08.000 2022 (UTC + 8:00)System Uptime: 0 days 21:59:52.396Process Uptime: 0 days 0:17:10.000Kernel time: 0 days 0:34:34.000User time: 0 days 0:39:05.000这个算频繁吗?触发点是否集中? 在DUMP这种照片下是不得而知的 , 为了稳一点再看看可有其他的线索 。
3. 还有其他线索吗?既然线程池堆积了很多任务 , 除了受到一些诸如 GC 的外因影响 , 内因肯定是最主要的 , 既然都是 http 请求 , 可以用 !whttp 观察各自的 HttpContext 。
0:117> !whttpHttpContextThread Time Out RunningStatus VerbUrl0000017b406b6f80102 00:05:00 00:08:56200 GET/xxxx/xxx/xxxLogOutputExcel0000017b46797110107 00:05:00 00:07:35200 GET/xxxx/xxx/xxxLogOutputExcel0000017b814572f897 00:05:00 00:08:49200 GET/xxxx/xxx/xxxLogOutputExcel0000017b84634490104 00:05:00 00:07:46200 GET/xxxx/xxx/xxxLogOutputExcel0000017bc04767b090 00:05:00 00:08:43200 GET/xxxx/xxx/xxxLogOutputExcel0000017e3e79cbb896 00:05:00 00:09:45200 GET/xxxx/xxx/xxxLogOutputExcel0000017e7ee10b8088 00:05:00 00:09:40200 GET/xxxx/xxx/xxxLogOutputExcel0000017e89b2cfb0109 00:05:00 00:04:37200 GET/xxxx/xxx/xxxLogOutputExcel0000017e8adb6b80106 00:05:00 00:02:53200 GET/xxxx/xxx/xxxLogOutputExcel0000017d41e90f28103 00:05:00 00:08:04200 GET/xxxx/xxx/xxxLogOutputExcel0000017d4385d528101 00:05:00 00:07:39200 GET/xxxx/xxx/xxxLogOutputExcel0000017d471b7d5898 00:05:00 00:06:50200 GET/xxxx/xxx/xxxLogOutputExcel0000017bc8283c48117 00:05:00 00:00:32200 GET/xxx/xxx/xxxMedTags...
记一次 .NET 某电子病历 CPU 爆高分析

文章插图
从卦中看 , 有两点信息:
  1. 高达 17 个 Excel 导出请求 , 一般来说导出操作都是 CPU 密集型的, 17 个请求可能刚好把 CPU 全部打满 , 可以通过 !cpuid 验证下 。
0:117> !cpuidCPF/M/SManufacturerMHz 06,79,1<unavailable>1995 16,79,1<unavailable>1995 26,79,1<unavailable>1995 36,79,1<unavailable>1995 46,79,1<unavailable>1995 56,79,1<unavailable>1995 66,79,1<unavailable>1995 76,79,1<unavailable>1995 86,79,1<unavailable>1995 96,79,1<unavailable>1995106,79,1<unavailable>1995116,79,1<unavailable>1995126,79,1<unavailable>1995136,79,1<unavailable>1995146,79,1<unavailable>1995156,79,1<unavailable>1995
  1. 触发 GC 的请求是 /xxx/xxx/xxxMedTags 也高达 32s  , 说明程序此时整体变慢 。
接下来就是把挖到的这两点信息告诉朋友 , 重点是 xxxLogOutputExcel 导出 , 一定要限定频次 。
三:总结总体来说这次生产事故诱发的因素有两个: