php-fpm 超时原因分析

 2021-05-13  |  7 分钟  |  3462 个字  |  axiaoxin
文章目录

背景

线上PHP服务，同一台机器上部有AB两个服务，A接收外部请求后再通过本地nginx请求部署在本地的B服务获取数据，同时也有大量的请求直接请求B服务获取数据，偶发会在一段时间内Nginx大量返回504请求超时和少量502连接被断开。

超时期间机器的CPU、内存、IO等负载都正常，请求量相对有增加但QPS不到100，比起高峰时间的请求量（QPS差不多2800）这点起伏几乎可以忽略不计，高峰时期服务却没有任何异常。通过日志中的requestid分析，发现从A服务到B服务之间的日志打印时间间隔很长，请求链路从A服务的最后一条日志到B服务的第一条日志之间间隔有10多秒之长。

问题定位

观测机器的全部基础指标，发现唯一能和超时日志量曲线对应起来的指标是CurrEstab指标，该指标表示TCP连接数，峰值到达900+，起伏和超时日志的起伏基本吻合，可以初步猜测导致超时原因是在这个时间段内TCP的连接数过多导致超时。

超时原因分析

线上PHP相关信息

php 版本：PHP 5.6.29 (fpm-fcgi) (built: Jan 12 2017 09:49:19)

php-fpm 线上服务配置：

[global]

; Pid file
; Note: the default prefix is /usr/local/services/php-5.3.6/var
; Default Value: none
;pid = run/php-fpm.pid
pid = /usr/local/services/php-5.6.29/log/php-fpm.pid

; Error log file
; Note: the default prefix is /usr/local/services/php-5.3.6/var
; Default Value: log/php-fpm.log
;error_log = log/php-fpm.log
error_log = /usr/local/services/php-5.6.29/log/php-fpm.log

; Log level
; Possible Values: alert, error, warning, notice, debug
; Default Value: notice
;log_level = notice

[www]
listen = 127.0.0.1:9000

user = user_00
group = users
pm = static

pm.max_children = 200

pm.max_requests = 2000
pm.status_path = /status
ping.path = /ping
ping.response = pong

access.log = log/$pool.access.log
access.format = "%R - %u %t \"%m %r%Q%q\" %s %f %{mili}d %{kilo}M %C%%"

slowlog = log/$pool.log.slow
request_slowlog_timeout = 5s
;request_terminate_timeout = 60s

线上 php-fpm.log 中存在一些看起来有一些危险的日志内容：

[16-Jul-2020 15:47:32] NOTICE: [pool www] child 12140 exited with code 0 after 7548.179510 seconds from start

了解完配置项后确认为无害日志无需关注， 配置中设置了 pm.max_requests 每个子进程处理了对应请求数后会自动重启，这里是打印子进程从启动到退出期间的运行时长。

PHP 配置项

先了解 php-fpm 各配置项的作用：

php-fpm的默认配置文件（php-fpm.conf.default）中有对当前版本php的每个配置项有详细解释和默认值说明，可以参考

pm参数

由于机器大多都是8G内存以上，这里的pm配置使用static是比较合理的，一般一个 php-fpm 占用 20M 内存左右，动态适合小内存机器，灵活分配进程，省内存。静态适用于大内存机器，动态创建回收进程对服务器资源也是一种消耗。

设置为static 后只有 pm.max_children 一个参数会有效

request_terminate_timeout参数

request_terminate_timeout的值如果设置为 0 或者过长的时间，可能会引起 file_get_contents 的资源问题。 如果 file_get_contents 请求的远程资源如果反应过慢， file_get_contents 就会一直卡在那里不会超时

php.ini 里面 max_execution_time 可以设置 PHP 脚本的最大执行时间，但是，在 php-cgi(php-fpm) 中，该参数不会起效。真正能够控制 PHP 脚本最大执行时间的是 php-fpm.conf 配置文件中的 request_terminate_timeout 参数。

backlog

backlog 的定义是已连接但未进行 accept 处理的 SOCKET 队列（全连接）大小

; Set listen(2) backlog.
; Default Value: 65535 (-1 on FreeBSD and OpenBSD)
;listen.backlog = 65535

当前该版本listen.backlog 默认值为65535，看网络文章介绍最新版已改为511

backlog 数，设置 TCP 建立连接时 listen 的全连接队列长度，-1 表示在 php-fpm 中不做限制，交由操作系统的 backlog 设置来决定，设置为其余数值，实际生效的是应用层面backlog值和系统层面 somaxconn 的最小值，即 min(backlog,somaxconn)，因此这里的65535并不一定是就是65535

查看相关参数值

查看php-fpm当前的全连接队列长度，可以看到实际生效的backlog数为操作系统设置的128：

ss -tlnp |egrep -i '(9000|Recv-Q)'
State      Recv-Q Send-Q Local Address:Port               Peer Address:Port
LISTEN     0      128    127.0.0.1:9000                     *:*                   users:(("php-fpm",pid=32558,fd=0),...)

