云计算之路-阿里云上：超级奇怪的“黑色10秒钟”

自从5月24日发布博文（云计算之路-阿里云上：两个重要突破）之后，情况有了明显改善。但是我们不但没有丝毫的放松，反而变得更加艰苦。我们被一个非常非常奇怪的问题所困扰，这段时间我们与阿里云一起在努力与之作艰苦斗争。

这个问题每天会出现十几次，每次出现都会持续10秒钟（“黑色10秒钟”由此而来）。

为了更清楚地表达问题，大家先看一张IIS处理请求的流程图（注：问题不是来自IIS，而是通过IIS定位出问题）。

（注：这张图对理解我们遇到的问题很重要）

问题现象一：出现问题时，在Windows性能监视器中的表现如下：

上图中绿色线条表示的是Web Service->Current Connections（Web Service就是第一张图中的World Wide Web Pulishing Service），出现问题时Current Connections会突然跳上去（通常会跳到200以上）。我们猜测这是瞬间的高并发请求引起的。（这种瞬间高并发请求在压力测试中很难模拟，所以我们一直未能通过压力测试重现这个问题）

上图中棕色线条表示的是ASP.NET Applications->Requests/s，在出问题时这个值会变为0，也就是ASP.NET没处理任何请求。而且ASP.NET->Requests Queued与Requests Current也都为0，说明ASP.NET不仅没有处理请求，可能根本没收到请求。

上图中蓝色线条表示的是TCPv4->Connections Established，出现问题时这个值也会飚上去，通常在1000以上，它稍稍滞后于Current Connections的上升。

上图中红色线条表示的是% Processor Time，出现问题时，Requests/s为0，但CPU却没有明显下降（本来绝大部分CPU占用都消耗在处理请求上）。这就是问题最奇特的地方，CPU被占用了，却什么活也没干。

问题现象二：在问题期间，IIS的http.sys能正常接收请求，但不响应请求，等到“黑色10秒钟”之后才响应累积的请求。

1. 在禁用Output Caching的情况下，“黑色10秒钟”期间的IIS日志显示IIS没有对任何请求进行响应。等到“黑色10秒钟”一过，会出现time-taken为10s, 9s, 8s...这样的请求，这些请求恰恰是在“黑色10秒钟”期间收到的，只是在“黑色10秒钟”之后才进行响应。

2. 如果开启Output Caching，会在IIS日志中看到“黑色10秒钟”期间IIS会正常响应一些静态文件。实际上这些静态文件是http.sys通过Kernel-Mode caching返回的。这说明在问题期间，http.sys是正常的。

问题现象三：在问题期间，ASP.NET应用程序没收到任何请求。

我们在应用程序中记录了访问日志，发现在“黑色10秒钟”期间应用程序也没有收到请求，确认了ASP.NET根本没收到请求，也就是说请求可能没有进入到w3wp进程（应用程序池我们用的是集成模式）。

综合上面的三个现象，我们可以分析出，在“黑色10秒钟”期间http.sys正常，请求没有到达w3wp进程。问题肯定出在http.sys->w3wp之间的某个环节。

再来看一下IIS请求处理流程图：

从图中可以知道，在http.sys->w3wp之间还有WWW service与WAS。而在性能监视器中显示“黑色10秒钟”期间WWW service的Current Connections的值是跳高的，说明WWW service也收到了请求。所以剩下的最大的嫌疑对像就是WAS。而WAS的主要任务就是将请求转发给对应的w3wp，如果它出问题了，w3wp自然收不到请求。

WAS resides in User Layer of IIS. It takes the request from HTTP.SYS and pass it to the respective application pool.

在之前我们走了很多很多弯路，但当我们把焦点放在WAS上，就开辟了一条最有希望的问题解决之路。

我们在Web服务器上通过Process Explorer拿到WAS进程的堆栈信息：

通过堆栈信息，我们发现WAS进程都会等SpinLock，当时我们一看到SpinLock眼前就一亮。因为之前阿里云技术人员问过我们有没有在应用程序中使用SpinLock，说SpinLock在虚拟机上可能会引发CPU空转（在物理机上没这个问题），虽然我们没有在应用程序中使用SpinLock，但是在WAS中用到了，而且是在Windows内核级别。

我们之前提到过在“黑色10秒钟”期间CPU占用没有明显下降（CPU被占用却不干活）的奇特现象如果用CPU空转来解决，简直是完美无缺。

在眼前一亮之后，我们意识到这是非常耀眼的一亮，一定要深挖下去。

SpinLock是在Windows内核级别使用了，而Windows内核出问题的可能性比虚拟机(阿里云用的是Xen)出问题的可能性要小很多很多。所以我们把嫌疑对象放在了Xen上。

在网上找到了两个重要的线索：

1. Kernel lockup running 3.0.0 and 3.2.0 on multiple EC2 instance types

Running lots of threads which utilize spinlocks, we hit a stage where the spinlock is still locked but none of the CPUs seem to be actively holding it.

注：“黑色10秒钟”期间的瞬时高并发请求会造成lots of threads。

2. xen: Send spinlock IPI to all waiters

There is a loophole between Xen's current implementation of pv-spinlocks and the scheduler.

注：Xen在处理spinlock时的确存在bug。

从这两个线索中，我们可以作出这样的假设——“黑色10秒钟”很可能是Xen的bug引起的，接下来要做的就是证明这个假设。

这就是我们发这篇博客时的当前局面，已经完全不一样了，从大海捞针变为做证明题。

阿里云会准备一台安装最新版Linux+最新版Xen的虚拟机以验证问题是否依然存在。

我们准备从Xen的spinlock.c源代码中找出为什么每次都是10秒的证据。

spinlock.c源代码详见：http://svn.dd-wrt.com/browser/src/linux/universal/linux-3.8/arch/x86/xen/spinlock.c

根据Kernel lockup running 3.0.0 and 3.2.0 on multiple EC2 instance types一文中的调用堆栈：