I've been studying the W3C format log files in IIS 7.5 for a while on a server with some performance issues, and it seems to me that, contrary to MSDN documentation, the "time" field is not
"the time, in Coordinated Universal Time (UTC), at which the request occurred"
... but rather it is the time at which the response was finished being sent.
I say this because when I track the sequence of page request from users in a somewhat controlled environment, they would have to be going back in time to submit the next request, or else they are able to submit their requests for pages shockingly fast for a page with a large time-taken entry.
For example (and I am redacting, abbreviating, and omitting, for security and clarity):
#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
If I interpret "time" as "request received" (either beginning or end, but before the response begins), then this looks wrong. Here's what I mean:
- At 22:25:17, the GET for /Main.aspx was received, and it took 764ms to deliver the response, which means the response didn't finish until 14:25:17.764.
- At 14:25:26, the POST for /Main.aspx was received. That's eight seconds after the previous response finished. It took 109ms to deliver this response, finishing at 14:25:26.109.
- At 14:25:56, the GET for /_Start.aspx was received. That's almost 30 seconds after the previous response finished. This seems appropriate; the user may have studied Main.aspx before clicking the link to _Start.aspx. It took, strangely, nearly 29 seconds to deliver this 302 Redirect response (28782ms), finishing at 14:26:24.782. But that's why I'm looking at the logs, to find out why.
- At 14:26:33, the GET for /Action.aspx was received. That's about 8 seconds after the previous response finished. That seems appropriate (8 seconds user response time). The response took 38032ms (much too long, hence the investigation), and finished at 14:27:11.032.
- At 14:26:46, the POST for /Action.aspx was received. That's 8.2 seconds before the previous response finished. Yes, I am fully aware that users don't always have to wait for the page to fully render before clicking on a link to get the next page, or pressing Refresh, but this happens a lot, even for much shorter requests. The response took 124ms, finishing at 14:26:46.124.
- At 14:27:39, the GET for /Information.aspx was received. That's 52.9 seconds after the previous response finished. That seems a little long, since the testers were told to hit the system as hard as they could, but it's not inappropriately long. The response took 52509ms (almost exactly 52.9 seconds!), finishing at 14:28:31.509. That's a very strange coincidence that happens very often if I interpret the time field as "request received."
- At 14:27:52, the POST for /Information.aspx was received. That's 39.5 seconds before the previous response finished.
This kind of pattern keeps going, over and over, in the logs.
Conversely, if I were to interpret the "time" field to mean "response finished", then I get saner numbers:
- At about 14:25:16.236 (764ms before 14:25:17), the GET for /Main.aspx was received, and it took 764ms to deliver, finishing the response at 14:25:17.
- At about 14:25:25.891, the POST for /Main.aspx was received. That's about 8.9 seconds after the previous response finished. It took 109ms to deliver this response, finishing at 14:25:26.
- At about 14:25:27.218, the GET for /_Start.aspx was received. That's 1.2 seconds after the previous response finished. That's fast for a user response, but not too much for these well-trained testers navigating through a well-known menu. The response took 28,782ms (too long, but this is the cause for the performance analysis), and finished at 14:25:56.
- At about 14:25:54.968, the GET for /Action.aspx was received. That's about 1.0 second before the previous response was finished. That could be a rounding error, since the time field doesn't capture milliseconds. The response took 38032ms, and was finished at 14:26:33.
- At about 14:26:45.876, the POST for /Action.aspx was received. That's about 12.9 seconds after the previous response finished. That's pretty normal for a user response time. The response took 124ms, and was finished at 14:26:46.
- At about 14:26:46.491, the GET for /Information.aspx was received. This was about 0.5 seconds after the previous response finished. That could be a script-initiated redirect or a fast user. The response took 52509ms, and finished at 14:27:39. Slow page.
- At about 14:27:51.860, the POST for /Information.aspx was received. This was about 12.9 seconds after the previous response finished. Normal user response time (coincidentally the same as the previous POST). The response took 140ms, and finished at 14:27:52.
The other reason that it just makes more sense to me that the "time" field represents the end of the response, rather than the beginning of the request is this:
The log entries are recorded physically in ascending order of the "time" field (chronologically ordered), but they always include the "time-taken" field, which could only be known after the response had been finally delivered.
So which way is it? Is the documentation wrong?
