一：背景

1. 講故事

這個(gè)月中旬，有位朋友加我wx求助他的程序線程占有率很高，尋求如何解決，截圖如下：

說(shuō)實(shí)話，和不同行業(yè)的程序員聊天還是蠻有意思的，廣交朋友，也能擴(kuò)大自己的圈子，朋友說(shuō)他因?yàn)檫@個(gè)bug還導(dǎo)致項(xiàng)目黃了一個(gè)…

哈哈，看樣子是客戶不買(mǎi)賬，驗(yàn)收不了，害。。。早找到我，這客戶不就撈回來(lái)啦，這也許就是技術(shù)的價(jià)值吧！

既然找到我，那就讓這個(gè)掛死問(wèn)題徹底消失吧，上windbg說(shuō)話。

二：Windbg 分析

1. 查看線程情況

既然朋友說(shuō)線程高，那就從線程入手，用 !t 命令即可。

0:000> !tThreadCount: 1006UnstartedThread: 0BackgroundThread: 1005PendingThread: 0DeadThread: 0Hosted Runtime: no Lock DBG ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception 0 1 10c8 00000000004D89A0 2a020 Preemptive 0000000000000000:0000000000000000 00000000002f1070 0 MTA 2 2 13c0 000000000031FF70 2b220 Preemptive 0000000000000000:0000000000000000 00000000002f1070 0 MTA (Finalizer) 3 3 12cc 000000000032B780 102a220 Preemptive 0000000000000000:0000000000000000 00000000002f1070 0 MTA (Threadpool Worker) 4 5 138c 000000000039E3C0 8029220 Preemptive 00000000B6D3CCA0:00000000B6D3D260 00000000002f1070 0 MTA (Threadpool Completion Port) 6 6 106c 0000000019E562A0 3029220 Preemptive 0000000000000000:0000000000000000 00000000002f1070 0 MTA (Threadpool Worker) 8 11 7f0 0000000019F8F9E0 20220 Preemptive 0000000000000000:0000000000000000 00000000002f1070 0 Ukn 9 1949 323c 000000009AA69E40 8029220 Preemptive 00000000B6BB8AD0:00000000B6BB94E0 00000000002f1070 0 MTA (Threadpool Completion Port) 10 1637 b3c 000000009AA1C260 8029220 Preemptive 00000000B6CD4220:00000000B6CD47E0 00000000002f1070 0 MTA (Threadpool Completion Port) 11 1947 223c 000000009ADB72E0 8029220 Preemptive 00000000B6D88D68:00000000B6D89550 00000000002f1070 0 MTA (Threadpool Completion Port) 12 1968 2e74 000000009AA1E330 8029220 Preemptive 00000000B6A8CD40:00000000B6A8D300 00000000002f1070 0 MTA (Threadpool Completion Port) ... 994 313 1fa4 000000009A81FFC0 8029220 Preemptive 00000000B6BFC1B8:00000000B6BFC410 00000000002f1070 0 MTA (Threadpool Completion Port) 995 1564 18ec 000000009A835510 8029220 Preemptive 00000000B6AC1ED0:00000000B6AC2490 00000000002f1070 0 MTA (Threadpool Completion Port) 996 1581 4ac 000000001C2E36E0 8029220 Preemptive 00000000B6C51500:00000000B6C51AC0 00000000002f1070 0 MTA (Threadpool Completion Port) 997 814 2acc 000000009A73B5E0 8029220 Preemptive 00000000B6D67BF8:00000000B6D683E0 00000000002f1070 0 MTA (Threadpool Completion Port) 998 517 25dc 000000009A838990 8029220 Preemptive 00000000B6D2CA10:00000000B6D2CFD0 00000000002f1070 0 MTA (Threadpool Completion Port) 999 670 2a10 000000001C2E4400 8029220 Preemptive 00000000B6CD0490:00000000B6CD0A50 00000000002f1070 0 MTA (Threadpool Completion Port) 1000 183 1704 000000009A81F930 8029220 Preemptive 00000000B6AE8670:00000000B6AE8C30 00000000002f1070 0 MTA (Threadpool Completion Port) 1001 117 1bcc 000000009A73BC70 8029220 Preemptive 00000000B6B92780:00000000B6B92D40 00000000002f1070 0 MTA (Threadpool Completion Port) 1002 1855 1d68 000000009A81E580 8029220 Preemptive 00000000B6B28460:00000000B6B28A20 00000000002f1070 0 MTA (Threadpool Completion Port) 1003 1070 2ef0 000000009A73C300 8029220 Preemptive 00000000B6B8F640:00000000B6B8FC00 00000000002f1070 0 MTA (Threadpool Completion Port) 1004 1429 210c 000000001C2E4A90 8029220 Preemptive 00000000B6D5F488:00000000B6D5FC70 00000000002f1070 0 MTA (Threadpool Completion Port) 1005 1252 2f38 000000009A838300 8029220 Preemptive 00000000B6A99240:00000000B6A99800 00000000002f1070 0 MTA (Threadpool Completion Port) 1006 1317 3118 000000001C2E5120 8029220 Preemptive 00000000B6DA3A30:00000000B6DA4440 00000000002f1070 0 MTA (Threadpool Completion Port) 1007 1837 3120 000000009A8375E0 8029220 Preemptive 00000000B6D38F10:00000000B6D394D0 00000000002f1070 0 MTA (Threadpool Completion Port) 1009 1964 2f64 000000009A81DEF0 1029220 Preemptive 0000000000000000:0000000000000000 00000000002f1070 0 MTA (Threadpool Worker)

