记一次生产请求耗时的问题

最近发现lb上记录的request_time比upstream_response_time大的比较多,例如upstream_response_time记录是0.062,request_time记录的就是5.064等等。整个耗时很反常。而且出现这个问题基本上都是一个返回值比较大的接口,基本上返回值是100K左右。领导让定位一下这个问题。

先说下我们的架构的背景,是这样的
阿里云的SLB-------我们自己的LB----------WEB机器

定位方向错误

跟踪这个问题之后,一直觉得 LB上记录的upstream_response_time的时间有问题,个人觉得100K的请求0.0xx秒无法完成,从这个入口查了一段时间,没有任何结果。当然也是收获的,协助WEB的同事发现有些请求的CACHE没有使用上。后来觉得应该钻牛角了,第一个Nginx的upstream_response_time肯定是没有问题的;第二个LB到WEB是都是内网访问,快是必然的。后来抓包也确实证明了LB到WEB特别快,upstream_response_time的时间是正确无误的。

Nagle 算法的问题?

排除掉upstream_response_time记录错误之后,一直没有发现。就看了些资料,学习了下课程。看了下极客时间
Linux性能优化实战 课程,40 | 案例篇:网络请求延迟变大了,我该怎么办?
看完之后,觉得可能真的是Nagle 算法的问题。解释下Nagle 算法,Nagle 算法,是 TCP 协议中用于减少小包发送数量的一种优化算法,目的是为了提高实际带宽的利用率。大概意思就是,合并TCP的小包,提高网络带宽的利用率。觉得可能是Nagle 算法的问题,就把一台LB的tcp_nodelay 打开了几小时,发现问题依然存在。那基本就排除Nagle 算法的问题。
后来仔细琢磨了一下,跟Nagle 算法应该没有关系,Nagle 算法的延迟是40ms才对,我们这个基本上是5秒。

lingering close 的问题

排除掉Nagle 算法的问题之后,又没有任何方向了。不知道怎么追查了。后来又抓包查看,没有发现有价值的线索。但是确定没有延迟4秒的,都是延迟5秒的。这是一个特别重要的线索。当时觉得应该有一个默认的配置是5秒。http://nginx.org/en/docs/http/ngx_http_core_module.html#
nginx http_core_module里面搜索下5s,发现了lingering_timeout 5s; lingering_timeout是个什么鬼?后来找到一篇跟我们很类似的问题的文章。文章里面很详细的解释了lingering_timeout。
http://shibing.github.io/2016/11/18/nginx%E7%9A%84%E5%BB%B6%E8%BF%9F%E5%85%B3%E9%97%AD-lingering-close/

下面的这些解释都来自上面的文章
该问题是由 Nginx 的延迟关闭(lingering close)连接导致的。Nginx 为了能够平滑关闭连接,采用了延迟关闭,它的工作方式如下:Nginx 在给客户端发送完最后一个数据包后会首先关闭 TCP 连接的写端(TCP 是全双工协议,任何一端都即可读也可写),表示服务端不会再向客户端发送任何数据,但是不会立即关闭 TCP 连接的读端,而是等待一个超时,在超时到达后如果客户端还没有数据发来,Nginx 才会关闭TCP的读端,从而关闭整个连接,然后再输出日志。另一方面,Nginx 是在关闭连接后才输出日志,所以在输出日志之前响应早就发送给了用户,因此对业务几乎没有影响。但是这也会导致 requset_time 值变得不准确,使其失去统计意义,开启 Keep-Alive 可以部分解决这一问题。

在 Nginx 发送完数据包并进入延迟关闭连接流程后,如果客户端在 lingering_timeout 时间内没有进行任何操作,那么就会关闭与客户端的连接然后输出日志,这就会导致导致访问日志滞后 lingering_timeout 才输出。我们线上并没有对该参数进行配置,那么会采用默认值,正好是5秒,与实际情况吻合。另外如果使用长连接,Nignx 在请求结束后不需要关闭连接而直接输出日志,那么就不会有这个问题,这也就解释了为什么开启 Keep-Alive 后问题消失。

基本上是可以确定是lingering_timeout的问题,把生产的一台的lingering_timeout的参数改为4s,发现5s的消失,4s的出现。知道这个原因之后,就能确定,其实真正的耗时有可能是2S 3S,只不过延迟关闭了,写日志的时间是5S。文章也介绍了只要客户端设置keep-alive长连接,Nginx就不会关闭连接,写日志时间就会快很多。但是阿里云的SLB不能开启长连接,因为这个问题,对我们来说是无解的,我们可以将lingering_timeout设置短一点,但是延时关闭的问题是不可避免的。好在是我们知道了原因,并不是真正的处理慢了,只不过是延时关闭导致日志时间有误。

------------------------------------end
一起关注高性能WEB后端技术,关注公众号

posted @ 2019-03-30 08:34 飞翔码农 阅读(...) 评论(...) 编辑 收藏