云计算之路-阿里云上：原来“黑色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》中的内容：