标签：des style blog class code java
在昨天的博文（云计算之路-阿里云上：读取缓存时的“黑色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的原因，还是阿里云虚拟机的原因？
期待有经验的朋友的指点！
【补充】
前面所说的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);
【附】
修改后的EnyimMemcached代码：https://github.com/cnblogs/EnyimMemcached
【推荐学习材料】
BufferedStream Improves .NET Sockets Performance
云计算之路-阿里云上：原来“黑色0.1秒”发生在socket读取数据时,布布扣,bubuko.com
云计算之路-阿里云上：原来“黑色0.1秒”发生在socket读取数据时
标签：des style blog class code java
原文地址：http://www.cnblogs.com/cmt/p/3720682.html
