Mysterious ASP.NET MVC Action High latency issue?

Question

Using Firebug and Chrome developer tools, I can see loading some javascript and css files through an action can take an extra 500ms on my development machine. This happens to different files on different calls and doesn't matter what order I put them in. If I link directly to the files this 500ms delay doesn't ever occur. I can refresh the page over and over and get different values, but they always look like 500ms was added to the request time. If I keep refreshing the page, the extra 500ms shows up on different single files or sometimes two files where one is a 1000ms delay like in the image below.

---

EDIT

Putting Monitor.Enter in my HttpModule's BeginRequest and Monitor.Exit in the EndRequest caused the delay to go away, so my guess is it has something to do with threading multiple requests.

---

I use the method descibed by Evan Nagel here for caching, but the same thing happens when I replace the links with calls to my own controller with an action that just passes a raw file through:

public FileResult RawFile(string path, string contentType)
{
    var server = HttpContext.Server;
    string decodedPath = server.UrlDecode(path);
    string mappedPath = server.MapPath(decodedPath);
    return File(mappedPath, contentType);
}

Here's the code I have in the head section of my html:

<link rel="stylesheet" href="@Url.Action("RawFile", new { controller = "Content", path = "~/Content/Site.css", contentType = "text/css" })" type="text/css" />
<script src="@Url.Action("RawFile", new { controller = "Content", path = "~/Scripts/debug/FBINFO.js", contentType = "application/x-javascript" })" type="text/javascript"></script>
<script src="@Url.Action("RawFile", new { controller = "Content", path = "~/Scripts/jquery-1.4.1.min.js", contentType = "application/x-javascript" })" type="text/javascript"></script>

This doesn't seem to happen on my production server, at least not as often but it is harder to tell because the latency is higher normally. Is this something not to worry about? What would cause it? It happens both with Cassini and with my local IIS server on Windows 7 Home Ultimate 64 bit.

I've added a custom attribute to time the calls and the times between OnAction/OnResult Executing and Executed are generally sub-millisecond. I've used a stopwatch around the action method (the ZipController writes to the response stream and doesn't return a result) and the times are likewise always small, average 1.5ms and always under 10ms.

The only real difference I can see in the Fiddler headers is the X-AspNetMvc-Version header, so I set it to not be appended and even removed the X-AspNet-Version header to no avail. I've tried enabling and disabling compression and about everything else I can think of too. This is after I added my own Cache-Control and ETag headers which had no effect. Interestingly the 500ms delay happens even in the case of a 304 Not Modified response where the body is not sent. Sometimes two of the files will have delays, one 500ms and the other 1000ms.

Direct file:

HTTP/1.1 200 OK
Content-Type: application/x-javascript
Last-Modified: Sun, 29 May 2011 22:42:27 GMT
Accept-Ranges: bytes
ETag: "b57a84af511ecc1:0"
Server: Microsoft-IIS/7.5
Date: Mon, 30 May 2011 04:38:20 GMT
Content-Length: 1336

RawFile action:

HTTP/1.1 200 OK
Cache-Control: public
Content-Type: application/x-javascript
ETag: "CD9F383D0537373C6D2DC8F60D6519A6"
Server: Microsoft-IIS/7.5
Date: Mon, 30 May 2011 04:34:37 GMT
Content-Length: 1336

Following IanT8's comment, I added an HttpModule to track begin/end request, as well as adding log calls as the first and last statements of my action methods. Long story short both requests come in at the same time and the 500ms delay occurs after the first EndRequest, before the action method of the second call is executed. This delay is usually 499ms, but it was 497ms once, 498ms once and 492ms once.

2011-05-31 00:55:19.1874|INFO|20110531 00:55:19.196 BeginRequest: http://localhost:51042/Zip/Style?Path=~/Content/Site.css
2011-05-31 00:55:19.1874|INFO|20110531 00:55:19.197 BeginRequest: http://localhost:51042/Zip/Script?Path=~/Scripts/jquery-1.4.1.min.js|~/Scripts/debug/FBINFO.js
2011-05-31 00:55:19.2034|INFO|20110531 00:55:19.203 Style() Start
2011-05-31 00:55:19.2034|INFO|20110531 00:55:19.208 Style() End
2011-05-31 00:55:19.2034|INFO|20110531 00:55:19.212 EndRequest: http://localhost:51042/Zip/Style?Path=~/Content/Site.css
2011-05-31 00:55:19.7044|INFO|20110531 00:55:19.704 Script() Start
2011-05-31 00:55:19.7044|INFO|20110531 00:55:19.712 Script() End
2011-05-31 00:55:19.7044|INFO|20110531 00:55:19.713 EndRequest: http://localhost:51042/Zip/Script?Path=~/Scripts/jquery-1.4.1.min.js|~/Scripts/debug/FBINFO.js

Now for the really interesting part. I created a static object on my HttpModule and called Monitor.Enter in the BeginRequest and Monitor.Exit in the EndRequest. The delay dissappeared. Chrome shows one call taking about 15-20ms and the other taking about 30-40ms because it has to wait for the first call to end, but the 500ms delay is gone. Obviously this solution is not optimal.

Answer 1

Try to disable session (SessionStateAttribute).