雲計算之路-阿里雲上：讀取緩存時的“黑色0.1秒”

看到標題中的“0.1秒”，你也許會呲之以鼻：不會吧，0.1秒也要計較，不是吃飽撐着，是沒吃飽也撐着。

依然沒撐着！在memcached應用場景中，響應速度是處於1ms級別的，0.1s可是比1ms慢了100倍啊。

如果你不相信1ms級別，請看這篇文章（微博CacheService架構淺析）中的一段話：

目前微博平台部分業務子系統的Cache服務已經遷移到了CacheService之上，它在實際的運行過程中也取得了良好的性能表現，目前整個集群在線上每天支撐着超過300W的QPS，平均響應耗時低於1ms。

進入正題。。。

自從使用阿里雲以來，我們一直被一個問題困擾——日志中時不時會記錄讀取緩存超過100ms的情況。

一開始我們用的是雲服務器跑memcached作為緩存服務，當時以為是虛擬機跑memcached性能跟不上，於是就期待阿里雲的緩存服務能解決這個問題。

可是等到阿里雲推出OCS（開放緩存服務），換上去之后，讀取緩存超過100ms的情況還是會出現。

難道是memcached客戶端EnyimMemcached的問題，看了EnyimMemcached的源代碼，也沒看出問題，EnyimMemcached只是Socket讀取數據然后二進制反序列化，這地方再慢也不至於超過100ms吧。

百思不得其解，這個問題就一直放着。。。

今天早上發現日志中記錄了00:00-8:00之間竟然發生了近1200次的讀取緩存超過100ms的情況，幾乎每分鍾都出現。昨天剛剛給“黑色n秒”問題找到了最合理的猜想，正處在勁頭上。於是趁熱打鐵，給“黑色n秒”家族添加了一位新成員——“黑色0.1秒”，好好分析一下。

那分析從何處開始呢？我們把懷疑對象鎖定在了網絡TCP層，所以從抓包開始。

對於Windows系統，最強大的抓包工具非Wireshark莫屬。

在雲服務器上啟動Wireshark，選擇與OCS進行通信的內網接口，配置Capture Filter只抓取與OCS進行通信的TCP包。

Wireshark Capture運行沒多久，就出現了一次“黑色0.1秒”。

成功抓到了包，根據日志中時間點及緩存Key找到了對應的TCP包：

然后在Wireshark的右擊菜單中選擇“Follow TCP Strem”，只顯示這個TCP流的包：

結果有了一個驚人的發現：雲服務器收到OCS響應包的時間是11:23:22.780498，而雲服務器發出ACK確認包的時間卻是11:23:793597，竟然相差了130.9913.099ms（不好意思，這個地方犯了一個低級錯誤，應該是13ms。下面對TCP層問題的推斷是錯誤的，我們會重新分析這個問題）；而日志中緩存讀取時間是132.8142ms，0.1秒都耗在了雲服務器TCP層在收到包與發ACK包之間。

這個問題應該是TCP層的問題，與上層沒問題，與EnyimMemcached就更沒關系了。

為了驗證這一點，我們修改了一下EnyimMemcached的源代碼，在Enyim.Caching.Memcached.Protocol.Binary.BinaryResponse的Read方法中添加了一行代碼System.Threading.Thread.Sleep(2000);，讓EnyimMemcached在讀取緩存數據時暫停2s：

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

    if (!socket.IsAlive)
        return false;

    System.Threading.Thread.Sleep(2000); var header = new byte[HeaderLength];
    socket.Read(header, 0, header.Length);

    int dataLength, extraLength;

    DeserializeHeader(header, out dataLength, out extraLength);

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

        this.Extra = new ArraySegment<byte>(data, 0, extraLength);
        this.Data = new ArraySegment<byte>(data, extraLength, data.Length - extraLength);
    }

    return this.StatusCode == 0;
}

然后在正常情況下抓包（沒有出現黑色0.1秒）

雲服務器收到OCS響應包與發ACK包之間只相差了0.00002秒（0.02ms）。

抓包數據證明了“黑色0.1秒”與EnyimMemcached沒有關系，屬於TCP層的問題。

於是又引發了一個問了無數次的問題？是微軟Windows的問題還是阿里雲虛擬機的問題？ 

【該問題的后續分析】

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

【推薦學習材料】

Understanding TCP Sequence and Acknowledgment Numbers