共计 8422 个字符，预计需要花费 22 分钟才能阅读完成。
一：背景
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
正文完
