一次.net cpu爆高分析-windbg sos基本命令使用及分析思路

admin 2024年4月10日09:54:30评论3 views字数 1870阅读6分14秒阅读模式
前几日接前方反馈,线上升级后,IIS CPU爆高,已影响用户使用体验,遂指导现场运维赶紧dump一份内存。笔者现将分析过程分享如下,欢迎讨论指教。

windbg sos使用就不写了,网上已有大量教程。

运维发来截图,IIS CPU爆高。
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
windbg走起:
使用!tp

如下图CPU 96%,且还有8个等待cpu调度的任务,已出现任务堆积现象,说明此时CPU已相当繁忙。
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
16核心CPU基本全部爆满。
使用PerfView对dump进行火焰图分析如下,可见大量占用时间片较多的基本是Newtonsoft.Json。
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
CPU高,无外乎这几种可能:锁(死锁、以及.net中大量其他锁类型,如:SyncBlock、ReaderWriter等)、GC、以及死循环,下面将逐一进行排查。

1、查看同步块表如下:
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
从同步块表的卦象上看,正常,故可以排出存在由于线程同步导致的死锁引发的cpu爆高问题。

2、查看GC,如下:有线程此时处于GC状态
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
如上图可见,有线程处于GC。
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
再使用x clr!gc_heap::settings,在内存检索关键字,查看。
由于线上.net设置是服务器模式,故查看第二个。

根据结构gc_heap::settings与枚举gc_reason对照。

从上图上看,有GC处于2代回收,回收原因为4(大对象分配),从下图也统计也可看出,在有10个线程上存在大对象分配操作,导致GC触发。这也是导致CPU高的其中一个原因(后续分析)。
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
3、既然同步块表中无锁等待,使用!mlocks命令再次查看其它锁类型,如下:存在大量thinlock锁
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
统计存在1023个thinlock锁。
使用!gcroot随便抽一个查看lock对象引用根,如下图,基本上来自于System.Collections.Generic.Dictionary。
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
使用命令:~*e!dumpstack 查看所有线程栈,在栈上搜索该方法对象,存在23次调用,如下图:
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
在托管堆上搜索该对象统计,如下图:
使用命令:!dumpheap -live -min 8196 -type System.Collections.Generic.Dictionary
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
如上图可知,托管堆上有较多此类对象,还有较大的这类对象。
抽一个较大对象,查看其引用根,如下图:
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
由图可知,最终这类lock对象来自于System.Collections.Generic.Dictionary中的table操作,由json序列化引发。

使用命令!mdt展开查看table对象,如下,由图可知,这里存在1024个lock对象,以及3w+个元素。
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
其引用来自json序列化,与前面火焰图分析一致。
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
反编译如下:
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
如上图在json序列化中,用到的table确实被上锁。
在前面分析我们提到有GC进行回收操作,且为大对象分配,接下来分析下大对象操作。

1、使用命令!dumpheap -stat查看所有托管堆状态,如下图:
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
从此卦象来看,首榜为string对象。

2、再使用!dumpheap -live -min 8196 -mt 来查看String方法表中>8196的对象信息,.net将>8196的对象定义为大对象,如下图,还不少:
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
3、随便挑一个较大的使用!do来查看对象信息
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
从笔者选取的几个来看基本上是json字符串,几百KB到1MB+不等。
综合上述分析:

大量较大的String对象使用json对象进行序列化与反序列化操作,其中使用到System.Collections.Generic.Dictionary中的table操作,table操作中为线程安全考虑使用lock锁,String大对象序列化成json对象,遍历Dictionary中的talbe,大量锁遍历,从而引发大对象分配,GC回收,导致此次CPU爆高。
从案发至今,现场共发回给笔者3份dump,其分析结论均指向序列化与反序列化问题,以及大对象导致的GC回收问题。
反馈:
笔者将分析反馈研发后于2024.3.21优化后当日中午紧急升级;
下午接前方反馈经监控cpu已回落至30%左右;
3.22上午监控平均也在30%左右。
一次.net cpu爆高分析-windbg sos基本命令使用及分析思路
此次故障解决!对于在多线程下System.Collections.Generic.Dictionary这个在网上已有不少踩坑的网友们。

一次.net cpu爆高分析-windbg sos基本命令使用及分析思路

看雪ID:cmdxhz

https://bbs.kanxue.com/user-home-116953.htm

*本文为看雪论坛优秀文章,由 cmdxhz 原创,转载请注明来自看雪社区

一次.net cpu爆高分析-windbg sos基本命令使用及分析思路

# 

原文始发于微信公众号(看雪学苑):一次.net cpu爆高分析-windbg sos基本命令使用及分析思路

  • 左青龙
  • 微信扫一扫
  • weinxin
  • 右白虎
  • 微信扫一扫
  • weinxin
admin
  • 本文由 发表于 2024年4月10日09:54:30
  • 转载请保留本文链接(CN-SEC中文网:感谢原作者辛苦付出):
                   一次.net cpu爆高分析-windbg sos基本命令使用及分析思路https://cn-sec.com/archives/2642417.html

发表评论

匿名网友 填写信息