1

记一次 .NET 某工控数据采集平台 线程数 爆高分析 - 一线码农

 1 year ago
source link: https://www.cnblogs.com/huangxincheng/p/16443889.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. 讲故事

前几天有位朋友在 B站 加到我,说他的程序出现了 线程数 爆高的问题,让我帮忙看一下怎么回事,截图如下:

a5b64282693a43dab0e2a07e0c6fd9a4~tplv-k3u1fbpfcp-zoom-1.image

说来也奇怪,这些天碰到了好几起关于线程数无缘无故的爆高,不过那几个问题比这一篇要复杂的多,主要涉及到非托管层面,分享这一篇的目的主要是它很有代表性,很有必要。

闲话不多说,既然线程数爆高,那就上 windbg 说话。

二:WinDbg 分析

1. 线程数真的高吗

既然说线程数高,那到底有多少呢? 我们可以用 !t 命令看一下。


0:000> !t
ThreadCount:      109
UnstartedThread:  0
BackgroundThread: 104
PendingThread:    0
DeadThread:       1
Hosted Runtime:   no
                                                                         Lock  
       ID OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception
   0    1 2970 00581020     26020 Preemptive  0294AE60:00000000 0057a5f0 0     STA 
   2    2 1d2c 00590670     2b220 Preemptive  00000000:00000000 0057a5f0 0     MTA (Finalizer) 
   5    4 3388 0063a9b8   102a220 Preemptive  00000000:00000000 0057a5f0 0     MTA (Threadpool Worker) 
   6    5 265c 0063b458   1020220 Preemptive  00000000:00000000 0057a5f0 0     Ukn (Threadpool Worker) 
   7    7 3370 07100fa8   202b220 Preemptive  00000000:00000000 0057a5f0 0     MTA 
 ...
 113   41 4af4 0a85a490   8029220 Preemptive  0294F918:00000000 0057a5f0 0     MTA (Threadpool Completion Port) 
 114   75 4b9c 0a83d818   8029220 Preemptive  00000000:00000000 0057a5f0 0     MTA (Threadpool Completion Port) 
 115   76 4ba0 0a83d2d0   8029220 Preemptive  02B53AC4:00000000 0057a5f0 0     MTA (Threadpool Completion Port) 

从卦象看,当前有 115 个托管线程,从主线程的 STA 模式看 应该是一个 WinForm/WPF 程序,桌面程序这个线程数说多也不多,说少也不少,下一步的思路就是看下这些线程都在做什么。

2. 这些线程都在做什么

要探究每个线程都在做什么,可以用 ~*e !clrstack 调出所有线程栈,然后仔细耐心的观察这些线程。


0:000> ~*e !clrstack 
OS Thread Id: 0x488c (109)
Child SP       IP Call Site
114de760 7704018d [GCFrame: 114de760] 
114de90c 7704018d [GCFrame: 114de90c] 
114de8bc 7704018d [HelperMethodFrame: 114de8bc] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
114de94c 6dfe2767 System.Threading.Monitor.Enter(System.Object, Boolean ByRef)
114de95c 056107e3 CSRedis.Internal.IO.RedisIO.Write(Byte[])
114de998 05cb338c CSRedis.Internal.RedisConnector.Write(CSRedis.RedisCommand)
114de9dc 05cb32fc CSRedis.Internal.RedisListener`1[[System.__Canon, mscorlib]].Write[[System.__Canon, mscorlib]](CSRedis.RedisCommand`1<System.__Canon>)
114de9f0 05cb3263 CSRedis.Internal.SubscriptionListener.Send(CSRedis.Internal.Commands.RedisSubscription)
114dea0c 050c4ffd CSRedis.RedisClient.Unsubscribe(System.String[])
114dea24 050c01e3 CSRedis.CSRedisClient+SubscribeObject+c__DisplayClass13_0.b__1(System.Object)
114deab4 6e026471 System.Threading.TimerQueueTimer.CallCallbackInContext(System.Object)
114deab8 6dfe2925 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
114deb24 6dfe2836 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
114deb38 6e026377 System.Threading.TimerQueueTimer.CallCallback()
114deb6c 6e0261fe System.Threading.TimerQueueTimer.Fire()
114debac 6e02612f System.Threading.TimerQueue.FireNextTimers()
114debec 6e025ff1 System.Threading.TimerQueue.AppDomainTimerCallback()
114dee10 6f38eaf6 [DebuggerU2MCatchHandlerFrame: 114dee10] 
...

