¿Qué indica exactamente el campo" hora " en el registro?

He estado estudiando los archivos de registro de formato W3C en IIS 7.5 durante un tiempo en un servidor con algunos problemas de rendimiento, y me parece que, contrariamente a la documentación de MSDN, el campo "tiempo" es no

"la hora, en Tiempo Universal Coordinado (UTC), en la que se produjo la solicitud"

... pero más bien es el momento en el que se terminó de enviar la respuesta.

Digo esto porque cuando hago un seguimiento de la secuencia de solicitud de página de los usuarios en un entorno algo controlado, tendrían que retroceder en el tiempo para enviar la siguiente solicitud, o de lo contrario son capaces de enviar sus solicitudes de páginas sorprendentemente rápido para una página con una entrada de gran tiempo.

Por ejemplo (y estoy redactando, abreviando y omitiendo, para seguridad y claridad):

#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

Si interpreto "tiempo" como " solicitud recibida" (ya sea principio o fin, pero antes de que comience la respuesta), entonces esto parece incorrecto. Esto es lo que Quiero decir:

• A las 22:25:17, el GET for /Main.aspx fue recibido, y tomó 764ms para entregar la respuesta, lo que significa que la respuesta no terminó hasta las 14:25:17.764.
• A las 14:25:26, el POST de /Main.aspx fue recibido. Eso es ocho segundos después de que la respuesta anterior terminó. Tomó 109ms para entregar esta respuesta, terminando a las 14: 25: 26.109.
• A las 14:25:56, el GET for /_Start.aspx fue recibido. Eso es casi 30 segundos después de que la respuesta anterior terminó. Esto parece apropiado; el usuario puede haber estudiado Principal.aspx antes de hacer clic en el enlace a _Start.aspx. Tomó, extrañamente, casi 29 segundos para entregar esta respuesta de redirección 302 (28782ms), terminando en 14:26:24.782. Pero es por eso que estoy mirando los registros, para averiguar por qué.
• A las 14:26:33, el GET for /Action.aspx fue recibido. Eso es alrededor de 8 segundos después de que la respuesta anterior terminó. Eso parece apropiado (8 segundos de tiempo de respuesta del usuario). La respuesta tomó 38032ms (demasiado tiempo, de ahí la investigación), y terminó a las 14:27:11.032.
• A las 14:26:46, el POST para /Acción.aspx fue recibido. Eso es 8.2 segundos antes de la respuesta anterior terminó. Sí, soy plenamente consciente de que los usuarios no siempre tienen que esperar a que la página se renderice completamente antes de hacer clic en un enlace para obtener la siguiente página, o presionar Actualizar, pero esto sucede mucho, incluso para solicitudes mucho más cortas. La respuesta tomó 124ms, terminando en 14: 26: 46.124.
• A las 14: 27:39, el GET for /Información.aspx fue recibido. Eso es 52.9 segundos después de que la respuesta anterior terminó. Eso parece un poco largo, ya que se les dijo a los probadores que golpearan el sistema tan fuerte como pudieran, pero no es inapropiadamente largo. La respuesta tomó 52509ms (casi exactamente 52.9 segundos!), terminando a las 14: 28: 31.509. Esa es una coincidencia muy extraña que sucede muy a menudo si interpreto el campo de tiempo como " solicitud recibida."
• A las 14:27: 52, el POST para /Información.aspx fue recibido. Eso es 39.5 segundos antes de la respuesta anterior terminó.

Este tipo de patrón se mantiene, una y otra vez, en los registros.

Por el contrario, si interpretara que el campo "tiempo" significa "respuesta terminada", entonces obtendría números más sanos:

• Aproximadamente a las 14:25:16.236 (764ms antes de las 14:25:17), el GET for /Main.aspx fue recibido, y tomó 764ms para entregar, terminando la respuesta a las 14: 25: 17.
• En aproximadamente 14: 25: 25.891, el PUESTO de /Main.aspx fue recibido. Eso es aproximadamente 8.9 segundos después de que la respuesta anterior terminó. Tomó 109ms para entregar esta respuesta, terminando a las 14: 25: 26.
• Alrededor de las 14:25:27.218, el GET for /_Start.aspx fue recibido. Eso es 1.2 segundos después de que la respuesta anterior terminó. Eso es rápido para una respuesta del usuario, pero no demasiado para estos probadores bien entrenados que navegan a través de un menú bien conocido. La respuesta tomó 28.782 ms (demasiado tiempo, pero esta es la causa de la análisis de rendimiento), y terminó a las 14: 25: 56.
• Alrededor de las 14:25:54.968, el GET for /Action.aspx fue recibido. Eso es aproximadamente 1.0 segundos antes de la respuesta anterior se terminó. Eso podría ser un error de redondeo, ya que el campo de tiempo no captura milisegundos. La respuesta tomó 38032ms, y se terminó a las 14: 26: 33.
• Alrededor de las 14:26:45.876, el POST para /Acción.aspx fue recibido. Eso es aproximadamente 12.9 segundos después de que la respuesta anterior terminó. Eso es bastante normal para un tiempo de respuesta del usuario. La respuesta tomó 124ms, y se terminó a las 14: 26: 46.
• Alrededor de las 14:26:46.491, el GET for /Information.aspx fue recibido. Esto fue aproximadamente 0.5 segundos después de que la respuesta anterior terminara. Eso podría ser una redirección iniciada por script o un usuario rápido. La respuesta tomó 52509ms, y terminó a las 14: 27: 39. Página lenta.
• Alrededor de las 14:27:51.860, el POST for /Information.aspx fue recibido. Esto fue aproximadamente 12.9 segundos después de la respuesta anterior terminar. Tiempo de respuesta normal del usuario (coincidentemente el mismo que el POST anterior). La respuesta tomó 140ms, y terminó a las 14: 27: 52.

La otra razón por la que simplemente tiene más sentido para mí que el campo" tiempo " represente el final de la respuesta, en lugar del comienzo de la solicitud, es esta:

Las entradas de registro se registran físicamente en orden ascendente del campo "time" (cronológicamente ordenado), pero siempre incluyen el campo" time-taken", que solo podría ser conocido después de la respuesta había sido finalmente entregado.

Entonces, ¿por dónde es? ¿La documentación es incorrecta?