I have an ASP.NET MVC application running on IIS6 with enabled wildcard mapping. After performing some load tests I digged into log files with focus on the slow requests. I have a log file from the load testing application, IIS log file and the log file from the IHttpModule I develop for this purpose which records time of Application.BeginRequest and Application.EndRequest.
When I compared data for slow requests in the IIS log file and the log file of my module I've discovered some odd behavior.
var request_processing_start = iis_log_file.time - iis_log_file.taken
var aspnet_processing_start = my_module_log_file.begin_request_called
var aspnet_processing_end = my_module_log_file.end_request_called
var request_processing_end = iis_log_file.time
For all requests values of aspnet_processing_end and request_processing_end match pretty close (difference no more then few milliseconds). However some requests have timespan between request_processing_start and aspnet_processing_start up to 30 seconds. What is the cause of this lag and a how can I prevent it?
Some more details of load test I've done:
- Number of requests: on long time average 2 per seconds, in the peaks no more then 20 per second. (This is really low, we cannot blame wildcard mapping)
- Processor usage: flat line bellow 5% (We cannot blame lack of cpu power)
- Free memory: more than 1GB (Memory isn't also issue).
- The lag I described is occurring only when the server is under load. When the load testing application isn't running it cannot be reproduced.