在 listen 状态情况下： Recv-Q 表示存在于 backlog 当中未被服务端应用程序 accept 的队列大小； Send-Q 表示最大的 backlog 的大小

如果nginx配置了php-fpm的status路径，也可以通过请求status查看相关状态：

pool:                 www
process manager:      static
start time:           21/Jul/2020:11:22:12 +0800
start since:          35033
accepted conn:        6178811
listen queue:         0
max listen queue:     0
listen queue len:     128
idle processes:       199
active processes:     1
total processes:      200
max active processes: 201
max children reached: 0
slow requests:        0

查看操作系统全连接最大值

cat /proc/sys/net/core/somaxconn  ## 定义了系统中每一个端口最大的监听队列的长度
128

半连接最大值

cat /proc/sys/net/ipv4/tcp_max_syn_backlog
4096

ss -s 查看队列的溢出统计数据

当全连接到达backlog限制后会发生什么？

TCP 在第二次握手时 server 端收到 syn 包后将相关信息放到 syn queue 这个半连接队列中同时向 client 发送 syn+ack ， client 收到后向 server 端回 ack 并确认后，会将信息从 syn 半连接队列取出到 accept 全连接队列，进到这个队列才能从 listen()变成 accept()，backlog 限制达到，系统将停止对 SYN 包响应 SYN/ACK 包。

参考文章：https://jm.taobao.org/2017/05/25/525-1/

cat /proc/sys/net/ipv4/tcp_abort_on_overflow
0

tcp_abort_on_overflow 为 0 表示如果三次握手第三步的时候全连接队列满了那么 server 忽略 client 发过来的 ack ， server 端没有收到 ack 认为连接还没建立起来会重传 SYN ACK ，而客户端以为连接已建立，开始后续调用等待直至超时，1 表示第三步的时候如果全连接队列满了， server 发送一个 reset 包给 client

超时原因总结

超时期间，tcp连接数激增，导致php-fpm的全连接队列被占满，后续的请求在建立tcp连接时，A服务在完成三次握手时最后的ack被B服务忽略导致到accept的调用而无法真正建立连接但A服务侧却认为连接已经建立，而B服务认为A服务的连接还没建立，一直在重传syn ack，在A服务端就会一直等待B服务的响应，最后直到超时。

backlog 应该设置为多少？

在设置 backlog 时，既不能太大，也不能太小，设置太大，当访问流量突然增加超过服务器的负载时，客户端不能快速失败，造成读取连接超时，对服务端来讲，会影响网络 I/O ，同时造成内存使用过大， cpu 负载增加；

如果设置太小，不能充分发挥服务端的负载能力，并且会客户端造成连接失败的情况。应根服务端能够承受的最大 qps 进行设置， backlog 的大小，应设置成在服务端最大能够承受 qps 的 1-1.5 倍左右。

参考文章：https://juejin.im/post/5d8488256fb9a06b065cad98

本地搭建服务模拟线上服务进行压测来确认backlog值

  • 服务接口平均耗时： 0.14s
  • 最大 qps: 2850
  • 本地机器：4核8G

配置 nginx 模拟接口

sleep.conf

server {
    listen 2142;

    location ~ \.php$ {
        root /path/to/phpfile;
        include fastcgi_params;
        fastcgi_param REQUEST_METHOD $request_method;
        fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
        fastcgi_pass 127.0.0.1:9000;
        fastcgi_index sleep.php;
    }
}

sleep.php

<?php
$i = 0.14;
$seconds = $i * 1000 * 1000;
usleep($seconds);
echo "wakeup!";
?>

原始线上配置压测数据

不配置 backlog（线上配置，128）：

