我要评论云上真是无奇不有，这两天我们什么也没动，“黑色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日）。
发表评论