记一次 .NET某设备监控自动化系统 CPU爆高分析

慈天华

一：背景

1. 讲故事

先说一下题外话，一个监控别人系统运行状态的程序，结果自己出问题了，有时候想一想还是挺讽刺的，哈哈，开个玩笑，我们回到正题，前些天有位朋友找到我，说他们的系统会偶发性CPU爆高，CPU上去了就下不来了，让我帮忙看一下怎么回事，而且自己也分析过了，没找到哪里有问题，写监控的都是高手，给我的第一感觉就是这个dump可能解决起来不容易，不管怎么说，有了dump就开干吧！
二：WinDbg 分析

1. CPU真的爆高吗

作为调试人，第一准则就是不要轻信任何人透露给你的信息，因为人家在这块是一个小白，往往他的信息会把你带偏，我们只相信数据即可，切记!!! 所以我们先用 !tp 观察下CPU使用率。

1. 0:198> !tp
2. CPU utilization: 100%
3. Worker Thread: Total: 197 Running: 42 Idle: 154 MaxLimit: 32767 MinLimit: 8
4. Work Request in Queue: 0
5. --------------------------------------
6. Number of Timers: 0
7. --------------------------------------
8. Completion Port Thread:Total: 10 Free: 5 MaxFree: 16 CurrentLimit: 10 MaxLimit: 1000 MinLimit: 8

复制代码

从卦中信息看当前 CPU=100%，还是蛮惨的，那到底谁在吃CPU资源呢？根据经验先查一下是不是触发了2代GC，接下来用 !t 观察下是否有GC标记。

1. 0:198> !t
2. ThreadCount:      214
3. UnstartedThread:  0
4. BackgroundThread: 211
5. PendingThread:    0
6. DeadThread:       1
7. Hosted Runtime:   no
8.                                                                                                         Lock  
9.        ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
10.    0    1 276f0 000002789526b5f0    2a020 Preemptive  0000000000000000:0000000000000000 000002789525e840 0     MTA
11.    2    2 25e5c 0000027895296d00    2b220 Preemptive  0000000000000000:0000000000000000 000002789525e840 0     MTA (Finalizer)
12.    3    3 260e8 00000278ae35f0c0  202b020 Preemptive  0000000000000000:0000000000000000 000002789525e840 0     MTA
13.    ...
14. 169 2113 10c20 00000278c26766c0  1029220 Preemptive  00000278B5D7D188:00000278B5D7D188 000002789525e840 1     MTA (GC) (Threadpool Worker) xxxException 00000278b5d46ce0
15. ...

复制代码

尼玛从卦中的  (GC) 来看，还真的触发了GC，接下来的研究方向就是洞察下是不是CPU爆高的祸首。
2. GC触发导致的吗

要寻找这个问题的答案，首先就是看下这次GC是不是 FullGC 即可，可以切到 169 号线程，观察下线程栈。

1. 0:169> k 10
2. # Child-SP          RetAddr               Call Site
3. 00 000000c4`36ffb798 00007ffc`d5f14313     ntdll!NtWaitForSingleObject+0x14
4. 01 000000c4`36ffb7a0 00007ffc`c927cb27     KERNELBASE!WaitForSingleObjectEx+0x93
5. 02 000000c4`36ffb840 00007ffc`c927cadf     clr!CLREventWaitHelper2+0x3c
6. 03 000000c4`36ffb880 00007ffc`c927ca5c     clr!CLREventWaitHelper+0x1f
7. 04 000000c4`36ffb8e0 00007ffc`c926bd32     clr!CLREventBase::WaitEx+0x7c
8. 05 000000c4`36ffb970 00007ffc`c9269bc4     clr!ThreadSuspend::SuspendRuntime+0x32c
9. 06 000000c4`36ffba60 00007ffc`c91814e3     clr!ThreadSuspend::SuspendEE+0x128
10. 07 000000c4`36ffbb60 00007ffc`c9185f51     clr!WKS::GCHeap::GarbageCollectGeneration+0xb7
11. 08 000000c4`36ffbbc0 00007ffc`c9260f56     clr!WKS::gc_heap::trigger_gc_for_alloc+0x2d
12. 09 000000c4`36ffbc00 00007ffc`c6b0f7e7     clr!JIT_NewArr1+0xa97
13. 0a 000000c4`36ffc030 00007ffc`6a388270     mscorlib_ni!System.String.ToCharArray+0x27 [f:\dd\ndp\clr\src\BCL\system\string.cs @ 758]
14. 0b 000000c4`36ffc080 00007ffc`6a3880ed     0x00007ffc`6a388270
15. 0c 000000c4`36ffc100 00007ffc`6a56056d     0x00007ffc`6a3880ed
16. 0d 000000c4`36ffc150 00007ffc`6a3cd749     0x00007ffc`6a56056d
17. 0e 000000c4`36ffc1b0 00007ffc`c911989d     0x00007ffc`6a3cd749
18. 0f 000000c4`36ffc220 00007ffc`c9119764     clr!ExceptionTracker::CallHandler+0xfd

