云计算之路-阿里云上：从ASP.NET线程角度对“黑色30秒”问题的全新分析

在这篇博文中，咱们抛开对阿里云的怀疑，彻底从ASP.NET的角度进行分析，看能不能找到针对问题现象的更合理的解释。

“黑色30秒”问题现象的主要特征是：排队的请求（Requests Queued）突增，到达HTTP.SYS的请求数（Arrival Rate）降低，QPS（Requests/Sec）降低，CPU消耗降低，Current Connections上升。

昨天晚上18:08左右发生了1次“黑色30秒”，正好借此案例分析一下。

一、为何Requests Queued会突增？

最直接的缘由是ASP.NET没有可用的线程处理当前请求。为何会没有可用的线程呢？ASP.NET可用的线程毕竟是有限的，多是当时瞬间的并发请求太多，ASP.NET来不及建立足够的线程处理这些请求。

咱们来看一下ASP.NET中线程相关的设置——machine.config中的processModel（位于C:\Windows\Microsoft.NET\Framework64\v4.0.30319\Config）。

有4个相关设置：maxWorkerThreads（默认值是20）, maxIoThreads（默认值是20）, minWorkerThreads（默认值是1）, minIoThreads（默认值是1）。（这些设置是针对每一个CPU核）

咱们用的就是默认设置，因为咱们的Web服务器是8核的，因而实际的maxWorkerThreads是160，实际的maxIoThreads是160，实际的minWorkerThreads是8，实际的minIoThreads是8。

基于这样的设置，是否是若是瞬间并发请求是169，就会出现排队？不是的，ASP.NET没这么傻！由于CLR 1秒只能建立2个线程（"The CLR ThreadPool injects new threads at a rate of about 2 per second. "），等线程用完时才建立，黄花菜都凉了。咱们猜想ASP.NET只是根据这个设置去预测线程池中的可用线程是否是紧张，是否是须要建立新的线程，以及建立多少线程。

那什么状况下会出现“黑色30秒”期间那样的大量请求排队？假如并发请求数平时是300，忽然某个瞬间并发请求数是600，超出了ASP.NET预估的所需的可用线程数，因而那些拿不到线程的请求只能排队等待正在执行的请求释放线程以及CLR建立新的线程。随着时间的推移，释放出来的线程+新建立的线程足以处理这些排队的请求，就恢复了正常。

那如何验证这个猜想呢？ 修改maxWorkerThreads, maxIoThreads, minWorkerThreads, minIoThreads的设置，让ASP.NET提供更多的可用线程，目前咱们采用的设置以下：

<processModel enable="true"  requestQueueLimit="5000" maxWorkerThreads="100" maxIoThreads="100" minWorkerThreads="50" minIoThreads="50"/>

若是采用这个设置以后，“黑色30秒”现象几乎不出现，就能验证问题出在这个地方。如今主站www.cnblogs.com已经使用了这个设置，须要观察一段时间进行验证。

【启示】

1) 经过Windows性能监视器监视\ASP.NET\Requests Queued能够直观地评估ASP.NET应用程序的吞吐能力（throughput）。

2) 经过ASP.NET异步编程（async/await）能够有效减小可用线程紧张形成的请求排队问题。

二、为何Arrival Rate会降低？

（上图中的橙色线条）

这是“黑色30秒”问题中最让人不解的地方，ASP.NET中请求再怎么排队，怎么会形成到达HTTP.SYS的请求数降低呢？一开始咱们老是不相信是请求排队引发的Arrival Rate降低，可是监视图中却铁证如山。

写这篇博客以前，咱们忽然想通了！以前忽略了一个地方——当你打这篇博文时，第1个请求是html页面，若是这个请求获得正常响应，浏览器在加载这个页面时会发出多个ajax请求；若是第1个请求被排队，浏览器处于等待状态，后续的ajax请求就不会发出，这样到达HTTP.SYS的请求数就会降低。这也解释了为何有时会在“黑色30秒”的中间阶段Arrival Rate会飙高，正是由于当时被排队的请求所对应的页面中有不少ajax，当它结束排队被执行后，后续的不少ajax请求（可能排队的不少是这样的请求）到达了HTTP.SYS。

因而，咱们相信了是请求排队引发的Arrival Rate降低。

【启示】

不能把目光局限于当前看到的问题表现，而要综合考虑，将诸多因素联系起来理清各类现象之间的关系。

三、QPS降低

与Arrival Rate降低同理，QPS(Requests/Sec)与Arrival Rate是直接相关的，成正比关系。

因而，QPS降低也是由于请求排队。

四、CPU消耗降低

也是同理，Arrival Rate与QPS降低，说明CPU要干的活少了，天然消耗就降低。

因而，CPU消耗降低也是由于请求排队。

五、Current Connections上升

Current Connections是请求排队的一个直接表现，请求还没被执行，链接固然会保持着。

因而，Current Connection上升也是由于请求排队。

六、看一个新指标Requests Executing

（上图绿色的线条表示的是Requests Executing）

在请求排队的期间，正在被ASP.NET执行的请求数（Requests Executing）在增长，说明随着被释放出来的线程增多以及更多的新线程被建立，排列中的请求正在被愈来愈多地执行。这从侧面说明了执行中的线程多是正常的，没有被卡住。（接下来的IIS日志信息会进一步验证这一点）

因而，Requests Executing在增长也是由于请求被排队，并且说明这个排队是正常的，没有哪一个地方卡住了。

七、再来看看IIS日志中请求的time-taken

在“黑色30秒”阶段，IIS日志中没有time-taken超过1s的请求！这说明了什么？说明了正在被执行的请求处理速度很快，没有什么地方被卡住。。。除了由于可用线程不够，请求被排队。

因而，IIS日志说明除了请求排队，其余地方一切正常。

【总结】

若是把“黑色30秒”问题归因于ASP.NET线程问题，除了30秒左右的这个时间，其余问题表现都获得了更合理的解释。

写这篇博客以前，咱们当时以为ASP.NET线程问题引发“黑色30秒”问题的可能性是80%，写完这7点分析以后，咱们以为可能性是99%，除非此次分析的“黑色30秒”与以前的“黑色30秒”不是同一个问题。

如今还须要咱们使用新设置(maxWorkerThreads="100", maxIoThreads="100", minWorkerThreads="50", minIoThreads="50")以后的验证。

大结局即未来临，重要的可能不是结局是什么，而是其中的过程，咱们分享的也是解决问题的过程。

【“黑色30秒”相关博文】

云计算之路-阿里云上：Web服务器遭遇奇怪的“黑色30秒”问题

云计算之路-阿里云上：排查“黑色30秒”问题-为何请求会排队

云计算之路-阿里云上：对“黑色30秒”问题的猜测

云计算之路-阿里云上：结合IIS日志分析“黑色30秒”问题

云计算之路-阿里云上：借助IIS Log Parser Studio分析“黑色30秒”问题

【参考资料】

ASP.NET Thread Usage on IIS 7.5, IIS 7.0, and IIS 6.0

Tuning IIS - machine.config settings