最近在提供后台API时,提供了一个简单逻辑的接口
部署在测试环境，自测没问题，提交测试
突然有一天,接口响应延迟严重，几乎每次都是3-4秒返回
这对于一个接口来说，肯定是有问题的
于是便有了以下的方法尝试
最开始以为不是什么大问题，猜想可能是fpm问题
毕竟测试环境，部署代码繁多
重启后，接口响应正常，可不一会就又复现
重新分析定位问题经过几次的尝试后，发现问题其实没有那么简单
重启fpm后，过了不到几秒，问题依然复现
编写简单的php文件，无复杂逻辑，只输出字符串，问题复现
命令行执行文件，无此问题
经过以上尝试，确认是FPM的问题
或者PHP的初始化解析执行的问题，当时想是不是有特定的模块加载
经过php -m 查看，无特殊模块(其实应该仔细看看,所以才绕了弯路)
有了上面的分析，最先想到的是利用日志查看问题
查看nginx日志 nginx 日志 格式，添加详细的 各个时间段的相应 log_format main '$remote_addr [$host] - $remote_user [$time_local] $request upstream_response_time: $upstream_response_time request_time: $request_time upstream_connect_time: $upstream_connect_time upstream_header_time:$upstream_header_time $status $body_bytes_sent $http_referer $http_user_agent '; 添加了 upstream_response_time upstream_connect_time upstream_header_time 含义如下: request_time nginx服务，从发起请求的客户端获取到第一个字节开始，到返回给客户端最后一个字节，日志写入文件后，所经过的时间。单位为秒。 upstream_connect_time nginx服务，从与上游服务开始建立连接，到连接建立成功，所经过的时间。单位为秒。 upstream_header_time nginx服务，从与上游服务开始建立连接，到接收到响应返回头的第一个字节，所经过的时间。单位为秒。 upstream_response_time nginx服务，从与上游服务开始建立连接，到接收完响应返回的最后一个字节，所经过的时间。单位为秒  程序真正的运行时间 = $upstream_header_time - $upstream_connect_time $request_time 中包含了数据返回时间 $request_time 中包含了日志打印的时间 nginx 日志显示 xxx [xxx] - - [11/Jul/2020:13:36:45 +0000] POST /xxx/xxx HTTP/1.1 upstream_response_time: 3.048 request_time: 3.048 upstream_connect_time: 0.000 upstream_header_time:3.048 200 98 - Dalvik/2.1.0 (Linux; U; Android 8.1.0; vivo 1808 Build/O11019) 从中可以看出确实是 上游服务FPM 返回延迟了 配置 FPM 慢日志lowlog = /xxx/www-slow.log request_slowlog_timeout = 1s
发现 慢日志中，并没有记录
于是怀疑是否 日志文件权限有问题，修改后依然未写入
想到用sleep的方式，写入慢日志，成功写入
现象就是 配置了1秒的FPM慢日志，接口响应超过1s，但没有写入慢日志
那就说明 PHP 程序执行完成后，又做了什么处理，导致了延迟
或者 其他的配置问题
网上搜索, 可能是 文件的打开数量有限制, 并没有做优化
于是 查看对应的配置
nginx 配置文件 worker_rlimit_nofile
ulimit -n
是做了优化的的
也并不是网上所说的问题
所有的PHP程序响应都有延迟，超过3s左右
所以并不是个例，和其他的如mysql redis 连接没关系
突然间出现的，原来是没问题的，应该是近期做了更改
但由于测试环境，东西太多，一时也找不到是什么改动
命令行模式下，没有延迟，所以和FPM有关
而重复FPM后,几秒内正常,后又复现
一直以为是FPM配置有什么问题,目前看并不是
所以肯定是 程序处理完成后，又做了什么，导致了延迟
那有什么办法可以追踪代码的执行吗
对于php而言，xhprof扩展 是可以很好的展示一个流程中的耗时
而且还有对应的图片展示(需要安装扩展)，但还需要安装
于是就有了下面的方法
简单来说，strace是用来跟踪进程内的系统调用和接受的信号。
对程序调试很有帮助
于是,来调试FPM的进程，看看都做了哪些调用
strace -t -f $(pidof php-fpm| sed 's/\([0-9]*\)/\-p \1/g') -epoll -o /tmp/strace.txt
打开文件
12406 06:55:13 poll([{fd=5, events=POLLIN}], 1, 5000) = 1 ([{fd=5, revents=POLLIN}])
12406 06:55:13 poll([{fd=6, events=POLLOUT|POLLWRNORM}], 1, 10000) = 1 ([{fd=6, revents=POLLOUT|POLLWRNORM|POLLERR|POLLHUP}])
12405 06:55:16 --- SIGQUIT {si_signo=SIGQUIT, si_code=SI_USER, si_pid=12401, si_uid=0} ---
12405 06:55:16 +++ exited with 0 +++
12401 06:55:16 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=12405, si_status=0, si_utime=0, si_stime=0} ---`