关键词:
一:背景
1.讲故事
前些天有位朋友微信找到我,说他的程序出现了CPU阶段性爆高,过了一会就下去了,咨询下这个爆高阶段程序内部到底发生了什么?画个图大概是下面这样,你懂的。
按经验来说,这种情况一般是程序在做 CPU 密集型运算
,所以让朋友在 CPU 高的时候间隔 5~10s
抓两个 dump 下来,然后就是用 WinDbg 分析。
二:WinDbg 分析
1. CPU 真的爆高吗
耳听为虚,眼见为实,我们用 !tp
观察下当前的CPU情况。
0:000> !tp
CPU utilization: 100%
Worker Thread: Total: 16 Running: 2 Idle: 14 MaxLimit: 32767 MinLimit: 2
Work Request in Queue: 0
--------------------------------------
Number of Timers: 2
--------------------------------------
Completion Port Thread:Total: 2 Free: 2 MaxFree: 4 CurrentLimit: 2 MaxLimit: 1000 MinLimit: 2
果不其然,CPU直接打满,接下来就是看看当前有几个CPU逻辑核,这么不够扛。。。
0:000> !cpuid
CP F/M/S Manufacturer MHz
0 6,106,6 <unavailable> 2700
1 6,106,6 <unavailable> 2700
我去,一个生产环境居然只有两个核。。。果然这大环境下公司活着都不够滋润。
2. 到底是谁引发的
既然是阶段性爆高,最简单粗暴的就是看下各个线程栈,使用 ~*e !clrstack
命令即可,因为只有两核,所以理论上两个线程就可以把 CPU 干趴下,扫了一下线程栈,果然有对号入座的,输出信息如下:
0:000> ~*e !clrstack
OS Thread Id: 0x146c (42)
Child SP IP Call Site
00000089abcfca18 00007ffc4baffdb4 [InlinedCallFrame: 00000089abcfca18] System.Drawing.SafeNativeMethods+Gdip.IntGdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089abcfca18 00007ffbdd4a7a48 [InlinedCallFrame: 00000089abcfca18] System.Drawing.SafeNativeMethods+Gdip.IntGdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089abcfc9f0 00007ffbdd4a7a48 DomainNeutralILStubClass.IL_STUB_PInvoke(System.Runtime.InteropServices.HandleRef)
00000089abcfcaa0 00007ffbdd52ad0a System.Drawing.SafeNativeMethods+Gdip.GdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089abcfcae0 00007ffbdd52ac3f System.Drawing.Image.Dispose(Boolean)
00000089abcfcb30 00007ffbdd556b5a System.Drawing.Image.Dispose()
00000089abcfcb60 00007ffbe39397c7 NPOI.SS.Util.SheetUtil.GetCellWidth(NPOI.SS.UserModel.ICell, Int32, NPOI.SS.UserModel.DataFormatter, Boolean)
00000089abcfcc00 00007ffbe3939654 NPOI.SS.Util.SheetUtil.GetCellWidth(NPOI.SS.UserModel.ICell, Int32, NPOI.SS.UserModel.DataFormatter, Boolean)
00000089abcfcd30 00007ffbe39382e1 NPOI.SS.Util.SheetUtil.GetColumnWidth(NPOI.SS.UserModel.ISheet, Int32, Boolean)
00000089abcfcdc0 00007ffbe39380bc NPOI.XSSF.UserModel.XSSFSheet.AutoSizeColumn(Int32, Boolean)
...
OS Thread Id: 0x1c8c (46)
Child SP IP Call Site
00000089ad43dba8 00007ffc4baffdb4 [InlinedCallFrame: 00000089ad43dba8] System.Drawing.SafeNativeMethods+Gdip.IntGdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089ad43dba8 00007ffbdd4a7a48 [InlinedCallFrame: 00000089ad43dba8] System.Drawing.SafeNativeMethods+Gdip.IntGdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089ad43db80 00007ffbdd4a7a48 DomainNeutralILStubClass.IL_STUB_PInvoke(System.Runtime.InteropServices.HandleRef)
00000089ad43dc30 00007ffbdd52ad0a System.Drawing.SafeNativeMethods+Gdip.GdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089ad43dc70 00007ffbdd52ac3f System.Drawing.Image.Dispose(Boolean)
00000089ad43dcc0 00007ffbdd556b5a System.Drawing.Image.Dispose()
00000089ad43dcf0 00007ffbe39397c7 NPOI.SS.Util.SheetUtil.GetCellWidth(NPOI.SS.UserModel.ICell, Int32, NPOI.SS.UserModel.DataFormatter, Boolean)
00000089ad43dd90 00007ffbe3939654 NPOI.SS.Util.SheetUtil.GetCellWidth(NPOI.SS.UserModel.ICell, Int32, NPOI.SS.UserModel.DataFormatter, Boolean)
00000089ad43dec0 00007ffbe39382e1 NPOI.SS.Util.SheetUtil.GetColumnWidth(NPOI.SS.UserModel.ISheet, Int32, Boolean)
00000089ad43df50 00007ffbe39380bc NPOI.XSSF.UserModel.XSSFSheet.AutoSizeColumn(Int32, Boolean)
...
00000089ad43e460 00007ffbe115b193 System.Web.Mvc.ControllerActionInvoker.InvokeActionMethod(System.Web.Mvc.ControllerContext, System.Web.Mvc.ActionDescriptor, System.Collections.Generic.IDictionary`2<System.String,System.Object>)
...
00000089abcfd310 00007ffbe115b147 System.Web.Mvc.Async.AsyncControllerActionInvoker+c.b__9_0(System.IAsyncResult, ActionInvocation)
...
有些朋友要问了,你是怎么确定就是这两个线程呢?其实有两个方法可以验证。
使用 !whttp 看http请求
既然是 web 请求,自然就可以拿到里面的 HttpContext
,这里面记录着当前请求的运行时间,这个信息非常重要,截图如下:
从图中可以看到,有两个 xxxx/Export
请求运行时间非常高,一个是 4min30s
,一个是 50s
,刚好落在了 42
和 46
号线程上。
借助第二个 dump 文件
这就是为什么要抓二个dump的原因了,因为另一个dump会给我们相当有价值的对比信息,同样使用 !whttp
验证。
接下来我们就要调研为什么这两个线程会运行这么久?
3. 为什么会运行这么久
既然是 Export 导出文件,第一时间就应该想到是不是和数据量有关?通过线程栈上的方法,发现是一个List
集合,接下来用 !dso
命令找出来看看。
0:042> !dso
OS Thread Id: 0x146c (42)
RSP/REG Object Name
00000089ABCFCAC8 0000020683b7c128 System.Drawing.Bitmap
00000089ABCFCAF8 0000020683b7c158 System.Drawing.Graphics
00000089ABCFCB10 0000020683b7c128 System.Drawing.Bitmap
00000089ABCFCB30 0000020683b7c128 System.Drawing.Bitmap
00000089ABCFCB40 0000020683b7c4d0 NPOI.XSSF.UserModel.XSSFCellStyle
00000089ABCFCB50 0000020683b7c198 NPOI.XSSF.UserModel.XSSFRichTextString
00000089ABCFCB68 0000020683b7c198 NPOI.XSSF.UserModel.XSSFRichTextString
00000089ABCFCBC0 0000020683b7c198 NPOI.XSSF.UserModel.XSSFRichTextString
00000089ABCFCBC8 0000020683b7c2e8 System.String[]
00000089ABCFCBD0 0000020683b7c360 System.Drawing.Font
00000089ABCFCDE8 0000020666501240 System.Collections.Generic.List`1[[System.Collections.Generic.List`1[[System.Object, mscorlib]], mscorlib]]
...
0:042> !do 0000020666501240
Name: System.Collections.Generic.List`1[[System.Collections.Generic.List`1[[System.Object, mscorlib]], mscorlib]]
MethodTable: 00007ffbde342440
EEClass: 00007ffc36fc2af8
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
00007ffc36e4e250 40018a0 8 System.__Canon[] 0 instance 00000207658592d8 _items
00007ffc36e385a0 40018a1 18 System.Int32 1 instance 44906 _size
00007ffc36e385a0 40018a2 1c System.Int32 1 instance 44906 _version
00007ffc36e35dd8 40018a3 10 System.Object 0 instance 0000000000000000 _syncRoot
00007ffc36e4e250 40018a4 0 System.__Canon[] 0 shared static _emptyArray
>> Domain:Value dynamic statics NYI 0000020563eec3c0:NotInit dynamic statics NYI 0000020795f5b9a0:NotInit <<
可以清楚的看到,这个list高达 4.5w
,这个量级说多也不多,说少也不少,言外之意就是代码写的也不好不到哪里去。
4. 用户代码要承担责任吗
要判断用户代码是不是很烂,除了白盒看代码,也可以黑盒观察这几个线程栈,可以发现两个dump 显示的栈信息都和 AutoSizeColumn
方法有关。
00000089abcfcae0 00007ffbdd52ac3f System.Drawing.Image.Dispose(Boolean)
00000089abcfcb30 00007ffbdd556b5a System.Drawing.Image.Dispose()
00000089abcfcb60 00007ffbe39397c7 NPOI.SS.Util.SheetUtil.GetCellWidth(NPOI.SS.UserModel.ICell, Int32, NPOI.SS.UserModel.DataFormatter, Boolean)
00000089abcfcc00 00007ffbe3939654 NPOI.SS.Util.SheetUtil.GetCellWidth(NPOI.SS.UserModel.ICell, Int32, NPOI.SS.UserModel.DataFormatter, Boolean)
00000089abcfcd30 00007ffbe39382e1 NPOI.SS.Util.SheetUtil.GetColumnWidth(NPOI.SS.UserModel.ISheet, Int32, Boolean)
00000089abcfcdc0 00007ffbe39380bc NPOI.XSSF.UserModel.XSSFSheet.AutoSizeColumn(Int32, Boolean)
从名字看是 NOPI 提供的自动调整列宽
的方法,那是不是这个方法的单次性能很慢呢?要寻找答案,只能求助百度啦。。。
图一
图二
到这里我们基本就搞清楚了,导致 reqeust 高达 5min + 的诱因大概有三个。
数据量大
AutoSizeColumn 速度慢
代码上的其他因素
跟朋友沟通后,朋友说这块请求中的 AutoSizeColumn
方法忘了改掉。
三:总结
这个 Dump 分析起来其实非常简单,思路也比较明朗,重点还是提醒一下大家慎用 NPOI 的 AutoSizeColumn
方法,弄不好就得出个生产事故!
记一次.net某供应链web网站cpu爆高事故分析(代码片段)
一:背景1.讲故事年前有位朋友加微信求助,说他的程序出现了偶发性CPU爆高,寻求如何解决,截图如下:我建议朋友用procdump在cpu高的时候连抓两个dump,这样分析起来比较稳健,朋友也如期的成功抓到,接下来就用windbg一起来... 查看详情
记一次.net某制造业mes系统崩溃分析(代码片段)
一:背景1.讲故事前段时间有位朋友微信找到我,说他的程序偶尔会出现内存溢出崩溃,让我帮忙看下是怎么回事,咨询了下程序是x86部署,听到这个词其实心里已经有了数,不管怎么样还是用windbg分析一... 查看详情
记一次苏宁小店事故分析和总结
转java3年了,记一个最近的坑; 临近818,苏宁小店线上app搞了个秒杀活动,后台服务出现了异常。活动是周五10点,收到了系统的告警短信,同事开始有人在公司豆芽(苏宁内部通信工具)反馈有部分用户下单失败;  ... 查看详情
记一次.net某企业erp网站系统崩溃分析(代码片段)
一:背景1.讲故事前段时间收到了一个朋友的求助,说他的ERP网站系统会出现偶发性崩溃,找了好久也没找到是什么原因,让我帮忙看下,其实崩溃好说,用procdump自动抓一个就好,拿到dump之后,接下来就是一顿分析了。二:WinD... 查看详情
记一次某应用虚拟化系统远程代码执行(代码片段)
微步在线漏洞团队通过“X漏洞奖励计划”获取到瑞友天翼应用虚拟化系统远程代码执行漏洞情报(0day),攻击者可以通过该漏洞执行任意代码,导致系统被攻击与控制。瑞友天翼应用虚拟化系统是基于服务器计算架构的应用虚拟... 查看详情
记一次.net某娱乐聊天流平台cpu爆高分析(代码片段)
一:背景1.讲故事前段时间有位朋友加微信,说他的程序直接CPU=100%,每次只能手工介入重启,让我帮忙看下到底怎么回事,哈哈,这种CPU打满的事故,程序员压力会非常大,我让朋友在CPU高的时候抓2... 查看详情
生产事故-记一次特殊的oom排查(代码片段)
入职多年,面对生产环境,尽管都是小心翼翼,慎之又慎,还是难免捅出篓子。轻则满头大汗,面红耳赤。重则系统停摆,损失资金。每一个生产事故的背后,都是宝贵的经验和教训,都是项目成员的血泪史。为了更好地防范和... 查看详情
记一次.net某家装erp系统内存暴涨分析(代码片段)
一:背景1.讲故事前段时间微信上有一位老朋友找到我,说他的程序跑着跑着内存会突然爆高,有时候会下去,有什么会下不去,怀疑是不是某些情况下存在内存泄露,让我帮忙分析一下,其实内存泄露方面的问题还是比较好解... 查看详情
记一次生产kafka消息消费的事故(代码片段)
事故背景: 我们公司与合作方公司有个消息同步的需求,合作方是消息生产者,我们是消息消费者,他们通过kafka给我们推送消息,我们实时接收,然后进行后续业务处理。昨天上午,发现他们推送过来的广场门店信息我们... 查看详情
记一次线上事故,redis的keys问题,cpu引起的性能问题
公司的一个接口用redis存储pv/uv,一直以来,非常好用,某天发现,接口反映非常慢,经过长时间排查。是redis的cpu非常高,到了60%以上。之前设置的70%报警。然后有个广告使用了keys查询,我们的redis里面的key有几千万,致使cpu超... 查看详情
记一次某公司面试题:合并有序数组(代码片段)
来源2021/09/24:接到某公司面试,手撕一到合并有序数组的题,当时做的差不多了,面试官时间给的相对短了一些,临界值处理有问题,没完全写出来有些遗憾,不过至少自己思路没错,参考网上给... 查看详情
记一次某公司面试题:合并有序数组(代码片段)
来源2021/09/24:接到某公司面试,手撕一到合并有序数组的题,当时做的差不多了,面试官时间给的相对短了一些,临界值处理有问题,没完全写出来有些遗憾,不过至少自己思路没错,参考网上给... 查看详情
记一次es事故(代码片段)
从报警来看,业务报接口超时,同时es错误日志也会提示:Causedby:org.elasticsearch.common.util.concurrent.EsRejectedExecutionException:rejectedexecutionoforg.elasticsearch.transport.TcpTransport$RequestHandle 查看详情
cpu使用率终于正常了——记一次订餐统事故处理
引子 经过漫长的等待,儿子终于出生了。欣喜之余,就是各种手足无措,顾此失彼了。因为不懂,心里总是慌慌的,有点小毛病,恨不得一步就到医院。 婆媳育儿观念的差异,让心乱如麻的我,又成了风箱里的老鼠,两... 查看详情
cpu使用率终于正常了——记一次订餐统事故处理
引子 经过漫长的等待,儿子终于出生了。欣喜之余,就是各种手足无措,顾此失彼了。因为不懂,心里总是慌慌的,有点小毛病,恨不得一步就到医院。 婆媳育儿观念的差异,让心乱如麻的我,又成了风箱里的老鼠,两... 查看详情
记一次.net某智慧物流wcs系统cpu爆高分析(代码片段)
一:背景1.讲故事哈哈,再次见到物流类软件,上个月有位朋友找到我,说他的程序出现了CPU爆高,让我帮忙看下什么原因,由于那段时间在苦心研究C++,分析和经验分享也就懈怠了,今天就... 查看详情
记一次生产事故:30万单就这样没了!(代码片段)
背景你好,我是彤哥。昨天晚上下班回家,在地铁上,老大突然打来电话,B系统生产环境响应缓慢,影响了A系统的使用,几万小哥收不了单,大概有30万单卡住了,你去帮忙定位一下。我8点半左右... 查看详情
记一次.net某智慧物流wcs系统cpu爆高分析
一:背景1.讲故事哈哈,再次见到物流类软件,上个月有位朋友找到我,说他的程序出现了CPU爆高,让我帮忙看下什么原因,由于那段时间在苦心研究C++,分析和经验分享也就懈怠了,今天就给大家安排上。话不多说,上windbg说... 查看详情