记一次 .NET医院公众号程序 线程CPU双高分析
一：背景
1. 講故事
上周四有位朋友加wx咨詢他的程序出現(xiàn) CPU + 線程 雙高的情況，希望我能幫忙排查下，如下圖：
從截圖看只是線程爆高，沒看到 cpu 爆高哈????????????，有意思的是這位朋友說他：一直在手動回收 ，不知道為啥看著特別想笑，但笑著笑著就哭了。
可能朋友知道老規(guī)矩，發(fā)了兩份dump過來，接下來我就可以開工了，既然說高峰期分分鐘上千個線程，和我前幾天分享的那篇 串口 的問題很像，肯定是個別線程退不出 鎖，導致 CLR 需要創(chuàng)建更多的線程池線程來應付不斷累積的 Work Queue，所以還是得優(yōu)先看 同步塊表，還是那句話，十個人用鎖，八個人用 lock ????????????。
二：windbg 分析
1. 查找 CLR 同步塊表
可以用 !syncblk 看看有沒有 lock 的情況。
0:000>?!syncblk Index?SyncBlock?MonitorHeld?Recursion?Owning?Thread?Info??SyncBlock?Owner95?00000262b8a30ca8??????????193?????????1?00000262b8a36b50?116b8??53???0000025e2a8ded70?System.Object118?00000262b8a32098??????????107?????????1?00000262bad503b0?710c?135???00000260ea8a9b00?NLog.Logger200?00000262ba236cc8???????????13?????????1?00000262b9df1660?8858??69???0000025e2a8dcdf0?System.Object ----------------------------- Total???????????305 CCW?????????????3 RCW?????????????6 ComClassFactory?0 Free????????????116雖然卦象上出現(xiàn)了超過正常指標的持有鎖值：193，107，13，但直覺更告訴我，是不是死鎖啦？？？用 sosex 擴展的 !dlk 命令可以自動檢索是不是真的有？
0:000>?!dlk Examining?SyncBlocks... Scanning?for?ReaderWriterLock?instances... Scanning?for?holders?of?ReaderWriterLock?locks... Scanning?for?ReaderWriterLockSlim?instances... Scanning?for?holders?of?ReaderWriterLockSlim?locks... Examining?CriticalSections... Scanning?for?threads?waiting?on?SyncBlocks... Scanning?for?threads?waiting?on?ReaderWriterLock?locks... Scanning?for?threads?waiting?on?ReaderWriterLocksSlim?locks... Scanning?for?threads?waiting?on?CriticalSections... No?deadlocks?detected.從最后一行看沒有任何 deadlocks，看樣子我的直覺是錯的????????????。
只能回頭看那最高的 193 ，表示有 1 個線程持有鎖 (53號線程)，96個線程等待鎖，確定了是 lock 的問題就好辦了，查看它的線程棧就好啦。
2. 查看線程棧
為了穩(wěn)一點，我就用 !dumpstack 調出 53 線程的托管和非托管棧，如下圖：
從上面的調用棧可以看到，程序用 NLog.Write 寫日志后，最終卡死在 calling ntdll!NtCreateFile 這個 Win32 函數(shù)上 ，我也很驚訝，是不是磁盤寫入速度太低了？馬上問了下朋友是否為 SSD ，朋友說可能不是 ????????????，而且朋友還說高峰期半個小時能up到 600M 日志，我想問題應該是出在磁盤寫入太慢的根源上了。。。
3. 真的決定讓磁盤背鍋嗎？
把這個答案丟給朋友好像也不太合適，讓朋友換 SSD ？那日志量起來了SSD也扛不住怎么辦？所以言外之意就是：耕田有責任，耕牛也得負責任，那怎么從它身上找責任呢??? 再回頭看一下這個調用棧。
0:053>?!clrstack OS?Thread?Id:?0x116b8?(53)Child?SP???????????????IP?Call?Site 0000006d65d3d238?00007ff849ac65b4?[InlinedCallFrame:?0000006d65d3d238]?NLog.Internal.Win32FileNativeMethods.CreateFile(System.String,?FileAccess,?Int32,?IntPtr,?CreationDisposition,?NLog.Targets.Win32FileAttributes,?IntPtr) 0000006d65d3d238?00007ff7d2d8c33e?[InlinedCallFrame:?0000006d65d3d238]?NLog.Internal.Win32FileNativeMethods.CreateFile(System.String,?FileAccess,?Int32,?IntPtr,?CreationDisposition,?NLog.Targets.Win32FileAttributes,?IntPtr) 0000006d65d3d1f0?00007ff7d2d8c33e?DomainBoundILStubClass.IL_STUB_PInvoke(System.String,?FileAccess,?Int32,?IntPtr,?CreationDisposition,?NLog.Targets.Win32FileAttributes,?IntPtr) 0000006d65d3d300?00007ff7d2d8bcdc?NLog.Internal.FileAppenders.BaseFileAppender.WindowsCreateFile(System.String,?Boolean) 0000006d65d3d380?00007ff7d2d8b94f?NLog.Internal.FileAppenders.BaseFileAppender.TryCreateFileStream(Boolean) 0000006d65d3d3e0?00007ff7d2d8b673?NLog.Internal.FileAppenders.BaseFileAppender.CreateFileStream(Boolean) 0000006d65d3d440?00007ff7d2d8b501?NLog.Internal.FileAppenders.RetryingMultiProcessFileAppender.Write(Byte[]) 0000006d65d3d490?00007ff7d2d8aca0?NLog.Targets.FileTarget.WriteToFile(System.String,?NLog.LogEventInfo,?Byte[],?Boolean) 0000006d65d3d4e0?00007ff7d2a44dd3?NLog.Targets.FileTarget.ProcessLogEvent(NLog.LogEventInfo,?System.String,?Byte[]) 0000006d65d3d550?00007ff7d2a485c9?NLog.Targets.Target.Write(NLog.Common.AsyncLogEventInfo) 0000006d65d3d590?00007ff7d2a487b7?NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo) 0000006d65d3d610?00007ff7d2a48ab5?NLog.LoggerImpl.WriteToTargetWithFilterChain(NLog.Internal.TargetWithFilterChain,?NLog.LogEventInfo,?NLog.Common.AsyncContinuation) 0000006d65d3d670?00007ff7d2a38c45?NLog.LoggerImpl.Write(System.Type,?NLog.Internal.TargetWithFilterChain,?NLog.LogEventInfo,?NLog.LogFactory) 0000006d65d3d6d0?00007ff7d2a39282?NLog.Logger.Trace(System.String)不知道你有沒有發(fā)現(xiàn)，53號線程tmd的不僅要處理業(yè)務，還要調用 Win32（用戶態(tài) <-> 內核態(tài)） 寫入文件，這量起來了誰受的住？？？
一個高效的日志系統(tǒng)，走的應該是 專有線程 + 日志緩沖隊列 ?的路子，找了下 NLog 的資料，嘿，NLog 還真提供了這種方案。
所以得優(yōu)化一下 NLog 的默認配置，貌似這樣就可以結束本文了，不行，既然都到這里了，我還得找點開發(fā)人員責任????????????。
3. 如何找開發(fā)人員責任
如果你細心的話，會不會覺得還漏了點什么？對，就是那個同步塊，卦象上有三條信息，對吧，為了方便查看，我再贅貼一下。
0:000>?!syncblk Index?SyncBlock?MonitorHeld?Recursion?Owning?Thread?Info??SyncBlock?Owner95?00000262b8a30ca8??????????193?????????1?00000262b8a36b50?116b8??53???0000025e2a8ded70?System.Object118?00000262b8a32098??????????107?????????1?00000262bad503b0?710c?135???00000260ea8a9b00?NLog.Logger200?00000262ba236cc8???????????13?????????1?00000262b9df1660?8858??69???0000025e2a8dcdf0?System.Objectindex=95 和 NLoger 相關，那怎么 index=118 又和 NLog.Logger 相關呢？接下來把這兩個對象 0000025e2a8ded70, 00000260ea8a9b00 的源碼導出來,可以用 !gcroot + ?!name2ee + !savemodule。
0:053>?!gcroot?0000025e2a8ded70 Thread?116b8:0000006d65d3d590?00007ff7d2a487b7?NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo)rbp-48:?0000006d65d3d5b8->??0000025e2a8ded70?System.Object 0:053>?!name2ee?*!NLog.Targets.Target.WriteAsyncLogEvent -------------------------------------- Module:??????00007ff7d2b172d8 Assembly:????NLog.dll Token:???????0000000006000b5e MethodDesc:??00007ff7d2be3330 Name:????????NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo) JITTED?Code?Address:?00007ff7d2a48700 -------------------------------------- 0:053>?!savemodule?00007ff7d2b172d8?E:\dumps\1.dll 3?ps?in?file p?0?-?VA=2000,?VASize=7faa4,?FileAddr=200,?FileSize=7fc00 p?1?-?VA=82000,?VASize=3e8,?FileAddr=7fe00,?FileSize=400 p?2?-?VA=84000,?VASize=c,?FileAddr=80200,?FileSize=2000:053>?!gcroot?00000260ea8a9b00 Thread?710c:0000006d68f3df30?00007ff7d2d8a3b2?xxx.Logger.log(System.String)rdi:?->??00000260ea8a9b00?NLog.Logger 0:053>?!name2ee?*!xxx.Logger.log -------------------------------------- Module:??????00007ff7d29b5558 Assembly:????xxx.dll Token:???????0000000006001ead MethodDesc:??00007ff7d29b9a38 Name:????????xxx.Logger.log(System.String) JITTED?Code?Address:?00007ff7d2d8a260 -------------------------------------- 0:053>?!savemodule?00007ff7d29b5558?E:\dumps\2.dll 3?ps?in?file p?0?-?VA=2000,?VASize=221cf0,?FileAddr=200,?FileSize=221e00 p?1?-?VA=224000,?VASize=3c8,?FileAddr=222000,?FileSize=400 p?2?-?VA=226000,?VASize=c,?FileAddr=222400,?FileSize=200用 ILSpy 打開 2.dll 后，發(fā)現(xiàn)了那段有趣的 Logger.log() 代碼，真的是太有趣了。。。如下所示。
public?class?Logger {private?static?Logger?Log?=?LogManager.GetLogger("");private?static?object?lockCache?=?new?object();public?static?void?WriteLog(string?message){Task.Run(delegate{log(message);});}public?static?void?log(string?message){try{if?(message.Contains("xxxxxxx")){lock?(Log){Log.Warn("????"?+?message?+?"\r\n\r\n");}}else{lock?(Log){Log.Info("????"?+?message?+?"\r\n\r\n");}}}catch?(Exception){}}public?static?void?WriteLog(string?message,?params?object[]?args){lock?(Log){Log.Info("????"?+?string.Format(message,?args));}} }居然在 ?log() 方法里加了一個鎖，這是有多么不信任 NLog 哈 ????????????，還有一點在 WriteLog() 方法中使用了 Task.Run 記錄日志，難怪朋友說分分鐘上千個線程，這回我可是明白了。。。
當我以為就這樣吐吐槽就結束了，不爭氣的我又看了另外一個 dump ，然后我就不想吐槽了????
0:000>?!t ThreadCount:??????200 UnstartedThread:??0 BackgroundThread:?200 PendingThread:????0 DeadThread:???????0 Hosted?Runtime:???noLock??ID?OSID?ThreadOBJ???????????State?GC?Mode?????GC?Alloc?Context??????????????????Domain???????????Count?Apt?Exception78???47?afb8?000001cd7abbf1d0??3029220?Preemptive??000001CBB81648C0:000001CBB8166318?000001cd798a9d30?2?????MTA?(Threadpool?Worker)?System.IO.FileLoadException?000001cbb81644a80:000>?!PrintException?/d?000001cbb81644a8 Exception?object:?000001cbb81644a8 Exception?type:???System.IO.FileLoadException Message:??????????另一個程序正在使用此文件，進程無法訪問。?(異常來自 HRESULT:0x80070020) InnerException:???<none> StackTrace?(generated):SP???????????????IP???????????????Function0000001B3703E750?0000000000000000?mscorlib_ni!System.Runtime.InteropServices.Marshal.ThrowExceptionForHRInternal(Int32,?IntPtr)+0x10000001B3703E750?00007FF7D2D30D87?UNKNOWN!NLog.Internal.FileAppenders.BaseFileAppender.WindowsCreateFile(System.String,?Boolean)+0x1570000001B3703E7D0?00007FF7D2D3092F?UNKNOWN!NLog.Internal.FileAppenders.BaseFileAppender.TryCreateFileStream(Boolean)+0x5f0000001B3703E830?00007FF7D2D30593?UNKNOWN!NLog.Internal.FileAppenders.BaseFileAppender.CreateFileStream(Boolean)+0xd3StackTraceString:?<none> HResult:?80070020 The?current?thread?is?unmanaged?竟然還有 進程占用異常 。。。而且異常堆棧中不就是那個熟悉的文件創(chuàng)建函數(shù) WindowsCreateFile 嗎？？？好吧，好奇心驅使著我決定要拿到那個文件名，可以切換到 78 號線程，使用 !clrstack -a 調出參數(shù)和局部變量，找到最后的 FileName。
0:078>?!clrstack?-a OS?Thread?Id:?0xafb8?(78) 0000001b3703e750?00007ff7d2d30ce1?NLog.Internal.FileAppenders.BaseFileAppender.WindowsCreateFile(System.String,?Boolean)PARAMETERS:this?(<CLR?reg>)?=?0x000001c9771abf40 0:078>?!do?0x000001c9771abf40 Name:????????NLog.Internal.FileAppenders.RetryingMultiProcessFileAppender Fields:MT????Field???Offset?????????????????Type?VT?????Attr????????????Value?Name 00007ff830f88760??40000dd????????8????????System.Random??0?instance?000001c9771abf80?random 00007ff830f99808??40000de???????10????????System.String??0?instance?000001c9772fd418?<FileName>k__BackingField0:078>?!DumpObj?/d?000001c9772fd418 Name:????????System.String MethodTable:?00007ff830f99808 EEClass:?????00007ff830876cb8 Size:????????142(0x8e)?bytes File:????????C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll String:??????D:\xxx\wwwroot\WebService\log\2021-04-16\file.txt還記得文章開頭第二張截圖嗎？朋友開了WebService程序的多個副本，沒想到都寫一個文件了，這是大忌哈。。。
三：總結
吐槽了這么多，可能我和朋友都在做涉醫(yī)行業(yè)的業(yè)務，來自于甲方的壓力還是挺大的????????????，最后給出的優(yōu)化措施如下。
修改 NLog 的配置文件，支持 專有線程 + Queue 模式，從而釋放業(yè)務線程。
NLog 的寫法和調用方式太雜亂，需要重新封裝，對外只需提供一個接口即可，用它就要信任它。
有條件提升到 SSD。
最后的彩蛋就是反饋好消息啦????????????
END
工作中的你，是否已遇到 ...?
1. CPU爆高
2. 內存暴漲
3. 資源泄漏
4. 崩潰死鎖
5. 程序呆滯
等緊急事件，全公司都指望著你能解決...? 危難時刻才能展現(xiàn)你的技術價值，作為專注于.NET高級調試的技術博主，歡迎微信搜索: 一線碼農(nóng)聊技術，免費協(xié)助你分析Dump文件，希望我能將你的踩坑經(jīng)驗分享給更多的人。
總結
以上是生活随笔為你收集整理的记一次 .NET医院公众号程序 线程CPU双高分析的全部內容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： 优化 .NET Core logging
- 下一篇： WPF 如何实现颜色值拾取