记一次医院.NET公众号系统线程CPU双高分析

一：背景

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 线程的托管和非托管栈，如下图：

记一次医院.NET公众号系统线程CPU双高分析

从上面的调用栈可以看到，程序用 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 还真提供了这种方案。

记一次医院.NET公众号系统线程CPU双高分析

所以得优化一下 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程序的多个副本，没想到都写一个文件了，这是大忌哈。。。