☰

如何找出为什么请求需要很长时间才能出现在 Apache 访问日志中？

tag-icon • tag-icon apache-2.2 performance httpd logging
如何找出为什么请求需要很长时间才能出现在 Apache 访问日志中？

我有一个客户端软件，它调用安装在同一台机器上的 apache httpd 服务器。在调用 apache 之前，它会记录一条日志条目：

2011-11-23 13:27:43,777 | 8323|1381677376 | root | DEBUG | Calling http://mydomain.com/api/project/325/postings/add_and_remove_labels

如您所见，该调用是在当地时间 13:27:43 进行的。域名 mydomain.com 解析了同一台机器的外部 IP。

然而，当我查看 access.log 文件时，我发现日志条目的时间戳 [1] 比 5 秒晚：

[23/Nov/2011:13:27:48 +0100] "GET /api/project/325/postings/add_and_remove_labels

这是一个以守护进程模式运行的 mod_wsgi 基础服务器，但我不确定它是否相关（如果请求在 apache 级别，则时间戳应该是开始）。

我怎样才能最好地找到这 5 秒的根源？

欢呼吧，波阿兹

澄清：[1] - 时间戳是指请求开始确实，条目是在请求结束时写入日志的，但时间是从请求开始的。

答案1

这是因为访问日志写在结尾请求的开始，而不是开始。因此，如果您在 12:00 发出请求，并且需要一分钟才能完成，则直到 12:01 才会写入条目。它可以包含传输的字节数等内容，这一事实肯定表明了这一点。

您还可以从一台主机到另一台主机执行跟踪路由，以查看它是否真正收到了请求 - 如果您在路由过程中看到延迟，那么您就找到了问题的根源。

答案2

需要检查两件事：
- 在服务器上解析名称 mydomain.com 的时间（在评论中感谢 TokenMacGuy）
- 脚本的执行时间，因为请求完成后会写入日志

相关内容