记一次 .NET 某工厂无人车调度系统 线程爆高分析

叮当乱响的小铃铛

一：背景

1. 讲故事

前些天有位朋友找到我，说他程序中的线程数爆高，让我帮忙看下怎么回事，这种线程数爆高的情况找问题相对比较容易，就让朋友丢一个dump给我，看看便知。
二：为什么会爆高

1. 查看托管线程

别人说的话不一定是真，得自己拿数据出来说话，可以用  !t 命令观察一下便知。

1. 0:000> !t
2. ThreadCount:      4683
3. UnstartedThread:  0
4. BackgroundThread: 4663
5. PendingThread:    0
6. DeadThread:       19
7. Hosted Runtime:   no
8.                                                                                                             Lock  
9. DBG   ID     OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
10.    0    1     cc44 00000268048778C0  202a020 Preemptive  0000000000000000:0000000000000000 00000268048c6d50 -00001 MTA
11.    ...
12. 4670 4679     51bc 0000026D143F0420  302b220 Preemptive  0000000000000000:0000000000000000 00000268048c6d50 -00001 MTA (Threadpool Worker)
13. 4671 4680     3a68 0000026D143F52E0  302b220 Preemptive  0000000000000000:0000000000000000 00000268048c6d50 -00001 MTA (Threadpool Worker)
14. 4672 4681     337c 0000026D143F1140  302b220 Preemptive  0000026A88AAF5B8:0000026A88AB08D0 00000268048c6d50 -00001 MTA (Threadpool Worker)
15. 4673 4682    188d4 0000026D143F0AB0  302b220 Preemptive  000002698881A760:000002698881C0B8 00000268048c6d50 -00001 MTA (Threadpool Worker)
16. 4674 4683     4bcc 0000026D143EF700  302b220 Preemptive  0000026B889C4488:0000026B889C5E18 00000268048c6d50 -00001 MTA (Threadpool Worker)

复制代码

从卦中信息看确实有 4600+ 的线程，说明确实存在问题，接下来用 ~*e !clrstack 观察每一个线程都在做什么，线程太多没法全部输出完毕，不过很容易的看到有大量的线程卡在 RoutingService.Push 上，截图如下：

接下来就是观察下这个 Push 方法的逻辑，发现卡死在 Result 上，整理后的代码大概如下：

1. private readonly SemaphoreSlim slim = new SemaphoreSlim(1, 1);
3. public void Push(string xxx, xxx xxx)
4. {
5.     int num = (xxx.Serial = GetSerial().Result);
6. }
8. private async Task<int> GetSerial()
9. {
10.     await slim.WaitAsync();
11.     try
12.     {
13.         Interlocked.Increment(ref serial);
14.     }
15.     finally
16.     {
17.         slim.Release();
18.     }
19.     return serial;
20. }

复制代码

上面的代码看起来挺奇葩的，为什么 GetSerial() 中不直接用 Interlocked.Increment() 呢？套一个 SemaphoreSlim 显得非常多余。
先不管多余不多余，既然 Result 得不到值，就说明这个异步方法得不到完成，那为什么得不到完成呢？
2. 为什么异步得不到完成

熟悉 SemaphoreSlim.WaitAsync() 的朋友应该知道，这里涉及不到异步IO，所以这个是假异步，本质上就是动态生成了一个串联的 Task，要想知道得不到完成的根本原因，还得要挖一挖此时的 slim 信号量情况。

1. 0:000> !do 000002690664b5a0
2. Name:        System.Threading.SemaphoreSlim
3. MethodTable: 00007ff894e56fc0
4. EEClass:     00007ff894e3f230
5. Tracked Type: false
6. Size:        64(0x40) bytes
7. File:        D:\xxx\System.Private.CoreLib.dll
8. Fields:
9.               MT    Field   Offset                 Type VT     Attr            Value Name
10. 00007ff8948094b0  4000c2e       28         System.Int32  1 instance                0 m_currentCount
11. 00007ff8948094b0  4000c2f       2c         System.Int32  1 instance                1 m_maxCount
12. 00007ff8948094b0  4000c30       30         System.Int32  1 instance                0 m_waitCount
13. 00007ff8948094b0  4000c31       34         System.Int32  1 instance                0 m_countOfWaitersPulsedToWake
14. 00007ff8962871e0  4000c32        8 ...Private.CoreLib]]  0 instance 000002690664b5e0 m_lockObjAndDisposed
15. 00007ff894e555f0  4000c33       10 ....ManualResetEvent  0 instance 0000000000000000 m_waitHandle
16. 00007ff894e57870  4000c34       18 ...horeSlim+TaskNode  0 instance 0000026b86919a30 m_asyncHead
17. 00007ff894e57870  4000c35       20 ...horeSlim+TaskNode  0 instance 0000026b889c4378 m_asyncTail
18. 00007ff894a4a1f0  4000c36      888 ...Private.CoreLib]]  0   static 00000268864f83a0 s_cancellationTokenCanceledEventHandler

复制代码

从卦中看当前的 m_currentCount=0，表明当前的信号量被消费完了，所以其他的线程都在等待就能很好理解，接下来的问题是那个从 1->0 的持有线程为什么不归还？ 这个就比较难搞了，可以从如下两个思路思考：

