而且还是阵发性的，有某个用户投诉慢的时候，你访问却很快，本地又复现不出来？今天你访问了博客园真是太幸运了，也许这里就有你想要的一个答案——假如你的站点动态处理了图片或者其他原本不会动态处理的非网页资源的话。没想到吧，这是Session惹的祸！
我们公司某个站点访问量一直很大，几年前就已经发现客户经常投诉说很慢，而这个问题我们一直都在排查和解决。从线路问题，到数据库连接泄露，到数据库死锁、索引，以及程序的优化问题，我们都查找过，并且解决过。然而，这个问题总还是存在。比如说，在IIS日志中，就会经常看到time-taken大于10秒钟的访问。而最近我们的KPI要求解决这个问题，不得已，再次踏上这趟艰难的排查之旅。
之所以说艰难，是因为这个现象在本地几乎无法复现，一个是这个现象是阵发性的，第二个是本地访问量或者数据量不够大。我们也尝试过在本地加载线上服务器的数据库，然后拿服务器的IIS的Log文件重播，结果确实是偶尔发现IIS日志中的time-taken也会比较长，但是本地服务器性能不如线上服务器的，比如说IO就差很远，于是总说不清楚到底是什么问题。而线上服务器也不方便用做Dump的形式查找：第一是因为线上一做Dump，站点就会在几分钟内失去响应，这样我们客服的电话就会被打爆；另一个原因还是阵发性的问题，我们不可能一直盯着性能看，然后在发生问题的瞬间做Dump。再说了，看性能也看不出来，因为那些响应时间很长的访问，其前后附近的响应都特别的快。不可避免的，我们只能够在代码里面塞入一些调试和日志的代码，以期望能够得到一些有用的信息。
最开始的时候，我们认为最可能的原因是数据库阻塞，比如正好某一个访问锁住某个数据库对象（比如一张表或者某几行），如果这个时候访问特定的页面，可能就会比较慢。于是在数据库层塞入了一堆代码，这些代码会在数据库连接数量多，或者某个数据库连接时间特别长的时候，将所有数据库连接的当前访问语句、连接持续总时间，以及这些连接当前的堆栈情况都输出到文件中。与此同时，我们还打开Sql profiler对这个数据库进行监视，将持续时间超过1秒钟的都记录下来。然而跑了一天之后，却发现什么都没有被记录下来，但IIS日志中仍然在这段时间内出现许多10秒以上的访问。这个时候，我们就意识到，可能方向错了。
接着，我们就开始塞另外一段代码：一个IHttpModule。这个模块就只是截获每一个页面访问的完整生命周期中的所有事件，比如BeginRequest、PreAuthenticateRequest等。同时在BeginRequest开始的时候设置一个定时器，每隔一秒钟就会出发一个事件，来记录本次访问过程中，本模块收集到的所有线程中当前的堆栈情况。最后，在EndRequest的时候，如果访问时间超过5秒，就将之前截获的所有信息输出到文件中。这一下子问题就变得非常的清晰了，比如说，下面这种输出（片断）就是非常典型的一个情况：
#Steps:
#Fields: date time threadId stepName
#---------------------------------------------------
2009-07-09 16:48:01.752 0024 BeginRequest
2009-07-09 16:48:01.752 0024 AuthenticateRequest
2009-07-09 16:48:01.752 0024 PostAuthenticateRequest
2009-07-09 16:48:01.752 0024 AuthorizeRequest
2009-07-09 16:48:01.752 0024 PostAuthorizeRequest
2009-07-09 16:48:01.752 0024 ResolveRequestCache
2009-07-09 16:48:01.752 0024 PostResolveRequestCache
2009-07-09 16:48:01.752 0024 PostMapRequestHandler
2009-07-09 16:48:06.284 0007 AcquireRequestState
2009-07-09 16:48:06.284 0007 PostAcquireRequestState
2009-07-09 16:48:06.284 0007 PreRequestHandlerExecute
2009-07-09 16:48:06.284 0007 EndRequest
#---------------------------------------------------
#End of steps.
也就是说，在PostMapRequestHandler之后，AcquireRequestState之前，有一大段的等待时间。而这个报告后面的堆栈情况，则显得很奇怪：线程7从第一次截快照的时候开始，一直到结束都是空白的！甚至在其他的一些报告中甚至会发现这个线程已经被分派处理其他页面的工作了（堆栈中的调用很明显指出是另一个aspx页面的代码）。结果一Google“PostMapRequestHandler”和“AcquireRequestState”这两个关键字，就找到了国外另一个有类似遭遇的受害者：
这个楼主是一个aspx页面里面有好几个iframe，并且每一个iframe里面都是访问同一个Web应用下的Aspx页面。现象就是iframe内的页面会一个个蹦出来，尤其是这些页面都比较慢的时候。和我这里截获到的情况一样，也是PostMapRequestHandler事件到AcquireRequestState之间有很长的空白时间。顺藤摸瓜，又找到了这么一个帖子：
?dg=microsoft.public.dotnet.framework.aspnet&mid=7f56033f-caac-47c2-bd9c-95512aa14b47
原来，在AcquireRequestState之前，需要等待上一个同SessionId的页面处理完毕之后，才会继续处理当前页面。其根本原因是：同一个SessionId下面的Session对象不应该被同时写入，否则就会全乱套了，原理和多线程竞争是一样的。因此在设计上，同一个SessionId的页面（或者IHttpHandler）就会顺序执行。
好了，到这里真相又一次大白了！（指不定还有别的问题，还会有下一次大白的时候）在我们的系统中，由于特殊的原因，对图片的输出我们会通过Asp.Net来处理，比如说加上一些合适的缓存标记，甚至会动态生成图片输出（令人惊讶的是，这个动态输出的总时间消耗甚至不到100毫秒，所以不要说动态生成是一种不好的实施方式）。但是，由于没有经过特殊处理，Asp.Net底层认为这些访问时需要对Session进行写操作的，于是就在AcquireRequestState之前挂起，等待上一次同SessionId访问结束。可想而知，图片多了就会导致排队，甚至排很长的队。如果在排队结束之前访问下一个页面，正好系统又没有丢掉之前的队列，则这次访问就会变得比较漫长了。那么怎么做呢？ 在一次顺藤摸瓜，找到了确切的说法：
注意下面的这段话：