当前位置:首页 > 运维 > 正文内容

nginx中request_time和upstream_response_time详解

phpmianshi5年前 (2016-07-01)运维375

背景


最近监控报警有短暂的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%飙高等;

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



版权声明:本文由PHP面试资料网发布,如需转载请注明出处。
分享给朋友:

相关文章

linux中如何排查负载过高的问题

概况Linux的负载高,主要是由于CPU使用、内存使用、IO消耗三部分构成。任意一项使用过多,都将导致服务器负载的急剧攀升。如何判断系统是否已经Over Loadw、uptime、top 等命令都可以...

linux中Cannot assign requested address的问题处理

问题描述:最近系统报警有类型如下错误:Cannot assign requested address  主要是连接mysql时产生的错误。分析原因:客户端与服务端每建立一个连接,客户端一侧都...

linux中netstat和ss命令详解

由于nio的普及,ck10k的问题已经成为过去式。现在随便一台服务器,都可以支持数十万级别的连接了。那么10万的连接需要多少资源呢?由于一个连接都是文件句柄,所以需要文件描述符数量支持才行,每一个so...

linux中sed用法读这一篇就够了

1.概念sed是一种行编辑器,它一次处理一行内容。处理时,把 当前处理的行存储在临时缓冲区中,称为“模式空间”(pattern space),接着用sed命令处理缓冲区中的内容,处理完成后,把缓冲区的...

linux中iptables防火墙详解

1、iptables入门简介Netfilter/Iptables(以下简称Iptables)是unix/linux自带的一款优秀且开放源代码的完全自由的基于包过滤的防火墙工具,主要工作在OSI七层的二...

linux中浅谈端口占用和开闭管理

背景平时开发或线上运维少不了跟端口打交道,今天我们简单聊聊平时跟端口相关的几个场景首先查看某台主机某个端口服务是否正常比如查看本机 redis服务是否正常telnet 127.0.0.1&n...

发表评论

访客

◎欢迎参与讨论,请在这里发表您的看法、交流您的观点。