云计算之路-阿里云上：黑色1秒，微软的问题还是阿里云的问题？

时间：2014-06-10 16:13:40 阅读：216 评论：0 收藏：0 [点我收藏+]

“黑色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) 日志查询结果

bubuko.com,布布扣

发生了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) 日志查询结果

bubuko.com,布布扣

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

bubuko.com,布布扣

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) 日志查询结果

bubuko.com,布布扣
通过对比“黑色1秒”前后处理的请求量，可以分析出，10:37:35收到的请求，除了http.sys缓存中有的内容，其他请求都被延迟到10:37:36才被处理。

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

bubuko.com,布布扣

可以推断这些请求是在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，也许可以避开这个问题。这也只有阿里云可以做到。