云上真是无奇不有,这两天我们什么也没动,“黑色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),详见。
这次会不会也是卡在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秒都有记录。
(上图所用工具是)
这是啥情况?
有两点很重要: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日)。