一：背景
1. 讲故事
年前有位朋友找到我，说他们的系统会偶发性的CPU爆高，有时候是爆高几十秒，有时候高达一分多钟，自己有一点分析基础，但还是没找到原因，让我帮忙看下怎么回事？
二：CPU爆高分析
1. CPU 真的爆高吗
还是那句话，一定要相信数据，不要被别人带偏，使用 !tp 和 !cpuid 观察下CPU的利用率和大哥的实力。
0:232> !tp
CPU utilization: 59%
Worker Thread: Total: 77 Running: 5 Idle: 59 MaxLimit: 32767 MinLimit: 64
Work Request in Queue: 0
--------------------------------------
Number of Timers: 2
--------------------------------------
Completion Port Thread:Total: 3 Free: 3 MaxFree: 128 CurrentLimit: 3 MaxLimit: 1000 MinLimit: 64
0:232> !cpuid
CP F/M/S Manufacturer MHz
06,15,11 <unavailable> 2195
16,15,11 <unavailable> 2195
...
636,15,11 <unavailable> 2195
从卦中数据看，虽然没有朋友说的100%，但针对64核的场景下把CPU干到59%也是需要思考的，起码有 38 个核被打满了。
2. 到底发生了什么
我的调试训练营里的朋友都知道，我绘制过CPU爆高的分析套路，所以先看下有没有GC触发，使用 !t -special 观察是否有 SuspendEE 标记，结果发现没有，但这里要注意了，没有不代表GC没触发，所以稳一点的做法就是观察每一个线程的调用栈，使用 ~*k观察，截图如下：
从调用栈来看，当前有 21个线程正在backgroundgc 的 SetFree 方法中，即将收集到的垃圾对象点掉，从经验上来说，虽然 bgc 是属于 2代，但由它引发的 cpu 爆高，我还真没遇见过。
接下来的路在哪里呢？使用兜底的方法 ~*e !clrstack 观察下每个线程都在做什么，毕竟CPU的爆高都是 线程 抬起来的。
OS Thread Id: 0x57cc (247)
Child SP IP Call Site
000000fb8187ae98 00007ffa9683f94a [HelperMethodFrame: 000000fb8187ae98]
000000fb8187afe0 00007ffa35808441 CSRedis.CSRedisClient+c.<.ctor>b__38_6()
000000fb8187b050 00007ffa35808368 CSRedis.CSRedisClient.DeserializeObject[[System.__Canon, mscorlib]](System.String)
000000fb8187b170 00007ffa3580807e CSRedis.CSRedisClient.DeserializeRedisValueInternal[[System.__Canon, mscorlib]](Byte[])
000000fb8187b540 00007ffa3582a605 CSRedis.CSRedisClient.HGet[[System.__Canon, mscorlib]](System.String, System.String)
000000fb8187b5d0 00007ffa3582a3ee xxx.RedisCoreHelper.HGet[[System.__Canon, mscorlib]](System.String, System.String)
...
000000fb8187b780 00007ffa367890e8 xxx.ProcessOrder4Print(...)
000000fb621bbc10 00007ffa3677bbd2 xxx.getOrderPrintData(...)
...
000000fb621bdcc0 00007ffa353be227 System.Web.Http.WebHost.HttpControllerHandler.ProcessRequestAsyncCore(System.Web.HttpContextBase)
...
000000fb621beb10 00007ffa354623ae DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, System.Web.RequestNotificationStatus ByRef)
000000fb621bebd0 00007ffa35150221 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
000000fb621bed70 00007ffa3514f8c3 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
000000fb621bedb0 00007ffa3514f1d2 DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)
000000fb621bef88 00007ffa93802463 [ContextTransitionFrame: 000000fb621bef88]
OS Thread Id: 0x180 (248)
Child SP IP Call Site
GetFrameContext failed: 1
00000000000000000000000000000000
OS Thread Id: 0x3f54 (249)
Child SP IP Call Site
GetFrameContext failed: 1
00000000000000000000000000000000
OS Thread Id: 0x2b00 (250)
Child SP IP Call Site
GetFrameContext failed: 1
00000000000000000000000000000000
OS Thread Id: 0x6cbc (251)
Unable to walk the managed stack. The current thread is likely not a
managed thread. You can run !threads to get a list of managed threads in
the process
Failed to start stack walk: 80070057
...
通览卦中数据，只有 4 个线程有托管栈，都和 getOrderPrintData 方法有关，这就很让人无语了，即使最坏情况下 4 个线程死循环，也就占用区区占用4个逻辑核，怎么滴也不会导致目前的现状。。。
3. 敢问路在何方
到这里就很难分析了，需要考察调试者的思维缜密性。。。 既然 CPU 能被短时打爆，目前来看也只有后台GC默认配备的 64个bgc线程能做到，正常情况下它的性格很温顺，肯定遭到了一些不为人知的打压，再结合23个线程都在 SetFree，冥冥之中感觉它要点掉的东西太多了？让 bgc 线程成了 CPU 密集性 操作，有些朋友应该知道 后台GC 有一个特征就是并发性，即 工作线程 和 bgc 线程可以同时运行，刚才用 !t -special 没有找到 SuspendEE，也正说明了这一点，接下来的调查方向就是观察谁在猛烈的丢垃圾，回到 getOrderPrintData 方法上来，观察这个调用栈可以发现是一个 http 请求，首先用 !whttp 观察下 http 请求情况。
0:247> !whttp
HttpContext Thread Time Out Running Status Verb Url
...
0:247> !whttp
HttpContext Thread Time Out Running Status Verb Url
000002d9f6f5b330 22500:01:5000:01:08 200 POST http://xxxx/getOrderPrintData
000002dcb6c9d8c0 24700:01:5000:01:08 200 POST http://xxxx/getOrderPrintData
000002e4f700a8e0 26000:01:5000:01:03 200 POST http://xxxx/getOrderPrintData
000002e6b6fcc1d0 22700:01:5000:01:03 200 POST http://xxxx/getOrderPrintData
...
25HttpContext object(s) found matching criteria
You may also be interested in
================================
Dump HttpRuntime info: !wruntime
从卦中看到了4个 getOrderPrintData 请求，并且目前耗时 1分50秒 都没有处理完，好奇心马上就起来了，到底在干什么奇葩逻辑？将 getOrderPrintData 方法的逻辑模糊如下：
public ApiResponse<xxxxPrintVO> getOrderPrintData(xxxOrder xxxOrder)
{
xxxxPrintVO xxxPrintVO = new xxxxPrintVO();
...
List<xxxOrder> list2 = (from p in DbContext.db.Queryable<xxxOrder>().Where(xxxxOrder.buildQuery().ToExpression())
orderby p.SORT_NO
select p).ToList();
IEnumerable<IGrouping<string, xxxOrder>> enumerable = from p in list2
group p by p.COMB_ID;
foreach (IGrouping<string,xxxOrder> item in enumerable)
{
... //大量的临时对象
}
ProcessOrder4Print(orderType, list2, ref pageOrders);
}
private void ProcessOrder4Print(xxx, List<xxxOrder> orderList,xxx)
{
foreach (MedIpOrder order in orderList)
{
... //大量的临时对象
}
}
结合内存的实时情况，发现问题出在了这个 list2 上，居然有高达 10w+ 个，输出如下：
0:247> !do000002dcb6cd2368
Name: System.Collections.Generic.List`1[[xxxIpOrder, xxx]]
MethodTable: 00007ffa352a6150
EEClass: 00007ffa916cacb0
Size: 40(0x28) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
MT Field Offset Type VT Attr Value Name
00007ffa91cd2f60 400187c 8 System.__Canon[] 0 instance 000002e9369a0468 _items
00007ffa91ca9428 400187d 18 System.Int32 1 instance 106929 _size
00007ffa91ca9428 400187e 1c System.Int32 1 instance 106929 _version
00007ffa91ca6fd8 400187f 10 System.Object 0 instance 0000000000000000 _syncRoot
00007ffa91cd2f60 4001880 8 System.__Canon[] 0 static <no information>
难怪执行快2分钟还没执行完? 相信其他3个线程的 list2 也不少，这么多的循环得要产生多少个瞬时临时对象，难怪导致后台GC直接变成了CPU密集型操作。
接下来就是告诉朋友为什么要从 DbContext 中捞 10w 条数据？朋友经过分析说是 UI上的参数问题，后台没有过滤掉，导致把数据全部给捞出来了,无语了。。。
三：总结
这次CPU爆高事故属于典型的 蝴蝶效应，用 4 个线程间接的把64核的CPU直接干爆，这种问题有一定的隐蔽性，需要调试者对 后台GC 有一个总体的认识，否则还真不好解决，最后来一张 引发龙卷风 的小蝴蝶。。。