nginx中request_time和upstream_response_time详解

背景

最近监控报警有短暂的502，赶紧分析问题原因，查看nginx的access_log 发现短暂报警的request_time比较大，但是upstream_response_time有2个值，一个比较小，一个比较大，日志如下：

request:GET /index/all HTTP/1.1 request_time:30.049 up_resp_time:0.015 : 30.033  up_addr:11.11.11.11:80 : 22.22.22.22:80 bytes:556 status:502

概念

request_time

官网描述：

request processing time in seconds with a milliseconds resolution; time elapsed between the first bytes were read from the client and the log write after the last bytes were sent to the client 。

指的就是从接受用户请求的第一个字节到发送完响应数据的时间，即包括接收请求数据时间、程序响应时间、输出响应数据时间。

upstream_response_time

官网描述：

keeps times of responses obtained from upstream servers; times are kept in seconds with a milliseconds resolution. Several response times are separated by commas and colons like addresses in the $upstream_addr variable

是指从Nginx向后端php-fpm建立连接开始到接受完数据然后关闭连接为止的时间。

分析

从上面的描述可以看出，$request_time肯定比$upstream_response_time值大，特别是使用POST方式传递参数时，因为Nginx会把request body缓存住，接收完毕后才会把数据一起发给后端。所以如果用户网络较差，或者传递数据较大时，$request_time会比$upstream_response_time大很多。

所以如果使用nginx的accesslog查看php程序中哪些接口比较慢的话，记得在log_format中加入$upstream_response_time。

我们的情况是request_time比较大，猜测有可能是如下问题产生的：

1. 用户端网络问题tcp传输如果分包时，每个tcp包大约1400字节，之前那个请求响应body有1500K左右，要分成100多个tcp包。tcp有个慢启动过程，起初每次发送10个包，之后再根据网络情况调整每次发包数量，假设网络不好，就得分10次发送。然后由于tcp是可靠传输，需要确保每个包对方都收到了（通过给每个包编序号，以及接收对方发送的ack实现），如果在约定时间内没收到对方发的ack会重传该包。此外，tcp有发送窗口的概念，假设发送窗口为10，那么一次性可以发送10个包，之后每收到一个ack才能把这个包对应的发送窗口位置空余出来，发送下一个包。因此，用户端网络不好是会影响响应body全部发完的时间，进而影响nginx日志中request_time的时间。
2. 请求响应body体过大
   因为请求接口输出的数据中有些过大的无用数据导致请求响应body过大导致分包发送影响了request_time
3. php-fpm进程处理时间过长

我们的架构比较特殊，有2套项目，一套重构的项目，一套老项目，请求会先转发到重构的新项目上，如果返回404，则再转发到老的项目上，所以我们的upstream_response_time有2个值:

up_resp_time:0.015 : 30.033  up_addr:11.11.11.11:80 : 22.22.22.22:80

11.11.11.11:80 是新项目，因为返回了404，所以响应时间是 0.015很快

22.22.22.22:80 是老项目，因为处理时间过长，所以响应时间很长，超过30s

查看老项目nginx_error.log

[error] 22705#0: *692770681 recv() failed (104: Connection reset by peer) while reading response header from upstream

上面错误的两大主要原因：

1.php-fpm超时进程终止

2.可用内存不够进程终止

查看php-fpm配置

request_terminate_timeout = 30

我们得出结论：nginx告诉我们没有收到反馈，php-fpm告诉我们进程中断了

再查看老乡们的access.log

up_resp_time": "30.029","request_time": "30.030

up_resp_time超过30s，结合我们php-fpm.conf的配置和上面的报错,可以肯定就是执行时间太长了

再去查看php-slow.log 发现是因为请求一个外部接口导致的过慢

解决方案

调用外部接口增加超时时间，避免过长时间占用php-fpm

总结

对偶然出现的少量响应时间长的问题，可能是外部影响、网络异常等造成

偶然出现少量响应时间过长时，可以排查以下几个方面来定位问题，

查看当时服务器日志是否有错误；

检查服务器资源使用情况是否正常，load average、CPU使用率（尤其是单核CPU）是否有飙高现象；

检查是否出现磁盘短暂负载较高，比如iostat util%飙高等；

确认当时网络情况是否正常，是否有网络丢包等现象。以上排查建议在有全面监控的基础上进行，偶现问题比较难定位，有全面的监控数据进行排查就方便多了。