云计算之路-阿里云上:什么是“黑色1秒”?

黑色1秒

为了更好地分享我们解决“黑色1秒”问题的过程,在这篇博文中我们将专门描述一下“黑色1秒”问题的表现。

“黑色1秒”是我们使用阿里云以来继“黑色10秒”之后遭遇的最奇特、最诡异、最难以捉摸、最富有戏剧性的问题。

它有2个最显著的特征:

第一个是最直观的表现,在Windows性能监视器(Performace Monitor)中会出现1秒的ASP.NET Applications -> Requests/Sec(简称QPS)为0的情况(注:性能监视器的采样周期也是1秒)。

黑色1秒时QPS为0的情况

QPS表示的是The number of requests executed per second. 那17:33:01的时候QPS为0究竟表示的是一种什么状况?

由于在.NET开放出来的源代码中没有找到QPS在性能监视器中的计算方法(这部分可能是在非托管代码webengine.dll中实现的),我们只能猜测。

估计有个Timer每隔1秒读取一个针对requests executed的计数器变量值,然后再清零。在17:33:01时候的QPS为0表示的是在17:33:00-17:33:01之间,用于累加requests executed的计数器变量的值为0。

所以猜测下来的结论是:17:33:01的时候QPS为0,表示17:33:00.000-17:33:01.000这1秒内,没有任何请求被处理。

第二个表现是在IIS日志中会出现1秒无任何记录的情况。

比如上面的案例中,在17:33:00.000-17:33:01.000这1秒内QPS为0,而在IIS日志中17:33:00这个时间点(IIS日志只能记录到秒级)没有任何记录,正好可以对应。

下面是Log Parser Studio的查询结果(UTC时间):

我们再分别看一下前1秒与后1秒的情况。

前1秒——[17:32:59]

只有98条记录,正常情况下应该有200多条记录。这说明了在“黑色1秒”之前的1秒已经有处理能力下降的表现。

后1秒——[17:33:01]

有516条记录,这说明了在“黑色1秒”(17:33:00)内到达http.sys的请求延迟了1秒才被处理(包括部分在17:32:59发出的请求)。

假设http.sys是一个环岛道路的出入口,你站在这个路口观察,正常情况下你看到的是每秒进来200多辆、出去200多辆;突然某1秒,出去的车少了一半多;再过1秒,竟然没车出去;再过1秒,出去的有500多辆。这时你会怎么想?。。。肯定是环岛中间某个地方堵车了。

假设计算QPS的性能监视器是环岛道路中间位置(ASP.NET Runtime所在的位置)的一个收费站,经过一辆车就收一次费(QPS加1)。正常情况下生意很好,每秒200多辆(收入200多块)。突然某1秒,没车经过,这时收费站很紧张——怎么搞的,难道今天的收费指标完不成了?过了1秒,500多辆纷涌而至,原来是虚惊一场,收入一分没少。如果作为收费站的收费员,你会怎么想?。。。肯定是收费站之前的路上某个地方堵车了?

把这两个看到的情况综合一下,通过环岛道路的出入口(http.sys)的情况,可以推断出在“黑色1秒”期间环岛道路中间某个地方堵住了;通过收费站(ASP.NET Runtime所在位置)的情况,可以推断“黑色1秒”期间进入收费站之前的道路上堵住了。于是可以得出,问题肯定出在 http.sys(环岛入口)  -> asp.net runtime(中间的收费站) 的某个中间环节。

另外,通过阿里云的抓包分析,在“黑色1秒”期间,http.sys能正常接收请求,OCS(缓存服务)没收到任何请求,再加上静态文件也没能被处理,进一步说明了问题出在http.sys与asp.net runtime之间的环节。

所以“黑色1秒”问题的本质是:在请求由http.sys开向asp.net runtime的道路上堵车了,为什么堵车?堵在哪里?这是我们努力要揭开的谜?

写到这里,我们不得不再次想到去年遭遇的黑色10秒,实在太相似了。

另外,今天我们解决了http.sys缓存不工作的问题,减少了由http.sys开向asp.net runtime的车辆(请求),这也许有利于减少堵车机会,效果有待一段时间的观察(观察结果显示“黑色1秒”依然会出现)。

【6月5日更新】

1. “黑色1秒”的表现有了新的变化,现在性能监视器中发生QPS为0的时间点与IIS日志无记录的时间点相差2秒。

2. 在“黑色1秒”期间,性能监视器中监测到的W3SVC_W3WP->Requests/Sec是正常的,说明请求已经正常到达W3WP进程。

posted @ 2014-05-29 16:23  博客园团队  阅读(5075)  评论(12编辑  收藏  举报