线上 PHP 服务故障排查之路

现象：使用人员反馈出现转圈(查询慢)和登录出现 504 错误。

初步判断就是 PHP 进程被占满了，服务处于繁忙状态，Nginx 的请求 PHP 未能及时回应，用了最简单粗暴的方式，重启 php-fpm 服务。重启服务后正常，并调整 pm.max_children 参数。

过了一个星期后又出现，又出现了一样的现象，根据网上的资料，优化 Nginx 和 php-fpm 参数，详细如下：

php-fpm.conf

pm.max_children = 60 修改为 pm.max_children = 70;

request_terminate_timeout = 0 修改为 request_terminate_timeout = 300

nginx.conf

worker_processes 4; 修改为 worker_processes 16;

增加：

worker_rlimit_nofile 200000;

use epoll;

fastcgi_connect_timeout 300;

fastcgi_read_timeout 300;

fastcgi_send_timeout 300;

fastcgi_buffer_size 128k;

fastcgi_buffers   4 64k;

fastcgi_busy_buffers_size 128k;

fastcgi_temp_file_write_size 128k; 

做了一次调优，相信应该有所改善。不出意外，第二天问题再次出现。

因出现问题的服务器，运行着多个业务项目，这给排查原因增加了很多难度。

首先，可以判断的是此服务器 php 服务在那个时间段已经满负载在跑。因无法断定是哪个项目出现问题，只能一个一个项目排除。第一，查询 Nginx 日志，看到的情况是一秒内同个接口有多次调用，按我们的业务量，那个项目不可能出现此情况，但这个并不是此次出现的原因。

第二，查询 php-fpm 日志(/usr/local/php/var/log/php-fpm.log)，终于在此日志中，找到蛛丝马迹：

[24-Sep-2017 10:05:24] WARNING: [pool www] child 23085, script '/usr/local/nginx/html/project/index.php' (request: "POST /index.php") execution timed out (372.841606 sec), terminating[24-Sep-2017 10:05:24] WARNING: [pool www] child 23084, script '/usr/local/nginx/html/project/index.php' (request: "POST /index.php") execution timed out (348.815395 sec), terminating[24-Sep-2017 10:05:24] WARNING: [pool www] child 23083, script '/usr/local/nginx/html/project/index.php' (request: "POST /index.php") execution timed out (372.849417 sec), terminating[24-Sep-2017 10:05:24] WARNING: [pool www] child 23081, script '/usr/local/nginx/html/project/index.php' (request: "POST /index.php") execution timed out (336.801517 sec), terminating[24-Sep-2017 10:05:24] WARNING: [pool www] child 23080, script '/usr/local/nginx/html/project/index.php' (request: "POST /index.php") execution timed out (390.862969 sec), terminating[24-Sep-2017 10:05:24] WARNING: [pool www] child 23077, script '/usr/local/nginx/html/project/index.php' (request: "POST /index.php") execution timed out (390.859550 sec), terminating[24-Sep-2017 10:05:24] WARNING: [pool www] child 23076, script '/usr/local/nginx/html/project/index.php' (request: "POST /index.php") execution timed out (384.855514 sec), terminating[24-Sep-2017 10:05:24] WARNING: [pool www] child 23075, script '/usr/local/nginx/html/project/index.php' (request: "POST /index.php") execution timed out (360.829416 sec), terminating[24-Sep-2017 10:05:24] WARNING: [pool www] child 23074, script '/usr/local/nginx/html/project/index.php' (request: "POST /index.php") execution timed out (372.788659 sec), terminating…………

共一秒钟，这个项目同一秒钟 69 个子进程超时(此日志的打印得益于参数优化的调整)。查询此项目出现问题的时间点都有一个共同的操作：几十万的消息推送。

初步可以断定，问题的原因是出现在这里。

处理方案，暂时关闭此功能，增加对 php-fpm 的监控，来进一步确认(另外就是把此项目移到另外的服务器再继续观察)。

php-fpm 的监控处理步骤如下：

1、查看 php-fpm 配置文件，开启。

cat /usr/local/php/etc/php-fpm.conf | grep statuspm.status_path = /php-fpm_status

2、Nginx 配置文件增加

server {

  listen 80;

        server_name 127.0.0.1;

        location /php-fpm_status {

    fastcgi_pass 127.0.0.1:9000;

    include fastcgi_params;

    fastcgi_param SCRIPT_FILENAME $fastcgi_script_name;

  }

3、查看curl 127.0.0.1/php-fpm_status

4、 php-fpm status 参数说明

pool:                 www    ( 池子名称 )

process manager:      static ( 进程管理方式,值：static, dynamic )

start time:           26/Sep/2017:00:36:08 +0800 ( 启动日期,如果 reload 了 php-fpm，时间会更新 )

start since:          47933    ( 运行时长 )

accepted conn:        120873    ( 当前池子接受的请求数 )

listen queue:         0        ( 请求等待队列，如果这个值不为 0，那么要增加 FPM 的进程数量 )

max listen queue:     1        (   请求等待队列最高的数量 )

listen queue len:     128      ( socket 等待队列长度 )

idle processes:       65        ( 空闲进程数量 )

active processes:     5        ( 活跃进程数量 )

total processes:      70        ( 总进程数量 )

max active processes: 26        ( 最大的活跃进程数量（FPM 启动开始算） )

max children reached: 0            ( 进程最大数量限制的次数，如果这个数量不为 0，那说明你的最大进程数量太小了，请改大一点。 )

slow requests:        0            (   启用了 php-fpm slow-log ，缓慢请求的数量 )

总结:对于问题的排查， 一定要善用排除法。当然必要的参数优化，可能对我们排查问题有很大的帮助(像我此次，如果没有看到超时日志，可能还需要更长的时间查找问题)