![Apache 日志 - 列出的请求有较长的延迟](https://linux22.com/image/670374/Apache%20%E6%97%A5%E5%BF%97%20-%20%E5%88%97%E5%87%BA%E7%9A%84%E8%AF%B7%E6%B1%82%E6%9C%89%E8%BE%83%E9%95%BF%E7%9A%84%E5%BB%B6%E8%BF%9F.png)
我使用的是 Apache/2.2.15 (Unix)。在特定项目(使用 php 5.3)中,日志显示请求(来自复杂表单的 POST)是在请求执行很长时间之后(40-50 分钟)才执行的。
有时请求会超时;有时(如用户所述)请求会正常进行。但我无法解释请求发出时间和记录时间之间的巨大时间差。
你知道为什么会发生这种情况吗?你有没有注意到类似的情况?
以下是一些日志行:
[12/Oct/2015:11:32:01 -0500] "GET /adm/manageCompanies.php....
[12/Oct/2015:11:32:04 -0500] "GET /adm/manageCompanies.php....
[12/Oct/2015:**10:25:00** -0500] "POST /adm/manageCompanies.ph....
[12/Oct/2015:11:32:04 -0500] "GET /adm/manageCompanies.php....
[12/Oct/2015:11:32:08 -0500] "GET /adm/manageCompanies.php....
带有粗体时间的行就是问题所在 - 它完全是按顺序记录的......
下面再举一个例子:
[13/Oct/2015:08:18:05 -0500] "POST /adm/manageCompanies.php....
[13/Oct/2015:08:18:05 -0500] "GET /adm/manageCompanies.php ....
[13/Oct/2015:08:22:53 -0500] "GET /adm/manageCompanies.php ....
[13/Oct/2015:**07:37:37** -0500] "POST /adm/manageCompanies.php....
[13/Oct/2015:08:32:48 -0500] "GET /adm/manageCompanies.php ....
[13/Oct/2015:08:32:50 -0500] "GET /adm/manageCompanies.php ....
我该如何找到这个问题的原因?这不是日志记录的问题,而是提交的表单超时并造成“损坏”。
答案1
这个时间是Apache收到请求的时间。
Apache 在请求完成后写入日志。
您可以检查服务器状态哪些请求太长,如果发现一个请求太长,就获取其 PID。
然后你可以 strace 此过程来查看它在做什么:
strace -t -tt -p PID
lsof 可以帮助您查看文件描述符 id 末尾的内容(连接到数据库、web 服务......)
答案2
我通常启用请求持续时间日志记录,请参见此处的 %D:
http://httpd.apache.org/docs/2.2/mod/mod_log_config.html
它打印出满足请求所需的时间(以微秒为单位)。这样你就可以轻松找到最慢的脚本。
也就是说,在您的情况下,我将开始调试 manageCompanies.php 脚本,也许在脚本的“战略”部分向某些文件添加一些 echo 或 print_r,从处理 POST 方法的部分开始,在循环之前和之后以及最终的 DB 查询,写入时间戳和例如“开始循环 foo / 结束循环 foo”,希望您明白了。