记一次 .NET 某新能源系统线程疯涨分析

标签：hslTimeOut 疯涨 00000000 Preemptive 线程 00e4b408 NET MTA

一：背景

1. 讲故事

前段时间收到一个朋友的求助，说他的程序线程数疯涨，寻求如何解决。

记一次 .NET 某新能源系统线程疯涨分析_2d

等我分析完之后，我觉得这个问题很有代表性，所以拿出来和大家分享下，还是上老工具 WinDbg。

二： WinDbg 分析

1. 线程真的在疯涨吗

要想查线程有没有疯涨，可以用 !t 命令看一下。

0:000:x86> !t
ThreadCount:      382
UnstartedThread:  1
BackgroundThread: 376
PendingThread:    0
DeadThread:       2
Hosted Runtime:   no
                                                                         Lock  
       ID OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception
   0    1  59c 00e52fb0     26020 Preemptive  12D67610:00000000 00e4b408 0     STA 
   2    2 2b30 00e61aa0     2b220 Preemptive  00000000:00000000 00e4b408 0     MTA (Finalizer) 
   3    3 18cc 00ea72b8   202b220 Preemptive  00000000:00000000 00e4b408 0     MTA 
   5    4 1f18 00f02998   1020220 Preemptive  00000000:00000000 00e4b408 0     Ukn (Threadpool Worker) 
XXXX    6    0 00f056f8     39820 Preemptive  00000000:00000000 00e4b408 0     MTA 
   6    7 2154 09052448   202b020 Preemptive  12E353E0:00000000 00e4b408 0     MTA 
   ...
 377  373 2ee8 21a90958   1029220 Preemptive  12D1FCCC:00000000 00e4b408 0     MTA (Threadpool Worker) 
 378  374 227c 21b1d510   1029220 Preemptive  12DCBFC8:00000000 00e4b408 0     MTA (Threadpool Worker) 
 379  375  7e8 21b1baa8   1029220 Preemptive  12D39ADC:00000000 00e4b408 0     MTA (Threadpool Worker) 
 380  376 1d1c 21a8fec8   1029220 Preemptive  12D11F40:00000000 00e4b408 0     MTA (Threadpool Worker) 
 381  366 19ec 215c1bd0   1029220 Preemptive  12DB42D8:00000000 00e4b408 0     MTA (Threadpool Worker) 
 382  377 1dc8 21b1bff0   1029220 Preemptive  12C71F9C:00000000 00e4b408 0     MTA (Threadpool Worker) 
 383  378  f94 215bc750   1029220 Preemptive  12E10568:00000000 00e4b408 0     MTA (Threadpool Worker) 
 384  379 17d4 21ac5580   1029220 Preemptive  12D8EE98:00000000 00e4b408 0     MTA (Threadpool Worker) 
 385  381 2c1c 21b1b018   1029220 Preemptive  12D0DD00:00000000 00e4b408 0     MTA (Threadpool Worker) 
 386  380 309c 21b1da58   1029220 Preemptive  12E25028:00000000 00e4b408 0     MTA (Threadpool Worker) 
 387  382 3048 21ac6aa0   1029220 Preemptive  12DFA918:00000000 00e4b408 0     MTA (Threadpool Worker)

从卦中看，主线程是一个 STA，说明是一个窗体程序，一个窗体能做到 387 个线程，也是挺牛的，同时也能观察到大多都是 ThreadPool Worker ，也就是线程池工作线程。

2. 这些线程都在干嘛

这里有一个小技巧，那就是线程号越大，往往都是最新创建的，往往从这里面就能套出来一些有用的东西，言外之意就扒一扒 380 ~ 387 这些线程的调用栈。

0:387:x86> ~387s
ntdll_77380000!NtWaitForSingleObject+0xc:
773f29dc c20c00          ret     0Ch
0:387:x86> k
CvRegToMachine(x86) conversion failure for 0x14f
X86MachineInfo::SetVal: unknown register 0 requested
 # ChildEBP RetAddr      
