如何找出为什么一个请求需要很长时间出现在Apache访问日志?

我有一个客户端软件,调用和安装在同一台机器上的Apache HTTP服务器。 在调用apache之前logging日志条目:

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.comparsing同一台计算机的外部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] – 时间戳是请求开始的时间 。 当请求结束时,条目是写入日志的,但是时间是请求开始的时间。

这是因为访问日志是在请求结束时写入的,而不是开头。 所以,如果你在12:00提出要求,而且需要一分钟才能完成,那么直到12:01才能写入。 它可以包含像传输的字节数这样的事实是一个确定的指标。

您也可以从一台主机到另一台主机执行跟踪路由,以查看是否实际获得请求 – 如果在路由期间看到延迟,则说明问题的根源。

两件事情要检查:
– 在服务器上parsing名称mydomain.com的时间(在评论中记入TokenMacGuy)
– 在完成请求时写入日志的脚本的执行时间