zoukankan      html  css  js  c++  java
  • 云计算之路-阿里云上:“黑色30秒”走了,“黑色1秒”来了,真相也许大白了团队

    云上真是无奇不有,这两天我们什么也没动,“黑色30秒”招呼不打一声就走了,而来了一位不速之客——“黑色1秒”;就写了一篇博文,30秒就变成了1秒,看来多写博客是硬道理。

    在上篇博文的评论中有人说——就30秒,有必要这么较真吗——当时想,别说30秒,哪怕1秒,我们也会较真。结果说1秒,1秒就来了。

    我们看一下“黑色1秒”的情况(以下是今天上午Windows性能监视器的一次截图)。

    1. ASP.NET的QPS(Requests/Sec)为0

    QPS

    在10:10:39的时候,QPS为0(就出现了1秒)。这是“黑色1秒”期间最显著的特征,我们一开始也是通过这个特征发现“黑色1秒”的。

    QPS为0是一种什么状况呢?请看下图:

    IIS请求处理流程图

    QPS为0是因为IIS应用程序池没有收到底层转发过来的请求,从上图中可以看出到达应用程序池之前的请求处理流程是这样的:HTTP.SYS->WWW service->WAS。由此我们可以推断,如果这3环节有一个地方卡住了,就会造成应用程序池收不到请求,从而QPS为0;当然,这有个前提条件——请求已经到达了HTTP.SYS的处理队列。

    接下来,我们就来找数据验证请求是否到达了HTTP.SYS的处理队列。

    2. Arrival Rate不为0

    Arrrival Rate

    Arrrival Rate

    在QPS为0的时间点10:10:39,Arrival Rate的值在472-102之间(性能监视器上点不出这个时间点的数值),说明有请求到达了HTTP.SYS。

    那这能不能说明HTTP.SYS当时是正常呢?

    HTTP.SYS不能逃脱嫌疑,因为Arrival Rate表示的是"Rate at which requests are arriving in the queue",只是代表请求到了HTTP.SYS的队列。如果HTTP.SYS的线程卡住了,请求还是能照常到达HTTP.SYS的队列。

    通过Arrival Rate的数据分析,造成QPS为0的嫌疑对象只剩下3个:HTTP.SYS,WWW service,WAS。

    分析到这里,自然就想起了去年遭遇的“黑色10秒”,当时的表现也是QPS为0,最后发现是卡在了WAS(Windows Process Activation Service),详见云计算之路-阿里云上:超级奇怪的“黑色10秒钟”

    这次会不会也是卡在WAS呢?

    上次将最大的嫌疑对象锁定在WAS是因为在故障期间,IIS日志中有静态文件的响应记录(从HTTP.SYS缓存返回的),证明了HTTP.SYS当时是正常的。

    所以,接下自然要去看IIS日志。

    3. QPS为0的前1秒IIS日志中竟然无任何记录

    在QPS为0发生的时间点10:10:39的前1秒——10:10:38,IIS日志中竟然无任何记录(这也是无意中发现的,开始是通过10:10:39这个时间点去查询,是有记录的)。而这个时间点(10:10:38)的前1秒、后1秒都有记录。

    IIS日志

    (上图所用工具是Log Parser Studio

    这是啥情况?

    有两点很重要:1)记录IIS日志是HTTP.SYS干的活;2)HTTP.SYS是在将响应内容发给客户端后,收到客户端的TCP确认包后记录的。

    由于Arrival Rate有数据,说明不是因为没有请求到达造成IIS日志无记录。

    那是不是因为网络问题造成HTTP.SYS没收到TCP确认包?这个可以通过HTTP ERROR日志进行确认,日志文件在C:WindowsSystem32LogFilesHTTPERR文件夹中,对应的时间点并没有TCP错误。

    所以,造成IIS日志无记录的嫌疑对象应该在HTTP.SYS以及上层处理环节,结合第1部分对QPS为0的分析,还是这三者:HTTP.SYS,WWW service,WAS。

    不管从上到下,还是从下到上,都是HTTP.SYS,WWW service,WAS。

    【进一步分析】

    本来准备写这篇博客时,还打算分析性能监视器中的其他指标。在写的过程中,与曾经的“黑色10秒”进行对比时,突然恍然大悟!再次验证了多写博客是硬道理!

    恍然大悟的是什么呢?

    三个嫌疑对象分别是HTTP.SYS,WWW service,WAS,在“黑色10秒”中IIS日志中有静态文件的记录(来自HTTP.SYS的缓存),说明HTTP.SYS是正常的;而在“黑色1秒”中,IIS日志中没有任何记录,显然说明了HTTP.SYS当时是不正常的。也就是说HTTP.SYS卡住了1秒种,更准确地说是HTTP.SYS的所有处理线程卡住了1秒。

    当HTTP.SYS卡住时,请求转发不到上层,应用程序池收不到请求,ASP.NET没活干,QPS自然为0。

    当HTTP.SYS卡住时,ASP.NET处理完的请求发不出去,IIS日志中自然没记录,而且记录日志就是HTTP.SYS干的活。

    于是,我们的分析结论是“黑色1秒”就是HTTP.SYS卡住了1秒。

    而且卡住之后的1秒的IIS日志也证明了这一点。

    iis log

    从日志分析中看,很多请求time-taken都超过了1s,超过1s恰恰是因为HTTP.SYS卡住了1秒。

    阿里云SLB的日志也进一步证明了这一点。

    所以性能监视器上的表现只是HTTP.SYS卡住的结果:

    performance monitor

    为什么性能监视器中QPS为0的发生点比IIS卡住要晚1秒呢,我们觉得可能是性能监视器采样周期的原因。

    真相大白了?“黑色1秒”问题可以划上圆满的句号了?不,没这么简单!

    【大胆猜想】

    就在我们写博客的期间,又来了一个新的不速之客——“黑色5秒”。

    黑色10秒,黑色30秒,黑色1秒,黑色5秒。。。就叫黑色n秒吧。

    不管黑色多少秒,这些都只是问题的表象,而真正的黑色在虚拟机层面,更准确地说就是Xen。

    在某种触发条件下,Windows中的线程在Xen的虚拟化处理中会被卡住。

    黑色10秒,是因为WAS被卡住,从Windows Server 2008升级至Windows Server 2012只是避开了问题的触发条件。

    黑色30秒,是因为ASP.NET的线程被卡住。

    黑色1秒,是因为HTTP.SYS的线程被卡住。

    黑色5秒,不用管它了,如果问题不解决,还有更多的黑色n秒。。。

    这就是我们的大胆猜想,这就是我们被“黑”无数次之后,最让我们确信的一个猜想!

    而我们能做的也只是猜想,下面就看阿里云的了!

    【最新进展更新】

    2014年5月9日 10:43,阿里云怀疑可能是Windows更新补丁引起的,准备将系统回滚至之前的某个时间点进行观察。

    2014年5月10日 10:15:58,再次出现“黑色1秒”(服务器上安装Windows补丁的最新时间是2014年3月5日)。

  • 相关阅读:
    Do You See Me? Ethical Considerations of the Homeless
    ELDER HOMELESSNESS WHY IS THIS AN ISSUE?
    Endoflife support is lacking for homeless people
    html内联框架
    html字体
    html块 div span
    html列表
    html表格
    SQL Server管理员专用连接的使用   作为一名DBA,经常会处理一些比较棘手的服务无响应问题,鉴于事态的严重性,多数DBA可能直接用“重启”大法,以便尽快的恢复生产环境的正常运转,但是多数情况
    如何配置最大工作线程数 (SQL Server Management Studio)
  • 原文地址:https://www.cnblogs.com/cmt/p/3716523.html
Copyright © 2011-2022 走看看