记一次 .NET某云HIS系统 CPU爆高分析

摘要：年前有位朋友找到我，说他们的系统会偶发性的CPU爆高，有时候是爆高几十秒，有时候高达一分多钟，自己有一点分析基础，但还是没找到原因，让我帮忙看下怎么回事？

1. 讲故事

年前有位朋友找到我，说他们的系统会偶发性的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 RequestinQueue: 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
0 6,15,11 2195
1 6,15,11 2195
...
63 6,15,11 2195

从卦中数据看，虽然没有朋友说的100%，但针对64核的场景下把CPU干到59%也是需要思考的，起码有 38 个核被打满了。

2. 到底发生了什么我的调试训练营里的朋友都知道，我绘制过CPU爆高的分析套路，所以先看下有没有GC触发，使用!t -special观察是否有SuspendEE标记，结果发现没有，但这里要注意了，没有不代表GC没触发，所以稳一点的做法就是观察每一个线程的调用栈，使用观察，截图如下：

从调用栈来看，当前有 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.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)

GetFrameContext failed: 1
00000000000000000000000000000000
OS Thread Id: 0x3f54 (249)

OS Thread Id: 0x2b00 (250)

OS Thread Id: 0x6cbc (251)
Unable to walk the managed stack. The current threadislikely not a
managed thread. You can run !threads togeta list of managed threadsin
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

000002d9f6f5b330 22500:01:50 00:01:08 200 POST http://xxxx/getOrderPrintData
000002dcb6c9d8c0 24700:01:50 00:01:08 200 POST http:
000002e4f700a8e0 26000:01:50 00:01:03 200 POST http:
000002e6b6fcc1d0 22700:01:50 00:01:03 200 POST http:
...

25HttpContextobject(s) found matching criteria

You may also be interestedin

Dump HttpRuntime info: !wruntime

从卦中看到了4个 getOrderPrintData 请求，并且目前耗时1分50秒都没有处理完，好奇心马上就起来了，到底在干什么奇葩逻辑？将 getOrderPrintData 方法的逻辑模糊如下：
publicApiResponsegetOrderPrintData(xxxOrder xxxOrder)
{
xxxxPrintVO xxxPrintVO =newxxxxPrintVO;
...
List list2 = (frompinDbContext.db.Queryable.Where(xxxxOrder.buildQuery.ToExpression)
orderbyp.SORT_NO
selectp).ToList;

IEnumerablestring, xxxOrder>> enumerable =frompinlist2
grouppbyp.COMB_ID;

foreach(IGroupingstring,xxxOrder> iteminenumerable)
{
...//大量的临时对象
}
ProcessOrder4Print(orderType, list2,refpageOrders);
}

privatevoidProcessOrder4Print(xxx, List orderList,xxx)
{
foreach(MedIpOrder orderinorderList)
{
...//大量的临时对象
}
}

结合内存的实时情况，发现问题出在了这个 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 0static

难怪执行快2分钟还没执行完? 相信其他3个线程的 list2 也不少，这么多的循环得要产生多少个瞬时临时对象，难怪导致后台GC直接变成了CPU密集型操作。

接下来就是告诉朋友为什么要从 DbContext 中捞 10w 条数据？朋友经过分析说是 UI上的参数问题，后台没有过滤掉，导致把数据全部给捞出来了,无语了。。。

这次CPU爆高事故属于典型的蝴蝶效应，用 4 个线程间接的把64核的CPU直接干爆，这种问题有一定的隐蔽性，需要调试者对后台GC 有一个总体的认识，否则还真不好解决，最后来一张引发龙卷风的小蝴蝶。。。