云计算之路-阿里云上：读取缓存时的“黑色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