阿里云上：“黑色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日）。