日志中的“时间”字段究竟表示什么？

Question

我在一台存在一些性能问题的服务器上研究 IIS 7.5 中的 W3C 格式日志文件有一段时间了，在我看来，与MSDN documentation 相反，“时间”字段是 不是

“请求发生的时间，以协调世界时 (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 请求，发送响应耗时 764 毫秒，这意味着响应直到 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,782 毫秒（太长，但这是性能分析的原因），并在 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 秒。这对于用户响应时间来说是很正常的。响应耗时 124 毫秒，于 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 结束。

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

日志条目是按“时间”字段的升序（按时间顺序）物理记录的，但它们始终包含“时间”字段，该字段只有在响应之后才能知道终于发货了。

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

Answer 1

在这个页面上：http://blogs.msdn.com/b/mike/archive/2008/11/13/time-vs-time-taken-fields-in-iis-logging.aspx

上面写着：

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

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

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