記一次 .NET醫院公眾號系統 執行緒CPU雙高分析

一線碼農發表於2021-04-25
執行緒

一：背景

1. 講故事

上週四有位朋友加wx諮詢他的程式出現 CPU + 執行緒 雙高的情況，希望我能幫忙排查下，如下圖：

從截圖看只是執行緒爆高，沒看到 cpu 爆高哈???，有意思的是這位朋友說他： 一直在手動回收 ，不知道為啥看著特別想笑，但笑著笑著就哭了。

可能朋友知道老規矩，發了兩份dump過來，接下來我就可以開工了，既然說高峰期分分鐘上千個執行緒，和我前幾天分享的那篇 串列埠 的問題很像，肯定是個別執行緒退不出 鎖，導致 CLR 需要建立更多的執行緒池執行緒來應付不斷累積的 Work Queue，所以還是得優先看 同步塊表，還是那句話，十個人用鎖，八個人用 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

雖然卦象上出現了超過正常指標的持有鎖值：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. 檢視執行緒棧

為了穩一點，我就用 !dumpstack 調出 53 執行緒的託管和非託管棧，如下圖：

從上面的呼叫棧可以看到，程式用 NLog.Write 寫日誌後，最終卡死在 calling ntdll!NtCreateFile 這個 Win32 函式上 ，我也很驚訝，是不是磁碟寫入速度太低了？ 馬上問了下朋友是否為 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)

不知道你有沒有發現，53號執行緒tmd的不僅要處理業務，還要呼叫 Win32（使用者態 <-> 核心態） 寫入檔案，這量起來了誰受的住？？？

一個高效的日誌系統，走的應該是 專有執行緒 + 日誌緩衝佇列 的路子，找了下 NLog 的資料，嘿，NLog 還真提供了這種方案。

所以得優化一下 NLog 的預設配置，貌似這樣就可以結束本文了，不行，既然都到這裡了，我還得找點開發人員責任???。

3. 如何找開發人員責任

如果你細心的話，會不會覺得還漏了點什麼？ 對，就是那個同步塊，卦象上有三條資訊，對吧，為了方便檢視，我再贅貼一下。


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 相關，那怎麼 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 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 後，發現了那段有趣的 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:   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:          另一個程式正在使用此檔案，程式無法訪問。 (異常來自 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

竟然還有 程式佔用異常 。。。而且異常堆疊中不就是那個熟悉的檔案建立函式 WindowsCreateFile 嗎？？？ 好吧，好奇心驅使著我決定要拿到那個檔名，可以切換到 78 號執行緒，使用 !clrstack -a 調出引數和區域性變數，找到最後的 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程式的多個副本，沒想到都寫一個檔案了，這是大忌哈。。。

三：總結

吐槽了這麼多，可能我和朋友都在做涉醫行業的業務，來自於甲方的壓力還是挺大的???，最後給出的優化措施如下。

  • 修改 NLog 的配置檔案，支援 專有執行緒 + Queue 模式，從而釋放業務執行緒。

  • NLog 的寫法和呼叫方式太雜亂，需要重新封裝，對外只需提供一個介面即可，用它就要信任它。

  • 有條件提升到 SSD。

最後的彩蛋就是反饋好訊息啦???

更多高質量乾貨：參見我的 GitHub: dotnetfly

圖片名稱

相關文章