记一次 .NET 差旅管理后台 CPU 爆高分析
一：背景
1. 讲故事
前段时间有位朋友在微信上找到我，说他的 web 系统 cpu 运行一段时候后就爆高了，让我帮忙看一下是怎么回事，那就看吧，声明一下，我看 dump 是免费的，主要是锤炼自己技术，没有某软工程师高额的技术分析费。 😅😅😅
闲话不多说，我们上 windbg 说话。
二：WinDbg 分析
1. CPU 真的爆高吗
是否真的爆高，我们得自己先验证下，使用 !tp 命令看一下即可。
0:065> !tp
CPU utilization: 81%
Worker Thread: Total: 32 Running: 7 Idle: 25 MaxLimit: 8191 MinLimit: 32
Work Request in Queue: 1
AsyncTimerCallbackCompletion TimerInfo@018eedc8
--------------------------------------
Number of Timers: 1
--------------------------------------
Completion Port Thread:Total: 4 Free: 4 MaxFree: 64 CurrentLimit: 4 MaxLimit: 1000 MinLimit: 32
从卦象看，确实存在 CPU 爆高的情况，根据过往经验，托管程序爆高大多是因为GC触发所致，但触发 GC 的原因千奇百怪，毕竟在 clr 层面 GC 触发的原因高达 14 种，代码如下：
static const char* const str_gc_reasons[] =
{
"alloc_soh",
"induced",
"lowmem",
"empty",
"alloc_loh",
"oos_soh",
"oos_loh",
"induced_noforce",
"gcstress",
"induced_lowmem",
"induced_compacting",
"lowmemory_host",
"pm_full_gc",
"lowmemory_host_blocking"
};
2. 真的是 GC 触发吗
验证当前程序是否为 GC 触发，方式有很多，可以用 !t 或者 !t -special，但这两种方式不是特别准，最准的就是根据GC模式直接到 CLR 里去搜全局变量 clr!SVR::gc_heap::gc_started 的值就可以了，参考如下：
0:038> dp clr!SVR::gc_heap::gc_started L1
712d3190 00000001
可以看到，此时的 gc_started=1，说明 GC 是触发状态，接下来可以从所有的线程栈中搜 garbage_collect 或者 gc1 什么的关键词即可。
0:038> k
# ChildEBP RetAddr
00 0318f934 70de8248 clr!SVR::gc_heap::relocate_survivor_helper+0x1ea
01 0318f944 70de83df clr!SVR::gc_heap::relocate_survivors_in_plug+0x24
02 0318f970 70de84ac clr!SVR::gc_heap::relocate_survivors_in_brick+0x70
03 0318f9a8 70de830b clr!SVR::gc_heap::relocate_survivors+0xe4
04 0318fa00 70de218a clr!SVR::gc_heap::relocate_phase+0xb9
05 0318fbb4 70de18bf clr!SVR::gc_heap::plan_phase+0x136e
06 0318fbec 70de1d49 clr!SVR::gc_heap::gc1+0x101
07 0318fc3c 70de1421 clr!SVR::gc_heap::garbage_collect+0x746
08 0318fc58 70ddacde clr!SVR::gc_heap::gc_thread_function+0x14a
09 0318fc6c 70ddac6f clr!SVR::gc_heap::gc_thread_stub+0x72
0a 0318fc80 770a6a14 clr!GCThreadStub+0x1f
0b 0318fc94 77e4a9ef kernel32!BaseThreadInitThunk+0x24
0c 0318fcdc 77e4a9ba ntdll!__RtlUserThreadStart+0x2f
0d 0318fcec 00000000 ntdll!_RtlUserThreadStart+0x1b
从卦象看，gc_thread_stub 表示当前是一个 GC 线程，它正在处于 relocate_phase 阶段，这表明当前是一个 压缩回收，GC回收流程图可以看下官方文档。
GarbageCollectGeneration()
{
SuspendEE();
garbage_collect();
RestartEE();
}
garbage_collect()
{
generation_to_condemn();
gc1();
}
gc1()
{
mark_phase();
plan_phase();
}
plan_phase()
{
// actual plan phase work to decide to
// compact or not
if (compact)
{
relocate_phase();
compact_phase();
}
else
make_free_lists();
}
在这个阶段，托管堆也会是损坏状态，你可以用 !dumpheap -stat 验证下。
0:038> !dumpheap -stat
The garbage collector data structures are not in a valid state for traversal.
It is either in the "plan phase," where objects are being moved around, or
we are at the initialization or shutdown of the gc heap. Commands related to
displaying, finding or traversing objects as well as gc heap segments may not
work properly. !dumpheap and !verifyheap may incorrectly complain of heap
consistency errors.
Object <exec cmd="!ListNearObj /d 03301000">03301000</exec> has an invalid method table.
3. 为什么会出现压缩回收
一般来说，GC 分清除和压缩回收，后者属于一种重量级操作，很伤GC，在临时段上还稍微好一些，接下来我们看下当前 GC 是在回收哪一代？可以到 CLR 里面去查一下判决代字段。clr!WKS::GCHeap::GcCondemnedGeneration。
0:038> dp clr!SVR::GCHeap::GcCondemnedGeneration L1
712d79d8 00000002
糟了，结果是个 2，这个 2 表示 fullGC, 也就是全量回收，大多对应着 gc_reason=lowmem 的情况，也就是内存不足。
4. 真的内存不足吗
要想找到答案，我们用 !address -summary 看下当前的虚拟内存情况。
0:038> !address -summary
--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
<unknown> 1835 dce6e000 ( 3.452 GB) 91.56% 86.29%
Image 842 f436000 ( 244.211 MB) 6.33% 5.96%
Free 312 eba5000 ( 235.645 MB) 5.75%
Stack 451 2d80000 ( 45.500 MB) 1.18% 1.11%
Heap 72 2342000 ( 35.258 MB) 0.91% 0.86%
TEB 150 96000 ( 600.000 kB) 0.02% 0.01%
Other 7 4e000 ( 312.000 kB) 0.01% 0.01%
PEB 1 1000 ( 4.000 kB) 0.00% 0.00%
--- Type Summary (for busy) ------ RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_PRIVATE 2051 dd635000 ( 3.459 GB) 91.76% 86.48%
MEM_IMAGE 1267 11ad1000 ( 282.816 MB) 7.33% 6.90%
MEM_MAPPED 40 2345000 ( 35.270 MB) 0.91% 0.86%
--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_COMMIT 2604 cbe7d000 ( 3.186 GB) 84.51% 79.65%
MEM_RESERVE 754 255ce000 ( 597.805 MB) 15.49% 14.60%
MEM_FREE 312 eba5000 ( 235.645 MB) 5.75%
--- Largest Region by Usage ----------- Base Address -------- Region Size ----------
<unknown> 3300000 20087000 ( 512.527 MB)
Image 6f819000 f5f000 ( 15.371 MB)
Free fea50000 1590000 ( 21.562 MB)
Stack 3110000 7a000 ( 488.000 kB)
Heap 3bc80000 621000 ( 6.129 MB)
TEB fe6e5000 1000 ( 4.000 kB)
Other fea10000 33000 ( 204.000 kB)
PEB fea49000 1000 ( 4.000 kB)
从卦象看，当前的 MEM_COMMIT=3.186G， 最大的Free块 Free=15.371MB，再根据之前展示的内存地址，我们发现这个程序是 32bit ，跑了 64bit 机器上，这种情况下程序最多可占用 4G 内存空间，虽然 MEM_RESERVE= 597.805 MB, 但这种 RESERVE 是零散的，本质上来说此时的程序处于虚拟地址紧张，由于 虚拟地址 紧张，导致 GC 在不断的做 全量内存 回收。
三：总结
根据上面的分析， GC 触发的原因主要还是 32bit 程序的 4G 内存限制所致， 导致 GC 在不停的做全量回收，这种场景真的让 GC 很尴尬，优先解决办法就是将程序改成 64bit，后面再看看如何优化程序内存，毕竟现在托管堆处于损坏状态，也不好分析啦。
