☰

PHP-FPM 慢日志返回无效结果

tag-icon • tag-icon logging php-fpm
PHP-FPM 慢日志返回无效结果

问题

我在 RHEL 8 上的 Apache 2.4 下运行 PHP-FPM 7.4.30，但无法让 PHP 的 slowlog 正常工作。它不会返回有关长时间运行的脚本的有效信息。

当我启用 slowlog 时（即使将值设置为request_slowlog_timeout10 秒或更长时间），我会看到日志中出现许多条目，包括我知道不会长时间运行的脚本。列表看起来是随机的，显示各种脚本及其内部函数的回溯。没有明显的模式。我确信返回的信息无效。这些脚本在请求和将结果返回给 Apache 之间根本不需要那么长时间。

应该发生什么

根据 PHP 文档，慢速日志应该只标记那些自要求向服务器发送请求的时间。换句话说，它应该测量从发出请求到脚本运行完成之间的时间。但是，当我启用 slowlog 时，情况并非如此。

似乎发生了什么

我的理论是，slowlog 并没有测量个人请求来自 Apache，而是一个子进程已运行。由于子进程可以运行相当长的时间，因此对于 slowlog 来说，它们可能看起来像是长时间运行的脚本。当 slowlog 发现子进程运行时间超过 时request_slowlog_timeout，它会输出当前正在运行的脚本的回溯（可以是当时正在运行的任何脚本）。

我的问题

  1. 为什么 PHP-FPM 会在慢速日志中显示这样的无效条目？它无法检测到请求的开始吗？
  2. 如何配置慢速日志以仅记录预期内容：单个请求的运行时间？

我还没有发现有关此问题的任何其他报告，但每次我在生产服务器以及只有一个用户的测试服务器上启用慢速日志时，我都能生成它。

非常感谢您的任何见解或帮助。

答案1

您是否偶然找到了答案？

我遇到了同样的问题，花了几个小时才弄清楚。更令人困惑的是，php-fpm 错误日志中会有类似这样的条目

警告：[pool www] 子进程 7559 在启动后 166.818268 秒因信号 15 (SIGTERM) 而退出

或者

[2023 年 6 月 19 日 16:24:56] 警告：[pool www] 子进程 7646，脚本 ''（请求：“ ”）执行超时（66.168368 秒），正在终止

但是，在达到 request_terminate_timeout 之前，慢速日志中找不到相同的 PID。逻辑似乎表明，在终止之前运行了 66 秒以上的请求也会在 10 秒后记录到慢速日志中。

我困惑了

相关内容