1.故障业务侧现象
XXX系统,无法派单、无法查询代办,系统卡变慢。总之服务在一步步裂变,性能在一点点下降。
2.故障主机侧现象
查看主机,发现内存正常,CPU占用率80%,一直下不来。 数据库采用oracle数据库,数据库为发现大量IOW及锁表的现象,数据库主机内存、CPU均正常。
3.故障定位
既然数据库性能没问题,那问题肯定出在业务主机侧。 主机侧查看系统内存、java堆内存情况均正常,并且服务器只有CPU飙高,那就从线程入手。
3.1查看导出进程快照
查看服务器Java进程,使用率非常高,高峰期进程占用CPU1300%。导出改进程的线程快照。jstack 21372 >threads_tops.txt
3.2定位线程
根据十进制进程PID换算成16进制的nid值,进入线程快照搜索匹配得到快照点,耗费CPU的线程代码。再次通过源码快照,定位到系统平台源码依赖jar包。 可以定位到java进程高的原因,平台查询代办人员代办后,将人员信息报文转成List实体类过程中耗费大量CPU。
定位获取查询人员接口源码,发现如果不传参数,默认会查询整个所有人员信息(73328个人员)。将7万个工号转List实体类会耗费大量CPU。
4.故障验证
查看数据库查询记录,发现10分钟内,没有传入参数的参与者查询为30余次。可见生产时间调用量会更大。
5.故障处理
修改业务类型,禁止不传参数情况下,查询所有人。观察后,故障彻底解决。
6.复盘
6.1jstack命令
jstack命令用于打印指定Java进程、核心文件或远程调试服务器的Java线程的Java堆栈跟踪信息
jstack [ options ] pid
pid:Java进程的ID,可以通过jps命令查询到。
6.2日志文件分析:明显异常
可以通过 jstack [options] pid >> /xxx/xx/x/dump.log命令,将堆栈信息输出到dump.log文件后,然后下载到本地排查文件。
在dump.log日志文件里,需要重点关注的线程状态
Deadlock(死锁)
死锁线程,一般指多个线程调用间,进入相互资源占用,导致一直等待无法释放的情况。
Waiting on condition(等待资源)
该状态出现在线程等待某个条件的发生。最常见的情况是线程在等待网络的读写,比如当网络数据没有准备好读时,线程处于这种等待状态。而一旦有数据准备好读之后,线程会重新激活,读取并处理数据。
如果发现有大量的线程都在处在 Wait on condition,从线程堆栈看,正等待网络读写,这可能是一个网络瓶颈的征兆,因为网络阻塞导致线程无法执行,原因有两种:一种情况是网络非常忙,几 乎消耗了所有的带宽,仍然有大量数据等待网络读写;另一种情况也可能是网络空闲,但由于路由等问题,导致包无法正常的到达。
Blocked(阻塞)
线程阻塞,是指当前线程执行过程中,所需要的资源长时间等待却一直未能获取到,被容器的线程管理器标识为阻塞状态,可以理解为等待资源超时的线程。
6.3日志分析:非明显异常
以上是异常点,如果线程快照中出现了上述异常点,有很好的定位。但是如果没有出现上述异常点,应该怎么定位, 线程快照基本是“RUNNABLE”、“TIMED_WAITING”、“TERMINATED”等状态。
RUNNABLE(运行时)
运行态:当线程已被占用,在Java虚拟机中正常执行时,就处于此状态。
我们可以通过“寻找进程” 》》“寻找线程”》》查看线程状态来定位
寻找进程:执行命令jps找出Java进程ID,或者top,或者ps -ef |grep java 命令查看耗费资源的进程PID
寻找线程:得到进程ID为22343,第二步找出该进程内最耗费CPU的线程,可以使用
`1. ps -Lfp pid
-
ps -mp pid -o THREAD, tid, time
-
top -Hp pid`
TIME列就是各个Java线程耗费的CPU时间,CPU时间最长的是线程ID为21742的线程,用
转换10禁止线程ID为16禁止值
`[root@oms ~]# printf "%x\n" 22414
带着线程16禁止ID去线程快照去匹配,定位
同时如果线程中出现大量同一个请求的RUNNABLE线程,并结合代码并没有什么异常。则需要考虑其他问题点。