可以看到當(dāng)前有 1006 個(gè)線程，其中 1000 個(gè)是 Threadpool Completion Port，這么多IO線程卡死也是第一次遇到，。

說(shuō)實(shí)話，看到 Threadpool Completion Port 我就想到這是一個(gè)異步操作的回調(diào)，那為什么會(huì)有這么多IO線程被卡死 ? 要想尋找答案，抽個(gè)線程看一下。

0:1000> ~1000sntdll!NtNotifyChangeDirectoryFile 0xa:00000000`77c7a75a c3 ret0:1000> !clrstack OS Thread Id: 0x1704 (1000) Child SP IP Call Site00000000A99FF4C0 0000000077c7a75a [InlinedCallFrame: 00000000a99ff4c0] Interop Kernel32.ReadDirectoryChangesW(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte[], Int32, Boolean, Int32, Int32 ByRef, System.Threading.NativeOverlapped*, IntPtr)00000000A99FF4C0 000007fe8e87bd20 [InlinedCallFrame: 00000000a99ff4c0] Interop Kernel32.ReadDirectoryChangesW(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte[], Int32, Boolean, Int32, Int32 ByRef, System.Threading.NativeOverlapped*, IntPtr)00000000A99FF470 000007fe8e87bd20 DomainBoundILStubClass.IL_STUB_PInvoke(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte[], Int32, Boolean, Int32, Int32 ByRef, System.Threading.NativeOverlapped*, IntPtr)00000000A99FF560 000007fef19dab6e System.IO.FileSystemWatcher.Monitor(AsyncReadState) [E:A_work322scorefxsrcSystem.IO.FileSystem.WatchersrcSystemIOFileSystemWatcher.Win32.cs @ 141]00000000A99FF5E0 000007fef19dae6c System.IO.FileSystemWatcher.ReadDirectoryChangesCallback(UInt32, UInt32, System.Threading.NativeOverlapped*) [E:A_work322scorefxsrcSystem.IO.FileSystem.WatchersrcSystemIOFileSystemWatcher.Win32.cs @ 227]00000000A99FF630 000007feedbe0af9 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [E:A_work191ssrcmscorlibsharedSystemThreadingExecutionContext.cs @ 167]00000000A99FF6B0 000007feede094dc System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*) [E:A_work191ssrcmscorlibsrcSystemThreadingOverlapped.cs @ 108]00000000A99FF7F0 000007feee359ed3 [GCFrame: 00000000a99ff7f0] 00000000A99FF9D0 000007feee359ed3 [DebuggerU2MCatchHandlerFrame: 00000000a99ff9d0]

我去，又見(jiàn) FileSystemWatcher ，追這個(gè)系列的朋友應(yīng)該知道，我上個(gè)月分析了一篇 記一次 .NET 某流媒體獨(dú)角獸 API 句柄泄漏分析 ,這其中就是 FileSystemWatcher 導(dǎo)致的 文件句柄 爆高，他的形成原因是 定時(shí)刷新 appsetttings reloadOnChange=true 所致，這世界真小，莫不會(huì)撞車(chē)了。。。 接下來(lái)我們重點(diǎn)關(guān)注一下它。

2. 探究 FileSystemWatcher

要想進(jìn)一步分析，先用 !dso 命令看一下當(dāng)前的線程棧對(duì)象。

0:1000> !dsoOS Thread Id: 0x1704 (1000)RSP/REG Object Name00000000A99FF508 00000000263285d8 System.Byte[]00000000A99FF518 00000000242aeb10 System.Threading._IOCompletionCallback00000000A99FF560 00000000242ae1b0 Microsoft.Win32.SafeHandles.SafeFileHandle00000000A99FF568 00000000242aeaa8 System.Threading.PreAllocatedOverlapped00000000A99FF578 00000000242aeb10 System.Threading._IOCompletionCallback00000000A99FF5E0 00000000242a8538 System.IO.FileSystemWatcher00000000A99FF5E8 00000000242aea10 System.IO.FileSystemWatcher AsyncReadState00000000A99FF608 00000000242aea10 System.IO.FileSystemWatcher AsyncReadState00000000A99FF610 0000000023206e30 System.Threading.ExecutionContext00000000A99FF618 0000000001032928 System.Threading.ContextCallback00000000A99FF630 00000000242a8538 System.IO.FileSystemWatcher00000000A99FF678 00000000b6a69a40 System.Threading.Thread00000000A99FF688 00000000242aeb10 System.Threading._IOCompletionCallback00000000A99FF690 0000000023206e30 System.Threading.ExecutionContext00000000A99FF6C0 0000000021fa55d8 System.Threading._IOCompletionCallback00000000A99FF6C8 000000002052e6e0 System.Threading.ExecutionContext00000000A99FF7E0 000000000560d2b0 System.Threading.OverlappedData

由于線程棧上的對(duì)象是向小擴(kuò)展的，所以看那個(gè)最小地址上的 System.Byte[] 內(nèi)容就知道當(dāng)前回調(diào)的是啥啦，截圖如下：

經(jīng)過(guò)上一役的分析經(jīng)驗(yàn)，到這里我基本就搞清楚了，這又是一個(gè)不斷構(gòu)建 ConfigurationRoot 時(shí)配了 reloadOnChange: true 的經(jīng)典案例，它的后果會(huì)導(dǎo)致內(nèi)存中新增大量的 FileSystemWatcher 和 ConfigurationRoot 無(wú)法釋放，而誘發(fā)點(diǎn)就是上圖中的日志文件的不斷變更導(dǎo)致的海量回調(diào)函數(shù)觸發(fā)的卡死案例，具體詳情… 請(qǐng)聽(tīng)我慢慢分解，先驗(yàn)證下這兩個(gè)類(lèi)在托管堆上的個(gè)數(shù)。

0:1000> !dumpheap -stat -type FileSystemWatcherStatistics: MT Count TotalSize Class Name000007fe8ed5bc90 2 160 System.Collections.Generic.Dictionary`2[[System.String, System.Private.CoreLib],[System.IO.FileSystemWatcher, System.IO.FileSystem.Watcher]]000007fe8e9f11a0 34480 1930880 System.IO.FileSystemWatcher AsyncReadState000007fe8e9d69c8 34480 4137600 System.IO.FileSystemWatcherTotal 68962 objects0:1000> !dumpheap -stat -type ConfigurationRootStatistics: MT Count TotalSize Class Name000007fe8e9f1e70 34480 827520 Microsoft.Extensions.Configuration.ConfigurationRoot <>c__DisplayClass2_0000007fe8e999560 34480 1103360 Microsoft.Extensions.Configuration.ConfigurationRootTotal 68960 objects

