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

Question

我一直在服务器上研究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.在上一次响应结束后的8秒钟.花了109ms来完成这个响应,结束于14:25:26.109.
• 在14:25:56,收到了/_Start.aspx的GET.在上一次响应结束后差不多30秒.这似乎合适; 在单击指向_Start.aspx的链接之前,用户可能已经学习过Main.aspx.奇怪的是,差不多29秒才发送302重定向响应(28782ms),结束时间为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秒.花了109ms来完成这个响应,在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秒.这可能是舍入错误,因为时间字段不捕获毫秒.响应时间为38032毫秒,于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

它说:

时间字段非常简单:它指定何时创建日志条目.请注意,这并不总是与日志条目实际写入日志时相同,因为某些请求/响应方案可能会发生缓冲.

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

如果要计算请求的近似开始时间,则应从时间值中减去Time-Taken值.