Java学习笔记

线上如何排查FullGC(系统 CPU 突然飙升且 GC 频繁，你该如何排查)

zszdevelop大约 8 分钟

线上如何排查FullGC(系统 CPU 突然飙升且 GC 频繁，你该如何排查)

1. 背景

处理过线上问题的同学基本上都会遇到系统突然运行缓慢，CPU 100%,以及Full GC 次数过多的问题。

2. 初步解决方案

如果出现该问题导致线上系统不可用，那么首先需要做的就是，导出jstack和内存信息，然后重启系统。尽快保证系统的可用性。

3. 产生的原因

常见原因

  1. 代码中某个位置读取数据量较大，导致系统内存耗尽，从而导致Full GC次数过多，系统缓慢
  2. 代码中有较多消耗CPU的操作，导致CPU过高，系统运行缓慢

相对来说，这是出现频率最高的两种线上问题，而且它们会直接导致系统不可用。另外有几种情况也会导致某个功能运行缓慢，但是不至于导致系统不可用：

  1. 代码某个位置有阻塞性的操作，导致该功能调用整体比较耗时，但出现是比较随机的
  2. 某个线程由于某种原因而进入WAITING状态，从而导致系统整体比较缓慢
  3. 由于锁使用不当，导致多个线程进入死锁状态，从而导致系统整体比较缓慢

对于这三种情况，通过查看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.34
KiB Mem:   2046460 total,  1923864 used,   122596 free,    14388 buffers
KiB 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 -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 13.2 14.2   0:06.78 java

可以看到，在进程为9的Java程序中各个线程的CPU占用情况，接下来我们可以通过jstack命令查看线程id为10的线程为什么耗费CPU最高。需要注意的是，在jsatck命令展示的结果中，线程id都转换成了十六进制形式。可以用如下命令查看转换结果，也可以找一个科学计算器进行转换：

root@a39de7e7934b:/# printf "%x\n" 10
a

这里打印结果说明该线程在jstack中的展现形式为0xa，通过jstack命令我们可以看到如下信息

"main" #1 prio=5 os_prio=0 tid=0x00007f8718009800 nid=0xb runnable [0x00007f871fe41000]
   java.lang.Thread.State: RUNNABLE
	at com.aibaobei.chapter2.eg2.UserDemo.main(UserDemo.java:9)

"VM Thread" os_prio=0 tid=0x00007f871806e000 nid=0xa runnable

这里的VM Thread一行的最后显示nid=0xa，这里nid的意思就是操作系统线程id的意思。而VM Thread指的就是垃圾回收的线程。这里我们基本上可以确定，当前系统缓慢的原因主要是垃圾回收过于频繁，导致GC停顿时间较长。我们通过如下命令可以查看GC的情况：

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

可以看到，这里FGC指的是Full GC数量，这里高达6793，而且还在不断增长。从而进一步证实了是由于内存溢出导致的系统缓慢。那么这里确认了内存溢出，但是如何查看你是哪些对象导致的内存溢出呢，这个可以dump出内存日志，然后通过eclipse的mat工具进行查看，如下是其展示的一个对象树结构：

![image-20200317004122623](/Users/zsz/Library/Application Support/typora-user-images/image-20200317004122623.png)

经过mat工具分析之后，我们基本上就能确定内存中主要是哪个对象比较消耗内存，然后找到该对象的创建位置，进行处理即可。这里的主要是PrintStream最多，但是我们也可以看到，其内存消耗量只有12.2%。也就是说，其还不足以导致大量的Full GC，此时我们需要考虑另外一种情况，就是代码或者第三方依赖的包中有显示的System.gc()调用。这种情况我们查看dump内存得到的文件即可判断，因为其会打印GC原因：

[Full GC (System.gc()) [Tenured: 262546K->262546K(349568K), 0.0014879 secs] 262546K->262546K(506816K), [Metaspace: 3109K->3109K(1056768K)], 0.0015151 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC (Allocation Failure) [DefNew: 2795K->0K(157248K), 0.0001504 secs][Tenured: 262546K->402K(349568K), 0.0012949 secs] 265342K->402K(506816K), [Metaspace: 3109K->3109K(1056768K)], 0.0014699 secs] [Times: user=0.00

比如这里第一次GC是由于System.gc()的显示调用导致的，而第二次GC则是JVM主动发起的。总结来说，对于Full GC次数过多，主要有以下两种原因：

  • 代码中一次获取了大量的对象，导致内存溢出，此时可以通过eclipse的mat工具查看内存中有哪些对象比较多；
  • 内存占用不高，但是Full GC次数还是比较多，此时可能是显示的System.gc()调用导致GC次数过多，这可以通过添加-XX:+DisableExplicitGC来禁用JVM对显示GC的响应。

3.2 CPU过高

查看参考文章

3.3 不定期出现的接口耗时现象

查看参考文章

3.4 某个线程进入WAITING状态

查看参考文章

3.5 死锁

查看参考文章

4. 总结

  1. 通过top命令查看cpu情况，
  2. 如果CPU比较高，
    1. 则通过top -Hp <pid> 命令查看当前进程的各个线程运行情况，
    2. 找出CPU过高的线程之后，将其线程id转换为十六进制的表现形式
    3. 然后在jstack日志中查看该线程主要在进行的工作
      1. 如果是正常的用户线程，则通过该线程的堆栈信息查看其具体是在哪处用户代码处运行比较消耗CPU；
      2. 如果该线程是VM Thread，则通过jstat -gcutil 命令监控当前系统的GC状况，然后通过jmap dump:format=b,file= 导出系统当前的内存数据。导出之后将内存情况放到eclipse的mat工具中进行分析即可得出内存中主要是什么对象比较消耗内存，进而可以处理相关代码；
    4. 如果通过top命令看到CPU并不高，并且系统内存占用率也比较低。此时就可以考虑是否是由于另外三种情况导致的问题
      1. 如果是接口调用比较耗时，并且是不定时出现，则可以通过压测的方式加大阻塞点出现的频率，从而通过jstack查看堆栈信息，找到阻塞点；
      2. 如果是某个功能突然出现停滞的状况，这种情况也无法复现，此时可以通过多次导出jstack日志的方式对比哪些用户线程是一直都处于等待状态，这些线程就是可能存在问题的线程；
      3. 如果通过jstack可以查看到死锁状态，则可以检查产生死锁的两个线程的具体阻塞点，从而处理相应的问题。

面试实战

FullGC你再线上遇到问题你应该怎么排查？

  1. 使用 jstat -gcutil 命令监控当前系统GC状况
  2. 通过jmap dump：format=b,file=导出系统当前的内存数据
  3. 通过mat工具分析得出内存中主要什么对象消耗内存，进而可以处理相关代码

参考文章

面试被问：如果系统 CPU 突然飙升且 GC 频繁，你该如何排查？open in new window

Loading...