我一直在有一些性能问题的服务器上研究 IIS 7.5 中的 W3C 格式日志文件一段时间，在我看来，与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 收到 /Main.aspx 的 GET 请求，发送响应需要 764ms，这意味着响应直到 14:25:17.764 才完成。
- 在 14:25:26，收到 /Main.aspx 的 POST。这是上一个响应完成后的八秒。发送此响应花了 109 毫秒，在 14:25:26.109 结束。
- 在 14:25:56，收到了 /_Start.aspx 的 GET。上一个响应完成后将近 30 秒。这似乎是合适的；在单击 _Start.aspx 的链接之前，用户可能已经研究过 Main.aspx。奇怪的是，发送这个 302 重定向响应（28782 毫秒）花了将近 29 秒，在 14:26:24.782 结束。但这就是为什么我要查看日志以找出原因。
- 在 14:26:33，收到了 /Action.aspx 的 GET。上一个响应完成后大约 8 秒。这似乎很合适（8 秒的用户响应时间）。响应耗时 38032 毫秒（太长了，因此进行了调查），并在 14:27:11.032 结束。
- 在 14:26:46，收到了 /Action.aspx 的 POST。距离上一个响应完成还有8.2 秒。是的，我完全知道用户不必总是等待页面完全呈现，然后再单击链接以获取下一页或按刷新，但这种情况经常发生，即使对于更短的请求也是如此。响应耗时 124 毫秒，于 14:26:46.124 结束。
- 在 14:27:39，收到了 /Information.aspx 的 GET。这是上一个响应完成后的 52.9 秒。这似乎有点长，因为测试人员被告知要尽可能地打击系统，但这并不是不合适的长。响应耗时 52509 毫秒（几乎正好是 52.9 秒！），在 14:28:31.509 结束。如果我将时间字段解释为“收到的请求” ，这是一个非常奇怪的巧合 。
- 在 14:27:52，收到了 /Information.aspx 的 POST。那是上一个响应完成前的 39.5 秒。
这种模式在日志中一遍又一遍地继续存在。
相反，如果我将“时间”字段解释为“响应完成”，那么我会得到更理智的数字：
- 14:25:16.236左右（14:25:17之前的764ms），/Main.aspx的GET收到了，投递耗时764ms，14:25:17完成响应。
- 大约在 14:25:25.891，收到了 /Main.aspx 的 POST。上一个响应完成后大约 8.9 秒。发送此响应花了 109 毫秒，在 14:25:26 结束。
- 大约在 14:25:27.218，收到了 /_Start.aspx 的 GET。这是上一个响应完成后的 1.2 秒。这对于用户响应来说很快，但对于这些训练有素的测试人员浏览知名菜单来说并不算多。响应耗时 28,782ms（太长了，但这是性能分析的原因），并在 14:25:56 结束。
- 大约在 14:25:54.968，收到了 /Action.aspx 的 GET。这大约是前一个响应完成前的 1.0 秒。这可能是一个舍入错误，因为时间字段不捕获毫秒。响应耗时 38032ms，于 14:26:33 结束。
- 大约在 14:26:45.876，收到了 /Action.aspx 的 POST。上一个响应完成后大约 12.9 秒。这对于用户响应时间来说是很正常的。响应耗时 124ms，于 14:26:46 结束。
- 大约在 14:26:46.491，收到了 /Information.aspx 的 GET。这大约是上一个响应完成后的 0.5 秒。这可能是脚本启动的重定向或快速用户。响应耗时 52509ms，于 14:27:39 结束。页面慢。
- 大约在 14:27:51.860，收到了 /Information.aspx 的 POST。这大约是上次响应完成后的 12.9 秒。正常的用户响应时间（巧合的是与之前的 POST 相同）。响应耗时 140 毫秒，于 14:27:52 结束。
“时间”字段表示响应的结束而不是请求的开始对我来说更有意义的另一个原因是：
日志条目以“时间”字段的升序（按时间顺序）物理记录，但它们始终包含“时间”字段，该字段只有在最终交付响应后才能知道。
那么到底是哪条路呢？文档有错吗？