一、前言
处理过线上问题的同学基本上都会遇到系统突然运行缓慢,CPU 100%,以及Full GC次数过多的问题。当然,这些问题的最终导致的直观现象就是系统运行缓慢,并且有大量的报警。本文主要针对系统运行缓慢这一问题,提供该问题的排查思路,从而定位出问题的代码点,进而提供解决该问题的思路。
二、分析原因
对于线上系统突然产生的运行缓慢问题,如果该问题导致线上系统不可用,那么首先需要做的就是,导出jstack和内存信息,然后重启系统,尽快保证系统的可用性。这种情况可能的原因主要有两种:
代码中某个位置读取数据量较大,导致系统内存耗尽,从而导致Full GC次数过多,系统缓慢;
代码中有比较耗CPU的操作,导致CPU过高,系统运行缓慢;
相对来说,这是出现频率最高的两种线上问题,而且它们会直接导致系统不可用。另外有几种情况也会导致某个功能运行缓慢,但是不至于导致系统不可用:
代码某个位置有阻塞性的操作,导致该功能调用整体比较耗时,但出现是比较随机的;
某个线程由于某种原因而进入WAITING状态,此时该功能整体不可用,但是无法复现;
由于锁使用不当,导致多个线程进入死锁状态,从而导致系统整体比较缓慢。
对于这三种情况,通过查看CPU和系统内存情况是无法查看出具体问题的,因为它们相对来说都是具有一定阻塞性操作,CPU和系统内存使用情况都不高,但是功能却很慢。下面我们就通过查看系统日志来一步一步甄别上述几种问题。
三、排查步骤
3.1 Full GC次数过多
相对来说,这种情况是最容易出现的,尤其是新功能上线时。对于Full GC较多的情况,其主要有如下两个特征:
线上多个线程的CPU都超过了100%,通过jstack命令可以看到这些线程主要是垃圾回收线程
通过jstat命令监控GC情况,可以看到Full GC次数非常多,并且次数在不断增加。
首先我们可以使用top命令查看系统CPU的占用情况,如下是系统CPU较高的一个示例:
top - 08:31:10 up 30 min, 0 users, load average: 0.73, 0.58, 0.34KiB Mem: 2046460 total, 1923864 used, 122596 free, 14388 buffersKiB Swap: 1048572 total, 0 used, 1048572 free. 1192352 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 9 root 20 0 2557160 288976 15812 S 98.0 14.1 0:42.60 java
可以看到,有一个Java程序此时CPU占用量达到了98.8%,此时我们可以复制该进程id9,并且使用top命令查看呢该进程的各个线程运行情况:
top -Hp 9
该进程下的各个线程运行情况如下:
top - 08:31:16 up 30 min, 0 users, load average: 0.75, 0.59, 0.35Threads: 11 total, 1 running, 10 sleeping, 0 stopped, 0 zombie%Cpu(s): 3.5 us, 0.6 sy, 0.0 ni, 95.9 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 stKiB Mem: 2046460 total, 1924856 used, 121604 free, 14396 buffersKiB Swap: 1048572 total, 0 used, 1048572 free. 1192532 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 10 root 20 0 2557160 289824 15872 R 79.3 14.2 0:41.49 java 11 root 20 0 2557160 289824 15872 S 13.2 14.2 0:06.78 java
可以看到,在进程为9的Java程序中各个线程的CPU占用情况,接下来我们可以通过jstack命令查看线程id为10的线程为什么耗费CPU最高。需要注意的是,在