复制代码

从卦中看此时的GC还处于早期的 SuspendEE 阶段，无法获取内部的 settings 结构，这就比较麻烦了，那怎么办呢？只能看看 GarbageCollectGeneration 的第一个参数有没有保存在栈中，要是没有就惨了。。。方法签名如下：

1. size_t
2. GCHeap::GarbageCollectGeneration (unsigned int gen, gc_reason reason)
3. {
5. }

复制代码

根据 x64调用协定，gen是保存在 rdx 寄存器里，接下来观察汇编代码。

1. 0:000> uf 00007ffc`c91814e3
2. clr!WKS::GCHeap::GarbageCollectGeneration:
3. 00007ffc`c918142c 48895c2418      mov     qword ptr [rsp+18h],rbx
4. 00007ffc`c9181431 89542410        mov     dword ptr [rsp+10h],edx
5. 00007ffc`c9181435 48894c2408      mov     qword ptr [rsp+8],rcx
6. 00007ffc`c918143a 55              push    rbp
7. 00007ffc`c918143b 56              push    rsi
8. 00007ffc`c918143c 57              push    rdi
9. 00007ffc`c918143d 4154            push    r12
10. 00007ffc`c918143f 4155            push    r13
11. 00007ffc`c9181441 4156            push    r14
12. 00007ffc`c9181443 4157            push    r15
13. ...
15. 0:169> dd 000000c4`36ffbbc0-0x8+0x10 L1
16. 000000c4`36ffbbc8  00000000

复制代码

从卦中看，谢天谢地，edx保存在 rsp+10h 的位置，通过dp观察内存地址的值发现是0，也就表示当前是 0 代GC，这种smallgc 经常触发是很正常的，并不是我们CPU爆高的诱因，接下来就陷入迷茫了。。。
3. 路在何方

撞了南墙之后得要看看其他路子，其实刚才用 !t 观察线程列表的时候我就注意到一个特征，那就是很多线程上挂了异常，截图如下：

从卦中看此时有19个线程在抛 xxxResultException 异常，做过开发的朋友都知道，如果频繁的抛异常是很耗CPU资源的，因为它要设计到用户态到内核态的切换，如果有 19 个线程一起抛异常，那绝对是一个灾难。。。
有些朋友说我cpu猛一点是不是就可以了，哈哈，理论上是可以的，可以用 !cpuid 观察下这台机器的cpu核心数。

1. 0:169> !cpuid
2. CP  F/M/S  Manufacturer     MHz
3. 0  6,167,1  <unavailable>   3408
4. 1  6,167,1  <unavailable>   3408
5. 2  6,167,1  <unavailable>   3408
6. 3  6,167,1  <unavailable>   3408
7. 4  6,167,1  <unavailable>   3408
8. 5  6,167,1  <unavailable>   3408
9. 6  6,167,1  <unavailable>   3408
10. 7  6,167,1  <unavailable>   3408

复制代码

从证据链的完整性上来说，其实这里还需要再做一个验证，就是19个线程抛异常不代表他们的并发性，言外之意就是能不能再找一些其他证据，怎么找其他证据呢？
做C#开发的朋友应该知道，Exception 属于引用类型，如果密集抛了很多异常，那托管堆上自然就有很多，直到GC回收，所以我们观察下这个时间差即可，使用 !wdae 命令，这里为了隐私性我就模糊了哈。

1. 0:169> !wdae
2.      384 of Type: xxxResultException 000002789fdb6478 000002789fdb69b0 000002789fdb9848
3. Message: xxxFailed
4. Inner Exception: (none)
5. Stack:
6. IP               Function
7. 00007ffc6a269861 xxx.ChannelAsyncOperation`1[[System.Int32, mscorlib]].End(Int32, Boolean)
8. ...
9.      411 of Type: xxxResultException 000002789fdb6e90 000002789fdb7090 000002789fdb72a8
10. Message: xxxClosed
11. Inner Exception: (none)
12. Stack:
13. IP               Function
14. 00007ffc6a269861 xxx.ChannelAsyncOperation`1[[System.Int32, mscorlib]].End(Int32, Boolean)
15. ...
16. 808 Exceptions in 12 unique type/stack combinations (duplicate types in similar stacks may be rethrows)

复制代码

从卦中看当前抛了808个异常，大多是和channel通信有关，结合16个线程并发抛，这就稳了，看样子cpu爆高期间就是由于高频的抛异常所致，分析出这些信息之后，就是告诉朋友把这些异常给解决掉即可。
三：总结

CPU爆高的诱因非常多，高频的抛异常就属于其中一例，其实这种通信时发生了突发异常正是 Polly 这种 弹性和瞬态故障处理库 大显身手的地方。

来源:https://www.cnblogs.com/huangxincheng/p/18056337
免责声明：由于采集信息均来自互联网，如果侵犯了您的权益，请联系我们【E-Mail:cb@itdo.tech】 我们会及时删除侵权内容，谢谢合作！