近期项目新版本上线遇到cpu冲高现象,依据之前的经验,把这次排查过程记录下。
步骤一:确定环境上cpu占用高的进程
环境cpu冲高,首先确定cpu占用高的进程,使用命令:
top
java进程cpu占用达765%,确定是java进程cpu占用高,进程id为1(容器环境)。
根据上篇博客的经验,java进程cpu占用高,基本为如下两个原因:
(1)执行任务的java线程本身存在bug,死循环或者操作本身耗cpu,导致cpu占用过高
(2)jvm发生频繁gc,导致cpu过高
步骤二:判断是否是gc导致的cpu冲高
排查是否为gc导致,看如下两点:
(1)gc频率和耗时
(2)内存占用率
(1)gc频率和耗时有两种手段看:
第一种:根据gc日志的打印时间,可确定每次gc间隔的时间和耗时:
使用这种方式的前提是配置了gc日志的打印,参考jvm参数如下:
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:../../logs/gc.log
第二种:使用如下命令,可每隔5s打印一次gc情况,从打印结果可以判断gc频率,在通过YGCT/YGC和FGCT/FGC可以计算出每次gc的耗时。
jstat -gc <java_pid> 5000
若gc频率低,且耗时短,则基本可以排除是gc导致的cpu冲高问题。
(2)jvm内存占用,可使用如下命令,打印堆内存使用情况
jmap -heap <java_pid>
也可通过top查看系统的内存占用情况。若内存占用低,也可基本排除是频繁gc造成的cpu冲高。
上篇博客,其原因就是频繁gc导致的cpu占用高。
而本次案例,ygc频率每隔70s发生一次,每次10ms左右,且未发生full gc,因此可基本排除是频繁gc造成的cpu冲高。
步骤三:排查是否为java线程本身的bug
使用如下命令查看java哪个线程cpu占用高:
top -H -p <java_pid>
确定线程id,再通过如下命令计算十六进制值:
printf "%x\n" <java_thread_id>
然后,再使用如下命令,打印该线程堆栈内容:
jstack <java_pid> | grep <线程id十六进制值> -A 30(-A 30表示向下打印30行)
堆栈信息参考案例:
[root@***-5b4f4bd999-7r84r logs]# jstack 1 | grep '0xec5' -A 100
"http-nio-8081-exec-227" #3768 daemon prio=5 os_prio=0 tid=0x00007ff490104800 nid=0xec5 runnable [0x00007ff3d7ee5000]
java.lang.Thread.State: RUNNABLE
at com.***.protocol.common.device.service.impl.DeviceCommonServiceImpl.getDeviceInfos(DeviceCommonServiceImpl.java:167)
at com.***.protocol.common.device.controller.DeviceCommonController.getDeviceInfos(DeviceCommonController.java:100)
通过上述日志可知,该线程一直在处理getDeviceInfos接口内容,分析DeviceCommonServiceImpl.java:167的代码,如下:
do {
if(DeviceSearchType.VEP_TYPE == searchType){
continue;
}
// ...省略
167: } while (startType == DmConstants.DeviceSearchType.DEFAULT_TYPE
&& CollectionUtils.isEmpty(deviceInfos)
&& searchType <= DeviceSearchType.GA1400);
第167行指向while循环,此时就要想到是否是死循环的问题。接着分析循环体内容,发现在循环开始的时候有个if判断和continue,再结合业务可知,这里造成死循环。
因此可以得出是死循环导致的cpu冲高。