阿里云上：“黑色30秒”走了，?“黑色1秒”来了，真相也许大白了

云上真是无奇不有，这两天我们什么也没动，“黑色30秒”招呼不打一声就走了，而来了一位不速之客——“黑色1秒”；就写了一篇博文，30秒就变成了1秒，看来多写博客是硬道理。在上篇博文的评论中有人说——就30秒，有必要这么较真吗——当时想，别说30秒，哪怕1秒，我们也会较真。结果说1秒，1秒就来了。

云上真是无奇不有，这两天我们什么也没动，“黑色30秒”招呼不打一声就走了，而来了一位不速之客——“黑色1秒”；就写了一篇博文，30秒就变成了1秒，看来多写博客是硬道理。

在上篇博文的评论中有人说——就30秒，有必要这么较真吗——当时想，别说30秒，哪怕1秒，我们也会较真。结果说1秒，1秒就来了。

我们看一下“黑色1秒”的情况（以下是今天上午Windows性能监视器的一次截图）。

1. ASP.NET的QPS(Requests/Sec)为0

在10:10:39的时候，QPS为0（就出现了1秒）。这是“黑色1秒”期间最显著的特征，我们一开始也是通过这个特征发现“黑色1秒”的。

QPS为0是一种什么状况呢？请看下图：

QPS为0是因为IIS应用程序池没有收到底层转发过来的请求，从上图中可以看出到达应用程序池之前的请求处理流程是这样的：HTTP.SYS->WWW service->WAS。由此我们可以推断，如果这3环节有一个地方卡住了，就会造成应用程序池收不到请求，从而QPS为0；当然，这有个前提条件——请求已经到达了HTTP.SYS的处理队列。

接下来，我们就来找数据验证请求是否到达了HTTP.SYS的处理队列。

2. Arrival Rate不为0

在QPS为0的时间点10:10:39，Arrival Rate的值在472-102之间（性能监视器上点不出这个时间点的数值），说明有请求到达了HTTP.SYS。

那这能不能说明HTTP.SYS当时是正常呢？

HTTP.SYS不能逃脱嫌疑，因为Arrival Rate表示的是"Rate at which requests are arriving in the queue"，只是代表请求到了HTTP.SYS的队列。如果HTTP.SYS的线程卡住了，请求还是能照常到达HTTP.SYS的队列。

通过Arrival Rate的数据分析，造成QPS为0的嫌疑对象只剩下3个：HTTP.SYS，WWW service，WAS。

分析到这里，自然就想起了去年遭遇的“黑色10秒”，当时的表现也是QPS为0，最后发现是卡在了WAS(Windows Process Activation Service)，详见云计算之路-阿里云上：超级奇怪的“黑色10秒钟”。

这次会不会也是卡在WAS呢？

上次将最大的嫌疑对象锁定在WAS是因为在故障期间，IIS日志中有静态文件的响应记录（从HTTP.SYS缓存返回的），证明了HTTP.SYS当时是正常的。

所以，接下自然要去看IIS日志。

3. QPS为0的前1秒IIS日志中竟然无任何记录

在QPS为0发生的时间点10:10:39的前1秒——10:10:38，IIS日志中竟然无任何记录（这也是无意中发现的，开始是通过10:10:39这个时间点去查询，是有记录的）。而这个时间点（10:10:38）的前1秒、后1秒都有记录。

（上图所用工具是Log Parser Studio）

这是啥情况？

有两点很重要：1）记录IIS日志是HTTP.SYS干的活；2）HTTP.SYS是在将响应内容发给客户端后，收到客户端的TCP确认包后记录的。

由于Arrival Rate有数据，说明不是因为没有请求到达造成IIS日志无记录。

那是不是因为网络问题造成HTTP.SYS没收到TCP确认包？这个可以通过HTTP ERROR日志进行确认，日志文件在C:\Windows\System32\LogFiles\HTTPERR文件夹中，对应的时间点并没有TCP错误。

所以，造成IIS日志无记录的嫌疑对象应该在HTTP.SYS以及上层处理环节，结合第1部分对QPS为0的分析，还是这三者：HTTP.SYS，WWW service，WAS。

不管从上到下，还是从下到上，都是HTTP.SYS，WWW service，WAS。

【进一步分析】

本来准备写这篇博客时，还打算分析性能监视器中的其他指标。在写的过程中，与曾经的“黑色10秒”进行对比时，突然恍然大悟！再次验证了多写博客是硬道理！

恍然大悟的是什么呢？

三个嫌疑对象分别是HTTP.SYS，WWW service，WAS，在“黑色10秒”中IIS日志中有静态文件的记录（来自HTTP.SYS的缓存），说明HTTP.SYS是正常的；而在“黑色1秒”中，IIS日志中没有任何记录，显然说明了HTTP.SYS当时是不正常的。也就是说HTTP.SYS卡住了1秒种，更准确地说是HTTP.SYS的所有处理线程卡住了1秒。

当HTTP.SYS卡住时，请求转发不到上层，应用程序池收不到请求，ASP.NET没活干，QPS自然为0。

当HTTP.SYS卡住时，ASP.NET处理完的请求发不出去，IIS日志中自然没记录，而且记录日志就是HTTP.SYS干的活。

于是，我们的分析结论是“黑色1秒”就是HTTP.SYS卡住了1秒。

而且卡住之后的1秒的IIS日志也证明了这一点。

从日志分析中看，很多请求time-taken都超过了1s，超过1s恰恰是因为HTTP.SYS卡住了1秒。

阿里云SLB的日志也进一步证明了这一点。

所以性能监视器上的表现只是HTTP.SYS卡住的结果：

为什么性能监视器中QPS为0的发生点比IIS卡住要晚1秒呢，我们觉得可能是性能监视器采样周期的原因。

真相大白了？“黑色1秒”问题可以划上圆满的句号了？不，没这么简单！

【大胆猜想】

就在我们写博客的期间，又来了一个新的不速之客——“黑色5秒”。

黑色10秒，黑色30秒，黑色1秒，黑色5秒。。。就叫黑色n秒吧。

不管黑色多少秒，这些都只是问题的表象，而真正的黑色在虚拟机层面，更准确地说就是Xen。

在某种触发条件下，Windows中的线程在Xen的虚拟化处理中会被卡住。

黑色10秒，是因为WAS被卡住，从Windows Server 2008升级至Windows Server 2012只是避开了问题的触发条件。

黑色30秒，是因为ASP.NET的线程被卡住。

黑色1秒，是因为HTTP.SYS的线程被卡住。

黑色5秒，不用管它了，如果问题不解决，还有更多的黑色n秒。。。

这就是我们的大胆猜想，这就是我们被“黑”无数次之后，最让我们确信的一个猜想！

而我们能做的也只是猜想，下面就看阿里云的了！

【最新进展更新】

2014年5月9日 10:43，阿里云怀疑可能是Windows更新补丁引起的，准备将系统回滚至之前的某个时间点进行观察。

2014年5月10日 10:15:58，再次出现“黑色1秒”（服务器上安装Windows补丁的最新时间是2014年3月5日）。

最新评论