☰

问题

tag-icon • tag-icon nginx php-fpm php7 502-error newrelic
问题

我们最近将长期运行（没有问题）的 Ubuntu 16.04 / nginx (1.10.3) / PHP 7.0 堆栈迁移到 Ubuntu 18.04 / nginx (1.14.0) / PHP 7.2 堆栈。结果导致 PHP-FPM 级别出现以前从未出现过的不稳定，经过数小时的调查，仍未找到问题的根本原因。

顺便说一句，这两种部署都是通过 AWS 进行管理的，并且在两种情况下，运行的 PHP 应用程序都使用相同的代码并连接到相同的 MySQL RDS 端点。

问题

升级后，系统正常运行了几个小时（有时超过 24 小时），没有出现问题。突然，在一分钟内，FPM 开始记录警告，指出脚本的执行在各个子进程上已超时，如下所示：

[15-Jul-2020 19:50:22] WARNING: [pool www] child 29649, script '/path/to/app.php' (request: "POST /app.php") execution timed out (140.371526 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 25847, script '/path/to/app.php' (request: "GET /app.php") execution timed out (136.178758 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 25617, script '/path/to/app.php' (request: "GET /app.php") execution timed out (135.822576 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 25401, script '/path/to/app.php' (request: "POST /app.php") execution timed out (135.927461 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 25229, script '/path/to/app.php' (request: "GET /app.php") execution timed out (143.179479 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 25110, script '/path/to/app.php' (request: "POST /app.php") execution timed out (141.080509 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 24904, script '/path/to/app.php' (request: "POST /app.php") execution timed out (142.441526 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 24679, script '/path/to/app.php' (request: "GET /app.php") execution timed out (138.165572 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 24652, script '/path/to/app.php' (request: "POST /app.php") execution timed out (142.414685 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 15982, script '/path/to/app.php' (request: "GET /app.php") execution timed out (125.469362 sec), terminating

此后不久，FPM 开始产生新的子进程来尝试处理来自 nginx 的负载。

[15-Jul-2020 19:50:37] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 46 total children
[15-Jul-2020 19:50:38] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 16 children, there are 1 idle, and 51 total children
[15-Jul-2020 19:50:39] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 32 children, there are 0 idle, and 55 total children
[15-Jul-2020 19:50:40] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 32 children, there are 0 idle, and 60 total children
[15-Jul-2020 19:50:41] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 32 children, there are 0 idle, and 65 total children

然后，一旦达到限制，服务器将达到 70 个子节点的最大容量，并且 FPM 会停止接受来自 nginx 的请求（[error] 1072#1072: *234300 connect() to unix:/run/php/php7.2-fpm.sock failed (11: Resource temporarily unavailable) while connecting to upstream），导致502错误。

[15-Jul-2020 19:50:42] WARNING: [pool www] server reached pm.max_children setting (70), consider raising it

在此刻，在 FPM 服务重新启动之前，应用程序实际上处于关闭状态。当FPM重新启动时，挂起的请求/进程会立即终止，问题将暂时得到解决。

笔记：值得注意的是应用程序可以正常使用 <= 10 个 worker，即使在高峰时段，因此由于长时间运行的进程而立即扩展的事实无疑是一种异常。

重复记录同一进程 ID

从表面上看，这些日志似乎是随机的，但如果你按子进程 ID 进行过滤，就会发现每个子进程都在一遍又一遍地尝试终止单个请求。更重要的是，给定进程 ID 的每个日志条目间隔约 40 秒，通过将每条日志开头的时间戳与每条日志结尾的相应脚本时间进行比较来证明。这里我通过特定的进程 ID 过滤了日志作为示例：

[15-Jul-2020 19:40:39] NOTICE: [pool www] child 25617 started
[15-Jul-2020 19:50:22] WARNING: [pool www] child 25617, script '/path/to/app.php' (request: "GET /app.php") execution timed out (135.847853 sec), terminating
[15-Jul-2020 19:51:03] WARNING: [pool www] child 25617, script '/path/to/app.php' (request: "GET /app.php") execution timed out (176.182362 sec), terminating
[15-Jul-2020 19:51:43] WARNING: [pool www] child 25617, script '/path/to/app.php' (request: "GET /app.php") execution timed out (216.516705 sec), terminating
[15-Jul-2020 19:52:23] WARNING: [pool www] child 25617, script '/path/to/app.php' (request: "GET /app.php") execution timed out (256.849969 sec), terminating
[15-Jul-2020 19:53:04] WARNING: [pool www] child 25617, script '/path/to/app.php' (request: "GET /app.php") execution timed out (297.183892 sec), terminating

在流量增加或达到高峰时发生

根据问题出现的时间，可以明显看出，问题出现在流量增加时。例如，在清晨或一天的高峰期，流量较高时，就会出现问题。我们还没有看到这个问题在流量较低时出现，例如在半夜。

New Relic 已安装

按照推荐安装方法在他们的网站上有概述。

   CGroup: /system.slice/php7.2-fpm.service
           ├─ 6554 php-fpm: master process (/etc/php/7.2/fpm/php-fpm.conf)
           ├─ 6583 /usr/bin/newrelic-daemon --agent --pidfile /var/run/newrelic-daemon.pid --logfile /var/log/newrelic/newrelic-daemon.log --port @newrelic --wait-for-port 0s --define utilization.detect_aws=true --define utilization.de
           ├─ 6603 /usr/bin/newrelic-daemon --agent --pidfile /var/run/newrelic-daemon.pid --logfile /var/log/newrelic/newrelic-daemon.log --port @newrelic --wait-for-port 0s --define utilization.detect_aws=true --define utilization.de
           ├─ 7228 php-fpm: pool www
           ├─ 7520 php-fpm: pool www
           ├─ 7548 php-fpm: pool www
           ├─ 7569 php-fpm: pool www
           ├─11835 php-fpm: pool www
           ├─11944 php-fpm: pool www
           ├─11997 php-fpm: pool www
           ├─12106 php-fpm: pool www
           ├─12934 php-fpm: pool www
           └─13049 php-fpm: pool www

笔记：我们还没有尝试禁用新的遗留代理，而且这表面上似乎不是一个相关原因。

FPM 池配置

这是池配置，与两个堆栈上使用的配置相同：

pm = dynamic
pm.max_children = 70
pm.start_servers = 5
pm.min_spare_servers = 5
pm.max_spare_servers = 10
pm.max_requests = 1000

Nginx 配置

两个部署都使用相同的 nginx 配置。

user www-data;
worker_processes auto;
pid /run/nginx.pid;

events {
  worker_connections 2048;
}

http {
  include /etc/nginx/mime.types;
  default_type application/octet-stream;

  client_max_body_size 24m;
  sendfile on;
  tcp_nopush on;
  tcp_nodelay on;
  keepalive_timeout 120;
  limit_req_status 429;
  limit_req_zone $http_x_forwarded_for zone=web:16m rate=10r/s;
  types_hash_max_size 2048;
  server_tokens off;
  ssl_protocols TLSv1.2;
  ssl_prefer_server_ciphers on;
  gzip on;
  gzip_disable "msie6";
  gzip_vary on;
  gzip_proxied any;
  gzip_comp_level 6;
  gzip_buffers 16 8k;
  gzip_http_version 1.1;
  gzip_min_length 256;
  gzip_types text/plain text/css application/json application/javascript text/xml application/xml text/javascript image/x-icon;
  log_format main '$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent" - $request_time X-Forwarded-For=$http_x_forwarded_for Host=$host';

  include /etc/nginx/conf.d/*.conf;
  include /etc/nginx/sites-enabled/*;
}

PHP 配置

两个部署都使用相同的配置，所有其他设置都保留为默认设置。

max_execution_time=120
max_input_vars=5000
memory_limit=256M
post_max_size=24M

我们尝试过和/或看过的东西

  • 我们尝试调整 FPM 池配置以包括request_terminate_timeout = 121（超出max_execution_timephp 中的设置），希望这可以终止这些卡住进程，但不起作用。进程继续terminating每 40 秒运行一次，有时甚至超过 1000 秒。

  • 主 FPM 配置保留为默认配置，未做任何更改，两个版本的 FPM 之间的默认配置php-fpm.conf文件完全相同。我们检查了emergency_restart_threshold和配置，但它们似乎不是我们遇到的问题的因素。emergency_restart_intervalprocess_control_timeout

  • 将应用程序恢复到 Ubuntu 16.04（PHP 7.0.33）奇迹般地解决了这个问题，但显然不是我们通过升级想要实现的目标。

  • seems busy当它（通过日志）解决问题时重新启动 FPM ，但仍然不是解决方案。

  • 检查了前端日志是否存在偶然发生 DOS 攻击的可能性，但流量并不异常。

  • 检查了 nginx/php 错误日志，查找脚本未正确关闭（即无响应）的迹象。未发现任何异常。

结论

php、nginx 或 fpm 中的某些内容以某种方式配置，最终会导致某种竞争条件，即整个 FPM 服务被休眠/卡住/陈旧的进程所消耗，这些进程使用所有可用资源，直到最终超出容量并无限期地拒绝所有流量，直到手动重新启动 FPM 进程。

我们不排除该问题也可能是应用程序本身的问题，但它在以前版本的 OS/PHP/FPM 上运行没有问题，这表明 PHP 级别存在不兼容问题，到目前为止我们还没有看到任何支持这一点的日志记录。

我的目标是弄清楚 a.) 为什么会发生这种情况，以及 b.) 我们可以做些什么来缓解或解决这个问题。

谢谢你的眼睛！

答案1

不同服务器上的相同代码可以非常简单地从各方面来看，运行方式都完全不同。

curl_exec一个简单的例子是任何对需要 HTTP / IP 地址授权的第三方（远程）Web 服务器进行调用的代码。

在后一种情况下，如果一台服务器被授权，但另一台服务器没有，您将得到一个挂起的代码，等待无限期的超时libcurl，其中页面处理只能通过max_execution_time配置来停止。

您确实需要按照@Michael Hampton 的建议检查 PHP-FPM 慢速日志。您可以查看有关如何执行此操作的详细说明这里。

没有提到您使用哪种缓存机制。为了大大提高您的网站可以处理的流量，请使用 Varnish Cache 等全页缓存机制。

也不要忘记 PHP 的 OPcache、真实路径缓存等等。

我也会调查MySQL 慢查询日志看看是否有缺失的索引。

随着数据规模的扩大（例如，随着时间的推移，您的网站数据变得越来越大），数据库架构中缺少 MySQL 索引的问题变得更加明显。 它会变得越来越糟，直到您调查有问题的查询并修复数据库架构，使那些少数错误的查询使用键，而不是在每次页面请求时扫描数百万行。

最后，查看 NGINX Amplify 等工具 - 这种监控工具可以查看 CPU 负载/NGINX 连接/PHP-FPM 指标的图表，帮助您了解负载与连接之间的关系。升级后 - 您可能只是收到比平时更多的流量。通过调查日志goaccess，查看最常用的 IP 地址，检查它们的用户代理，whois检查它们是否存在潜在的阻止对象等。

答案2

我知道这个问题已经很久了，还没有答案。过去几天，我也一直在尝试解决 PHP-FPM 类似的问题（这里])。对于您的问题，当出现突然高峰时，您会看到这些错误。可能有几个可能的解决方案，但这里可能是与进程未被释放有关的问题，因此耗尽了子进程，因此导致错误。

我建议你启用 PHP-FPM 状态页面，并使用 http://ip-or-domain/status?full 查看脚本实际运行了多长时间

您可以在此处查看带有说明的说明：http://cotourist.com/nginx-how-to-enable-and-read-php-fpm-status-page/

其次，添加request_terminate_timeout = 119s，它应该小于 php max_execution_time 才能优先。

我们采取上述措施是为了确保请求不会堆积。如果堆积，则需要找出真正的原因，即针对特定脚本。

如果不是上述问题，您可以增加打开文件限制，并将 php-fpm 从 unix-socks 切换到 TCP 模式。在某些情况下，如果使用 unix-socket 进行连接，突然的峰值会导致 PHP-FPM 无法跟上 nginx 的速度。

本文详细描述了这一点：https://easyengine.io/tutorials/php/fpm-sysctl-tweaking/

相关内容