記一次 .NET醫(yī)院公眾號程序 線程CPU雙高分析
一：背景
1. 講故事
上周四有位朋友加wx咨詢他的程序出現(xiàn) CPU + 線程 雙高的情況，希望我能幫忙排查下，如下圖：
從截圖看只是線程爆高，沒看到 cpu 爆高哈??????，有意思的是這位朋友說他：一直在手動回收 ，不知道為啥看著特別想笑，但笑著笑著就哭了。
可能朋友知道老規(guī)矩，發(fā)了兩份dump過來，接下來我就可以開工了，既然說高峰期分分鐘上千個線程，和我前幾天分享的那篇 串口 的問題很像，肯定是個別線程退不出 鎖，導(dǎo)致 CLR 需要創(chuàng)建更多的線程池線程來應(yīng)付不斷累積的 Work Queue，所以還是得優(yōu)先看 同步塊表，還是那句話，十個人用鎖，八個人用 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 命令可以自動檢索是不是真的有？
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 調(diào)出 53 線程的托管和非托管棧，如下圖：
從上面的調(diào)用棧可以看到，程序用 NLog.Write 寫日志后，最終卡死在 calling ntdll!NtCreateFile 這個 Win32 函數(shù)上 ，我也很驚訝，是不是磁盤寫入速度太低了？馬上問了下朋友是否為 SSD ，朋友說可能不是 ??????，而且朋友還說高峰期半個小時能up到 600M 日志，我想問題應(yīng)該是出在磁盤寫入太慢的根源上了。。。
3. 真的決定讓磁盤背鍋嗎？
把這個答案丟給朋友好像也不太合適，讓朋友換 SSD ？那日志量起來了SSD也扛不住怎么辦？所以言外之意就是：耕田有責(zé)任，耕牛也得負(fù)責(zé)任，那怎么從它身上找責(zé)任呢??? 再回頭看一下這個調(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號線程tmd的不僅要處理業(yè)務(wù)，還要調(diào)用 Win32（用戶態(tài) <-> 內(nèi)核態(tài)） 寫入文件，這量起來了誰受的住？？？
一個高效的日志系統(tǒng)，走的應(yīng)該是 專有線程 + 日志緩沖隊列 的路子，找了下 NLog 的資料，嘿，NLog 還真提供了這種方案。
所以得優(yōu)化一下 NLog 的默認(rèn)配置，貌似這樣就可以結(jié)束本文了，不行，既然都到這里了，我還得找點開發(fā)人員責(zé)任??????。
3. 如何找開發(fā)人員責(zé)任
如果你細(xì)心的話，會不會覺得還漏了點什么？對，就是那個同步塊，卦象上有三條信息，對吧，為了方便查看，我再贅貼一下。
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)呢？接下來把這兩個對象 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() 方法里加了一個鎖，這是有多么不信任 NLog 哈 ??????，還有一點在 WriteLog() 方法中使用了 Task.Run 記錄日志，難怪朋友說分分鐘上千個線程，這回我可是明白了。。。
當(dāng)我以為就這樣吐吐槽就結(jié)束了，不爭氣的我又看了另外一個 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: 另一個程序正在使用此文件，進(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)程占用異常 。。。而且異常堆棧中不就是那個熟悉的文件創(chuàng)建函數(shù) WindowsCreateFile 嗎？？？好吧，好奇心驅(qū)使著我決定要拿到那個文件名，可以切換到 78 號線程，使用 !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程序的多個副本，沒想到都寫一個文件了，這是大忌哈。。。
三：總結(jié)
吐槽了這么多，可能我和朋友都在做涉醫(yī)行業(yè)的業(yè)務(wù)，來自于甲方的壓力還是挺大的??????，最后給出的優(yōu)化措施如下。
修改 NLog 的配置文件，支持
專有線程 + Queue模式，從而釋放業(yè)務(wù)線程。NLog 的寫法和調(diào)用方式太雜亂，需要重新封裝，對外只需提供一個接口即可，用它就要信任它。
有條件提升到 SSD。
最后的彩蛋就是反饋好消息啦??????
又來一個神奇的網(wǎng)站！
人人影視字幕組涼了，這款美劇APP不能錯過！