一:背景 1. 講故事 前段時間有位朋友微信找到我,說他的程式使用 hsl 庫之後,採集 plc 時記憶體溢出,讓我幫忙看一下怎麼回事,哈哈,貌似是分析之旅中的第二次和 hsl 打交道,既然找到我,那就上 windbg 說話吧。 二:WinDbg 分析 1. 為什麼會記憶體溢出 簡單觀察程式的提交記憶體之 ...
一:背景
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()
這裡,這就很迷了,代碼如下:
OS Thread Id: 0x1144 (21)
Child SP IP Call Site
...
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]
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]
000000A1AFF3DF30 00007ffa9cac6a63 System.Net.Sockets.Socket.Connect(System.Net.EndPoint) [/_/src/System.Net.Sockets/src/System/Net/Sockets/Socket.cs @ 810]
000000A1AFF3DF80 00007ffa9b7bc75a HslCommunication.Core.NetSupport.CreateSocketAndConnect(System.Net.IPEndPoint, Int32, System.Net.IPEndPoint)
000000A1AFF3DFF0 00007ffa9cac8768 HslCommunication.Core.Net.NetworkBase.CreateSocketAndConnect(System.Net.IPEndPoint, Int32, System.Net.IPEndPoint)
000000A1AFF3E030 00007ffa9cac84ba HslCommunication.Core.Net.NetworkDoubleBase.CreateSocketAndInitialication()
000000A1AFF3E070 00007ffa9cac83b8 HslCommunication.Core.Net.NetworkDoubleBase.ConnectServer()
000000A1AFF3E0B0 00007ffa9c697f8b HslCommunication.Core.Net.NetworkDoubleBase.GetAvailableSocket()
000000A1AFF3E0F0 00007ffa9c697545 HslCommunication.Core.Net.NetworkDoubleBase.ReadFromCoreServer(Byte[], Boolean, Boolean)
000000A1AFF3E160 00007ffa9c6a2779 HslCommunication.Profinet.Siemens.SiemensS7Net.ReadS7AddressData(HslCommunication.Core.Address.S7AddressData[])
000000A1AFF3E1A0 00007ffa9bfedef5 HslCommunication.Profinet.Siemens.SiemensS7Net.Read(System.String, UInt16)
...
0:021> !dso
OS Thread Id: 0x1144 (21)
RSP/REG Object Name
000000A1AFF3E058 00000280c8ca33d8 HslCommunication.Profinet.Siemens.SiemensS7Net
000000A1AFF3E0C0 00000281c9150e58 Microsoft.Win32.SafeHandles.SafeWaitHandle
...
0:021> !gcroot 00000281c9150e58
Thread 1144:
-> 00000280C8CA37E8 HslCommunication.Core.SimpleHybirdLock
-> 00000280C8CA3860 System.Lazy`1[[System.Threading.AutoResetEvent, System.Private.CoreLib]]
-> 00000281C9150E40 System.Threading.AutoResetEvent
-> 00000281C9150E58 Microsoft.Win32.SafeHandles.SafeWaitHandle
0:021> !do 00000280C8CA37E8
Name: HslCommunication.Core.SimpleHybirdLock
Fields:
MT Field Offset Type VT Attr Value Name
00007ffa998a71d0 4000162 14 System.Boolean 1 instance 0 disposedValue
00007ffa998ab1f0 4000163 10 System.Int32 1 instance 614 m_waiters
00007ffa9bcea5e0 4000164 8 ...Private.CoreLib]] 0 instance 00000280c8ca3860 m_waiterLock
00007ffa998ac570 4000165 2e8 System.Int64 1 static 859 simpleHybirdLockCount
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中有沒有什麼異常。
0:021> !dso
OS Thread Id: 0x1144 (21)
RSP/REG Object Name
000000A1AFF3E350 00000281c8ac61a8 System.Object[] (System.Object[])
000000A1AFF3EA38 00000281c9c80608 System.String 172.16.3.208
....
提取到 IP 地址之後,接下來到用 !strings
到 dump 中搜一下可有這個 ip 相關的信息,果不其然,發現有大量的 IP 超時,截圖如下:
到這裡我們大概就知道了,原來是程式跑著跑著,由於網路等各方面的問題導致 IP 不可訪問,進而引發程式系統性崩盤。
4. hsl 真的很無辜嗎
這裡沒有任何針對性,只是從技術上進行一下探討,先上一下 hsl 對這塊的處理,簡化後如下:
public OperateResult<byte[]> ReadFromCoreServer(byte[] send, bool hasResponseData, bool usePackAndUnpack = true)
{
OperateResult<byte[]> operateResult = new OperateResult<byte[]>();
OperateResult<Socket> operateResult2 = null;
pipeSocket.PipeLockEnter();
try
{
operateResult2 = GetAvailableSocket();
if (!operateResult2.IsSuccess)
{
pipeSocket.IsSocketError = true;
pipeSocket.PipeLockLeave();
operateResult.CopyErrorFromOther(operateResult2);
return operateResult;
}
ExtraAfterReadFromCoreServer(operateResult3);
pipeSocket.PipeLockLeave();
}
catch
{
pipeSocket.PipeLockLeave();
throw;
}
if (!isPersistentConn)
{
operateResult2?.Content?.Close();
}
return operateResult;
}
internal static OperateResult<Socket> CreateSocketAndConnect(IPEndPoint endPoint, int timeOut, IPEndPoint local = null)
{
int num = 0;
while (true)
{
num++;
Socket socket = new Socket(endPoint.AddressFamily, SocketType.Stream, ProtocolType.Tcp);
HslTimeOut hslTimeOut = HslTimeOut.HandleTimeOutCheck(socket, timeOut);
try
{
if (local != null)
{
socket.Bind(local);
}
socket.Connect(endPoint);
hslTimeOut.IsSuccessful = true;
return OperateResult.CreateSuccessResult(socket);
}
catch (Exception ex)
{
socket?.Close();
hslTimeOut.IsSuccessful = true;
if (hslTimeOut.GetConsumeTime() < TimeSpan.FromMilliseconds(500.0) && num < 2)
{
Thread.Sleep(100);
continue;
}
if (hslTimeOut.IsTimeout)
{
return new OperateResult<Socket>(string.Format(StringResources.Language.ConnectTimeout, endPoint, timeOut) + " ms");
}
return new OperateResult<Socket>($"Socket Connect {endPoint} Exception -> " + ex.Message);
}
}
}
從代碼中可以看到,hsl 通過 catch 捕獲到了異常,但並沒有強制 throw 讓用戶自己做決斷,而是吞到了 OperateResult
返回類中,用戶層因為偷懶又沒有判斷這種異常狀態導致了此問題的發生。 從邏輯看 Socket
是一個非常基礎的功能,所以我覺得強制拋出更合理一點,逼迫用戶可以更早的強制介入。
5. 為什麼會有那麼多線程
其實還留了一個問題沒有解答,那就是為什麼會產生那麼多的線程,很顯然這是一個 hsl 強吞異常導致的副作用,上層沒有判斷 OperateResult
的異常碼,以為一切都 ok,繼續它的周期性調度,被迫生成更多的線程池線程去赴死,危機重重,那具體是怎麼調度的呢?可以觀察各個線程的創建時間即可。
0:021> ~*e .printf "tid=%x\n",@$tid ; .ttime
...
Created: Thu Mar 9 09:02:05.541 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.062
User: 0 days 0:00:00.125
tid=38e8
Created: Thu Mar 9 09:02:10.540 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.015
User: 0 days 0:00:00.000
tid=2d64
Created: Thu Mar 9 09:02:15.540 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.015
User: 0 days 0:00:00.015
tid=3aa4
Created: Thu Mar 9 09:02:20.540 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.015
User: 0 days 0:00:00.000
tid=41ec
Created: Thu Mar 9 09:02:25.540 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.203
User: 0 days 0:00:00.218
...
從各個線程的創建時間來看,大概是 5s 採集一次。
三:總結
這次事故主要是由於在設備採集的過程中 IP 出了問題 導致的線程數暴漲引發的系統性崩潰,個人覺得朋友和hsl都有一定的責任,一個不檢查錯誤碼,一個強吞異常。