云计算之路-阿里云上:黑色1秒,微软的问题还是阿里云的问题?

黑色1秒”问题经过一个多月的艰苦奋战,今天终于取得了重要进展!我们终于有了足够的数据证明不是微软IIS的问题,就是阿里云Xen虚拟机的问题。

这篇博文分享的是我们如何进行证明的,而且这次证明连Window性能监视器都不需要。

下面我们来分析一下今天10:37:35出现的“黑色1秒”(下面所用的IIS日志分析工具是Log Parser Studio,这是我们在排查“黑色1秒”问题期间对我们帮助最大的一个工具)。

1. 先从IIS日志中找出哪些时间点发生了“黑色1秒”。

a) 在Log Parser Studio中所用的日志查询语句(查询的是10:00-10:59的IIS日志文件)

SELECT  TO_STRING(TO_LOCALTIME(time), 'hh:mm:ss') as Time, COUNT(time) as Requests
FROM '[LOGFILEPATH]'
GROUP BY TIME
HAVING COUNT(time) < 20

b) 日志查询结果

IIS日志统计结果1

发生了2次,我们只分析10:37:35这次。

注:IIS是在请求处理完成后将响应内容发给客户端,客户端发来TCP ACK包时才写入日志。

2. “黑色1秒”期间,IIS日志中的记录情况

a) 日志查询语句

SELECT  TO_STRING(TO_LOCALTIME(time), 'hh:mm:ss') as time,cs-method,cs-uri-stem,time-taken
FROM '[LOGFILEPATH]'
WHERE TO_LOCALTIME(time)='10:37:35'

b) 日志查询结果

IIS日志统计结果2

为什么这12个请求能正常处理?因为这些请求走的是http.sys的kernel-mode缓存(见下图),这证明了在“黑色1秒”期间http.sys工作正常,也从侧面证明了网络层面没问题。

http.sys的kernel-mode缓存

3. “黑色1秒”前后IIS日志中的记录情况

a) IIS日志查询语句

SELECT TO_STRING(TO_LOCALTIME(time), 'hh:mm:ss') as Time, count(time) as Requests
FROM '[LOGFILEPATH]'
WHERE TO_LOCALTIME(time) > '10:37:33' AND TO_LOCALTIME(time) < '10:37:38'
GROUP BY time

b) 日志查询结果

IIS日志查询结果3
通过对比“黑色1秒”前后处理的请求量,可以分析出,10:37:35收到的请求, 除了http.sys缓存中有的内容,其他请求都被延迟到10:37:36才被处理。

c) 查询10:37:36日志中time-taken超过1秒的请求

查询10:37:36日志中time-taken超过1秒的请求

可以推断这些请求是在10:37:35收到的,然后在10:37:36才被处理。

通过1,2,3的分析,我们可以得出结论1:“黑色1秒”是因为请求在http.sys之后的处理环节中被卡住了1秒。

4. 看一下ASP.NET应用程序中的日志情况

在ASP.NET应用程序中我们记录了执行时间超过1秒的请求,代码如下:

public class Global : System.Web.HttpApplication
{
    protected void Application_BeginRequest(Object sender, EventArgs e)
    {
        Context.Items.Add("start-time", DateTime.Now);
    }

    protected void Application_EndRequest(Object sender, EventArgs e)
    {
        if (Context.Items["start-time"] != null)
        {
            var startTime = Convert.ToDateTime(Context.Items["start-time"]);
            if (startTime != default(DateTime))
            {
                var duration = (int)(DateTime.Now - startTime).TotalMilliseconds;
                if (duration > 1000)
                {                     
                    Logger.Default.Info("EndRequest-request-execution-time", duration + "ms", Context);
                }
            }
        }
    }
}

如果“黑色1秒”期间,请求已经进入ASP.NET,在应用程序执行过程中卡住了,那么在应用的日志中会记录这些执行时间超过1秒的请求。

查看应用日志的结果是:不仅10:37:36没有记录到有超过1秒的请求,就连10:37:36-10:37:58也没有超过1秒的请求。

由此我们可以得到结论2:“黑色1秒”期间,请求根本没有进入ASP.NET。

5. 分析小结

通过结论1与结论2,我们再次以真实的数据证明了“黑色1秒”的确是发生在http.sys与ASP.NET的中间处理环节。

那谁负责这些中间处理环节呢?——IIS的核心模块(user-mode的非托管代码),比如w3tp->w3dt->iiscore->webengine->wbhst_pm(详见之前的博文“黑色1秒”最新线索——w3tp与w3dt)。

所以,我们对“黑色1秒”问题分析的最终结论是——“黑色1秒”发生IIS的user-mode核心模块

如果用的是物理机,我们会毫无犹豫地将矛头指向微软;但是我们用的是虚拟机,矛头又多了一个指向——阿里云。

考虑到微软IIS的用户要远远远远多于阿里云的用户,仅仅从情理上,矛头也会指向阿里云更多一些。

我们用了10年多的IIS,之前从来没有遇到过IIS的底层问题;而我们仅用了1年多的阿里云,遇到的问题不计其数,仅仅从出问题的概率上,矛头也指向阿里云更多一些。

如果您关注过去年我们在阿里云上遇到“黑色10秒”问题,你会发现,如果把“1秒”改成“10秒”,这两个“黑色”竟然惊人的相似。而当时“黑色10秒”问题只是从表面解决,从Windows Server 2008 R2升级至Windows Server 2012,阿里云并没有从虚拟化底层去解决。仅仅从曾经的经历,矛头也指向阿里云更多一些。

6. 问题的最终验证

我们想到的最简单但也许是最难的验证方法,其他环境都不变,把虚拟机换成物理机。这只有阿里云可以做到。

7. 建议尝试的临时解决方案

从Windows Server 2012升级至Windows Server 2012 R2,也就是将IIS从8.0升级至8.5,也许可以避开这个问题。这也只有阿里云可以做到。

posted @ 2014-06-10 13:14  博客园团队  阅读(6754)  评论(42编辑  收藏  举报