“黑色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) 日志查询结果
发生了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) 日志查询结果
为什么这12个请求能正常处理？因为这些请求走的是http.sys的kernel-mode缓存（见下图），这证明了在“黑色1秒”期间http.sys工作正常，也从侧面证明了网络层面没问题。
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) 日志查询结果
通过对比“黑色1秒”前后处理的请求量，可以分析出，10:37:35收到的请求，
除了http.sys缓存中有的内容，其他请求都被延迟到10:37:36才被处理。
c) 查询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，也许可以避开这个问题。这也只有阿里云可以做到。