记一次 .NET 某工厂无人车调度系统 线程爆高分析
source link: https://www.cnblogs.com/huangxincheng/p/17802523.html
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
1. 讲故事
前些天有位朋友找到我,说他程序中的线程数爆高,让我帮忙看下怎么回事,这种线程数爆高的情况找问题相对比较容易,就让朋友丢一个dump给我,看看便知。
二:为什么会爆高
1. 查看托管线程
别人说的话不一定是真,得自己拿数据出来说话,可以用 !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 方法的逻辑,发现卡死在 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,所以这个是假异步,本质上就是动态生成了一个串联的 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 引发的死锁,用 !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 在这里就起不到很好的效果,不过仔细阅读代码,发现应该将 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
从卦中看已经自增到了 9061
,然后因为某种原因导致wait 和 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
细心的朋友会发现这里的 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
,直接用同步的方式执行 Interlocked.Increment(ref serial)
即可,简单粗暴。
这次线程爆高的事故原因还是挺有意思的,用了一个双同步来获取 serial 值,感觉像是一种聪明反被聪明误,代码一定要简单粗暴,代码越少bug越少。
Recommend
About Joyk
Aggregate valuable and interesting links.
Joyk means Joy of geeK