Don't Panic

Try Again

0%

php-fpm slow log

发表于 更新于 分类于 Disqus：

网站并发上升后，页面响应变慢，甚至出现504
由于网站主入口还是php处理，本地压测也无法复现，所以排查一番后决定通过php-fpm的slowlog来快速定位问题

响应慢，大量502,504

检测服务器配置

8核16G配置，带宽峰值无限制

CPU

高并发时均值50%，nginx占比很高
平时10%左右

内存

始终较低，20%左右

TCP连接数

出问题阶段，服务器监控显示tcp连接数达到了65000左右，然后在65000阶段小幅波动
怀疑是负载均衡转过来的QPS达到上限(后确认确实占大头)
网关与真实服务器之间TCP连接由（源IP，目的IP，源端口，目的端口）四元组组成，由此，只有源端口可变
但实际情况网关后有多台服务器，所以应该非此限制
但是在真实的业务服务器中，nginx转发到php-fpm的过程中，同样会有这个限制

文件句柄数

正常范围

检查PHP相关配置

php.ini配置

1
2
3
4
5
6
7
root@b616d73bd037:/# cat /etc/php/7.0/fpm/php.ini  | grep -v '^;' | grep -v '^$'
[PHP]
engine = On
short_open_tag = Off
precision = 14
output_buffering = 4096
...

php-fpm配置

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
root@b616d73bd037:/# cat /etc/php/7.0/fpm/pool.d/www.conf | grep -v '^;' | grep -v '^$'
[www]
user = www-data
group = www-data
listen = /run/php/php7.0-fpm.sock
listen.owner = www-data
listen.group = www-data
listen.allowed_clients = 127.0.0.1
;主要是static（静态）或者dynamic（动态）
pm = static
;静态方式下开启的php-fpm进程数量
;在动态方式下，限定php-fpm的最大进程数
;要注意pm.max_spare_servers的值只能小于等于pm.max_children
pm.max_children = 40
;动态方式下的起始php-fpm进程数量
pm.start_servers = 2
;动态方式空闲状态下的最小php-fpm进程数量
pm.min_spare_servers = 1
;动态方式空闲状态下的最大php-fpm进程数量
pm.max_spare_servers = 3
;children 处理多少个请求后被关闭，关闭时会有notice日志产生
;[12-Feb-2020 15:45:24] NOTICE: [pool www] child 30032 exited with code 0 after 2590.928501 seconds from start
pm.max_requests = 20000
pm.status_path = /status
slowlog = /var/log/$pool.log.slow
catch_workers_output = yes
php_admin_value[error_log] = /var/log/fpm-php.www.log
php_admin_flag[log_errors] = on
php_value[session.save_handler] = memcached
php_value[session.save_path]    = cdd400d84eec4b3c.m.cnhzalicm10pub001.ocs.aliyuncs.com:11211
php_value[soap.wsdl_cache_dir]  = /var/lib/php/wsdlcache

关键配置排查

php.ini

max_execution_time

当前设置30s，触发会返回500
这个字面意思，即脚本执行时间，所以sleep、curl等待响应一类耗时是不计入的

php-fpm

max_children

达到上限返回502？
每个按20M内存使用来计算，但静态由于长时间运行可按照每个30M来计算
当前40，参考配置来说，太低

request_terminate_timeout

执行超时触发502？
当前未设置

开启php-fpm慢日志

慢日志相关内容

; The log file for slow requests
; Default Value: not set
; Note: slowlog is mandatory if request_slowlog_timeout is set
;slowlog = log/$pool.log.slow

; The timeout for serving a single request after which a PHP backtrace will be
; dumped to the ‘slowlog’ file. A value of ‘0s’ means ‘off’.
; Available units: s(econds)(default), m(inutes), h(ours), or d(ays)
; Default Value: 0
;request_slowlog_timeout = 0

配置文件地址

1
2
3
4
5
root@ubuntu:/home/tb# ps -ef |grep php-fpm | grep master
root      3484     1  0 10:17 ?        00:00:01 php-fpm: master process (/etc/php/7.0/fpm/php-fpm.conf)

最终配置文件路径
include=/etc/php/7.0/fpm/pool.d/*.conf

修改配置，开启PHP慢日志

docker支持

  1. docker run 添加参数

    1
    --cap-add=SYS_PTRACE

  2. 改运行中容器的docker配置文件

    1
    2
    3
    4
    5
    6
    7
    8
    # 停止docker服务 
    systemctl stop docker
    # 修改docker配置，先找到容器id
    sudo vim /var/lib/docker/containers/container_id/hostconfig.json
    # 手动添加修改CapAdd内容
    "CapAdd":["SYS_PTRACE"],"CapDrop":null,
    # 启动docker服务
    systemctl start docker

php-fpm支持

1
2
3
4
5
6
# 修改php-fpm配置，不一定相同路径
vim /etc/php/7.0/fpm/pool.d/www.conf
slowlog = /var/log/$pool.log.slow 修改为 slowlog = /var/log/php.slow.log
;request_slowlog_timeout = 0 修改为 request_slowlog_timeout = 2s
# 重启php-fpm
kill -USR2 pid

其它

报错处理
ERROR: Unable to set php_value ‘soap.wsdl_cache_dir’.

1
2
# 注释掉，因为未使用
;php_value[soap.wsdl_cache_dir]  = /var/lib/php/wsdlcache
1
2
3
# 修改php-fpm的日志记录等级，默认notice
vim /etc/php/7.0/fpm/php-fpm.conf
;log_level = notice 修改为 log_level = warning

参考链接

链接1
链接2
原文链接