果不其然，托管堆有 3.4w 的 FileSystemWatcher 和 ConfigurationRoot，接下來(lái)就得和朋友溝通了。

3. 到底是什么代碼引起的?

詢問(wèn)朋友為什么會(huì)有 3.4w 的 ConfigurationRoot 對(duì)象，理論上一個(gè)程序只會(huì)有一個(gè)，根據(jù)這些信息，朋友很快就找到了問(wèn)題代碼，截圖如下：

就是因?yàn)樯蠄D中的 reloadOnChange: true 讓底層構(gòu)建了 FileSystemWatcher 對(duì) appsettings.json 的實(shí)時(shí)監(jiān)控，從而導(dǎo)致內(nèi)存出現(xiàn)了 3.4w 的對(duì)象無(wú)法釋放。

三：為什么日志變更會(huì)造成程序卡死

1. 當(dāng)初的困惑

其實(shí)我當(dāng)初分析到這里的時(shí)候也是很困惑的，就算內(nèi)存中有 3.4w 的 FileSystemWatcher，那也只是對(duì) appsettings.json 的監(jiān)控，只要這個(gè)文件不變動(dòng)就不會(huì)觸發(fā) 3.4w 的回調(diào)，不是嗎？ 可當(dāng)我分析完 ConfigurationRoot 源碼之后，我發(fā)現(xiàn)自己真tmd的天真。