Concurrency Level:      3000
Time taken for tests:   15.360 seconds
Complete requests:      3000
Failed requests:        949
(Connect: 0, Receive: 0, Length: 949, Exceptions: 0)
Write errors:           0
Non-2xx responses:      949
Total transferred:      669982 bytes
HTML transferred:       152911 bytes
Requests per second:    195.31 [##/sec] (mean)
Time per request:       15360.390 [ms] (mean)
Time per request:       5.120 [ms] (mean, across all concurrent requests)
Transfer rate:          42.60 [Kbytes/sec] received

Connection Times (ms)
            min  mean[+/-sd] median   max
Connect:        0   87  19.5     89     122
Processing:   141 6924 5903.2   4610   15051
Waiting:      140 6923 5902.9   4609   15051
Total:        252 7011 5885.4   4699   15127

参数调整

backlog：accept队列大小

以5秒超时为基准，目前以最大请求量的地域为参考的话平均一个子进程处理一个请求需要0.14秒，5秒内约处理35个，每秒约7个，共200个子进程，则5秒内处理完全部请求的话，backlog队列可以接收约7000个请求(5/0.14*200=7142.857142857141)

有的地域是100子进程，可接收约3500个请求，目前最大并发量不到3000，backlog设为1.5倍较为合适 3000*1.5=4500

max_children： php-fpm子进程数

当前为200，按当前最高并发量2800/s算，200个子进程每个子进程需每秒约处理14个请求，无法完成5秒内返回结果，调整为400可预防极端情况，每个进程约20M，满负荷时400*20=8000M，8G内存不适用。

max_requests：完成对应次请求处理后重启子进程

当前为2000，每个进程每秒完成7次处理，平均不到5分钟就会重启一次，这里调整为60分钟左右重启一次的量约 25000，避免频繁重启导致502

修改系统 somaxconn

临时修改：

sysctl -w net.core.somaxcon`

永久修改：在/etc/sysctl.conf中增加一行

net.core.somaxconn= 4000

然后执行命令

sysctl -p

新配置压测数据：

;;;;;;;;;;;;;;;;;;;;;
; FPM Configuration ;
;;;;;;;;;;;;;;;;;;;;;

; All relative paths in this configuration file are relative to PHP's install
; prefix (/usr/local/services/php-5.6.29). This prefix can be dynamically changed by using the
; '-p' argument from the command line.

[global]
pid = /usr/local/services/php-5.6.29/log/php-fpm.pid
error_log = /usr/local/services/php-5.6.29/log/php-fpm.log

[www]
user = user_00
group = users
listen = 127.0.0.1:9000
listen.backlog = 4500

pm = static
pm.max_children = 200
pm.max_requests = 25000

pm.status_path = /status

ping.path = /ping
ping.response = pong

access.log = log/$pool.access.log
access.format = "%R - %u %t \"%m %r%Q%q\" %s %f %{mili}d %{kilo}M %C%%"

slowlog = log/$pool.log.slow
request_slowlog_timeout = 5s

;request_terminate_timeout = 10s

ab 结果，3000并发完全无压力

Concurrency Level:      3000
Time taken for tests:   2.421 seconds
Complete requests:      3000
Failed requests:        0
Write errors:           0
Total transferred:      558000 bytes
HTML transferred:       21000 bytes
Requests per second:    1239.28 [##/sec] (mean)
Time per request:       2420.754 [ms] (mean)
Time per request:       0.807 [ms] (mean, across all concurrent requests)
Transfer rate:          225.10 [Kbytes/sec] received

Connection Times (ms)
            min  mean[+/-sd] median   max
Connect:        0   80  19.2     78     116
Processing:   140 1134 602.0   1121    2130
Waiting:      140 1134 602.1   1121    2130
Total:        238 1214 593.7   1174    2194


Concurrency Level:      3000
Time taken for tests:   10.860 seconds
Complete requests:      15000
Failed requests:        0
Write errors:           0
Total transferred:      2790000 bytes
HTML transferred:       105000 bytes
Requests per second:    1381.27 [##/sec] (mean)
Time per request:       2171.909 [ms] (mean)
Time per request:       0.724 [ms] (mean, across all concurrent requests)
Transfer rate:          250.90 [Kbytes/sec] received

Connection Times (ms)
            min  mean[+/-sd] median   max
Connect:        0   19  37.9      0     122
Processing:   141 1911 477.2   2106    2131
Waiting:      140 1911 477.3   2106    2131
Total:        247 1929 443.0   2106    2167

15000并发时偶发存在失败请求

Concurrency Level:      15000
Time taken for tests:   17.543 seconds
Complete requests:      15000
Failed requests:        107
(Connect: 0, Receive: 0, Length: 107, Exceptions: 0)
Write errors:           0
Non-2xx responses:      107
Total transferred:      2802626 bytes
HTML transferred:       119873 bytes
Requests per second:    855.06 [##/sec] (mean)
Time per request:       17542.629 [ms] (mean)
Time per request:       1.170 [ms] (mean, across all concurrent requests)
Transfer rate:          156.02 [Kbytes/sec] received

Connection Times (ms)
            min  mean[+/-sd] median   max
Connect:        0  429  86.1    430     585
Processing:   243 6360 4215.0   6603   16664
Waiting:      140 6360 4215.1   6603   16664
Total:        725 6788 4154.7   6973   17102

siege 1000并发下 100%可用

siege -c 1000 https://localhost:2142/sleep.php
^C
{       "transactions":                      5783157,
        "availability":                       100.00,
        "elapsed_time":                      4064.78,
        "data_transferred":                   148.91,
        "response_time":                        0.70,
        "transaction_rate":                  1422.75,
        "throughput":                           0.04,
        "concurrency":                        999.24,
        "successful_transactions":           5783157,
        "failed_transactions":                     0,
        "longest_transaction":                  1.40,
        "shortest_transaction":                 0.15
}

优化结果

修改配置后，持续观测服务状态，tcp连接依旧有暴涨，服务无超时

关注我

 编程  debug

也可以看看

全国大流量卡免费领

19元月租ㆍ超值优惠ㆍ长期套餐ㆍ免费包邮ㆍ官方正品