iis - 日志中的 "time"字段究竟表示什么？

Question

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

"the time, in Coordinated Universal Time (UTC), at which the request occurred"

... 而是响应完成发送的时间。

我之所以这么说是因为当我在一个有点受控的环境中跟踪用户的页面请求顺序时，他们将不得不及时返回提交下一个请求，否则他们能够以惊人的速度提交他们对页面的请求带有大量耗时条目的页面。

例如(为了安全和清晰，我正在编辑、缩写和省略):

#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,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 秒。这可能是脚本启动的重定向或快速用户。响应耗时 52509 毫秒，在 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

它说:

The Time field is quite straightforward: it specifies when the log entry was created. Note that this is not always the same as when the log entry actually gets written to the log, as buffering can occur for some request/response scenarios.

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

If you wanted to calculate the approximate Start Time of a request, you would subtract the Time-Taken value from the Time value.