首页 > 代码库 > 云计算之路-阿里云上:原来“黑色0.1秒”发生在socket读取数据时

云计算之路-阿里云上:原来“黑色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 = http://www.mamicode.com/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 =http://www.mamicode.com/ socket.ReadBytes(dataLength);
    }

    return this.StatusCode == 0;
}

采用BinaryReader之后,“黑色0.1秒”问题依旧。

这次我们再三确认,没有犯低级错误, “黑色0.1秒”的确是发生在socket读取数据时。

这次我们依然发出和上次一样的疑问:究竟是微软Windows的原因,还是阿里云虚拟机的原因?

期待有经验的朋友的指点!

【补充】

前面所说的socket.Read中只是读取了前24个字节,而后面真正读取数据时(剩下的字节),超过10ms的情况却少很多。日志中对比了一下,在16:38-18:10期间,超过10ms的header_socket_read出现了2254次,data_socket_read只出现了129次(超过100ms的只出现了1次)。

var data = http://www.mamicode.com/new byte[dataLength];
socket.Read(data, 0, dataLength);

【附】

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

【推荐学习材料】

BufferedStream Improves .NET Sockets Performance