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

在昨天针对“黑色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。

这篇博文先简单分享一下今天的进展，接下来咱们还要进行更多的分析与排查，阿里云的同窗也在努力排查问题，但愿早日找到问题的缘由并从根本上解决。