雲計算之路-阿里雲上：原來“黑色0.1秒”發生在socket讀取數據時

在昨天的博文（雲計算之路-阿里雲上：讀取緩存時的“黑色0.1秒”）中我們犯了一個很低級的錯誤——把13ms算成了130ms（感謝陳碩發現這個錯誤！），從而對問題的原因作出了錯誤的推斷，望大家諒解！

從中我們吸取到了一個教訓：趁熱打鐵要小心，容易失去冷靜，作出錯誤的判斷。

今天我們痛定思痛，用了一個下午的時間重新分析了“黑色0.1秒”問題，這次從EnyimMemcached的源代碼下手（https://github.com/enyim/EnyimMemcached）。

怎么下手呢？我們用了最粗魯、最原始的方法，在EnyimMemcached源代碼中反復找點寫日志，運行程序，觀察執行時間，逐步縮小范圍。

。。。

經過一次又一次的努力，終於鎖定了“黑色0.1秒”的引發點：

2014-05-10 15:29:29,903 Enyim.Caching.Memcached.Protocol.Binary.BinaryResponse
MemcachedBinaryResponse-header_socket_read: 103.5174ms

2014-05-10 15:29:29,904 Enyim.Caching.Memcached.MemcachedNode
$MemcachedExecuteOperation-InitPool: 104.4935ms

MemcachedBinaryResponse-header_socket_read的日志記錄代碼是添加在BinaryResponse的Read()方法中的：

public unsafe bool Read(PooledSocket socket)
{
    this.StatusCode = -1;

    if (!socket.IsAlive)
        return false;

    var header = new byte[HeaderLength];

    var startTime = DateTime.Now;            
    socket.Read(header, 0, header.Length);
    LogExecutionTime("header_socket_read", startTime, 10);

    int dataLength, extraLength;
    DeserializeHeader(header, out dataLength, out extraLength);

    if (dataLength > 0)
    {
        var data = new byte[dataLength];
        socket.Read(data, 0, dataLength);
    }

    return this.StatusCode == 0;
}

private void LogExecutionTime(string title, DateTime startTime, int thresholdMs)
{
    var duration = (DateTime.Now - startTime).TotalMilliseconds;
    if (duration > thresholdMs)
    {
        log.ErrorFormat("MemcachedBinaryResponse-{0}: {1}ms", title, duration);
    }
}

原來“黑色0.1秒”發生在執行socket.Read(header, 0, header.Length);的時候，而且從日志中發現EnyimMemcached讀取緩存數據時，超過10ms的操作絕大多數都發生在這個地方。

我們來看一下socket.Read的實現代碼：

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

    int read = 0;
    int shouldRead = count;

    while (read < count)
    {
        try
        {
            int currentRead = this.inputStream.Read(buffer, offset, shouldRead);
            if (currentRead < 1)
                continue;

            read += currentRead;
            offset += currentRead;
            shouldRead -= currentRead;
        }
        catch (IOException)
        {
            this.isAlive = false;
            throw;
        }
    }
}

inputStream的類型是BufferedStream，socket.Read的操作很簡單，就是從BufferedStream中讀取指定長度的Byte數據。

這個操作為什么會超過100ms？以我們有限的知識目前無法作出進一步的推斷。

為了排除BufferedStream讀取方式的原因，我們采用一種更簡潔的讀取方式——BinaryReader。

用下面的代碼取代了原先的socket.Read：

private BinaryReader binReader;
public PooledSocket(...)
{
   //...
   this.inputStream = new BufferedStream(new BasicNetworkStream(socket));   
   binReader = new BinaryReader(this.inputStream);
}

public byte[] ReadBytes(int count)
{
    this.CheckDisposed();

    try
    {
        return binReader.ReadBytes(count);
    }
    catch (IOException)
    {
        this.isAlive = false;
        throw;
    }
}

調用代碼變成了這樣：

public unsafe bool Read(PooledSocket socket)
{
    this.StatusCode = -1;

    if (!socket.IsAlive)
        return false;

    var startTime = DateTime.Now;
    var header = socket.ReadBytes(HeaderLength);            
    LogExecutionTime("header_socket_read", startTime, 10);

    int dataLength, extraLength;
    DeserializeHeader(header, out dataLength, out extraLength);

    if (dataLength > 0)
    {
        var data = socket.ReadBytes(dataLength);
    }

    return this.StatusCode == 0;
}

采用BinaryReader之后，“黑色0.1秒”問題依舊。

這次我們再三確認，沒有犯低級錯誤， “黑色0.1秒”的確是發生在socket讀取數據時。

這次我們依然發出和上次一樣的疑問：究竟是微軟Windows的原因，還是阿里雲虛擬機的原因？

期待有經驗的朋友的指點！

【補充】

1. 前面所說的socket.Read中只是讀取了前24個字節，而后面真正讀取數據時（剩下的字節），超過10ms的情況卻少很多。日志中對比了一下，在16:38-18:10期間，超過10ms的header_socket_read出現了2254次，data_socket_read只出現了129次（超過100ms的只出現了1次）。

var data = new byte[dataLength];
socket.Read(data, 0, dataLength);

2. 連執行System.Net.Sockets.Socket.Send(IList<ArraySegment<byte>> buffers, SocketFlags socketFlags, out SocketError errorCode)都會出現超過50ms的情況。

【附】

修改后的EnyimMemcached代碼：https://github.com/cnblogs/EnyimMemcached

【推薦學習材料】

1. BufferedStream Improves .NET Sockets Performance

2. 《TCP/IP Sockets in C#: Practical Guide for Programmers》中的內容：