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

最近发现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的延迟关闭-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后端技术，关注公众号