日志中的“时间”字段到底表示什么？

我在一台存在一些性能问题的服务器上研究了 IIS 7.5 中的 W3C 格式日志文件一段时间，在我看来，与MSDN 文档 http://technet.microsoft.com/en-us/library/cc754702%28WS.10%29.aspx，“时间”字段是not

“请求发生的时间，以协调世界时 (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 重定向响应花了近 29 秒（28782 毫秒），在 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秒before之前的回复结束了。是的，我完全意识到用户并不总是需要等待页面完全呈现，然后再单击链接获取下一页或按“刷新”，但这种情况经常发生，即使对于较短的请求也是如此。响应耗时 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 秒before之前的回复结束了。

这种模式在日志中不断出现。

相反，如果我将“时间”字段解释为“响应完成”，那么我会得到更理智的数字：

• 大约在 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秒before之前的回复已经结束了。这可能是一个舍入错误，因为时间字段不捕获毫秒。响应耗时 38032ms，于 14:26:33 完成。
• 大约 14:26:45.876，收到 /Action.aspx 的 POST。距离上次响应完成大约 12.9 秒。对于用户响应时间来说这是很正常的。响应耗时 124 毫秒，于 14:26:46 完成。
• 大约 14:26:46.491，收到了 /Information.aspx 的 GET。这距离上次响应完成大约 0.5 秒。这可能是脚本启动的重定向或快速用户。响应耗时 52509 毫秒，于 14:27:39 结束。页面缓慢。
• 大约 14:27:51.860，收到 /Information.aspx 的 POST。这距离上一次响应完成大约 12.9 秒。正常用户响应时间（恰好与之前的 POST 相同）。响应耗时 140 毫秒，于 14:27:52 结束。

“时间”字段代表响应的结束而不是请求的开始对我来说更有意义的另一个原因是：

日志条目以“时间”字段的升序（按时间顺序排列）物理记录，但它们始终包含“耗时”字段，该字段只能被知道after答复终于得到了。

那么是哪条路呢？文档有误吗？

在本页面：http://blogs.msdn.com/b/mike/archive/2008/11/13/time-vs-time-taken-fields-in-iis-logging.aspx https://web.archive.org/web/20160304052659/http://blogs.msdn.com/b/mike/archive/2008/11/13/time-vs-time-taken-fields-in-iis-logging.aspx

it says:

时间字段非常简单：它指定日志条目的创建时间。请注意，这并不总是与日志条目实际写入日志时相同，因为某些请求/响应场景可能会发生缓冲。

因此，您认为时间与请求完成的时间最接近是正确的。同一页继续澄清：

如果您想计算请求的大致开始时间，您可以 从时间值中减去所用时间值。