雲計算之路-阿里雲上:讀取緩存時的「黑色0.1秒」

看到標題中的「0.1秒」,你也許會呲之以鼻:不會吧,0.1秒也要計較,不是吃飽撐着,是沒吃飽也撐着。html

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

若是你不相信1ms級別,請看這篇文章(微博CacheService架構淺析)中的一段話:服務器

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

進入正題。。。架構

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

一開始咱們用的是雲服務器跑memcached做爲緩存服務,當時覺得是虛擬機跑memcached性能跟不上,因而就期待阿里雲的緩存服務能解決這個問題。tcp

但是等到阿里雲推出OCS(開放緩存服務),換上去以後,讀取緩存超過100ms的狀況仍是會出現。memcached

難道是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配置

Wireshark Capture運行沒多久,就出現了一次「黑色0.1秒」。

應用日誌

成功抓到了包,根據日誌中時間點及緩存Key找到了對應的TCP包:

wireshark抓包

而後在Wireshark的右擊菜單中選擇「Follow TCP Strem」,只顯示這個TCP流的包:

wireshark菜單

wireshark抓包

結果有了一個驚人的發現:雲服務器收到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

相關文章
相關標籤/搜索