事故现象
最近一段时间,请假系统每隔几天就会出现服务器无响应情况,访问URL后转半天,然后就显示请求失败。出现大量NGINX请求超时。重启服务器后业务又可以恢复正常,出问题又是不定时出现,没有一个确定的时间节点。
问题排查
首先查看了下Tomcat是否宕机
查看进程 ps指令查看进程存在,说明Tomcat并没有挂掉
查看Tomcat日志 catalina.out和localhost_access_log日志定格到某一时刻,并没有报错,也没有新的日志产生 查看CPU和内存 top指令查看,内存和cpu也没有异常情况 jinfo -flags 15183查看启动参数
-XX:CICompilerCount=4 -XX:+DisableExplicitGC -XX:InitialHeapSize=262144000
-XX:MaxHeapSize=4164943872 -XX:MaxNewSize=1388314624 -XX:MaxTenuringThreshold=15
-XX:MinHeapDeltaBytes=524288 -XX:NewRatio=2 -XX:NewSize=87031808 -XX:OldSize=175112192
-XX:SurvivorRatio=10 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
jmap指令生成dump 堆快照 堆内存显示正常
可以用 jvisualvm.exe 进行内存分析,或者采用 Eclipse Memory Analysis Tools (MAT)这个工具
jmap -dump:format=b,file=/neworiental/temp/dump.bin 15183
使用jstack 15183查看,没有发现死锁信息
分析NGINX
网页显示NGINX超时,说明NGINX是通的,可以正常访问,但是Tomcat没反应,猜测可能是NGINX到Tomcat通讯有问题 netstate -ano指令查看连接信息,发现大量NGINX到Tomcat请求处于time_wait状态,还有少部分Tomcat到MySQL的连接 netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'查看各状态连接数
netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'
返回结果示例:
TIME_WAIT 1057
分析问题
Tomcat使用的是默认配置,由于Tomcat默认并发连接数是200左右,所以超过的请求都被拒绝。 本来以为找到原因了,想着把这个值调大,就解决问题了,但是又仔细想了想,按道理系统的瞬时访问量不可能到200,总共6000员工,请假系统同时点击瞬时业务量达不到那么大量,所以根本原因不在这里,这时候分析陷入了僵局,思路有点断了。于是重启了服务器。
新的线索:MySQL异常信息
这时候我重启了服务器,突然有了新的线索,这次发现shutdown时日志动了,这时候出了一大堆MySQL断开的异常,结合上面netstat信息也存在很多MySQL连接,猜测会不会是MySQL慢查询语句导致请求不能及时返回,大量请求堆积导致Tomcat请求数量超过最大限制,出现假死状态。
验证第一次分析结果
系统是另一个人做的所以不知道哪些地方有慢查询语句,只能借助软件分析,这里使用durid连接池分析,通过SQL界面发现确实有好多慢查询语句,找到所有查询时间超过2秒的查询语录,在项目中找到并优化,优化过程有索引优化和查询语句结构优化,这里就不展开说了。 上线验证是否解决问题,运行了一个月没问题,第一次算是解决了问题。
第二个月又一次出现假死
本来以为问题已经解决,可是到了第二个月,又出现服务器假死情况,这次第一反应是不是还有慢查询上次没发现,想打开durid页面看看还有什么慢查询语句,但是出现问题时所有请求都被Tomcat拒之门外,durid页面也打不开。
再次分析问题
所以只好去MySQL查看连接状态,使用show PROCESSLIST指令查看链接状态,发现连接数只有5个,这时候想会不会是瞬时请求超过五个,连接数太少导致请求处理不过来,导致MySQL新请求被排队等待,从而出现阻塞,最终导致Tomcat连接数超载。于是打开MySQL配置文件,发现配置文件使用的是demo配置,最大连接数是5个。
[root@localhost][(none)]>show PROCESSLIST;
+--------+-----------------+--------------------+---------------+---------+----------+------------------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+--------+-----------------+--------------------+---------------+---------+----------+------------------------+------------------+
| 158280 | leave_db | 127.0.0.1:60594 | leaveapproval | Sleep | 6 | | NULL |
| 158282 | leave_db | 127.0.0.1:60634 | leaveapproval | Sleep | 6 | | NULL |
| 158306 | leave_db | 127.0.0.1:47244 | leaveapproval | Sleep | 6 | | NULL |
| 158309 | leave_db | 127.0.0.1:48752 | leaveapproval | Sleep | 48 | | NULL |
| 158312 | leave_db | 127.0.0.1:51522 | leaveapproval | Sleep | 6 | | NULL |
| 158315 | root | localhost | NULL | Query | 0 | starting | show PROCESSLIST |
+--------+-----------------+--------------------+---------------+---------+----------+------------------------+------------------+
14 rows in set (0.00 sec)
解决并验证
打开MySQL配置文件,最大连接数是5个,调到50后上线验证,运行几个月后没有再出现,问题告一段落。打开durid页面查看峰值最大连接数是50,这里也验证了之前5个肯定是不够用的,这里为了保险起见改成了100个最大连接数,运行半年后发现偶尔数据库最大连接数会达到75。
|