記一次 .NET 某工廠無人車調(diào)度系統(tǒng) 線程爆高分析
一：背景
1. 講故事
前些天有位朋友找到我，說他程序中的線程數(shù)爆高，讓我?guī)兔聪略趺椿厥?，這種線程數(shù)爆高的情況找問題相對比較容易，就讓朋友丟一個dump給我，看看便知。
二：為什么會爆高
1. 查看托管線程
別人說的話不一定是真，得自己拿數(shù)據(jù)出來說話，可以用 !t 命令觀察一下便知。
0:000> !t
ThreadCount: 4683
UnstartedThread: 0
BackgroundThread: 4663
PendingThread: 0
DeadThread: 19
Hosted Runtime: no
Lock
DBG ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 cc44 00000268048778C0 202a020 Preemptive 0000000000000000:0000000000000000 00000268048c6d50 -00001 MTA
...
4670 4679 51bc 0000026D143F0420 302b220 Preemptive 0000000000000000:0000000000000000 00000268048c6d50 -00001 MTA (Threadpool Worker)
4671 4680 3a68 0000026D143F52E0 302b220 Preemptive 0000000000000000:0000000000000000 00000268048c6d50 -00001 MTA (Threadpool Worker)
4672 4681 337c 0000026D143F1140 302b220 Preemptive 0000026A88AAF5B8:0000026A88AB08D0 00000268048c6d50 -00001 MTA (Threadpool Worker)
4673 4682 188d4 0000026D143F0AB0 302b220 Preemptive 000002698881A760:000002698881C0B8 00000268048c6d50 -00001 MTA (Threadpool Worker)
4674 4683 4bcc 0000026D143EF700 302b220 Preemptive 0000026B889C4488:0000026B889C5E18 00000268048c6d50 -00001 MTA (Threadpool Worker)從卦中信息看確實有 4600+ 的線程，說明確實存在問題，接下來用 ~*e !clrstack 觀察每一個線程都在做什么，線程太多沒法全部輸出完畢，不過很容易的看到有大量的線程卡在 RoutingService.Push 上，截圖如下：
圖片
接下來就是觀察下這個 Push 方法的邏輯，發(fā)現(xiàn)卡死在 Result 上，整理后的代碼大概如下：
private readonly SemaphoreSlim slim = new SemaphoreSlim(1, 1);
public void Push(string xxx, xxx xxx)
{
int num = (xxx.Serial = GetSerial().Result);
}
private async Task<int> GetSerial()
{
await slim.WaitAsync();
try
{
Interlocked.Increment(ref serial);
}
finally
{
slim.Release();
}
return serial;
}上面的代碼看起來挺奇葩的，為什么 GetSerial() 中不直接用 Interlocked.Increment() 呢？套一個 SemaphoreSlim 顯得非常多余。
先不管多余不多余，既然 Result 得不到值，就說明這個異步方法得不到完成，那為什么得不到完成呢？
2. 為什么異步得不到完成
熟悉 SemaphoreSlim.WaitAsync() 的朋友應該知道，這里涉及不到異步IO，所以這個是假異步，本質(zhì)上就是動態(tài)生成了一個串聯(lián)的 Task<bool>，要想知道得不到完成的根本原因，還得要挖一挖此時的 slim 信號量情況。
0:000> !do 000002690664b5a0
Name: System.Threading.SemaphoreSlim
MethodTable: 00007ff894e56fc0
EEClass: 00007ff894e3f230
Tracked Type: false
Size: 64(0x40) bytes
File: D:\xxx\System.Private.CoreLib.dll
Fields:
MT Field Offset Type VT Attr Value Name
00007ff8948094b0 4000c2e 28 System.Int32 1 instance 0 m_currentCount
00007ff8948094b0 4000c2f 2c System.Int32 1 instance 1 m_maxCount
00007ff8948094b0 4000c30 30 System.Int32 1 instance 0 m_waitCount
00007ff8948094b0 4000c31 34 System.Int32 1 instance 0 m_countOfWaitersPulsedToWake
00007ff8962871e0 4000c32 8 ...Private.CoreLib]] 0 instance 000002690664b5e0 m_lockObjAndDisposed
00007ff894e555f0 4000c33 10 ....ManualResetEvent 0 instance 0000000000000000 m_waitHandle
00007ff894e57870 4000c34 18 ...horeSlim+TaskNode 0 instance 0000026b86919a30 m_asyncHead
00007ff894e57870 4000c35 20 ...horeSlim+TaskNode 0 instance 0000026b889c4378 m_asyncTail
00007ff894a4a1f0 4000c36 888 ...Private.CoreLib]] 0 static 00000268864f83a0 s_cancellationTokenCanceledEventHandler從卦中看當前的 m_currentCount=0，表明當前的信號量被消費完了，所以其他的線程都在等待就能很好理解，接下來的問題是那個從 1->0 的持有線程為什么不歸還？這個就比較難搞了，可以從如下兩個思路思考：
- 觀察 Result
首先懷疑是不是 Result 引發(fā)的死鎖，用 !eeversion 看了下是 asp.net core ，并沒有所謂的同步上下文，所以這個問題不存在。
0:000> !eeversion
6.0.2023.32017 free
6,0,2023,32017 @Commit: a08d9ce2caf02455c0b825bcdc32974bdf769a80
Server mode with 8 gc heaps
SOS Version: 7.0.8.30602 retail build- 觀察代碼
因為 SemaphoreSlim 并不記錄持有線程，windbg 在這里就起不到很好的效果，不過仔細閱讀代碼，發(fā)現(xiàn)應該將 await slim.WaitAsync(); 放到 try 中更合理一點，否則無法保證 WaitAsync 和 Release 一定是成雙成對的，截圖如下：
圖片
3. 什么時候開始阻塞的
仔細觀察這個 GetSerial 方法，看看里面的 serial 值就知道大概是進行到哪一步才出的問題。
0:4674> !DumpObj /d 000002690664b258
Name: xxx.RoutingService
MethodTable: 00007ff895283ed0
EEClass: 00007ff89526ae08
Tracked Type: false
Size: 112(0x70) bytes
File: D:\xxx\xxx.dll
Fields:
MT Field Offset Type VT Attr Value Name
...
00007ff894e56fc0 4000214 48 ...ing.SemaphoreSlim 0 instance 000002690664b5a0 slim
00007ff8948094b0 4000215 60 System.Int32 1 instance 9061 serial從卦中看已經(jīng)自增到了 9061 ，然后因為某種原因?qū)е聎ait 和 release 不匹配了，像這種情況線程池也會有大量的任務積壓，可以用 !tp 觀察下。
0:4674> !tp
logStart: 33
logSize: 200
CPU utilization: 22 %
Worker Thread: Total: 4652 Running: 4652 Idle: 0 MaxLimit: 32767 MinLimit: 8
Work Request in Queue: 0
--------------------------------------
Number of Timers: 1
--------------------------------------
Completion Port Thread:Total: 2 Free: 2 MaxFree: 16 CurrentLimit: 2 MaxLimit: 1000 MinLimit: 8細心的朋友會發(fā)現(xiàn)這里的 Work Request in Queue: 0 ，既然是 0 何來積壓？其實這是 sos 的bug，我們需要自己到線程池隊列中提取，從當前的線程棧上尋找 ThreadPoolWorkQueue 對象即可。
0:4674> !dso
OS Thread Id: 0x4bcc (4674)
000000EF384FF5C8 0000026b06544848 System.Threading.ThreadPoolWorkQueue
0:4674> !DumpObj /d 0000026b06544848
Name: System.Threading.ThreadPoolWorkQueue
MethodTable: 00007ff894e59d80
EEClass: 00007ff894ee01d0
Tracked Type: false
Size: 168(0xa8) bytes
File: D:\xxx\System.Private.CoreLib.dll
Fields:
MT Field Offset Type VT Attr Value Name
00007ff89476bf38 4000c61 18 System.Boolean 1 instance 0 loggingEnabled
00007ff89476bf38 4000c62 19 System.Boolean 1 instance 0 _dispatchTimeSensitiveWorkFirst
00007ff89637fc20 4000c63 8 ...Private.CoreLib]] 0 instance 0000026b065448f0 workItems
00007ff89637fe00 4000c64 10 ...Private.CoreLib]] 0 instance 0000026b06544930 timeSensitiveWorkQueue
00007ff894e59d10 4000c65 20 ...acheLineSeparated 1 instance 0000026b06544868 _separated
0:4674> !ext dcq 0000026b065448f0
System.Collections.Concurrent.ConcurrentQueue<System.Object>
1 - dumpobj 0x0000026806c782f8
...
119419 - dumpobj 0x000002690a097658
119420 - dumpobj 0x000002690a097810
119421 - dumpobj 0x000002690a0981a8
---------------------------------------------
119421 items從卦中可以看到大概有12w的積壓。上面就是我的完整分析思路，最后就是告訴朋友最好的辦法就是去掉多余累贅的 SemaphoreSlim ，直接用同步的方式執(zhí)行 Interlocked.Increment(ref serial) 即可，簡單粗暴。
三：總結(jié)
這次線程爆高的事故原因還是挺有意思的，用了一個雙同步來獲取 serial 值，感覺像是一種聰明反被聰明誤，代碼一定要簡單粗暴，代碼越少bug越少。
