问题描述
最近线上一个PHP服务接口出现大量超时,开始以为业务处理慢。追查原因后发现PHP的业务处理并不慢,只是nginx收到php处理结果的时间慢。
比如:php-fpm access log记录请求处理时间 90ms,nginx日志显示php处理时间1s,差了10倍,一直没找到原因。
注:php-fpm 和 nginx 处于一台服务器
nginx 监听80端口,php-fpm监听9000端口
nginx fastcgi_pass 127.0.0.1:9000
问题出现的环境背景及自己尝试过哪些方法
最近几天大量出现这个问题,服务器无压力,qps < 30
接口逻辑会查一次mysql,请求2次外网http API,整体处理时间100ms左右。
并不是每次请求都会有问题,只是最近今天出现概率变大
相关代码
php-fpm access log:
127.0.0.1 - 14/Jan/2021:18:14:31 +0800 "POST /inner/video/getMetaByVideoUrl" 200 86.510 70f03cc97ec7da080ad1537811c49e1e 2048 11.56%
注:70f03cc97ec7da080ad1537811c49e1e 是traceID 用来追踪请求, 86.510 是php-fpm记录的请求时间 单位ms
nginx acces log:
{"@timestamp":"2021-01-14T18:14:32+08:00","server_addr":"xxxx","remote_addr":"xxxx","scheme":"-","host":"image.prod.xxxx.lan","http_host":"image.prod.xxxx.lan","trace_id":"70f03cc97ec7da080ad1537811c49e1e","hostname":"dqd-image-web01.bj.ks","method":"POST","uri":"/inner/video/getMetaByVideoUrl","url":"/index.php","protocol":"HTTP/1.1","status":200,"size":82,"request_time":1.088,"upstream_time":"1.088","upstream_host":"127.0.0.1:9000","referer":"-","agent":"-","xff":"-","uuid":"-","authorization":"-","lang":"-","sign":"-","usertag":"-"}
注:upstream_time 对应nginx $upstream_response_time 1.088s
这是典型的例子 php处理时间 86ms,nginx 处理时间1s
出现这条记录的时候服务器负载0.06,无网络波动,内存磁盘均没有异常
你期待的结果是什么?实际看到的错误信息又是什么?
希望找到解决办法