自从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一文中的调用堆栈:
目前我们初步判断“10秒钟”可能发生在调用xen_proll_irq_timeout时,源代码见http://lxr.free-electrons.com/source/drivers/xen/events.c?v=2.6.39#L1500。
在Xen的源代码中找出“10秒钟”的来源不知要花多少时间,所以先写了这篇博文把当前的情况向大家汇报一下——我们与阿里云一直在努力解决问题。