• 观察 Result
  

首先怀疑是不是 Result 引发的死锁，用 !eeversion 看了下是 asp.net core ，并没有所谓的同步上下文，所以这个问题不存在。

1. 0:000> !eeversion
2. 6.0.2023.32017 free
3. 6,0,2023,32017 @Commit: a08d9ce2caf02455c0b825bcdc32974bdf769a80
4. Server mode with 8 gc heaps
5. SOS Version: 7.0.8.30602 retail build

复制代码

• 观察代码
  

因为 SemaphoreSlim 并不记录持有线程，windbg 在这里就起不到很好的效果，不过仔细阅读代码，发现应该将 await slim.WaitAsync(); 放到 try 中更合理一点，否则无法保证 WaitAsync 和 Release 一定是成双成对的，截图如下：

3. 什么时候开始阻塞的

仔细观察这个 GetSerial 方法，看看里面的 serial 值就知道大概是进行到哪一步才出的问题。

1. 0:4674> !DumpObj /d 000002690664b258
2. Name:        xxx.RoutingService
3. MethodTable: 00007ff895283ed0
4. EEClass:     00007ff89526ae08
5. Tracked Type: false
6. Size:        112(0x70) bytes
7. File:        D:\xxx\xxx.dll
8. Fields:
9.               MT    Field   Offset                 Type VT     Attr            Value Name
10. ...
11. 00007ff894e56fc0  4000214       48 ...ing.SemaphoreSlim  0 instance 000002690664b5a0 slim
12. 00007ff8948094b0  4000215       60         System.Int32  1 instance             9061 serial

复制代码

从卦中看已经自增到了 9061 ，然后因为某种原因导致wait 和 release 不匹配了，像这种情况线程池也会有大量的任务积压，可以用 !tp 观察下。

1. 0:4674> !tp
2. logStart: 33
3. logSize: 200
4. CPU utilization: 22 %
5. Worker Thread: Total: 4652 Running: 4652 Idle: 0 MaxLimit: 32767 MinLimit: 8
6. Work Request in Queue: 0
7. --------------------------------------
8. Number of Timers: 1
9. --------------------------------------
10. Completion Port Thread:Total: 2 Free: 2 MaxFree: 16 CurrentLimit: 2 MaxLimit: 1000 MinLimit: 8

复制代码

细心的朋友会发现这里的 Work Request in Queue: 0 ，既然是 0 何来积压？其实这是 sos 的bug，我们需要自己到线程池队列中提取，从当前的线程栈上寻找 ThreadPoolWorkQueue 对象即可。

1. 0:4674> !dso
2. OS Thread Id: 0x4bcc (4674)
3. 000000EF384FF5C8 0000026b06544848 System.Threading.ThreadPoolWorkQueue
5. 0:4674> !DumpObj /d 0000026b06544848
6. Name:        System.Threading.ThreadPoolWorkQueue
7. MethodTable: 00007ff894e59d80
8. EEClass:     00007ff894ee01d0
9. Tracked Type: false
10. Size:        168(0xa8) bytes
11. File:        D:\xxx\System.Private.CoreLib.dll
12. Fields:
13.               MT    Field   Offset                 Type VT     Attr            Value Name
14. 00007ff89476bf38  4000c61       18       System.Boolean  1 instance                0 loggingEnabled
15. 00007ff89476bf38  4000c62       19       System.Boolean  1 instance                0 _dispatchTimeSensitiveWorkFirst
16. 00007ff89637fc20  4000c63        8 ...Private.CoreLib]]  0 instance 0000026b065448f0 workItems
17. 00007ff89637fe00  4000c64       10 ...Private.CoreLib]]  0 instance 0000026b06544930 timeSensitiveWorkQueue
18. 00007ff894e59d10  4000c65       20 ...acheLineSeparated  1 instance 0000026b06544868 _separated
20. 0:4674> !ext dcq 0000026b065448f0
21. System.Collections.Concurrent.ConcurrentQueue<System.Object>
22.    1 - dumpobj 0x0000026806c782f8
23. ...
24. 119419 - dumpobj 0x000002690a097658
25. 119420 - dumpobj 0x000002690a097810
26. 119421 - dumpobj 0x000002690a0981a8
27. ---------------------------------------------
28. 119421 items

复制代码

从卦中可以看到大概有12w的积压。上面就是我的完整分析思路，最后就是告诉朋友最好的办法就是去掉多余累赘的 SemaphoreSlim ，直接用同步的方式执行 Interlocked.Increment(ref serial) 即可，简单粗暴。
三：总结

这次线程爆高的事故原因还是挺有意思的，用了一个双同步来获取 serial 值，感觉像是一种聪明反被聪明误，代码一定要简单粗暴，代码越少bug越少。

来源:https://www.cnblogs.com/huangxincheng/archive/2023/11/01/17802523.html
免责声明：由于采集信息均来自互联网，如果侵犯了您的权益，请联系我们【E-Mail:cb@itdo.tech】 我们会及时删除侵权内容，谢谢合作！