记一次网站故障排查过程（nginx 504状态码、 upstream timed out (110: Connection timed out）以及jbd2引起IO高

一、问题描述

客户侧反馈无法正常访问系统，页面转圈，时好时坏，访问不稳定。

二、系统环境：

机器环境：UOS 、 nginx 、php（对接其他服务器kingbase 、钉钉、redis 、KF）
ELB：192.168.1.100
web1: 192.168.1.101 ，web2: 192.168.1.102

三、流量流向示意：

用户访问系统 > ELB > nginx > web1/web2

四、排查过程

4.1

1、按巡检项检查系统所要启动的端口和服务，均已启动。
2、检查网闸，telnet访问网闸正常。tcping 端口也是通的。
3、检查PHP日志文件laravel.log ，无异常。
4、但仅有1.101服务器的nginx的error.log发现报错upstream timed out 
upstream: "http://192.168.1.100:8080/xxx/xxxid", 且同时间段的access.log有504异常状态码；
而129.72是没有time out 的error.log日志。
5、咨询华为云ELB工程师ELB状况。反馈ELB状况无异常，但ELB负载均衡查不了日志。
根据nginx的报错日志，重启101服务器，且修改101服务器的nginx.conf添加proxy_connect_timeout 300等配置项

4.2

次日，客户侧还是反馈系统转圈现象。 101服务器error.log仍有报timed out信息。昨日操作101服务器的时候，发现操作时，有偶尔卡顿现象。
（下面是101服务器的状况）

1、top指令下load average数值很高（8.39，6.11，4.92）。wa值也很高（99）
这说明磁盘读写紧张，I/O等待久。
2、使用iotop指令查看异常I/O信息。发现jdb2/vda2-8的IO>达到了90%+ 。
参考网上资料，操作系统自身jbd2高会引起IO高的问题，会导致高load average ，卡顿。
 
3、为了保证业务的正常运作，晚上将ELB切成单边形式，只让web2进行服务。 
web1关闭外网业务后，还是会出现操作卡顿的现象。重启过机器后还是有卡顿现象。

4.3

服务器系统是统信UOS
1、分析syslog、kern.log  ；ps -exf| grep jdb2;  pstree pid 、 strace -p pid 
systemctl set-default multi-user.target
systemctl restart default
reboot -f （这过程中重启了2次，第一次直接卡死在图形化界面。）（关闭GUI桌面，改成字符（黑窗口）系统） 

4.4 其他角度的排查思路

#网络方面
1、筛选error.log日志time out出现时间段12:00~14:00 ，此时是午休时间段，非系统使用高峰期。
但还是出现了9条time out记录，该系统的PV量不算很大，就处理类似OA流程的操作。单台机器的网络带宽是 100Mbit/s ，网络性能是过剩了。
那可能不是网络问题了。网络的话要么全挂，要么全好。

五、异常截图信息

5.1 nginx的error.log和access.log

#error.log
2022/01/04 20:37:30 [error] 11362#11362: *7694845 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 100.64.14.178, server: _, request: "GET /ticket/index?page=1&size=10&status[]=3&node_status=true HTTP/1.1", upstream: "http://192.168.1.100:8080/xxx/index?page=1&size=10&status[]=3&node_status=true", host: "xx.com.cn", referrer: "https://xx.com.cn/xx/"

#access.log
100.64.14.178 - - [04/Jan/2022:20:37:30 +0800] "GET /xxx/index?page=1&size=10&status[]=3&node_status=true HTTP/1.1" 504 176 "https://xx.com.cn/xx/" "Mozilla/5.0 (iPhone; CPU iPhone OS 15_2 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/19C56 AliApp(DingTalk/6.3.20) /22475258 Channel/201200 language/zh-Hans-CN UT4Aplus/0.0.6 WK" 

5.2 系统卡顿截图

iotop指令（按p键， 按o键，按a键 ）

io>值高的：jdb2

六、排查结论

初步判断是（ jbd2进程导致磁盘 io 高）系统内核bug导致IO阻塞，影响到了系统服务（192.168.1.101）。
最开始因为是nginx的问题。但最终后面这IO高也会导致nginx出现time out

UOS排查过程/结论

6.1 Xorg.0.log日志

客户的xorg 爆出(EE) modeset(0): glamor initialization failed 。 看来窗口管理有问题。

ls -l | egrep ^[^d] | awk '{print $(NF)}' | xargs -i grep -H "glamor" {}

dmesg日志

看的出来jbd2存在一些问题，它是日志的相关服务 journaling block driver 文件系统的日志功能
根据之前的现象看
1、可能是进程的写入过于频繁 --经过查看没有进程对主机操作，目前看就是日志的进程再读写
2、有可能磁盘存在性能瓶颈 --需要用户确认磁盘的性能
进一步查看dmesg日志，这个io高可能是用户再做perf测试过程中引起中，网络异常导致的这个IO的高的现象，因为内核日志中有perf的中断报错。实际表现在日志的读写方面。
（下图最左边的绿色的字体。 从5秒开始 到90000秒，在报错。 （大概意思是网络异常 perf中断 ，导致io阻塞））

目前由于问题无法复现，建议用户直接用非图形化去规避吧

重点术语

1、 load average
top命令中load average显示的是最近1分钟、5分钟和15分钟的系统平均负载数值。

一个类比的例子：
数值0.00 和 1.00之间 表示目前桥面上几乎没有任何的车流，道路畅通。 
数值1.00 表示刚好是在这座桥的承受范围内，车流会有些堵。
数值超过 1.00，那么说明这座桥已经超出负荷，交通严重的拥堵。


2、 wa
wa, IO-wait : time waiting for I/O completion
wa 列显示了IO等待所占用的CPU时间的百分比。这里wa的参考值为30%，如果wa超过30%，说明IO等待严重，
这可能是磁盘大量随机访问造成的，也可能磁盘或者磁盘访问控制器的带宽瓶颈造成的。

3、 iotop
查看IO占用的监控工具。 IO>列的数值越高，说明该程序是高I/O消耗程序。

 
4、jdb2
jbd（journaling block driver） 文件系统的日志功能，jbd2是ext4文件系统版本；可以肯定的是对文件系统的操作太频繁，会导致IO压力过大。


日志块设备（JBD）为文件系统日志提供了一个独立于文件系统的接口。
The Journaling Block Device (JBD) provides a filesystem-independent interface for filesystem journaling. 

参考博客

https://blog.csdn.net/lcj_star/article/details/76672748 《nginx报504超时错误》
https://blog.aliasmee.com/post/questions-about-proxy-connect-timeout-on-nginx/ 《关于Nginx proxy_connect_timeout 的问题》
https://blog.ohyeahwoo.com/?p=792 《访问WEB报timeout》


https://cloud.tencent.com/developer/article/1465600 《性能分析之又见jbd2引起IO高》
https://easyice.cn/archives/328 《jbd2进程导致磁盘 io 高的分析》

https://madflojo.medium.com/troubleshooting-high-i-o-wait-in-linux-358080d57b69   （这篇写的很好）
https://serverfault.com/questions/155882/wa-waiting-for-i-o-from-top-command-is-big/155887


无意间也发现iotop可以看到后台运行的进程（指nohup 、& 、setsid执行的后台脚本）
也感谢运维岗的各位大佬的帮助。通过这次故障 学到不少知识。