磁盘IO导致的NGINX超时问题

背景

收到接口超时的告警，本以为和往常一样，按照公网、负载均衡、nginx、java服务层层抽丝剥茧很容易定位到问题，结果打脸了 。通过排查，定位到问题在nginx层，同样的请求，直接在nginx所在主机上curl后端服务响应很快（几十毫秒），但是请求nginx通过nginx代理后端的服务就非常慢（十几秒）。百思不得其解。

排查结果现象

• 现象1：netstat 查看连接状态，NGINX 主机出现大量CLOSE_WAIT 状态的连接

• 现网2：抓包发现，TCP握手阶段出现重传
  

• 现象3： netstat -s |grep -i listen ，发现出现SYN到LISTEN的包的丢失一直在增加
  

• 现象4：ss -ln|grep <nginx端口> 发现nginx对应监听端口的半连接队列为512，且已经基本满了（截图是已经修改后截的）
  

• 现象5：同一个NGINX 进程，A端口的代理不超时，B端口下的所有代理都超时了

• 现象6：分析NGINX 的访问日志中，超时请求较多的时候，出现大量状态码为499的请求

• 手动测试一次向nginx代理地址的请求，发现虽然超时，但是访问日志里request_time和upstream_response_time 字段的值都非常低（几十毫秒）。

处理过程

1、半连接队列满

通过TCP重传、SYN到LISTEN 阶段的丢包，ss -ln的 信息，基本确认是半连接队列满，很激动地开始了内核参数的修改

vim /etc/sysctl.conf 
net.core.somaxconn = 3072
net.ipv4.tcp_max_syn_backlog = 3072

#让配置生效
sudo sysctl -p

#修改nginx的半连接队列长度，还需要在listen的配置项显示设置backlog值
vim nginc.conf 
listen 8084 backlog=3072；

重启Nginx再次ss -ln|grep 8084 查看，当前队列已经调整为3072

处理完半连接的问题后，发现超时问题还是依旧，而且半连接队列过不了多久又会满，正常Nginx的处理性能，3072应该是错错有余的。继续找原因

2、磁盘使用率高

期间发现了磁盘使用率高，但是大意的认为不是根本原因，因为在出现超时请求之前磁盘IO也高。查看的方法如下图：

在出问题的时间段，%iowait 值达到10+%，%util 达到90+%，且经常飙升到100%。因为查看历史监控，主机的%util 一直比较高，因此认为主机磁盘不是根因。期间甚至怀疑是nginx的bug、更换了腾讯的tengine。结果问题依旧。

3、凌晨3点超时现象自动恢复

准备日次再定位问题，等早上再看的时候，超时问题已恢复，再查看一下状态码为499的请求分布情况，凌晨3点左右断崖式下降，不得其解，以为是业务上有什么变化，看了业务曲线，并没有业务量的的明显变化。

4、偶然的发现解决所有疑惑

无意中执行 ps -ef|grep nginx ，发现有一个tac nginx/logs/access.log 的进程，跟踪其父进程，发现是管理平台上一个定时任务在扫描nginx的访问日志，而且每次扫描都是tac 全量文件扫描。当前nginx日志已经达到好几个G，这个定时任务每5分钟全量读一下日志，虚拟机的普通盘肯定吃不消。于是赶紧停了这个任务。

任务停止后再次验证，发现磁盘IO使用率立即下降了，接口也不超时了，状态码499的问题也没有了。联想到nginx日志切割的时间是凌晨3点左右，那么3点左右超时恢复就说的过去了 ，因为最新的 access.log 数据量小，所以tac查看的时候不怎么消耗磁盘IO，因此业务在3点左右自动恢复。

结论

放过了一个磁盘IO的线索，坑了自己。原先也了解过iostat -m -x 查看的磁盘使用率，util=100% 不一定就表示繁忙程度就是100%，只是表示在每一个时钟刻度内都有磁盘IO发生。看来以后在运维和定位问题的时候，磁盘UTIL 超过60%的时候就得引起重视，超过90% 肯定要考虑扩容或者升级高配存储了。当前CPU使用率中%iowait指标也值得重点关注，在笔者的环境中，%iowait到10+% 就出现了前面的问题。