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

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

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

它有2个最显著的特征：

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

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进程。