Thursday, July 30, 2015

IIS 8.5 awful performance on first request to MVC site

My home dev machine is (currently) running Windows 8.1, with IIS 8.5 therefore, has 16GB RAM, a well proportioned SSD, 4 cores@3.5Ghz. When I develop my MVC applications, I normally run an MVC app itself as a web site under IIS, with its own app pool - mainly because, although IIS express is good, I don't find it good enough for my purposes.

Everything has been going swimmingly. After building any site, response to the first request has been < 5 seconds; sure, some compilation is going on, and I'm in full debug mode, but these times do not matter too much in the grand scheme of things.

Except when it spikes, and remains spiked.

This happened a few days ago. The site I was currently extending ballooned its first request response time from about 4 seconds to 2 minutes and finally to 3 minutes in next to no time at all. Now, I like the opportunity to think as much as the next person, but 3 minutes is beyond a joke.

Cue a Google search regarding such IIS performance issues. The list went on an on as to culprits; perhaps an unreachable database connection, slow DNS lookup, running as 32 bit (!),  all sorts of variations on IIS app pool settings (auto start, suspend and so on), secret Microsoft CRL queries - you get the idea.

A couple of the less whacky ones I tried, to no avail. Then I thought I'd give DebugDiag a go, so downloaded, installed, created some rules, captured some dumps. Nothing.

Back to basics seemed to be in order. So I installed procmon, recycled the app pool in question, set procmon going, filtering on just w3wp.exe.

I then issue the first request, and the response is, as expected, glacial. But this is where a blunt instrument like procmon sometimes wins out - because it highlighted immediately that w3wp.exe was issuing hundreds of thousands of requests to write files. Examining one of the files told me immediately that this was my fault - it was an assembly binding log file, as produced by the Fusion sub system. Fully 2 minutes 50+ was creating log files.

I'd forced Fusion logging on some months before, to debug an obscure issue I had with loading AForge.NET assemblies. So, open regedit, navigate to HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Fusion, and set ForceLog to 0.

Recycle app pool, issue first request. 4 second response time again!

No comments: