一：背景
1. 講故事
這個月中旬，有位朋友加我wx求助他的程式執行緒占有率很高，尋求如何解決，截圖如下：
說實話，和不同行業的程式員聊天還是蠻有意思的，廣交朋友，也能擴大自己的圈子，朋友說他因為這個bug還導致專案黃了一個... ??????
哈哈，看樣子是客戶不買賬，驗收不了，害，，，早找到我，這客戶不就撈回來啦，這也許就是技術的價值吧！ ??????
既然找到我，那就讓這個掛死問題徹底消失吧，上windbg說話，
二：Windbg 分析
1. 查看執行緒情況
既然朋友說執行緒高，那就從執行緒入手，用 !t 命令即可，
0:000> !t
ThreadCount: 1006
UnstartedThread: 0
BackgroundThread: 1005
PendingThread: 0
DeadThread: 0
Hosted 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)
可以看到當前有 1006 個執行緒，其中 1000 個是 Threadpool Completion Port，這么多IO執行緒卡死也是第一次遇到，????，
說實話，看到 Threadpool Completion Port 我就想到這是一個異步操作的回呼，那為什么會有這么多IO執行緒被卡死 ? 要想尋找答案，抽個執行緒看一下，
0:1000> ~1000s
ntdll!NtNotifyChangeDirectoryFile+0xa:
00000000`77c7a75a c3 ret
0:1000> !clrstack
OS Thread Id: 0x1704 (1000)
Child SP IP Call Site
00000000A99FF4C0 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\_work\322\s\corefx\src\System.IO.FileSystem.Watcher\src\System\IO\FileSystemWatcher.Win32.cs @ 141]
00000000A99FF5E0 000007fef19dae6c System.IO.FileSystemWatcher.ReadDirectoryChangesCallback(UInt32, UInt32, System.Threading.NativeOverlapped*) [E:\A\_work\322\s\corefx\src\System.IO.FileSystem.Watcher\src\System\IO\FileSystemWatcher.Win32.cs @ 227]
00000000A99FF630 000007feedbe0af9 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [E:\A\_work\191\s\src\mscorlib\shared\System\Threading\ExecutionContext.cs @ 167]
00000000A99FF6B0 000007feede094dc System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*) [E:\A\_work\191\s\src\mscorlib\src\System\Threading\Overlapped.cs @ 108]
00000000A99FF7F0 000007feee359ed3 [GCFrame: 00000000a99ff7f0]
00000000A99FF9D0 000007feee359ed3 [DebuggerU2MCatchHandlerFrame: 00000000a99ff9d0]
我去，又見 FileSystemWatcher ，追這個系列的朋友應該知道，我上個月分析了一篇 記一次 .NET 某流媒體獨角獸 API 句柄泄漏分析 ,這其中就是 FileSystemWatcher 導致的 檔案句柄 爆高，他的形成原因是 定時重繪 appsetttings + reloadOnChange=true 所致，這世界真小，莫不會撞車了，，， 接下來我們重點關注一下它，
2. 探究 FileSystemWatcher
要想進一步分析，先用 !dso 命令看一下當前的執行緒堆疊物件，
0:1000> !dso
OS Thread Id: 0x1704 (1000)
RSP/REG Object Name
00000000A99FF508 00000000263285d8 System.Byte[]
00000000A99FF518 00000000242aeb10 System.Threading._IOCompletionCallback
00000000A99FF560 00000000242ae1b0 Microsoft.Win32.SafeHandles.SafeFileHandle
00000000A99FF568 00000000242aeaa8 System.Threading.PreAllocatedOverlapped
00000000A99FF578 00000000242aeb10 System.Threading._IOCompletionCallback
00000000A99FF5E0 00000000242a8538 System.IO.FileSystemWatcher
00000000A99FF5E8 00000000242aea10 System.IO.FileSystemWatcher+AsyncReadState
00000000A99FF608 00000000242aea10 System.IO.FileSystemWatcher+AsyncReadState
00000000A99FF610 0000000023206e30 System.Threading.ExecutionContext
00000000A99FF618 0000000001032928 System.Threading.ContextCallback
00000000A99FF630 00000000242a8538 System.IO.FileSystemWatcher
00000000A99FF678 00000000b6a69a40 System.Threading.Thread
00000000A99FF688 00000000242aeb10 System.Threading._IOCompletionCallback
00000000A99FF690 0000000023206e30 System.Threading.ExecutionContext
00000000A99FF6C0 0000000021fa55d8 System.Threading._IOCompletionCallback
00000000A99FF6C8 000000002052e6e0 System.Threading.ExecutionContext
00000000A99FF7E0 000000000560d2b0 System.Threading.OverlappedData
由于執行緒堆疊上的物件是向小擴展的，所以看那個最小地址上的 System.Byte[] 內容就知道當前回呼的是啥啦，截圖如下：
經過上一役的分析經驗，到這里我基本就搞清楚了，這又是一個不斷構建 ConfigurationRoot 時配了 reloadOnChange: true 的經典案例，它的后果會導致記憶體中新增大量的 FileSystemWatcher 和 ConfigurationRoot 無法釋放，而誘發點就是上圖中的日志檔案的不斷變更導致的海量回呼函式觸發的卡死案例，具體詳情... 請聽我慢慢分解，先驗證下這兩個類在托管堆上的個數，
0:1000> !dumpheap -stat -type FileSystemWatcher
Statistics:
MT Count TotalSize Class Name
000007fe8ed5bc90 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+AsyncReadState
000007fe8e9d69c8 34480 4137600 System.IO.FileSystemWatcher
Total 68962 objects
0:1000> !dumpheap -stat -type ConfigurationRoot
Statistics:
MT Count TotalSize Class Name
000007fe8e9f1e70 34480 827520 Microsoft.Extensions.Configuration.ConfigurationRoot+<>c__DisplayClass2_0
000007fe8e999560 34480 1103360 Microsoft.Extensions.Configuration.ConfigurationRoot
Total 68960 objects
果不其然，托管堆有 3.4w 的 FileSystemWatcher 和 ConfigurationRoot，接下來就得和朋友溝通了，
3. 到底是什么代碼引起的?
詢問朋友為什么會有 3.4w 的 ConfigurationRoot 物件，理論上一個程式只會有一個，根據這些資訊，朋友很快就找到了問題代碼，截圖如下：
就是因為上圖中的 reloadOnChange: true 讓底層構建了 FileSystemWatcher 對 appsettings.json 的實時監控，從而導致記憶體出現了 3.4w 的物件無法釋放，
三：為什么日志變更會造成程式卡死
1. 當初的困惑
其實我當初分析到這里的時候也是很困惑的，就算記憶體中有 3.4w 的 FileSystemWatcher，那也只是對 appsettings.json 的監控，只要這個檔案不變動就不會觸發 3.4w 的回呼，不是嗎？ 可當我分析完 ConfigurationRoot 原始碼之后，我發現自己真tmd的天真，
2. 從原始碼中尋找答案
首先我們看看 FileSystemWatcher 到底監控的是啥？ 可以在它的建構式中設一個斷點，如下圖所示：
很明顯的看到，它 watch 的是程式根目錄，這就能解釋為什么日志檔案有變更就會觸發檔案變更的回呼函式，為了驗證，我可以在 ReadDirectoryChangesCallback 方法中下一個斷點，再丟一個日志檔案到根目錄，看是否能觸發就知道了，，， 截圖如下：
回到本案例，也就是說一旦有日志變動，就會觸發 3.4w 個回呼函式，如果變動100次，就會觸發 340w 次回呼，而日志變更不停止，自然就會因為海量的回呼把程式搞死，，，對吧，，，
四：總結
本次事故可能是由于朋友偷懶，沒有將 Configuration 或 IOptions 注下去，而是采用重新構建 ConfigurationRoot 的方式獲取 ConnectionString，并錯誤的配置 reloadOnChange: true， 導致IO執行緒無法及時處理由于日志檔案的變更導致的海量回呼函式，進而導致程式掛死，
知道整個來龍去脈之后，優化措施就很簡單了，提供兩種方法，
-
將
reloadOnChange: true改成reloadOnChange: false， -
想辦法將 Configuration 注入到 DataBaseConfig 類中，做成靜態變數也行 ，??????
最后上一個彩蛋，朋友太客氣了，
轉載請註明出處，本文鏈接：https://www.uj5u.com/net/304133.html
標籤：C#
上一篇：Consul+Ocelot+Polly在.NetCore中使用(.NET5)-Ocelot+Polly快取、限流、熔斷、降級