zoukankan      html  css  js  c++  java
  • 云计算之路-阿里云上:结合IIS日志分析“黑色30秒”问题团队

    在昨天针对“黑色30秒”问题的分析中,我们猜测Requests Queued上升是由于正在处理的请求出不去(到达不了客户端)。今天我们结合IIS日志验证这个猜测。

    IIS日志中有一个重要的指标——time-taken,time-taken不仅包含了请求在服务端执行的时间,还包含了响应的内容从服务端到达客户端的时间(详见以下的引用内容)。

    Beginning in IIS 6.0, the time-taken field typically includes network time. Before HTTP.sys logs the value in the time-taken field, HTTP.sys usually waits for the client to acknowledge the last response packet send operation or HTTP.sys waits for the client to reset the underlying TCP connection. Therefore, when a large response or large responses are sent to a client over a slow network connection, the value of the time-taken field may be more than expected.

    计算time-taken的结束时间是在HTTP.sys将响应内容发送给客户端之后,等到客户端发来确认包或者客户端重置了TCP连接。

    另外,“黑色30秒”只在访问高峰期出现,我们觉得“黑色30秒”可能是某种小问题在高并发时的放大。

    所以,今天我结合IIS日志分析了一些小波动情况。下面是分析的情况:

    1)13:47:13性能监视器中出现耗时562ms的请求

    2)根据time-taken的计算方法,这个请求的time-taken肯定大于562ms,所以我们就在IIS日志中找对应的记录。

    上图就是这个请求在IIS日志中的记录,05:47:15是GMT时间,对应的北京时间是13:47:15。

    time-taken竟然比Request Execution Time多了2秒多(2640ms),13:47:13 ASP.NET执行完请求发送给客户端之后,2秒之后才收到客户端的确认包。

    再看看13:47:15,性能监视器中究竟发生了什么?

    3)Requests Queued飙升

    4)Arrival Rate突降

    5)CPU消耗突降

    6)Current Connections在上升,在后1秒(13:47:16)到达最高点。

    13:47:13-13:47:15究竟发生了什么?尤其是在13:47:15。。。

    再来看另外一次波动情况:

    竟然在IIS日志中没找到对应的记录,这种情况很让人怀疑是TCP连接被偷偷断掉,也是就是昨天的猜想2

    这篇博文先简单分享一下今天的进展,接下来我们还要进行更多的分析与排查,阿里云的同学也在努力排查问题,希望早日找到问题的原因并从根本上解决。

  • 相关阅读:
    【某集训记录】
    【bzoj 4407】于神之怒加强版
    【bzoj 3529】【sdoi 2014】数表
    PHP消息队列实现及应用
    (转)PHP DB 数据库连接类
    站点http升级到https
    虚拟主机发送邮件出现getmypid禁用的解决方案
    企业微信API集成登录以及其他操作开发
    微信小程序发送模版消息常见错误解决方案
    (转) Laravel自带SMTP邮件组件实现发送邮件(QQ、163、企业邮箱都可)
  • 原文地址:https://www.cnblogs.com/cmt/p/3688683.html
Copyright © 2011-2022 走看看