admin 发表于 2022-7-7 12:38:51

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

一:背景
1. 讲故事
前段时间收到一个朋友的求助,说他的程序线程数疯涨,寻求如何解决。

等我分析完之后,我觉得这个问题很有代表性,所以拿出来和大家分享下,还是上老工具 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 ContextDomain   Count Apt Exception
   0    159c 00e52fb0   26020 Preemptive12D67610:00000000 00e4b408 0   STA
   2    2 2b30 00e61aa0   2b220 Preemptive00000000:00000000 00e4b408 0   MTA (Finalizer)
   3    3 18cc 00ea72b8   202b220 Preemptive00000000:00000000 00e4b408 0   MTA
   5    4 1f18 00f02998   1020220 Preemptive00000000:00000000 00e4b408 0   Ukn (Threadpool Worker)
XXXX    6    0 00f056f8   39820 Preemptive00000000:00000000 00e4b408 0   MTA
   6    7 2154 09052448   202b020 Preemptive12E353E0:00000000 00e4b408 0   MTA
   ...
377373 2ee8 21a90958   1029220 Preemptive12D1FCCC:00000000 00e4b408 0   MTA (Threadpool Worker)
378374 227c 21b1d510   1029220 Preemptive12DCBFC8:00000000 00e4b408 0   MTA (Threadpool Worker)
3793757e8 21b1baa8   1029220 Preemptive12D39ADC:00000000 00e4b408 0   MTA (Threadpool Worker)
380376 1d1c 21a8fec8   1029220 Preemptive12D11F40:00000000 00e4b408 0   MTA (Threadpool Worker)
381366 19ec 215c1bd0   1029220 Preemptive12DB42D8:00000000 00e4b408 0   MTA (Threadpool Worker)
382377 1dc8 21b1bff0   1029220 Preemptive12C71F9C:00000000 00e4b408 0   MTA (Threadpool Worker)
383378f94 215bc750   1029220 Preemptive12E10568:00000000 00e4b408 0   MTA (Threadpool Worker)
384379 17d4 21ac5580   1029220 Preemptive12D8EE98:00000000 00e4b408 0   MTA (Threadpool Worker)
385381 2c1c 21b1b018   1029220 Preemptive12D0DD00:00000000 00e4b408 0   MTA (Threadpool Worker)
386380 309c 21b1da58   1029220 Preemptive12E25028:00000000 00e4b408 0   MTA (Threadpool Worker)
387382 3048 21ac6aa0   1029220 Preemptive12DFA918: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 命令。

经过仔细观察这近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 为何物,去找一下它的类库声明。
















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

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

1) 短期:

用 ThreadPool.SetMaxThreads 限定线程上限。

2) 长期:

找作者看看有没有最新版,或者到 https://github.com/dathlin/HslCommunication 上提一个 issue,让别人系统性解决一下。
页: [1]
查看完整版本: 记一次 .NET 某新能源系统 线程疯涨 分析