日志中的“时间”字段确切表示什么？

Question

日志中的“时间”字段确切表示什么？

iisloggingiis-7.5w3c

33

我一段时间以来一直在研究IIS 7.5中的W3C格式日志文件，该服务器存在某些性能问题。与MSDN文档相反，我认为“时间”字段不是:

“请求发生的协调世界时（UTC）时间”

...而实际上它是响应完成发送的时间。

我之所以这样说是因为当我跟踪用户在某种受控环境下的页面请求序列时，他们必须回到过去才能提交下一个请求，否则他们可以以惊人的速度提交带有大量“time-taken”条目的页面请求。

例如（出于安全和清晰起见，我进行了删除、缩写和省略）：

#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

如果我把“时间”解释为“请求接收”（无论是开始还是结束，但在响应开始之前），那么这看起来是错误的。如果我把“时间”解释为“响应完成”，则这些数字就是合理的。日志条目按“时间”字段的升序物理记录（按时间顺序排序），但它们始终包括“time-taken”字段，该字段只能在最终交付响应后才能知道。请问哪种解释正确？是否文档有误？这种模式一直在日志中重复出现。

- Alan McBee

可能是重复的问题：HttpErr Log has Future Time Stamps。 - Paul Sweatte

2

不是重复的问题。我的问题是关于时间字段是否表示请求的开始或结束（答案如下，它表示请求的结束）。另一个SO问题是关于时间值是否“未来”到本地时间（剧透：它是UTC时间）。 - Alan McBee

那就搞清楚了。对于造成的混淆，非常抱歉。 - Paul Sweatte

1个回答

网页内容由stack overflow 提供, 点击上面的

可以查看英文原文，
原文链接

- Wesley Smith · Accepted Answer

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

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

因此，您在思考时间最接近于请求完成时间时是正确的。同一页还进一步阐明：

如果您想计算请求的近似开始时间，您需要从时间值中减去Time-Taken 值。