.NET醫(yī)院公眾號(hào)系統(tǒng)線程CPU雙高問題分析
一：背景
1. 講故事
上周四有位朋友加wx咨詢他的程序出現(xiàn) CPU + 線程 雙高的情況，希望我能幫忙排查下，如下圖：
從截圖看只是線程爆高，沒看到 cpu 爆高哈😂😂😂，有意思的是這位朋友說他： 一直在手動(dòng)回收 ，不知道為啥看著特別想笑，但笑著笑著就哭了。
可能朋友知道老規(guī)矩，發(fā)了兩份dump過來，接下來我就可以開工了，既然說高峰期分分鐘上千個(gè)線程，和我前幾天分享的那篇 串口 的問題很像，肯定是個(gè)別線程退不出 鎖，導(dǎo)致 CLR 需要?jiǎng)?chuàng)建更多的線程池線程來應(yīng)付不斷累積的 Work Queue，所以還是得優(yōu)先看 同步塊表，還是那句話，十個(gè)人用鎖，八個(gè)人用 lock 🤣🤣🤣。
二： windbg 分析
1. 查找 CLR 同步塊表
可以用 !syncblk 看看有沒有 lock 的情況。
0:000> !syncblk Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner 95 00000262b8a30ca8 193 1 00000262b8a36b50 116b8 53 0000025e2a8ded70 System.Object 118 00000262b8a32098 107 1 00000262bad503b0 710c 135 00000260ea8a9b00 NLog.Logger 200 00000262ba236cc8 13 1 00000262b9df1660 8858 69 0000025e2a8dcdf0 System.Object ----------------------------- Total 305 CCW 3 RCW 6 ComClassFactory 0 Free 116
雖然卦象上出現(xiàn)了超過正常指標(biāo)的持有鎖值：193，107，13，但直覺更告訴我，是不是死鎖啦？？？ 用 sosex 擴(kuò)展的 !dlk 命令可以自動(dòng)檢索是不是真的有？
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，看樣子我的直覺是錯(cuò)的😤😤😤。
只能回頭看那最高的 193 ，表示有 1 個(gè)線程持有鎖 (53號(hào)線程)，96個(gè)線程等待鎖，確定了是 lock 的問題就好辦了，查看它的線程棧就好啦。
2. 查看線程棧
為了穩(wěn)一點(diǎn)，我就用 !dumpstack 調(diào)出 53 線程的托管和非托管棧，如下圖：
從上面的調(diào)用?？梢钥吹?，程序用 NLog.Write 寫日志后，最終卡死在 calling ntdll!NtCreateFile 這個(gè) Win32 函數(shù)上 ，我也很驚訝，是不是磁盤寫入速度太低了？ 馬上問了下朋友是否為 SSD ，朋友說可能不是 😂😂😂，而且朋友還說高峰期半個(gè)小時(shí)能up到 600M 日志，我想問題應(yīng)該是出在磁盤寫入太慢的根源上了。。。
3. 真的決定讓磁盤背鍋嗎？
把這個(gè)答案丟給朋友好像也不太合適，讓朋友換 SSD ？ 那日志量起來了SSD也扛不住怎么辦？ 所以言外之意就是：耕田有責(zé)任，耕牛也得負(fù)責(zé)任，那怎么從它身上找責(zé)任呢??? 再回頭看一下這個(gè)調(diào)用棧。
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號(hào)線程tmd的不僅要處理業(yè)務(wù)，還要調(diào)用 Win32（用戶態(tài) <-> 內(nèi)核態(tài)） 寫入文件，這量起來了誰受的??？？？
一個(gè)高效的日志系統(tǒng)，走的應(yīng)該是 專有線程 + 日志緩沖隊(duì)列 的路子，找了下 NLog 的資料，嘿，NLog 還真提供了這種方案。
所以得優(yōu)化一下 NLog 的默認(rèn)配置，貌似這樣就可以結(jié)束本文了，不行，既然都到這里了，我還得找點(diǎn)開發(fā)人員責(zé)任😁😁😁。
3. 如何找開發(fā)人員責(zé)任
如果你細(xì)心的話，會(huì)不會(huì)覺得還漏了點(diǎn)什么？ 對(duì)，就是那個(gè)同步塊，卦象上有三條信息，對(duì)吧，為了方便查看，我再贅貼一下。
0:000> !syncblk Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner 95 00000262b8a30ca8 193 1 00000262b8a36b50 116b8 53 0000025e2a8ded70 System.Object 118 00000262b8a32098 107 1 00000262bad503b0 710c 135 00000260ea8a9b00 NLog.Logger 200 00000262ba236cc8 13 1 00000262b9df1660 8858 69 0000025e2a8dcdf0 System.Object
index=95 和 NLoger 相關(guān)，那怎么 index=118 又和 NLog.Logger 相關(guān)呢？接下來把這兩個(gè)對(duì)象 0000025e2a8ded70, 00000260ea8a9b00 的源碼導(dǎo)出來,可以用 !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 sections in file
section 0 - VA=2000, VASize=7faa4, FileAddr=200, FileSize=7fc00
section 1 - VA=82000, VASize=3e8, FileAddr=7fe00, FileSize=400
section 2 - VA=84000, VASize=c, FileAddr=80200, FileSize=200
0: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 sections in file
section 0 - VA=2000, VASize=221cf0, FileAddr=200, FileSize=221e00
section 1 - VA=224000, VASize=3c8, FileAddr=222000, FileSize=400
section 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() 方法里加了一個(gè)鎖，這是有多么不信任 NLog 哈 😂😂😂，還有一點(diǎn)在 WriteLog() 方法中使用了 Task.Run 記錄日志，難怪朋友說分分鐘上千個(gè)線程，這回我可是明白了。。。
當(dāng)我以為就這樣吐吐槽就結(jié)束了，不爭(zhēng)氣的我又看了另外一個(gè) dump ，然后我就不想吐槽了😤
0:000> !t
ThreadCount: 200
UnstartedThread: 0
BackgroundThread: 200
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
Lock
ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
78 47 afb8 000001cd7abbf1d0 3029220 Preemptive 000001CBB81648C0:000001CBB8166318 000001cd798a9d30 2 MTA (Threadpool Worker) System.IO.FileLoadException 000001cbb81644a8
0:000> !PrintException /d 000001cbb81644a8
Exception object: 000001cbb81644a8
Exception type: System.IO.FileLoadException
Message: 另一個(gè)程序正在使用此文件，進(jìn)程無法訪問。 (異常來自 HRESULT:0x80070020)
InnerException: <none>
StackTrace (generated):
SP IP Function
0000001B3703E750 0000000000000000 mscorlib_ni!System.Runtime.InteropServices.Marshal.ThrowExceptionForHRInternal(Int32, IntPtr)+0x1
0000001B3703E750 00007FF7D2D30D87 UNKNOWN!NLog.Internal.FileAppenders.BaseFileAppender.WindowsCreateFile(System.String, Boolean)+0x157
0000001B3703E7D0 00007FF7D2D3092F UNKNOWN!NLog.Internal.FileAppenders.BaseFileAppender.TryCreateFileStream(Boolean)+0x5f
0000001B3703E830 00007FF7D2D30593 UNKNOWN!NLog.Internal.FileAppenders.BaseFileAppender.CreateFileStream(Boolean)+0xd3
StackTraceString: <none>
HResult: 80070020
The current thread is unmanaged
竟然還有 進(jìn)程占用異常 。。。而且異常堆棧中不就是那個(gè)熟悉的文件創(chuàng)建函數(shù) WindowsCreateFile 嗎？？？ 好吧，好奇心驅(qū)使著我決定要拿到那個(gè)文件名，可以切換到 78 號(hào)線程，使用 !clrstack -a 調(diào)出參數(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__BackingField
0: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程序的多個(gè)副本，沒想到都寫一個(gè)文件了，這是大忌哈。。。
三：總結(jié)
吐槽了這么多，可能我和朋友都在做涉醫(yī)行業(yè)的業(yè)務(wù)，來自于甲方的壓力還是挺大的😭😭😭，最后給出的優(yōu)化措施如下。
修改 NLog 的配置文件，支持 專有線程 + Queue 模式，從而釋放業(yè)務(wù)線程。
NLog 的寫法和調(diào)用方式太雜亂，需要重新封裝，對(duì)外只需提供一個(gè)接口即可，用它就要信任它。
有條件提升到 SSD。
最后的彩蛋就是反饋好消息啦😁😁😁
更多高質(zhì)量干貨：參見我的 GitHub: dotnetfly
到此這篇關(guān)于.NET醫(yī)院公眾號(hào)系統(tǒng) 線程CPU雙高分析的文章就介紹到這了,更多相關(guān).NET醫(yī)院公眾號(hào)系統(tǒng) 內(nèi)容請(qǐng)搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！
相關(guān)文章
asp.net(c#)下各種進(jìn)制間的輕松轉(zhuǎn)換(2進(jìn)制、8進(jìn)制、10進(jìn)制、16進(jìn)制)
在.NET Framework中，System.Convert類中提供了較為全面的各種類型、數(shù)值之間的轉(zhuǎn)換功能。2010-10-10
這篇文章主要介紹了如何去除HTML標(biāo)簽、刪除HTML。示例中使用到了一個(gè)正則，直接使用就可以了2014-06-06
c#將Excel數(shù)據(jù)導(dǎo)入到數(shù)據(jù)庫的實(shí)現(xiàn)代碼
這篇文章主要介紹了c#將Excel數(shù)據(jù)導(dǎo)入到數(shù)據(jù)庫的實(shí)現(xiàn)代碼，有需要的朋友可以參考一下2013-12-12
ASP.NET性能優(yōu)化建議包括以下幾點(diǎn)數(shù)據(jù)庫訪問性能優(yōu)化,字符串操作性能優(yōu)化,禁用調(diào)試模式等等，感興趣的盆友可以參考下2013-01-01
在asp.net中要遍歷像數(shù)據(jù)之類的內(nèi)容我們一般會(huì)用到for,foreach,while這種了，下面我來介紹利用for遍歷GridView控件2013-08-08
正常操作情況下會(huì)有ASP.NET Session丟失的情況出現(xiàn)。因?yàn)槌绦蚴窃诓煌５谋徊僮?，排除Session超時(shí)的可能。另外，Session超時(shí)時(shí)間被設(shè)定成60分鐘，不會(huì)這么快就超時(shí)的。2011-02-02
這篇文章主要介紹了ASP.NET上傳文件到數(shù)據(jù)庫,先從文字上了解一下上傳文件到數(shù)據(jù)庫的具體步驟，再從代碼上來實(shí)現(xiàn)，需要的朋友可以參考下2015-09-09
Asp.net SignalR創(chuàng)建實(shí)時(shí)聊天應(yīng)用程序
這篇文章主要介紹了Asp.net SignalR創(chuàng)建實(shí)時(shí)聊天應(yīng)用程序,具有一定的參考價(jià)值，感興趣的小伙伴們可以參考一下2016-11-11
解決分頁這個(gè)問題搞了一天半，耗時(shí)巨大，現(xiàn)在總結(jié)一下。2010-06-06
2010-06-06