記一次 醫院.NET公衆號系統 線程CPU雙高分析

時間  2021-04-25
標籤 git github dom 函數 優化 this spa 線程 3d 日誌 欄目 Git 简体版
原文   原文鏈接

一：背景

1. 講故事

上週四有位朋友加wx諮詢他的程序出現 CPU + 線程 雙高的狀況，但願我能幫忙排查下，以下圖：git

從截圖看只是線程爆高，沒看到 cpu 爆高哈😂😂😂，有意思的是這位朋友說他： 一直在手動回收 ，不知道爲啥看着特別想笑，但笑着笑着就哭了。github

可能朋友知道老規矩，發了兩份dump過來，接下來我就能夠開工了，既然說高峯期分分鐘上千個線程，和我前幾天分享的那篇 串口 的問題很像，確定是個別線程退不出 鎖，致使 CLR 須要建立更多的線程池線程來應付不斷累積的 Work Queue，因此仍是得優先看 同步塊表，仍是那句話，十我的用鎖，八我的用 lock 🤣🤣🤣。dom

二： 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，看樣子個人直覺是錯的😤😤😤。this

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

2. 查看線程棧

爲了穩一點，我就用 !dumpstack 調出 53 線程的託管和非託管棧，以下圖：線程

從上面的調用棧能夠看到，程序用 NLog.Write 寫日誌後，最終卡死在 calling ntdll!NtCreateFile 這個 Win32 函數上 ，我也很驚訝，是否是磁盤寫入速度過低了？ 立刻問了下朋友是否爲 SSD ，朋友說可能不是 😂😂😂，並且朋友還說高峯期半個小時能up到 600M 日誌，我想問題應該是出在磁盤寫入太慢的根源上了。。。3d

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

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程