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

    TCP/IP Sockets in C#: Practical Guide for Programmers

  • 相关阅读:
    Don't Dismiss Georgia Tech's $6,600 Online Master's Degree
    Java SPI机制学习笔记
    Java SPI机制简介
    Java SPI机制
    Java SPI机制原理和使用场景
    中文代码之Spring Boot集成H2内存数据库
    H2数据库攻略
    JAVA 项目中使用 H2 数据库
    Java内存数据库-H2介绍及实例(SpringBoot)
    内存数据库-H2简介与实践
  • 原文地址:https://www.cnblogs.com/cmt/p/3720682.html
Copyright © 2020-2023  润新知