記一次 .NET醫(yī)院公眾號(hào)程序 線程CPU雙高分析

一：背景

1. 講故事

上周四有位朋友加wx咨詢(xún)他的程序出現(xiàn) CPU + 線程 雙高的情況，希望我能幫忙排查下，如下圖：

從截圖看只是線程爆高，沒(méi)看到 cpu 爆高哈??????，有意思的是這位朋友說(shuō)他：一直在手動(dòng)回收 ，不知道為啥看著特別想笑，但笑著笑著就哭了。

可能朋友知道老規(guī)矩，發(fā)了兩份dump過(guò)來(lái)，接下來(lái)我就可以開(kāi)工了，既然說(shuō)高峰期分分鐘上千個(gè)線程，和我前幾天分享的那篇 串口 的問(wèn)題很像，肯定是個(gè)別線程退不出 鎖，導(dǎo)致 CLR 需要?jiǎng)?chuàng)建更多的線程池線程來(lái)應(yīng)付不斷累積的 Work Queue，所以還是得優(yōu)先看 同步塊表，還是那句話，十個(gè)人用鎖，八個(gè)人用 lock ??????。

二：windbg 分析

1. 查找 CLR 同步塊表

可以用 !syncblk 看看有沒(méi)有 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)了超過(guò)正常指標(biāo)的持有鎖值：193，107，13，但直覺(jué)更告訴我，是不是死鎖啦？？？用 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.

從最后一行看沒(méi)有任何 deadlocks，看樣子我的直覺(jué)是錯(cuò)的??????。

只能回頭看那最高的 193 ，表示有 1 個(gè)線程持有鎖 (53號(hào)線程)，96個(gè)線程等待鎖，確定了是 lock 的問(wèn)題就好辦了，查看它的線程棧就好啦。

2. 查看線程棧

為了穩(wěn)一點(diǎn)，我就用 !dumpstack 調(diào)出 53 線程的托管和非托管棧，如下圖：

從上面的調(diào)用?？梢钥吹?，程序用 NLog.Write 寫(xiě)日志后，最終卡死在 calling ntdll!NtCreateFile 這個(gè) Win32 函數(shù)上 ，我也很驚訝，是不是磁盤(pán)寫(xiě)入速度太低了？馬上問(wèn)了下朋友是否為 SSD ，朋友說(shuō)可能不是 ??????，而且朋友還說(shuō)高峰期半個(gè)小時(shí)能up到 600M 日志，我想問(wèn)題應(yīng)該是出在磁盤(pán)寫(xiě)入太慢的根源上了。。。

3. 真的決定讓磁盤(pán)背鍋嗎？

把這個(gè)答案丟給朋友好像也不太合適，讓朋友換 SSD ？那日志量起來(lái)了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)

不知道你有沒(méi)有發(fā)現(xiàn)，53號(hào)線程tmd的不僅要處理業(yè)務(wù)，還要調(diào)用 Win32（用戶(hù)態(tài) <-> 內(nèi)核態(tài)） 寫(xiě)入文件，這量起來(lái)了誰(shuí)受的??？？？

一個(gè)高效的日志系統(tǒng)，走的應(yīng)該是 專(zhuān)有線程 + 日志緩沖隊(duì)列  的路子，找了下 NLog 的資料，嘿，NLog 還真提供了這種方案。

所以得優(yōu)化一下 NLog 的默認(rèn)配置，貌似這樣就可以結(jié)束本文了，不行，既然都到這里了，我還得找點(diǎn)開(kāi)發(fā)人員責(zé)任??????。

3. 如何找開(kāi)發(fā)人員責(zé)任

如果你細(xì)心的話，會(huì)不會(huì)覺(jué)得還漏了點(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)呢？接下來(lái)把這兩個(gè)對(duì)象 0000025e2a8ded70, 00000260ea8a9b00 的源碼導(dǎo)出來(lái),可以用 !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 打開(kāi) 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 記錄日志，難怪朋友說(shuō)分分鐘上千個(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)程無(wú)法訪問(wèn)。 (異常來(lái)自 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

還記得文章開(kāi)頭第二張截圖嗎？朋友開(kāi)了WebService程序的多個(gè)副本，沒(méi)想到都寫(xiě)一個(gè)文件了，這是大忌哈。。。

三：總結(jié)

吐槽了這么多，可能我和朋友都在做涉醫(yī)行業(yè)的業(yè)務(wù)，來(lái)自于甲方的壓力還是挺大的??????，最后給出的優(yōu)化措施如下。

• 修改 NLog 的配置文件，支持 專(zhuān)有線程 + Queue 模式，從而釋放業(yè)務(wù)線程。

• NLog 的寫(xiě)法和調(diào)用方式太雜亂，需要重新封裝，對(duì)外只需提供一個(gè)接口即可，用它就要信任它。

• 有條件提升到 SSD。

最后的彩蛋就是反饋好消息啦??????