记一次 .NET 某传感器采集系统 线程爆高分析

六六八八

一：背景

1. 讲故事

前段时间有位朋友微信找到我，说他的程序使用 hsl 库之后，采集 plc 时内存溢出，让我帮忙看一下怎么回事，哈哈，貌似是分析之旅中的第二次和 hsl 打交道，既然找到我，那就上 windbg 说话吧。
二：WinDbg 分析

1. 为什么会内存溢出

简单观察程序的提交内存之后，发现内存的 Stack 区非常大，随用 !t 看了下到底有多少个线程，截图如下：

不看不知道，一看吓一跳，这个程序居然有近 1.5w 的线程，虽然我见过大世面(3w+线程)，但还是心有余悸，随用 ~*e !clrstack 看了下各个线程都在做什么，经过一顿观察，发现线程都卡在 Interactivelock.Enter 锁上，截图如下：

从代码中看，理论上存在 Interactivelock.Enter() 和 Interactivelock.Leave() 因为各种异常导致锁的不成对进而造成锁污染的情况，看起来是 hsl 代码不严谨造成的什么 bug，观察了下版本也不是最新的，而且最新版的锁这块也修改了逻辑，就让朋友升级下 hsl 再观察看看，看样子这个问题应该轻松搞定了，不过我保守的说了下，如果还是遇到大量的线程，可以随时联系我。
2. 真的搞定的吗

过了一天这位朋友又找到我，说把 hsl 升级到最新版本之后还是出现了大量线程，让我再看一下，继续用 ~*e !clrstack 观察各个线程栈，发现还是卡在 pipeSocket.PipeLockEnter() 这里，这就很迷了，代码如下：

