相对来说,这种情况是最容易出现的,尤其是新功能上线时。

对于 Full GC 较多的情况,其主要有如下两个特征:

  • 线上多个线程的 CPU 都超过了 *** 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 工具进行查看。

如下图是其展示的一个对象树结构:

频繁FullGC的排查_System

经过 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 的响应。