一：背景 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 还真提供了这种方案。
