Что конкретно указывает поле "время" в журнале?

Я изучал файлы журнала формата W3C в IIS 7.5 некоторое время на сервере с некоторыми проблемами производительности, и мне кажется, что, вопреки Документация MSDN, поле "время" не

"время в координированном универсальном времени (UTC), в котором произошел запрос"

... но скорее это время, когда ответ был отправлен.

Я говорю об этом, потому что, когда я отслеживаю последовательность запросов страницы от пользователей в несколько контролируемой среде, они должны были вернуться вовремя, чтобы отправить следующий запрос, иначе они смогут представить свои запросы на страницы потрясающе быстро для страницы с большой записью времени.

Например (и я исправляю, сокращаю и упускаю, для обеспечения безопасности и ясности):

#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip sc-status sc-substatus sc-win32-status time-taken
2012-11-28 22:25:17 192.168.0.21 GET /Main.aspx - 80 AWalker 192.168.0.100 200 0 0 764
2012-11-28 22:25:26 192.168.0.21 POST /Main.aspx - 80 AWalker 192.168.0.100 200 0 0 109
2012-11-28 22:25:56 192.168.0.21 GET /_Start.aspx - 80 AWalker 192.168.0.100 302 0 0 28782
2012-11-28 22:26:33 192.168.0.21 GET /Action.aspx - 80 AWalker 192.168.0.100 200 0 0 38032
2012-11-28 22:26:46 192.168.0.21 POST /Action.aspx - 80 AWalker 192.168.0.100 200 0 0 124
2012-11-28 22:27:39 192.168.0.21 GET /Information.aspx - 80 AWalker 192.168.0.100 200 0 0 52509
2012-11-28 22:27:52 192.168.0.21 POST /Information.aspx - 80 AWalker 192.168.0.100 200 0 0 140

Если я интерпретирую "время" как "полученный запрос" (начало или конец, но до начала ответа), это выглядит неправильно. Вот что я имею в виду:

В 22:25:17 был получен GET для /Main.aspx, и для ответа ответ получил 764ms, что означает, что ответ не завершился до 14: 25: 17.764.
В 14:25:26 был получен POST для /Main.aspx. Через восемь секунд после завершения предыдущего ответа. Для выполнения этого ответа потребовалось 109 мс, закончив в 14: 25: 26.109.
В 14:25:56 получен GET для /_Start.aspx. Это почти через 30 секунд после завершения предыдущего ответа. Это кажется уместным; пользователь, возможно, изучил Main.aspx перед тем, как щелкнуть ссылку на _Start.aspx. Поразительно, почти 29 секунд, чтобы доставить этот ответ 302 Redirect (28782ms), заканчивая 14: 26: 24.782. Но вот почему я смотрю журналы, чтобы узнать, почему.
В 14:26:33 получен GET для /Action.aspx. Это примерно через 8 секунд после завершения предыдущего ответа. Это кажется подходящим (время ответа пользователя 8 секунд). Ответ получил 38032мс (слишком долго, следовательно, расследование) и закончил с 14: 27: 11.032.
В 14:26:46 был получен POST для /Action.aspx. Это 8,2 секунды до, предыдущий ответ завершен. Да, я полностью знаю, что пользователям не всегда приходится ждать полной рендеринга страницы, прежде чем нажимать на ссылку, чтобы получить следующую страницу, или нажать "Обновить", но это происходит очень часто, даже для гораздо более коротких запросов. Ответ составил 124 мс, закончив в 14: 26: 46.124.
В 14:27:39 получен GET для /Information.aspx. Это 52,9 секунды после завершения предыдущего ответа. Это кажется немного длинным, так как тестировщикам было сказано, что они попали в систему так сильно, как могли, но это не слишком долго. Ответ составил 52509 мс (почти ровно 52,9 секунды!), Закончив в 14: 28: 31,509. Это очень странное совпадение, которое часто бывает , если я интерпретирую поле времени как "полученный запрос".
В 14:27:52 получен POST для /Information.aspx. В течение 39,5 секунд до предыдущий ответ завершен.

Этот вид шаблона продолжает повторяться снова и снова в журналах.

И наоборот, если бы я интерпретировал поле "время" как означающее "ответ завершен", тогда я получаю более зрелые числа:

Примерно в 14: 25: 16,236 (764 мс до 14:25:17) был получен GET для /Main.aspx, и потребовалось 764 мс для доставки, завершив ответ в 14:25:17.
Примерно в 14: 25: 25.891 был получен POST для /Main.aspx. Это примерно через 8,9 секунды после завершения предыдущего ответа. Потребовалось 109 мс, чтобы доставить этот ответ, закончив в 14:25:26.
Примерно в 14: 25: 27.218 получен GET для /_Start.aspx. Через 1,2 секунды после завершения предыдущего ответа. Это быстро для ответа пользователя, но не слишком много для этих хорошо обученных тестеров, проходящих через известное меню. Ответ составил 28 782 мс (слишком долго, но это послужило причиной анализа производительности) и закончилось в 14:25:56.
Примерно в 14: 25: 54,968 получен GET для /Action.aspx. Это примерно 1,0 секунды до, предыдущий ответ был закончен. Это может быть ошибка округления, так как поле времени не захватывает миллисекунды. Ответ получил 38032 мс и был закончен в 14:26:33.
Примерно в 14: 26: 45.876 был получен POST для /Action.aspx. Это примерно через 12,9 секунды после завершения предыдущего ответа. Это довольно нормально для времени ответа пользователя. Ответ заработал 124 мс и был закончен в 14:26:46.
Примерно в 14: 26: 46.491 получен GET для /Information.aspx. Это было примерно через 0,5 секунды после завершения предыдущего ответа. Это может быть перенаправление script или быстрый пользователь. Реакция заняла 52509 мс и закончилась в 14:27:39. Медленная страница.
Примерно в 14: 27: 51.860 был получен POST для /Information.aspx. Это было около 12,9 секунд после завершения предыдущего ответа. Нормальное время отклика пользователя (совпадающее с предыдущим POST). Ответ заработал 140 мс и закончил в 14:27:52.

Другая причина, по которой мне кажется более разумным, что поле "время" представляет собой конец ответа, а не начало запроса:

Записи журнала записываются физически в порядке возрастания поля "время" (хронологически упорядоченное), но они всегда включают поле "время" , которое может быть известно только после того, как ответ был окончательно доставлен.

И каким образом? Неправильная документация?

Ответ 1