《.NET 5.0 背鍋案》第2集：碼中的小窟窿，背後的大坑，發現重要嫌犯 EnyimMemcachedCore

部落格園團隊發表於2020-11-16

在第1集的劇情中，主角是“.NET 5.0 正式版 docker 映象”，它有幸入選第1位嫌疑物件，不是因為它的嫌疑最大，而是它的驗證方法最簡單，只需要再進行一次釋出即可。我們在週五晚上（11月13日）進行了釋出驗證，釋出後沒有出現故障，docker 映象的嫌疑指數下降，但這不能100%證明它的清白，因為可能是因為週五晚上的併發量不夠觸發故障。

在這一集中，主角是 memcached 客戶端 EnyimMemcachedCore，它是到目前為止我們發現的最大嫌疑物件，它是我們從 .NET Framework 版的 EnyimMemcached 遷移到 .NET Core 的，修修補補、補補修修了好幾年，最大的改動是實現非同步化（async/await）。

在 review EnyimMemcachedCore 原始碼的過程中，在 Enyim.Caching.Memcached.MemcachedNode.InternalPoolImpl 的 AcquireAsync() 方法中發現下面這行程式碼：

retval.Reset();

這行程式碼的作用是從 EnyimMemcachedCore 維護的 socket pool 中拿到空閒 socket 連線之後，對該連線進行重置，就比如你在餐廳等到一個空閒位置後，就坐之前服務員會將餐桌清理乾淨。

當看到這個方法的方法名之後沒有 Async 之後，我們當時頭腦中就嗡的一聲，怎麼會，怎麼會，這個地方怎麼會沒有呼叫非同步方法？在我們對 EnyimMemcached 進行非同步化改造時竟然漏掉了這個地方，罪過罪過，這個錯值得關禁閉1個月。

繼續追查案件，看看 Reset() 方法的實現程式碼

public void Reset()
{
    // discard any buffered data
    _inputStream.Flush();

    int available = _socket.Available;

    if (available > 0)
    {
        if (_logger.IsEnabled(LogLevel.Warning))
            _logger.LogWarning(
                "Socket bound to {0} has {1} unread data! This is probably a bug in the code. InstanceID was {2}.",
                _socket.RemoteEndPoint, available, this.InstanceId);

        byte[] data = new byte[available];

        this.Read(data, 0, available);

        if (_logger.IsEnabled(LogLevel.Warning))
            _logger.LogWarning(Encoding.ASCII.GetString(data));
    }
}

從表面上看，這個方法的實現意圖簡單明瞭，就是清除 Socket NetworkStream 的內部緩衝資料，如果清除之後，Socket 中還有資料，就讀取這些資料並在日誌中記錄。

F12檢視一下 NetworkStream.Flush 註釋

// Summary:
//     Flushes data from the stream. This method is reserved for future use.
public override void Flush();

不看不知道，一看嚇一跳，這個方法竟然是個擺設，什麼也沒實現，真的是這樣嗎？github 上檢視 .NET 5.0 的原始碼確認一下，找到 NetworkStream.cs#L743

// Flushes data from the stream.  This is meaningless for us, so it does nothing.
public override void Flush()
{
}

public override Task FlushAsync(CancellationToken cancellationToken)
{
    return Task.CompletedTask;
}

千真萬確，而且這是5年前就已經發生的事實

微軟為什麼放這樣一個擺設？這個擺設會帶來副作用嗎？在 NetworkStream.Flush 的幫助文件中找到了答案：

The Flush method implements the Stream.Flush method; however, because NetworkStream is not buffered, it has no effect on network streams. Calling the Flush method does not throw an exception.

原來 NetworkSteam 是一個與眾不同的 Stream，它沒有 buffered 資料，Flush 操作對它本來就沒有意義，所以這是一個無傷大雅的擺設。

既然 NetworkStream.Flush 是擺設，那 EnyimMemcachedCore 的 Reset 方法中呼叫 NetworkStream.Flush 也是擺設，也是無傷大雅，這裡是否呼叫非同步方法沒有影響，坑不在這裡。

繼續追查，來看後面讀取 _socket.Available 的程式碼

byte[] data = new byte[available];
this.Read(data, 0, available);

以及對應的 Read 方法實現程式碼

public void Read(byte[] buffer, int offset, int count)
{
    this.CheckDisposed();

    int read = 0;
    int shouldRead = count;

    while (read < count)
    {
        try
        {
            int currentRead = _inputStream.Read(buffer, offset, shouldRead);
            if (currentRead == count)
                break;
            if (currentRead < 1)
                throw new IOException("The socket seems to be disconnected");

            read += currentRead;
            offset += currentRead;
            shouldRead -= currentRead;
        }
        catch (Exception ex)
        {
            if (ex is IOException || ex is SocketException)
            {
                _isAlive = false;
            }
            throw;
        }
    }
}

坑在這裡！Read 方法中通過 NetworkStream.Read 同步方法從 socket 讀取資料會阻塞執行緒，如果有很多執行緒在進行這個操作，會造成執行緒池中的執行緒不夠用，在高併發場景下足以致命。

我們來設想一下掉進這個大坑裡的情形。正常情況下，EnyimMemcachedCore 維護著一個 socket 連線池，處理請求的執行緒通過連線池中的某個 socket 連線與 memacahed 伺服器傳輸資料，當發生某種異常情況造成客戶端很多連線突然斷開，很多沒有完成資料傳輸的連線被放回 socket pool，這些連線被後續的執行緒拿到，由於連線是客戶端突發斷開的，拿到 socket 連線的執行緒發現 socket 中還有資料，就在 Reset 方法中讀掉這些資料，對於 tcp 連線，如果想重用它，必須這麼幹（參考NetworkStream doesn't flush data）。在高併發的場景下，當有大量的執行緒忙於這個，如果是非同步方法，需要讀取 socket 資料的執行緒執行緒會被釋放出來，不會帶來大的影響，而如果是同步方法，大量執行緒阻塞在這裡等待讀取 socket 資料，執行緒池中的執行緒就不夠用，而對於 web 應用，每1個請求都需要1個執行緒來處理，執行緒不夠用就會造成請求排隊等分配執行緒，從使用者側看就是開啟頁面緩慢。

從目前來看，我們遇到的四次故障（一、二、三、四）很可能就掉進了這個大坑，但現在不能確認它就是罪魁禍首，需要進一步驗證。

上個週末我們已經實現了非同步的 ResetAsync 併發布上線

public async Task ResetAsync()
{
    int available = _socket.Available;

    if (available > 0)
    {
        if (_logger.IsEnabled(LogLevel.Warning))
        {
            _logger.LogWarning(
                "Socket bound to {0} has {1} unread data! This is probably a bug in the code. InstanceID was {2}.",
                _socket.RemoteEndPoint, available, this.InstanceId);
        }

        var data = new byte[available];

        await ReadAsync(data, 0, available);
    }
}

今天晚上8點左右會進行一次釋出操作，看是否還會出現故障。

對於這個驗證工作，需要至少5次工作日晚上的釋出驗證。

留下的疑問：這個坑埋在園碼中多年，為什麼最近才多次掉進去？而且恰恰是在我們將部落格系統升級到 .NET 5.0，是什麼樣的巧合造成讓 .NET 5.0 背鍋的尷尬？

相關文章