近期项目新版本上线遇到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冲高。

步骤四:结合业务修改代码解决问题