什么是“时间"?日志中的字段表明是什么? [英] What does the "time" field in the log indicate, exactly?

问题描述

我已经在有一些性能问题的服务器上研究IIS 7.5中的W3C格式日志文件有一段时间了，在我看来，这与 not

I've been studying the W3C format log files in IIS 7.5 for a while on a server with some performance issues, and it seems to me that, contrary to MSDN documentation, the "time" field is not

发出请求的时间，以世界标准时间(UTC)为准"

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

...但是恰好是响应发送完毕的时间.

... but rather it is the time at which the response was finished being sent.

之所以这样说，是因为当我在某种程度上受控制的环境中跟踪用户的页面请求顺序时，他们将不得不及时返回以提交下一个请求，否则他们就可以令人震惊地提交其对页面的请求耗费大量时间的网页很快.

I say this because when I track the sequence of page request from users in a somewhat controlled environment, they would have to be going back in time to submit the next request, or else they are able to submit their requests for pages shockingly fast for a page with a large time-taken entry.

例如(为了安全和清楚起见，我编辑，缩写和省略):

For example (and I am redacting, abbreviating, and omitting, for security and clarity):

#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

如果我将时间"解释为已收到请求"(开始或结束，但在响应开始之前)，那么这看起来是错误的.这就是我的意思:

If I interpret "time" as "request received" (either beginning or end, but before the response begins), then this looks wrong. Here's what I mean:

• 在22:25:17，收到了/Main.aspx的GET，它花了764ms来传递响应，这意味着响应直到14:25:17.764才结束.
• 在14:25:26，收到了/Main.aspx的POST.在上一个响应完成后的八秒钟.花费了109ms才能做出回应，并于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秒钟的用户响应时间).响应花费了38032ms(太长的时间，因此需要进行调查)，并在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秒.

• At 22:25:17, the GET for /Main.aspx was received, and it took 764ms to deliver the response, which means the response didn't finish until 14:25:17.764.
• At 14:25:26, the POST for /Main.aspx was received. That's eight seconds after the previous response finished. It took 109ms to deliver this response, finishing at 14:25:26.109.
• At 14:25:56, the GET for /_Start.aspx was received. That's almost 30 seconds after the previous response finished. This seems appropriate; the user may have studied Main.aspx before clicking the link to _Start.aspx. It took, strangely, nearly 29 seconds to deliver this 302 Redirect response (28782ms), finishing at 14:26:24.782. But that's why I'm looking at the logs, to find out why.
• At 14:26:33, the GET for /Action.aspx was received. That's about 8 seconds after the previous response finished. That seems appropriate (8 seconds user response time). The response took 38032ms (much too long, hence the investigation), and finished at 14:27:11.032.
• At 14:26:46, the POST for /Action.aspx was received. That's 8.2 seconds before the previous response finished. Yes, I am fully aware that users don't always have to wait for the page to fully render before clicking on a link to get the next page, or pressing Refresh, but this happens a lot, even for much shorter requests. The response took 124ms, finishing at 14:26:46.124.
• At 14:27:39, the GET for /Information.aspx was received. That's 52.9 seconds after the previous response finished. That seems a little long, since the testers were told to hit the system as hard as they could, but it's not inappropriately long. The response took 52509ms (almost exactly 52.9 seconds!), finishing at 14:28:31.509. That's a very strange coincidence that happens very often if I interpret the time field as "request received."
• At 14:27:52, the POST for /Information.aspx was received. That's 39.5 seconds before the previous response finished.

这种模式在日志中不断重复.

This kind of pattern keeps going, over and over, in the logs.

相反，如果我将时间"字段解释为响应已完成"，那么我会得到更清晰的数字:

Conversely, if I were to interpret the "time" field to mean "response finished", then I get saner numbers:

• 大约在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秒.这可能是舍入错误，因为时间字段无法捕获毫秒.响应耗时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结束.

• At about 14:25:16.236 (764ms before 14:25:17), the GET for /Main.aspx was received, and it took 764ms to deliver, finishing the response at 14:25:17.
• At about 14:25:25.891, the POST for /Main.aspx was received. That's about 8.9 seconds after the previous response finished. It took 109ms to deliver this response, finishing at 14:25:26.
• At about 14:25:27.218, the GET for /_Start.aspx was received. That's 1.2 seconds after the previous response finished. That's fast for a user response, but not too much for these well-trained testers navigating through a well-known menu. The response took 28,782ms (too long, but this is the cause for the performance analysis), and finished at 14:25:56.
• At about 14:25:54.968, the GET for /Action.aspx was received. That's about 1.0 second before the previous response was finished. That could be a rounding error, since the time field doesn't capture milliseconds. The response took 38032ms, and was finished at 14:26:33.
• At about 14:26:45.876, the POST for /Action.aspx was received. That's about 12.9 seconds after the previous response finished. That's pretty normal for a user response time. The response took 124ms, and was finished at 14:26:46.
• At about 14:26:46.491, the GET for /Information.aspx was received. This was about 0.5 seconds after the previous response finished. That could be a script-initiated redirect or a fast user. The response took 52509ms, and finished at 14:27:39. Slow page.
• At about 14:27:51.860, the POST for /Information.aspx was received. This was about 12.9 seconds after the previous response finished. Normal user response time (coincidentally the same as the previous POST). The response took 140ms, and finished at 14:27:52.

另一个使我觉得时间"字段代表响应结束而不是请求开始的原因是:

The other reason that it just makes more sense to me that the "time" field represents the end of the response, rather than the beginning of the request is this:

日志条目以时间"字段的升序(按时间顺序)进行物理记录，但它们始终包含花费时间"字段，只有在响应后 才能知道终于交付了.

The log entries are recorded physically in ascending order of the "time" field (chronologically ordered), but they always include the "time-taken" field, which could only be known after the response had been finally delivered.

那是哪种方式?文档不对吗?

So which way is it? Is the documentation wrong?

推荐答案

在此页面上:它说:

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

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.

因此，您认为时间最接近请求完成的时间是正确的.继续说明该页面:

Therefore, you are correct in thinking that the time most closely corresponds to the time that the request finished. That same page goes on to clarify:

如果您要计算请求的大概开始时间，则可以从时间"值中减去耗时"值.

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

这篇关于什么是“时间"?日志中的字段表明是什么?的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！