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