00 31fef104 755a1539     ntdll_77380000!NtWaitForSingleObject+0xc
01 31fef104 74b3ee3b     KERNELBASE!WaitForSingleObjectEx+0x99
02 31fef168 74b3efed     clr!CLRSemaphore::Wait+0xbe
03 31fef19c 74b3eee2     clr!ThreadpoolMgr::UnfairSemaphore::Wait+0x13a
04 31fef204 74a54c27     clr!ThreadpoolMgr::WorkerThreadStart+0x328
05 31feff24 7649fa29     clr!Thread::intermediateThreadProc+0x58
06 31feff34 773e7a7e     kernel32!BaseThreadInitThunk+0x19
07 31feff90 773e7a4e     ntdll_77380000!__RtlUserThreadStart+0x2f
0:387:x86> ~386s
ntdll_77380000!NtWaitForSingleObject+0xc:
773f29dc c20c00          ret     0Ch
0:386:x86> k
CvRegToMachine(x86) conversion failure for 0x14f
X86MachineInfo::SetVal: unknown register 0 requested
 # ChildEBP RetAddr      
00 31d6ede4 755a1539     ntdll_77380000!NtWaitForSingleObject+0xc
01 31d6ede4 74b3ee3b     KERNELBASE!WaitForSingleObjectEx+0x99
02 31d6ee48 74b3efed     clr!CLRSemaphore::Wait+0xbe
03 31d6ee7c 74b3eee2     clr!ThreadpoolMgr::UnfairSemaphore::Wait+0x13a
04 31d6eee4 74a54c27     clr!ThreadpoolMgr::WorkerThreadStart+0x328
05 31d6fb84 7649fa29     clr!Thread::intermediateThreadProc+0x58
06 31d6fb94 773e7a7e     kernel32!BaseThreadInitThunk+0x19
07 31d6fbf0 773e7a4e     ntdll_77380000!__RtlUserThreadStart+0x2f
0:386:x86> ~385s
ntdll_77380000!NtWaitForSingleObject+0xc:
773f29dc c20c00          ret     0Ch
0:385:x86> k
CvRegToMachine(x86) conversion failure for 0x14f
X86MachineInfo::SetVal: unknown register 0 requested
 # ChildEBP RetAddr      
00 31eaee64 755a1539     ntdll_77380000!NtWaitForSingleObject+0xc
01 31eaee64 74b3ee3b     KERNELBASE!WaitForSingleObjectEx+0x99
02 31eaeec8 74b3efed     clr!CLRSemaphore::Wait+0xbe
03 31eaeefc 74b3eee2     clr!ThreadpoolMgr::UnfairSemaphore::Wait+0x13a
04 31eaef64 74a54c27     clr!ThreadpoolMgr::WorkerThreadStart+0x328
05 31eafb7c 7649fa29     clr!Thread::intermediateThreadProc+0x58
06 31eafb8c 773e7a7e     kernel32!BaseThreadInitThunk+0x19
07 31eafbe8 773e7a4e     ntdll_77380000!__RtlUserThreadStart+0x2f

从线程栈上看，这些线程都在 UnfairSemaphore 处等待，这是一个正常现象，因为这些线程都是通过 UnfairSemaphore 锁来唤醒,不过奇怪的是，这些线程为什么产生，又为什么不被消亡？

根据经验预测：肯定有代码在不断的调度 线程池 线程，然后又做了一个短命的操作，导致线程池线程不断新增，又得不到线程可以被消亡的阈值。

3. 程序真的在频繁调度线程吗

既然猜测是程序在频繁的调用线程池线程，能做的只能是观察此时 dump 中的所有线程的线程栈，看能不能挖到点有价值的东西，可以使用 ~*e !clrstack 命令。

记一次 .NET 某新能源系统线程疯涨分析_.net_02

经过仔细观察这近400个线程栈，发现有 37 处都是 System.Threading.Thread.Sleep(Int32), 而且大多都是 HslCommunication.Core.Net.NetworkBase.ThreadPoolCheckTimeOut(System.Object) 函数，能清楚的看到是由线程池发起的，接下来就是用 ILSpy 反编译下这个函数看下到底是怎么回事。

protected void ThreadPoolCheckTimeOut(object obj)
        {
            HslTimeOut hslTimeOut;
            if ((hslTimeOut = obj as HslTimeOut) == null)
            {
                return;
            }
            while (!hslTimeOut.IsSuccessful)
            {
                Thread.Sleep(100);
                if ((DateTime.Now - hslTimeOut.StartTime).TotalMilliseconds > (double)hslTimeOut.DelayTime)
                {
                    if (!hslTimeOut.IsSuccessful)
                    {
                        LogNet?.WriteWarn(ToString(), "Wait Time Out : " + hslTimeOut.DelayTime);
                        hslTimeOut.Operator?.Invoke();
                        hslTimeOut.WorkSocket?.Close();
                    }
                    break;
                }
            }
        }

