首页 > 运维 > nginx中request_time和upstream_response_time详解
2016
07-01

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进程处理时间过长


因此:较高的request_time可能是由于连接速度较慢的客户端造成的,高request_time不一定代表服务器和/或应用程序的性能.

在分析时,你真的不应该在request_time上花费太多时间,而是测量应用程序的响应时间(即upstream_response_time).

我们的架构比较特殊,有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%飙高等;

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



本文》有 0 条评论

留下一个回复