What is consuming over 65% of time in an ASP.NET application?

Question

I have an .Net Framework 4.0, ASP.NET, ASP.NET MVC 3 web application hosted on a Windows 7 / IIS 7.5. IIS logging is enabled on this machine and set to log in W3C mode.

The application is compiled by using the Release configuration and has been deployed to IIS with <compilation debug='false' attribute set explicitly. The Web.config specifies the use of SQL Server based session state.

I have added the following statements in Global.asax in BeginRequest and EndRequest events respectively. The results i.e. "sw.Elapsed.TotalMilliseconds" are getting stored in an Application level list of values. I dump these values out via a debug page and get an average of the same.

// in BeginRequest
HttpContext.Current.Items.Add("RequestStartEnd", System.Diagnostics.Stopwatch.StartNew());

// in EndRequest
var sw = (System.Diagnostics.Stopwatch)HttpContext.Current.Items["RequestStartEnd"];
sw.Stop();

I have created a load test which runs a single request against this application with a concurrent user load of 20 users. The test is run in Visual Studio 2010 Ultimate edition.

After running the load test, I am getting an average time-taken as recorded by the stopwatch as 681 milliseconds.The average time-taken as per IIS for these requests (I cleaned out all logs before running the load test) is 2121 milliseconds. The average time-taken as per IIS tallys with the value shown in Visual Studio load test report.

The stopwatch time-taken only accounts for 32% of time-taken as reported by IIS logs / Visual Studio. Where does the other 68% time go?

Update 1: I set the session state to InProc and re-ran the load test. In this scenario the difference between the average time reported by stopwatch and average time-taken reported by IIS logs grew to more than 70%!!! Where is all that time going?

Update 2: @Peter - I tried out the failed request tracing by putting a trace rule to log on status code of 200. Next, I ran the load test with 20 concurrent users for approx 1.5 minutes. Went through last 50 trace files and found that the "Time Taken" field in that report had range of 750ms to 1300ms. The Visual Studio report showed avg. time taken as 2300ms. In the report, using the compact view, I see that the time taken changes between the following transitions (1) AspNetStart -> AspNetAppDomainEnter (2) ManagedPipelineHandler-start ManagedPipelineHandler-end. The (2) item is probably my application's code. Still there is a big difference between max of time-taken as per failed request logs i.e. 1300ms and the avg. time-taken as shown by Visual Studio 2300ms. How to find accounting for that? Thanks for this great tip though!

Answer 1

How long are you running your load test for? If you're running it under windows 7 you may get different results than under a windows server as well. You could be having issues with getting threads allocated to the thread pool under burst loads. .Net will immediately allocate threads up to the thread pool min and then slowly allocate up to the thread pool max. I believe the default settings for client OS's are different than for server OS's. It may be on a client OS the default min thread setting is equal to the number of cores on your machine, meaning that .net will then slowly allocate more threads to meet your burst load.

A simple check would be to let your load test run longer and see if the gap between your 2 measurements narrows.