在昨天的博文(云计算之路-阿里云上:读取缓存时的“黑色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》中的内容: