一：背景
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
- 0 6,15,11 <unavailable> 2195
- 1 6,15,11 <unavailable> 2195
- ...
- 63 6,15,11 <unavailable> 2195
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
- 0000000000000000 0000000000000000
- OS Thread Id: 0x3f54 (249)
- Child SP IP Call Site
- GetFrameContext failed: 1
- 0000000000000000 0000000000000000
- OS Thread Id: 0x2b00 (250)
- Child SP IP Call Site
- GetFrameContext failed: 1
- 0000000000000000 0000000000000000
- 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
- ...
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 225 00:01:50 00:01:08 200 POST http://xxxx/getOrderPrintData
- 000002dcb6c9d8c0 247 00:01:50 00:01:08 200 POST http://xxxx/getOrderPrintData
- 000002e4f700a8e0 260 00:01:50 00:01:03 200 POST http://xxxx/getOrderPrintData
- 000002e6b6fcc1d0 227 00:01:50 00:01:03 200 POST http://xxxx/getOrderPrintData
- ...
- 25 HttpContext object(s) found matching criteria
- You may also be interested in
- ================================
- Dump HttpRuntime info: !wruntime
- 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)
- {
- ... //大量的临时对象
- }
- }
- 0:247> !do 000002dcb6cd2368
- 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>
接下来就是告诉朋友为什么要从 DbContext 中捞 10w 条数据？朋友经太过析说是 UI上的参数问题，后台没有过滤掉，导致把数据全部给捞出来了,无语了。。。
三：总结
这次CPU爆高事故属于典型的 蝴蝶效应，用 4 个线程间接的把64核的CPU直接干爆，这种问题有一定的隐蔽性，需要调试者对 后台GC 有一个总体的认识，否则还真不好解决，最后来一张 引发龙卷风 的小蝴蝶。。。
免责声明：如果侵犯了您的权益，请联系站长，我们会及时删除侵权内容，谢谢合作！更多信息从访问主页：qidao123.com:ToB企服之家，中国第一个企服评测及商务社交产业平台。
|
