云计算之路-阿里云上：结合IIS日志分析“黑色30秒”问题

wang_rx

　　在昨天针对“黑色30秒”问题的分析中，我们猜测Requests Queued上升是由于正在处理的请求出不去（到达不了客户端）。今天我们结合IIS日志验证这个猜测。
　　IIS日志中有一个重要的指标——time-taken，time-taken不仅包含了请求在服务端执行的时间，还包含了响应的内容从服务端到达客户端的时间（详见以下的引用内容）。

　　Beginning in IIS 6.0, the time-taken field typically includes network time. Before HTTP.sys logs the value in the time-taken field, HTTP.sys usually waits for the client to acknowledge the last response packet send operation or HTTP.sys waits for the client to reset the underlying TCP connection. Therefore, when a large response or large responses are sent to a client over a slow network connection, the value of the time-taken field may be more than expected.

　　计算time-taken的结束时间是在HTTP.sys将响应内容发送给客户端之后，等到客户端发来确认包或者客户端重置了TCP连接。
　　另外，“黑色30秒”只在访问高峰期出现，我们觉得“黑色30秒”可能是某种小问题在高并发时的放大。
　　所以，今天我结合IIS日志分析了一些小波动情况。下面是分析的情况：
　　1）13:47:13性能监视器中出现耗时562ms的请求

　　2）根据time-taken的计算方法，这个请求的time-taken肯定大于562ms，所以我们就在IIS日志中找对应的记录。

　　上图就是这个请求在IIS日志中的记录，05:47:15是GMT时间，对应的北京时间是13:47:15。
　　time-taken竟然比Request Execution Time多了2秒多（2640ms），13:47:13 ASP.NET执行完请求发送给客户端之后，2秒之后才收到客户端的确认包。
　　再看看13:47:15，性能监视器中究竟发生了什么？
　　3）Requests Queued飙升

　　4）Arrival Rate突降

　　5）CPU消耗突降

　　6）Current Connections在上升，在后1秒（13:47:16）到达最高点。

　　13:47:13-13:47:15究竟发生了什么？尤其是在13:47:15。。。
　　再来看另外一次波动情况：

　　竟然在IIS日志中没找到对应的记录，这种情况很让人怀疑是TCP连接被偷偷断掉，也是就是昨天的猜想2。
　　这篇博文先简单分享一下今天的进展，接下来我们还要进行更多的分析与排查，阿里云的同学也在努力排查问题，希望早日找到问题的原因并从根本上解决。