5224bb38ce7c4f87b0ed2919725f6f57~tplv-k3u1fbpfcp-zoom-1.image

从卦象看,线程特征非常明显,有 86 个线程卡在 Monitor.ReliableEnter 处,它就是我们C#中的 监视锁 ,既然是监视锁,那就好办了,查看它的 同步块表,看看谁在 lock 里赖着不出来导致其他线程等待,使用 windbg 的 !syncblk 命令。


0:000> !syncblk
Index         SyncBlock MonitorHeld Recursion Owning Thread Info          SyncBlock Owner
   72 005ef1f0           87         1 07176838 12c8  13   028374e4 System.Object
   75 005efd1c           87         1 07176d80 32c0  14   028368ec System.Object
-----------------------------
Total           84
CCW             0
RCW             1
ComClassFactory 0
Free            17

从表中看,当前有两个 lock 对象,并且线程 1314 在 lock 区内不出来,导致各自有 43 个线程在等待,接下来思路就很清晰了,我们查看这两个线程到底在干嘛?

3. 持有线程正在做什么

我们就从 13 号线程入手,看看它正在做什么。


0:013> !clrstack 
OS Thread Id: 0x12c8 (13)
Child SP       IP Call Site
0971eb84 7703f901 [InlinedCallFrame: 0971eb84] 
0971eb80 6c5b940f DomainBoundILStubClass.IL_STUB_PInvoke(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
0971eb84 6c55b11d [InlinedCallFrame: 0971eb84] System.Net.UnsafeNclNativeMethods+OSSOCK.recv(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
0971ebbc 6c55b11d System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags, System.Net.Sockets.SocketError ByRef)
0971ebec 6c55b00e System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags)
0971ec10 6c55af43 System.Net.Sockets.NetworkStream.Read(Byte[], Int32, Int32)
0971ec40 6e05add8 System.IO.Stream.ReadByte()
0971ec50 05610d2c CSRedis.Internal.IO.RedisIO.ReadByte()
0971ec8c 05610c5a CSRedis.Internal.IO.RedisReader.ReadType()
0971ecb0 05610a9e CSRedis.Internal.IO.RedisReader.ExpectType(CSRedis.RedisMessage)
0971ed28 05cb3696 CSRedis.Internal.Commands.RedisSubscription.Parse(CSRedis.Internal.IO.RedisReader)
0971ed90 05cb35bd CSRedis.Internal.RedisConnector.Read[[System.__Canon, mscorlib]](System.Func`2<CSRedis.Internal.IO.RedisReader,System.__Canon>)
0971ede0 05cb3487 CSRedis.Internal.RedisListener`1[[System.__Canon, mscorlib]].Listen(System.Func`2<CSRedis.Internal.IO.RedisReader,System.__Canon>)
0971ee34 05cb32b9 CSRedis.Internal.SubscriptionListener.Send(CSRedis.Internal.Commands.RedisSubscription)
0971ee50 05cb3156 CSRedis.RedisClient.Subscribe(System.String[])
0971ee68 05cb255a CSRedis.CSRedisClient+SubscribeObject.Subscribe(System.Object)
0971ef98 6dfb6063 System.Threading.ThreadHelper.ThreadStart_Context(System.Object)
0971efa4 6dfe2925 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
0971f010 6dfe2836 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
0971f024 6dfe27f1 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
0971f03c 6e036ebe System.Threading.ThreadHelper.ThreadStart(System.Object)
0971f180 6f38eaf6 [GCFrame: 0971f180] 
0971f364 6f38eaf6 [DebuggerU2MCatchHandlerFrame: 0971f364] 

从线程栈看,是这位朋友使用了 CSRedis 的订阅功能,最后在 CSRedis.Internal.IO.RedisIO.ReadByte() 方法处迟迟出不来,问题点找到了,接下来就可以看下它的源码。

4. 查看源码

看源码的话,可以用 ILSpy 工具,编译后的代码如下:

4e2243f23e5c490aa7f670ad8d028dc3~tplv-k3u1fbpfcp-zoom-1.image

其实这地方用 lock 锁不太稳妥,一旦出现网络波动,持有线程就会一直等待,如果这个线程是由 ThreadPool 提供,那就会导致 ThreadPool 中的线程数暴增,从 Waiting 的线程上追查,发现这些线程数都是由 Timer 提供,线程栈和截图如下:


OS Thread Id: 0x40e8 (67)
Child SP       IP Call Site
0e7af608 7704018d [GCFrame: 0e7af608] 
0e7af7b4 7704018d [GCFrame: 0e7af7b4] 
0e7af764 7704018d [HelperMethodFrame: 0e7af764] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
0e7af7f4 6dfe2767 System.Threading.Monitor.Enter(System.Object, Boolean ByRef)
0e7af804 056107e3 CSRedis.Internal.IO.RedisIO.Write(Byte[])
0e7af840 05cb338c CSRedis.Internal.RedisConnector.Write(CSRedis.RedisCommand)
0e7af884 05cb32fc CSRedis.Internal.RedisListener`1[[System.__Canon, mscorlib]].Write[[System.__Canon, mscorlib]](CSRedis.RedisCommand`1<System.__Canon>)
0e7af898 05cb3263 CSRedis.Internal.SubscriptionListener.Send(CSRedis.Internal.Commands.RedisSubscription)
0e7af8b4 050c4ffd CSRedis.RedisClient.Unsubscribe(System.String[])
0e7af8cc 050c01e3 CSRedis.CSRedisClient+SubscribeObject+c__DisplayClass13_0.b__1(System.Object)
0e7af95c 6e026471 System.Threading.TimerQueueTimer.CallCallbackInContext(System.Object)

6184bba3a94048589edeb10d6d3b58b2~tplv-k3u1fbpfcp-zoom-1.image

整体分析下来,这应该算是 CSRedis 的一个 Bug,这种问题我能做的就是让朋友升级到最新版本看看,不过既然是 Bug 那其他人肯定也会遇到,看了下 CSRedis.dll 程序集给的 github 地址。


[assembly: CompilationRelaxations(8)]
[assembly: RuntimeCompatibility(WrapNonExceptionThrows = true)]
[assembly: Debuggable(DebuggableAttribute.DebuggingModes.Default | DebuggableAttribute.DebuggingModes.DisableOptimizations | DebuggableAttribute.DebuggingModes.IgnoreSymbolStoreSequencePoints | DebuggableAttribute.DebuggingModes.EnableEditAndContinue)]
[assembly: TargetFramework(".NETFramework,Version=v4.5", FrameworkDisplayName = ".NET Framework 4.5")]
[assembly: AssemblyCompany("CSRedisCore")]
[assembly: AssemblyConfiguration("Debug")]
[assembly: AssemblyDescription("CSRedis 是 redis.io 官方推荐库,支持 redis-trib集群、哨兵、私有分区与连接池管理技术,简易 RedisHelper 静态类。")]
[assembly: AssemblyFileVersion("3.6.6.0")]
[assembly: AssemblyInformationalVersion("3.6.6")]
[assembly: AssemblyProduct("CSRedisCore")]
[assembly: AssemblyTitle("CSRedisCore")]
[assembly: AssemblyMetadata("RepositoryUrl", "https://github.com/2881099/csredis")]
[assembly: AssemblyVersion("3.6.6.0")]

果然在 Issueshttps://github.com/2881099/csredis/issues/414 ) 中找到了同样的问题, 很可惜作者没给解答。

886233165f0644cb901e7e1b11573092~tplv-k3u1fbpfcp-zoom-1.image

说一个有意思的事情,我看了下提问者的昵称 thicktao 好像很熟悉,在微信上好像有这位朋友。

25c8efbaca394bc1be3887b92e8f169d~tplv-k3u1fbpfcp-zoom-1.image

我去,他去年就曾今找过我,.NET圈子真小,缘分哈。。。

图片名称

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK