У меня есть приложение ASP.NET MVC, работающее на IIS6 с включенным сопоставлением по шаблону. После выполнения некоторых нагрузочных тестов я копался в лог-файлах, сосредотачиваясь на медленных запросах. У меня есть файл журнала из приложения нагрузочного тестирования, файл журнала IIS и файл журнала из IHttpModule, который я разрабатываю для этой цели и который записывает время Application.BeginRequest и Application.EndRequest.
Когда я сравнил данные для медленных запросов в файле журнала IIS и файле журнала моего модуля, я обнаружил странное поведение.
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
Для всех запросов значения aspnet_processing_end и request_processing_end совпадают довольно близко (разница не более нескольких миллисекунд). Однако некоторые запросы имеют промежуток времени от request_processing_start до aspnet_processing_start до 30 секунд. В чем причина этого лага и как я могу его предотвратить?
Еще несколько подробностей о нагрузочном тесте, который я провел:
- Количество запросов: при длительном среднем 2 в секунду, в пиках не более 20 в секунду. (Это действительно низкий уровень, мы не можем винить сопоставление с подстановочными знаками)
- Использование процессора: плоская линия ниже 5% (мы не можем винить отсутствие мощности процессора)
- Свободная память: более 1 ГБ (Память также не проблема).
- Задержка, которую я описал, возникает только тогда, когда сервер находится под нагрузкой. Когда приложение нагрузочного тестирования не запущено, его невозможно воспроизвести.