经验首页 前端设计 程序设计 Java相关 移动开发 数据库/运维 软件/图像 大数据/云计算 其他经验
当前位置:技术经验 » 程序设计 » ASP.net » 查看文章
记一次 .NET某设备监控自动化系统 CPU爆高分析
来源:cnblogs  作者:一线码农  时间:2024/3/7 9:15:17  对本文有异议

一:背景

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. {
  4. }

根据 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. ...
  14. 0:169> dd 000000c4`36ffbbc0-0x8+0x10 L1
  15. 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

 友情链接:直通硅谷  点职佳  北美留学生论坛

本站QQ群:前端 618073944 | Java 606181507 | Python 626812652 | C/C++ 612253063 | 微信 634508462 | 苹果 692586424 | C#/.net 182808419 | PHP 305140648 | 运维 608723728

W3xue 的所有内容仅供测试,对任何法律问题及风险不承担任何责任。通过使用本站内容随之而来的风险与本站无关。
关于我们  |  意见建议  |  捐助我们  |  报错有奖  |  广告合作、友情链接(目前9元/月)请联系QQ:27243702 沸活量
皖ICP备17017327号-2 皖公网安备34020702000426号