Apache 日志行出现乱序 - 为什么？答案

【问题标题】：Apache log lines appearing out of sequence - why?Apache 日志行出现乱序 - 为什么？
【发布时间】：2019-06-29 14:03:34
【问题描述】：

我有一个 apache 网络服务器，当某个用户访问某个页面时，我得到一个日志行，其时间戳不同步。

样本输出：

IP1 - - [22/Jun/2009:12:20:40 +0000] "GET URL1" 200 3490 "REFERRING_URL1" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.04506.648; .NET CLR 3.5.21022)"

IP2 - - [22/Jun/2009:12:11:47 +0000] "GET URL2" 200 17453 "-" "Mozilla/5.0 (Macintosh; U; PPC Mac OS X 10.5; en-US; rv:1.9.0.11) Gecko/2009060214 Firefox/3.0.11"

IP3 - - [22/Jun/2009:12:20:41 +0000] "GET URL3" 200 889 "REFERRING_URL2" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.0; GTB6; SLCC1; .NET CLR 2.0.50727; Media Center PC 5.0; 3P_USEC 1.0.11.2; .NET CLR 3.5.30729; .NET CLR 3.0.30618)"

（我已匿名请求 IP - IP1、IP2 和 IP3，请求的 URL - URL1、URL2 和 URL3，以及两个引荐来源网址）

可以看出，三行（按此顺序出现在日志中）是不同步的。这仅在 IP2 请求 URL2 时发生 - 所有其他日志看起来都正常。

有什么想法吗？

【问题讨论】：

标签： apache

【解决方案1】：

日志是在请求完成时写入的，因此早期的长请求可能会在后期的短请求之后写入。将%D 添加到您的 LogFormat 定义中，以查看处理请求所用的时间（以微秒为单位）。

查看更多here

【讨论】：

有没有办法告诉apache在请求开始时而不是完成时写入日志行？
我不这么认为，因为许多数据（计算时间、响应大小等）在处理结束后是已知的。您提供动态内容吗？如果是这样，请让您的代码在请求开始时编写自己的日志
可能值得指出的是，该行包含的时间与请求的开始时间相对应。但是，在请求完成之前不会实际写入该行。因此，在 OP 的示例中，这意味着 IP2/URL2 请求需要很长时间才能完成。（更准确地说，可能不到 9 分钟）

【解决方案2】：

也许您正在执行某种 COMET 请求？

我的第一个想法是日志只记录请求完成的时间？所以也许 IP1 的请求需要一段时间才能完成，但在 IP2 之前到达。只有我知道这样的请求才是 AJAXey Comet 请求。

可能不是正确的答案，也许是一个线索。

编辑：http://www.linuxquestions.org/questions/linux-networking-3/apache-log-entries-order-516354/确认日志中的时间包括将内容传输到浏览器所需的时间。

【讨论】：

不，没有什么异国情调。进一步看，有问题的设备似乎是移动设备（通过其 IP），但有问题的页面（总共约 210k）需要将近 9 分钟才能加载，这似乎仍然很奇怪。
也许不是。试图节省带宽可能是延迟获取数据。强制您的服务器将内容保存在内存中，直到它需要传输页面的页面。（胡思乱想）我没在野外见过这个，但它是有道理的。