接下来通过 ILSpy 查看这个方法的引用，发现有很多处，抽几个如下：

protected OperateResult<TNetMessage> ReceiveMessage<TNetMessage>(Socket socket, int timeOut, TNetMessage netMsg) where TNetMessage : INetMessage
        {
            ...
            if (timeOut > 0)
            {
                ThreadPool.QueueUserWorkItem(ThreadPoolCheckTimeOut, hslTimeOut);
            }
            ...
        }

        protected OperateResult<Socket> CreateSocketAndConnect(IPEndPoint endPoint, int timeOut)
        {
            ...
            ThreadPool.QueueUserWorkItem(ThreadPoolCheckTimeOut, hslTimeOut);
            ...
        }

        protected void CreateSocketAndConnect(IPEndPoint endPoint, int timeOut, Action<OperateResult<Socket>> connectCallback)
        {
            ...
            ThreadPool.QueueUserWorkItem(ThreadPoolCheckTimeOut, hslTimeOut);
            ...
        }

从上面代码看，确实存在一些商榷的地方，很多的 socket 操作都用线程池来处理 ThreadPoolCheckTimeOut() 函数，而在这个函数内当 hslTimeOut.IsSuccessful =false 的时候，在 if ((DateTime.Now - hslTimeOut.StartTime).TotalMilliseconds > (double)hslTimeOut.DelayTime) 不满足的时间区间内会一直 sleep，这就导致当 socket 请求量上去后，导致很多线程处于 sleep 状态, 线程池又不得不生成更多的线程来处理 ThreadPoolCheckTimeOut() 逻辑。

到这里终于就找到了符合 线程池线程 疯涨的底层逻辑，接下来看看 HslCommunication.dll 为何物，去找一下它的类库声明。

[assembly: CompilationRelaxations(8)]
[assembly: RuntimeCompatibility(WrapNonExceptionThrows = true)]
[assembly: Debuggable(DebuggableAttribute.DebuggingModes.IgnoreSymbolStoreSequencePoints)]
[assembly: AssemblyTitle("HslCommunication")]
[assembly: AssemblyDescription("一个框架库，包含完善的网络通信及日志组件")]
[assembly: AssemblyConfiguration("")]
[assembly: AssemblyCompany("")]
[assembly: AssemblyProduct("HslCommunication")]
[assembly: AssemblyCopyright("Copyright © By Richard.Hu 2018")]
[assembly: AssemblyTrademark("")]
[assembly: ComVisible(false)]
[assembly: Guid("d3710b78-1b32-4d53-9604-0451a795a2f5")]
[assembly: AssemblyFileVersion("5.3.2.0")]
[assembly: AssemblyVersion("5.3.2.0")]

可以看到，这是一个商业组件。

记一次 .NET 某新能源系统线程疯涨分析_2d_03

三：总结

由于定位到疑似是 HslCommunication 组件的问题，看了下还是 商业版 , 这就尴尬了，建议的解决办法如下：

1）短期：

用 ThreadPool.SetMaxThreads 限定线程上限。

2）长期：

找作者看看有没有最新版，或者到 https://github.com/dathlin/HslCommunication 上提一个 issue，让别人系统性解决一下。

标签：hslTimeOut,疯涨,00000000,Preemptive,线程,00e4b408,NET,MTA
From： https://blog.51cto.com/u_15353947/5733033

记一次 .NET 某新能源系统线程疯涨分析

一：背景

1. 讲故事

二： WinDbg 分析

1. 线程真的在疯涨吗

2. 这些线程都在干嘛

3. 程序真的在频繁调度线程吗

三：总结

相关文章

赞助商

阅读排行

记一次 .NET 某新能源系统 线程疯涨 分析

一：背景

1. 讲故事

二： WinDbg 分析

1. 线程真的在疯涨吗

2. 这些线程都在干嘛

3. 程序真的在频繁调度线程吗

三：总结

相关文章

赞助商

阅读排行

记一次 .NET 某新能源系统线程疯涨分析