加强门户网站建设方案,云南人才网,国际新闻热点事件,wordpress个人博客动漫主题一#xff1a;背景 1.讲故事前些天有位朋友微信找到我#xff0c;说他的程序出现了CPU阶段性爆高#xff0c;过了一会就下去了#xff0c;咨询下这个爆高阶段程序内部到底发生了什么#xff1f;画个图大概是下面这样#xff0c;你懂的。按经验来说#xff0c;这种情况一…一背景 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 MHz0 6,106,6 unavailable 27001 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.SafeNativeMethodsGdip.IntGdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089abcfca18 00007ffbdd4a7a48 [InlinedCallFrame: 00000089abcfca18] System.Drawing.SafeNativeMethodsGdip.IntGdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089abcfc9f0 00007ffbdd4a7a48 DomainNeutralILStubClass.IL_STUB_PInvoke(System.Runtime.InteropServices.HandleRef)
00000089abcfcaa0 00007ffbdd52ad0a System.Drawing.SafeNativeMethodsGdip.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.SafeNativeMethodsGdip.IntGdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089ad43dba8 00007ffbdd4a7a48 [InlinedCallFrame: 00000089ad43dba8] System.Drawing.SafeNativeMethodsGdip.IntGdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089ad43db80 00007ffbdd4a7a48 DomainNeutralILStubClass.IL_STUB_PInvoke(System.Runtime.InteropServices.HandleRef)
00000089ad43dc30 00007ffbdd52ad0a System.Drawing.SafeNativeMethodsGdip.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.IDictionary2System.String,System.Object)
...
00000089abcfd310 00007ffbe115b147 System.Web.Mvc.Async.AsyncControllerActionInvokerc.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.List1[[System.Collections.Generic.List1[[System.Object, mscorlib]], mscorlib]]
...0:042 !do 0000020666501240
Name: System.Collections.Generic.List1[[System.Collections.Generic.List1[[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 方法弄不好就得出个生产事故
