記一次 .NET 某感測器採集系統 執行緒爆高分析

一線碼農發表於2023-03-30
執行緒

一：背景

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都有一定的責任，一個不檢查錯誤碼，一個強吞異常。

圖片名稱

相關文章