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 status
pm.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，缓慢请求的数量)

(大道进程，这个专业术语不是很明白，如果有知道，还请赐教)

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

仅以此文记录一下，每次在睡梦中被电话吵醒的历程。