自从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源代码详见:
根据kernel lockup running 3.0.0 and 3.2.0 on multiple ec2 instance types一文中的调用堆栈:
目前我们初步判断“10秒钟”可能发生在调用xen_proll_irq_timeout时,源代码见。
在xen的源代码中找出“10秒钟”的来源不知要花多少时间,所以先写了这篇博文把当前的情况向大家汇报一下——我们与阿里云一直在努力解决问题。