2. 從源碼中尋找答案

首先我們看看 FileSystemWatcher 到底監(jiān)控的是啥？ 可以在它的構(gòu)造函數(shù)中設(shè)一個(gè)斷點(diǎn)，如下圖所示：

很明顯的看到，它 watch 的是程序根目錄，這就能解釋為什么日志文件有變更就會(huì)觸發(fā)文件變更的回調(diào)函數(shù)，為了驗(yàn)證，我可以在 ReadDirectoryChangesCallback 方法中下一個(gè)斷點(diǎn)，再丟一個(gè)日志文件到根目錄，看是否能觸發(fā)就知道了。。。 截圖如下：

回到本案例，也就是說(shuō)一旦有日志變動(dòng)，就會(huì)觸發(fā) 3.4w 個(gè)回調(diào)函數(shù)，如果變動(dòng)100次，就會(huì)觸發(fā) 340w 次回調(diào)，而日志變更不停止，自然就會(huì)因?yàn)楹Ａ康幕卣{(diào)把程序搞死。。。對(duì)吧。。。

四：總結(jié)

本次事故可能是由于朋友偷懶，沒(méi)有將 Configuration 或 IOptions 注下去，而是采用重新構(gòu)建 ConfigurationRoot 的方式獲取 ConnectionString，并錯(cuò)誤的配置 reloadOnChange: true， 導(dǎo)致IO線程無(wú)法及時(shí)處理由于日志文件的變更導(dǎo)致的海量回調(diào)函數(shù)，進(jìn)而導(dǎo)致程序掛死。

知道整個(gè)來(lái)龍去脈之后，優(yōu)化措施就很簡(jiǎn)單了，提供兩種方法。

1. 將 reloadOnChange: true 改成 reloadOnChange: false 。
2. 想辦法將 Configuration 注入到 DataBaseConfig 類(lèi)中，做成靜態(tài)變量也行 。

最后上一個(gè)彩蛋，朋友太客氣了。