CPU100%问题排查
导致Java程序CPU与内存冲高的原因:
- 代码中某个位置读取数据量较大,导致系统内存耗尽,从而导致Full GC次数过多,系统缓慢。
- 代码中有比较耗CPU的操作,导致CPU过高,系统运行缓慢。
- 代码某个位置有阻塞性的操作,导致该功能调用整体比较耗时,但出现是比较随机的;
- 某个线程由于某种原因而进入WAITING状态,此时该功能整体不可用,但是无法复现;
- 由于锁使用不当,导致多个线程进入死锁状态,从而导致系统整体比较缓慢。
1 top命令查看CPU占用情况
PID为进程编号,COMMAND为其中执行命令,java即为要找的应用top: 展示所有进程占用情况
top -N num: 展示CPU占用最高的num个进程
root@8d36124607a0:/# top top - 14:01:23 up 1 day, 17:54, 1 user, load average: 0.00, 0.01, 0.05 Tasks: 101 total, 1 running, 100 sleeping, 0 stopped, 0 zombie %Cpu(s): 0.8 us, 1.2 sy, 0.0 ni, 98.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 3782864 total, 1477524 free, 329656 used, 1975684 buff/cache KiB Swap: 0 total, 0 free, 0 used. 3181392 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 9 root 20 0 1031064 52580 19248 S 90.3 10.4 26:30.37 javacatalina.sh
root@8d36124607a0:/# top -Hp 9 top - 08:31:16 up 30 min, 0 users, load average: 0.75, 0.59, 0.35 Threads: 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 st KiB Mem: 2046460 total, 1924856 used, 121604 free, 14396 buffers KiB 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 1.2 14.2 0:06.78 java
看到占用CPU消耗最高的PID为10,该ID即为线程ID,使用如下命令将其转化为16进制格式:
root@8d36124607a0:/# printf "%x\n" 10
得到输出a线程即为0xa
2 使用jstack查看Java线程信息
jstack 进程号 | grep 线程ID:查看线程堆栈信息,将上一步骤的Java线程进程ID与CPU占用量较高的线程ID(16进制格式)填入其中。jstack pid >> stack.txt:将今后曾所有堆栈信息都打印到stack.txt中
root@8d36124607a0:/# jstack 9 | grep 0xa "VM Thread" os_prio=0 tid=0x00007f871806e000 nid=0xa runnable”
第一个双引号圈起来的就是线程名,如果是“VM Thread”这就是虚拟机GC回收线程,如果是"main"则是其他线程,后面的runnable是线程状态。
3 使用jstat查看GC信息
jstat -gcutil 进程号 统计间隔毫秒 统计次数(缺省代表一直统计)
root@8d36124607a0:/# jstat -gcutil 9 1000 10 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 0.00 0.00 75.07 59.09 59.60 3259 0.919 6517 7.715 8.635 0.00 0.00 0.00 0.08 59.09 59.60 3306 0.930 6611 7.822 8.752 0.00 0.00 0.00 0.08 59.09 59.60 3351 0.943 6701 7.924 8.867 0.00 0.00 0.00 0.08 59.09 59.60 3397 0.955 6793 8.029 8.984
查看某进程GC持续变化情况,如果发现返回中FGC很大且一直增大,确认为Full GC! 可以使用“jmap -heap 进程ID”查看一下进程的堆内从是不是要溢出,特别是老年代内从使用情况一般是达到阈值就会进程Full GC。
4 使用Jmap分析内存
jmap -dump:format=b,file=文件名称 进程ID:生成内存dump文件,进行离线分析。
Full GC次数过多
- 线上多个线程的CPU都超过了100%,通过jstack命令可以看到这些线程主要是垃圾回收线程
- 通过jstat命令监控GC情况,可以看到Full GC次数非常多,并且次数在不断增加。
使用top与top -Hp命令找到CPU占用最高的Java线程,将其转为16进制后,使用jstack命令抓取该线程信息,发现线程名称是"VM Thread"垃圾回收线程。
进一步确认: 使用jstat -gcutil命令查看gc次数与增长情况。
进一步分析:使用jmap -dump命令dump内存,然后使用使用ha457.jar离线分析。
- 生成大量的对象,导致内存溢出
- 内存占用不高,但是Full GC次数还是比较多,此时可能是代码中手动调用 System.gc()导致GC次数过多。
某个业务逻辑执行时间过长
如果是Full GC次数过多,那么通过jstack得到的线程信息会是类似于VM Thread之类的线程,而如果是代码中有比较耗时的计算,那么我们得到的就是一个线程的具体堆栈信息。如下是一个代码中有比较耗时的计算,导致CPU过高的线程信息:
在请求UserController的时候,由于该Controller进行了一个比较耗时的调用,导致该线程的CPU一直处于100%。可以根据堆栈信息,直接定位到UserController的34行
死锁
关键字:deadlock。使用jstack打印线程信息会打印出业务死锁的位置。
立志如山 静心求实
浙公网安备 33010602011771号