1. OS Thread Id: 0x1144 (21)
2.         Child SP               IP Call Site
3. ...
4. 000000A1AFF3DE90 00007ffa9cac6e05 System.Net.Sockets.SocketPal.Connect(System.Net.Sockets.SafeSocketHandle, Byte[], Int32) [/_/src/System.Net.Sockets/src/System/Net/Sockets/SocketPal.Windows.cs @ 118]
5. 000000A1AFF3DEE0 00007ffa9cac6c52 System.Net.Sockets.Socket.DoConnect(System.Net.EndPoint, System.Net.Internals.SocketAddress) [/_/src/System.Net.Sockets/src/System/Net/Sockets/Socket.cs @ 4415]
6. 000000A1AFF3DF30 00007ffa9cac6a63 System.Net.Sockets.Socket.Connect(System.Net.EndPoint) [/_/src/System.Net.Sockets/src/System/Net/Sockets/Socket.cs @ 810]
7. 000000A1AFF3DF80 00007ffa9b7bc75a HslCommunication.Core.NetSupport.CreateSocketAndConnect(System.Net.IPEndPoint, Int32, System.Net.IPEndPoint)
8. 000000A1AFF3DFF0 00007ffa9cac8768 HslCommunication.Core.Net.NetworkBase.CreateSocketAndConnect(System.Net.IPEndPoint, Int32, System.Net.IPEndPoint)
9. 000000A1AFF3E030 00007ffa9cac84ba HslCommunication.Core.Net.NetworkDoubleBase.CreateSocketAndInitialication()
10. 000000A1AFF3E070 00007ffa9cac83b8 HslCommunication.Core.Net.NetworkDoubleBase.ConnectServer()
11. 000000A1AFF3E0B0 00007ffa9c697f8b HslCommunication.Core.Net.NetworkDoubleBase.GetAvailableSocket()
12. 000000A1AFF3E0F0 00007ffa9c697545 HslCommunication.Core.Net.NetworkDoubleBase.ReadFromCoreServer(Byte[], Boolean, Boolean)
13. 000000A1AFF3E160 00007ffa9c6a2779 HslCommunication.Profinet.Siemens.SiemensS7Net.ReadS7AddressData(HslCommunication.Core.Address.S7AddressData[])
14. 000000A1AFF3E1A0 00007ffa9bfedef5 HslCommunication.Profinet.Siemens.SiemensS7Net.Read(System.String, UInt16)
15. ...
17. 0:021> !dso
18. OS Thread Id: 0x1144 (21)
19. RSP/REG          Object           Name
20. 000000A1AFF3E058 00000280c8ca33d8 HslCommunication.Profinet.Siemens.SiemensS7Net
21. 000000A1AFF3E0C0 00000281c9150e58 Microsoft.Win32.SafeHandles.SafeWaitHandle
22. ...
24. 0:021> !gcroot 00000281c9150e58
25. Thread 1144:
26.             ->  00000280C8CA37E8 HslCommunication.Core.SimpleHybirdLock
27.             ->  00000280C8CA3860 System.Lazy`1[[System.Threading.AutoResetEvent, System.Private.CoreLib]]
28.             ->  00000281C9150E40 System.Threading.AutoResetEvent
29.             ->  00000281C9150E58 Microsoft.Win32.SafeHandles.SafeWaitHandle
31. 0:021> !do 00000280C8CA37E8
32. Name:        HslCommunication.Core.SimpleHybirdLock
33. Fields:
34.               MT    Field   Offset                 Type VT     Attr            Value Name
35. 00007ffa998a71d0  4000162       14       System.Boolean  1 instance                0 disposedValue
36. 00007ffa998ab1f0  4000163       10         System.Int32  1 instance              614 m_waiters
37. 00007ffa9bcea5e0  4000164        8 ...Private.CoreLib]]  0 instance 00000280c8ca3860 m_waiterLock
38. 00007ffa998ac570  4000165      2e8         System.Int64  1   static              859 simpleHybirdLockCount
39. 00007ffa998ac570  4000166      2f0         System.Int64  1   static              857 simpleHybirdLockWaitCount

复制代码

从上面的 m_waiters=614 来看，当前有 614 个线程在等待，这里要稍微吐槽一下，建议封装 SimpleHybirdLock 的时候最好记录下当前谁在持有这个锁，不然找起来太难了。。。
经过一顿摸索发现是 21号 线程正在持有 SimpleHybirdLock，正在调用 GetAvailableSocket 方法出不来，截图如下：

3. 为什么获取不到 Socket

既然有 600+ 线程在等待，大概率在获取可用 Socket 上出了什么问题，有了这个思路我们用 !dso 去找下 Socket 的 IP 地址是什么，看看dump中有没有什么异常。

1. 0:021> !dso
2. OS Thread Id: 0x1144 (21)
3. RSP/REG          Object           Name
4. 000000A1AFF3E350 00000281c8ac61a8 System.Object[]    (System.Object[])
5. 000000A1AFF3EA38 00000281c9c80608 System.String    172.16.3.208
6. ....

复制代码

提取到 IP 地址之后，接下来到用  !strings 到 dump 中搜一下可有这个 ip 相关的信息，果不其然，发现有大量的 IP 超时，截图如下：

到这里我们大概就知道了，原来是程序跑着跑着，由于网络等各方面的问题导致 IP 不可访问，进而引发程序系统性崩盘。
4. hsl 真的很无辜吗

这里没有任何针对性，只是从技术上进行一下探讨，先上一下 hsl 对这块的处理，简化后如下：

1. public OperateResult<byte[]> ReadFromCoreServer(byte[] send, bool hasResponseData, bool usePackAndUnpack = true)
2. {
3.     OperateResult<byte[]> operateResult = new OperateResult<byte[]>();
4.     OperateResult<Socket> operateResult2 = null;
5.     pipeSocket.PipeLockEnter();
6.     try
7.     {
8.         operateResult2 = GetAvailableSocket();
9.         if (!operateResult2.IsSuccess)
10.         {
11.             pipeSocket.IsSocketError = true;
12.             pipeSocket.PipeLockLeave();
13.             operateResult.CopyErrorFromOther(operateResult2);
14.             return operateResult;
15.         }
16.         ExtraAfterReadFromCoreServer(operateResult3);
17.         pipeSocket.PipeLockLeave();
18.     }
19.     catch
20.     {
21.         pipeSocket.PipeLockLeave();
22.         throw;
23.     }
24.     if (!isPersistentConn)
25.     {
26.         operateResult2?.Content?.Close();
27.     }
28.     return operateResult;
29. }
31. internal static OperateResult<Socket> CreateSocketAndConnect(IPEndPoint endPoint, int timeOut, IPEndPoint local = null)
32. {
33.     int num = 0;
34.     while (true)
35.     {
36.         num++;
37.         Socket socket = new Socket(endPoint.AddressFamily, SocketType.Stream, ProtocolType.Tcp);
38.         HslTimeOut hslTimeOut = HslTimeOut.HandleTimeOutCheck(socket, timeOut);
39.         try
40.         {
41.             if (local != null)
42.             {
43.                 socket.Bind(local);
44.             }
45.             socket.Connect(endPoint);
46.             hslTimeOut.IsSuccessful = true;
47.             return OperateResult.CreateSuccessResult(socket);
48.         }
49.         catch (Exception ex)
50.         {
51.             socket?.Close();
52.             hslTimeOut.IsSuccessful = true;
53.             if (hslTimeOut.GetConsumeTime() < TimeSpan.FromMilliseconds(500.0) && num < 2)
54.             {
55.                 Thread.Sleep(100);
56.                 continue;
57.             }
58.             if (hslTimeOut.IsTimeout)
59.             {
60.                 return new OperateResult<Socket>(string.Format(StringResources.Language.ConnectTimeout, endPoint, timeOut) + " ms");
61.             }
62.             return new OperateResult<Socket>($"Socket Connect {endPoint} Exception -> " + ex.Message);
63.         }
64.     }
65. }

复制代码

从代码中可以看到，hsl 通过 catch 捕获到了异常，但并没有强制 throw 让用户自己做决断，而是吞到了 OperateResult 返回类中，用户层因为偷懒又没有判断这种异常状态导致了此问题的发生。 从逻辑看 Socket 是一个非常基础的功能，所以我觉得强制抛出更合理一点，逼迫用户可以更早的强制介入。
5. 为什么会有那么多线程

其实还留了一个问题没有解答，那就是为什么会产生那么多的线程，很显然这是一个 hsl 强吞异常导致的副作用，上层没有判断 OperateResult 的异常码，以为一切都 ok，继续它的周期性调度，被迫生成更多的线程池线程去赴死，危机重重，那具体是怎么调度的呢？可以观察各个线程的创建时间即可。

1. 0:021> ~*e .printf "tid=%x\n",@$tid ; .ttime
2. ...
3. Created: Thu Mar  9 09:02:05.541 2023 (UTC + 8:00)
4. Kernel:  0 days 0:00:00.062
5. User:    0 days 0:00:00.125
6. tid=38e8
7. Created: Thu Mar  9 09:02:10.540 2023 (UTC + 8:00)
8. Kernel:  0 days 0:00:00.015
9. User:    0 days 0:00:00.000
10. tid=2d64
11. Created: Thu Mar  9 09:02:15.540 2023 (UTC + 8:00)
12. Kernel:  0 days 0:00:00.015
13. User:    0 days 0:00:00.015
14. tid=3aa4
15. Created: Thu Mar  9 09:02:20.540 2023 (UTC + 8:00)
16. Kernel:  0 days 0:00:00.015
17. User:    0 days 0:00:00.000
18. tid=41ec
19. Created: Thu Mar  9 09:02:25.540 2023 (UTC + 8:00)
20. Kernel:  0 days 0:00:00.203
21. User:    0 days 0:00:00.218
22. ...

复制代码

从各个线程的创建时间来看，大概是 5s 采集一次。
三：总结

这次事故主要是由于在设备采集的过程中 IP 出了问题 导致的线程数暴涨引发的系统性崩溃，个人觉得朋友和hsl都有一定的责任，一个不检查错误码，一个强吞异常。

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