【GC系列】JVM的常用GC参数及GC日志解析

>>强大,10k+点赞的 SpringBoot 后台管理系统竟然出了详细教程!



点击上方蓝字关注我吧,大家一起进步【GC系列】JVM的常用GC参数及GC日志解析





今天继续GC系列第三篇,熬夜不易,欢迎一键三连,给个鼓励,不点赞也没关系,我还可以,谢谢捧场[捂脸]。

【GC系列】JVM的常用GC参数及GC日志解析

常见垃圾回收器组合设定

在oracle官网上可以看到如何开启使用指定垃圾回收的命令:

https://docs.oracle.com/javase/8/docs/technotes/tools/unix/java.html

【GC系列】JVM的常用GC参数及GC日志解析

垃圾回收器通常是组合使用的,我根据官网总结一下常见垃圾回收器的组合。

  • 「-XX:+UseConcMarkSweepGC」

启用CMS垃圾收集器用于老年代。

当以吞吐量为主的垃圾回收器(-XX:+UseParallelGC)无法满足应用程序的延时要求时,Oracle建议使用的垃圾回收器是CMS或者G1(-XX:+UseG1GC)

默认情况下,此选项是禁用的,HotSpot VM会根据计算机的配置和JDK版本自动选择收集器。

启用此选项后,「-XX:+UseParNewGC选项将自动开启」,并且不应禁用它,因为在JDK 8中不推荐使用以下选项组合:-XX:+UseConcMarkSweepGC -XX:-UseParNewGC。

而CMS一旦老年代产生了很多内存碎片,它还会使用Serial Old进行清除。

所以,「-XX:+UseConcMarkSweepGC=ParNew+CMS+Serial Old」

  • 「-XX:+UseG1GC」

启用G1垃圾回收器。

它适用于具有大量RAM的多处理器计算机。它能「满足GC暂停时间目标,同时保持良好的吞吐量」

建议将G1收集器用于需要大堆(大小约为6 GB或更大)且GC延迟要求有限(稳定且可预测的暂停时间低于0.5秒)的应用程序。

  • 「-XX:+UseParallelGC」

使用并行清除垃圾收集器(也称为「吞吐量收集器」)来利用多个处理器来提高应用程序的性能。

默认情况下,此选项是禁用的,HotSpot根据计算机的配置和JDK版本自动选择收集器。

如果启用,则 「-XX:+UseParallelOldGC选项也将自动启用」,除非明确禁用它。

所以,「-XX:+UseParallelGC=Parallel Scavenge+Parallel Old」

  • 「-XX:+UseParallelOldGC」

FullGC时使用ParallelOld。默认情况下,此选项是禁用的。

-XX:+UseParallelGC时,会自动-XX:+UseParallelOldGC。

  • 「-XX:+UseParNewGC」

支持在年轻代中使用并行线程进行收集。

默认情况下,此选项是禁用的。

「设置-XX:+UseConcMarkSweepGC选项时,它将自动启用」

在JDK 8中,不建议使用-XX:+UseParNewGC选项而不使用-XX:+UseConcMarkSweepGC选项,也就是说ParNew和CMS最好同时启用,不要强行开一个禁一个。

  • 「-XX:+UseSerialGC」

启用Serial GC。

对于不需要垃圾回收具有任何特殊功能的「小型和简单的应用程序」,这通常是最佳选择。

默认情况下,此选项是禁用的,并且将「根据计算机的配置和JVM的类型自动选择收集器」

「-XX:+UseSerialGC=Serial New+Serial Old」

查看JDK默认的垃圾回收器

使用如下命令

java -XX:+PrintCommandLineFlags -version

可以查看当前使用的JDK版本、虚拟机名称及使用的垃圾回收器。

JDK 1.8 HotSpot VM默认GC是「ParallelGC」

【GC系列】JVM的常用GC参数及GC日志解析
jdk1.8默认GC

JDK 11 HotSpot VM默认GC是「G1」

【GC系列】JVM的常用GC参数及GC日志解析
jdk11默认的GC是G1

JVM常用命令参数

JVM命令可从如下网站查阅:

https://docs.oracle.com/javase/8/docs/technotes/tools/unix/java.html

「HotSpot参数分类」

  • 标准 -开头,所有的HotSpot都支持,比如java -version

保证Java虚拟机(JVM)的所有实现都支持标准选项。它们用于常见操作,例如检查JRE版本,设置类路径,启用详细输出等。

  • 非标准 -X开头,特定版本HotSpot支持特定命令

非标准选项是特定于Java HotSpot虚拟机的通用选项,因此不能保证所有JVM实现都支持它们,并且它们可能会发生变化。这些选项以-X开头。

  • 不稳定 -XX开头,下个版本可能取消

这是高级选项,以-XX开头,不建议随意使用。这些是开发人员选项,用于调整Java HotSpot虚拟机操作的特定区域,这些区域通常具有特定的系统要求,并且可能需要对系统配置参数的特权访问。也不能保证所有JVM实现都支持它们,并且它们可能会发生变化。

下面我们用一段程序,通过调JVM参数,使用JVM命令用不同的GC,看一下运行情况。

开始之前,先普及一下内存泄漏和内存溢出。

「内存泄漏」(memory leak):是指程序在申请内存后,无法释放已申请的内存空间,一次内存泄漏似乎不会有大的影响,但内存泄漏堆积后的后果就是内存溢出。

「内存溢出」(out of memory):指程序申请内存时,没有足够的内存供申请者使用。比如程序不断地产生对象到内存不够了报错OOM就是所谓的内存溢出。

【GC系列】JVM的常用GC参数及GC日志解析

再来看程序:

import java.util.LinkedList;
import java.util.List;

public class GCTest {
    public static void main(String[] args) {
        System.out.println("program start!");
        List list = new LinkedList();
        for (;;) {
            byte[] b = new byte[1024 * 1024];
            list.add(b);
        }
    }
}

很简单的一段测试代码,肯定会产生内存溢出,我们使用相关命令来观察一下。

默认情况下,运行代码:

[root@basic ~]# java GCTest
program start!
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
 at GCTest.main(GCTest.java:9)

报了内存溢出。

如果我们想知道他的内存分配过程,可以在运行的时候添加相应的JVM参数,下面来找几个常用的参数分别实验一下。

  • 「java -XX:+PrintCommandLineFlags GCTest」
[root@basic ~]# java -XX:+PrintCommandLineFlags GCTest
-XX:InitialHeapSize=32449856 -XX:MaxHeapSize=519197696 -XX:+PrintCommandLineFlags -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
program start!
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
 at GCTest.main(GCTest.java:9)

-XX:+PrintCommandLineFlags:打印人类可识别的JVM相关信息,例如堆空间大小和选定的垃圾收集器。

InitialHeapSize:起始堆大小,根据内存计算出来

MaxHeapSize:最大堆大小

UseCompressedClassPointers:使用压缩Class指针,比如Object.class,压缩后-XX:+UseCompressedClassPointer的情况在内存中占用4byte,不压缩-XX:-UseCompressedClassPointer的情况为8byte

UseCompressedOops:引用类型是否压缩,-XX:+UseCompressedOops表示压缩,压缩后的引用类型在内存中占4byte,不压缩的情况占用8byte。

  • 「java -Xmn10M -Xms40M -Xmx60M -XX:+PrintCommandLineFlags -XX:+PrintGC GCTest」

-Xmn 新生代大小

-Xms 最小堆大小

-Xmx 最大堆大小,最好和Xms设置一样的值,防止堆弹来弹去,影响性能

-XX:+PrintGC 打印GC信息

执行如下:

[root@basic ~]# java -Xmn10M -Xms40M -Xmx60M -XX:+PrintCommandLineFlags -XX:+PrintGC GCTest
-XX:InitialHeapSize=41943040 -XX:MaxHeapSize=62914560 -XX:MaxNewSize=10485760 -XX:NewSize=10485760 -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
program start!
[GC (Allocation Failure)  7839K->7592K(39936K), 0.0274278 secs]
[GC (Allocation Failure)  14920K->14704K(39936K), 0.0091149 secs]
[GC (Allocation Failure)  22024K->21872K(39936K), 0.0124746 secs]
[GC (Allocation Failure)  29195K->29008K(39936K), 0.0150616 secs]
[Full GC (Ergonomics)  29008K->28929K(55296K), 0.0209756 secs]
[GC (Allocation Failure)  36254K->36225K(55296K), 0.0102666 secs]
[GC (Allocation Failure)  43543K->43393K(55808K), 0.0087281 secs]
[Full GC (Ergonomics)  43393K->43265K(60928K), 0.0104380 secs]
[GC (Allocation Failure) -- 51630K->58798K(60928K), 0.0100362 secs]
[Full GC (Ergonomics)  58798K->51458K(60928K), 0.0055668 secs]
[Full GC (Ergonomics)  58793K->58626K(60928K), 0.0045510 secs]
[Full GC (Allocation Failure)  58626K->58614K(60928K), 0.0116986 secs]
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
 at GCTest.main(GCTest.java:9)

[GC (Allocation Failure)  7839K->7592K(39936K), 0.0274278 secs]:新生代的GC,GC后堆内存占用从7839K减少到7592K,堆大小为39936K

可以看到,多次YGC后,回收不了了,就产生了FGC:

[Full GC (Ergonomics)  29008K->28929K(55296K), 0.0170423 secs]:产生了FullGC,GC后堆内存占用从29008K较少到28929K

  • 「java -Xmn10M -Xms40M -Xmx60M -XX:+PrintCommandLineFlags -XX:+PrintGCDetails GCTest」

-XX:+PrintGCDetails可以打印更详细的GC信息:

[root@basic ~]# java -Xmn10M -Xms40M -Xmx60M -XX:+PrintCommandLineFlags -XX:+PrintGCDetails GCTest
-XX:InitialHeapSize=41943040 -XX:MaxHeapSize=62914560 -XX:MaxNewSize=10485760 -XX:NewSize=10485760 -XX:+PrintCommandLineFlags -XX:+PrintGCDetails -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
program start!
[GC (Allocation Failure) [PSYoungGen: 7839K->352K(9216K)] 7839K->7528K(39936K), 0.0074573 secs] [Times: user=0.00 sys=0.01, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 7680K->320K(9216K)] 14856K->14664K(39936K), 0.0070717 secs] [Times: user=0.00 sys=0.02, real=0.01 secs] 
[GC (Allocation Failure) [PSYoungGen: 7640K->320K(9216K)] 21984K->21832K(39936K), 0.0064630 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 7643K->320K(9216K)] 29155K->29000K(39936K), 0.0070857 secs] [Times: user=0.01 sys=0.02, real=0.00 secs] 
[Full GC (Ergonomics) [PSYoungGen: 320K->0K(9216K)] [ParOldGen: 28680K->28929K(46080K)] 29000K->28929K(55296K), [Metaspace: 2514K->2514K(1056768K)], 0.0181374 secs] [Times: user=0.04 sys=0.01, real=0.02 secs] 
[GC (Allocation Failure) [PSYoungGen: 7325K->128K(9216K)] 36254K->36225K(55296K), 0.0090166 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
[GC (Allocation Failure) [PSYoungGen: 7446K->128K(9728K)] 43543K->43393K(55808K), 0.0045376 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Ergonomics) [PSYoungGen: 128K->0K(9728K)] [ParOldGen: 43265K->43265K(51200K)] 43393K->43265K(60928K), [Metaspace: 2514K->2514K(1056768K)], 0.0076301 secs] [Times: user=0.01 sys=0.02, real=0.01 secs] 
[GC (Allocation Failure) --[PSYoungGen: 8365K->8365K(9728K)] 51630K->58798K(60928K), 0.0056167 secs] [Times: user=0.00 sys=0.01, real=0.00 secs] 
[Full GC (Ergonomics) [PSYoungGen: 8365K->1024K(9728K)] [ParOldGen: 50433K->50433K(51200K)] 58798K->51458K(60928K), [Metaspace: 2514K->2514K(1056768K)], 0.0113353 secs] [Times: user=0.02 sys=0.01, real=0.02 secs] 
[Full GC (Ergonomics) [PSYoungGen: 8360K->8192K(9728K)] [ParOldGen: 50433K->50433K(51200K)] 58793K->58626K(60928K), [Metaspace: 2514K->2514K(1056768K)], 0.0056429 secs] [Times: user=0.00 sys=0.01, real=0.00 secs] 
[Full GC (Allocation Failure) [PSYoungGen: 8192K->8192K(9728K)] [ParOldGen: 50433K->50422K(51200K)] 58626K->58614K(60928K), [Metaspace: 2514K->2514K(1056768K)], 0.0181221 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
 at GCTest.main(GCTest.java:9)
Heap
 PSYoungGen      total 9728K, used 8533K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
  eden space 9216K, 92% used [0x00000000ff600000,0x00000000ffe55678,0x00000000fff00000)
  from space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
  to   space 512K, 0% used [0x00000000fff00000,0x00000000fff00000,0x00000000fff80000)
 ParOldGen       total 51200K, used 50422K [0x00000000fc400000, 0x00000000ff600000, 0x00000000ff600000)
  object space 51200K, 98% used [0x00000000fc400000,0x00000000ff53d878,0x00000000ff600000)
 Metaspace       used 2545K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 275K, capacity 386K, committed 512K, reserved 1048576K

此外,关于GC信息的参数还有:

「-XX:+PrintGCTimeStamps」:在每个GC上打印时间戳。

「-XX:+PrintGCApplicationConcurrentTime」:打印自上一次暂停(例如GC暂停)以来经过的时间。

「-XX:+PrintGCDateStamps」:在每个GC上打印日期戳。

「-XX:+PrintGCTaskTimeStamps」:为每个单独的GC工作线程任务启用时间戳打印。

  • 「java -XX:+UseConcMarkSweepGC -XX:+PrintCommandLineFlags -XX:+PrintGC GCTest」

这个主要是看切换成CMS垃圾回收器的GC过程信息:

[root@basic ~]# java -XX:+UseConcMarkSweepGC -XX:+PrintCommandLineFlags -XX:+PrintGC GCTest
-XX:InitialHeapSize=32449856 -XX:MaxHeapSize=519197696 -XX:MaxNewSize=172666880 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 
program start!
[GC (Allocation Failure)  7865K->7452K(31680K), 0.0055673 secs]
[GC (Allocation Failure)  15815K->15634K(31680K), 0.0051261 secs]
[GC (CMS Initial Mark)  22965K(31680K), 0.0014019 secs]
[GC (Allocation Failure)  23989K->23956K(33736K), 0.0060109 secs]
[GC (Allocation Failure)  32314K->32191K(41960K), 0.0238551 secs]
[GC (Allocation Failure)  40551K->40280K(50184K), 0.0254390 secs]
[GC (Allocation Failure)  48641K->48486K(58408K), 0.0273632 secs]
[GC (Allocation Failure)  56847K->56655K(65796K), 0.0104898 secs]
[GC (CMS Final Remark)  65017K(65796K), 0.0020809 secs]
[GC (Allocation Failure)  65017K->64822K(74020K), 0.0080847 secs]
[GC (Allocation Failure)  73184K->72985K(116060K), 0.0048156 secs]
[GC (Allocation Failure)  81348K->81174K(116060K), 0.0156927 secs]
[GC (Allocation Failure)  89536K->89366K(116060K), 0.0164924 secs]
[GC (CMS Initial Mark)  91585K(116060K), 0.0005150 secs]
[GC (Allocation Failure)  97729K->97558K(116060K), 0.0200535 secs]
[GC (Allocation Failure)  105921K->105749K(116060K), 0.0195895 secs]
[GC (Allocation Failure)  114111K->113943K(123256K), 0.0185969 secs]
[GC (Allocation Failure)  122306K->122133K(131480K), 0.0174622 secs]
[GC (Allocation Failure)  130496K->130328K(139704K), 0.0168396 secs]
[GC (Allocation Failure)  138690K->138518K(147928K), 0.0222069 secs]
[GC (Allocation Failure)  146881K->146712K(156152K), 0.0189141 secs]
[GC (Allocation Failure)  155075K->154903K(164376K), 0.0212268 secs]
[GC (Allocation Failure)  163265K->163097K(172600K), 0.0184528 secs]
[GC (Allocation Failure)  171460K->171289K(180824K), 0.0230886 secs]
[GC (Allocation Failure)  179652K->179482K(189048K), 0.0197197 secs]
[GC (Allocation Failure)  187844K->187672K(197272K), 0.0211699 secs]
[GC (Allocation Failure)  196035K->195864K(205496K), 0.0219487 secs]
[GC (Allocation Failure)  204227K->204056K(213720K), 0.0221430 secs]
[GC (Allocation Failure)  212419K->212251K(221944K), 0.0237262 secs]
[GC (Allocation Failure)  220613K->220443K(230168K), 0.0274986 secs]
[GC (Allocation Failure)  228806K->228635K(238392K), 0.0253731 secs]
[GC (Allocation Failure)  236998K->236826K(246616K), 0.0186347 secs]
[GC (Allocation Failure)  245188K->245018K(254840K), 0.0188651 secs]
[GC (Allocation Failure)  253381K->253212K(263064K), 0.0232380 secs]
[GC (Allocation Failure)  261575K->261403K(271288K), 0.0192675 secs]
[GC (Allocation Failure)  269765K->269597K(279512K), 0.0250426 secs]
[GC (Allocation Failure)  277960K->277787K(287736K), 0.0230294 secs]
[GC (Allocation Failure)  286151K->285982K(295960K), 0.0252418 secs]
[GC (Allocation Failure)  294345K->294174K(304184K), 0.0195708 secs]
[GC (Allocation Failure)  302537K->302366K(312408K), 0.0252629 secs]
[GC (Allocation Failure)  310729K->310559K(320632K), 0.0241283 secs]
[GC (Allocation Failure)  318921K->318749K(328856K), 0.0235919 secs]
[GC (Allocation Failure)  327112K->326943K(336052K), 0.0204393 secs]
[GC (Allocation Failure)  335306K->335133K(344276K), 0.0242358 secs]
[Full GC (Allocation Failure)  343496K->343313K(344276K), 0.0948962 secs]
[GC (Allocation Failure)  344507K->347589K(349120K), 0.0145370 secs]
[Full GC (Allocation Failure)  347589K->344337K(349120K), 0.0053974 secs]
[GC (CMS Initial Mark)  345361K(491072K), 0.0031466 secs]
[GC (CMS Final Remark)  352315K(491072K), 0.0021340 secs]
[Full GC (Allocation Failure)  489533K->488726K(491072K), 0.0355269 secs]
[GC (CMS Initial Mark)  489750K(491072K), 0.0017936 secs]
[Full GC (Allocation Failure)  490513K->489750K(491072K), 0.0029711 secs]
[Full GC (Allocation Failure)  489750K->489739K(491072K), 0.0662137 secs]
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
 at GCTest.main(GCTest.java:9)

乍一看,和默认的ParallelGC日志信息差不多,就是长了点,其实他就是多了一些CMS Initial Mark、CMS Final Remark等信息,

CMS初始标记、重新标记这些概念在上一篇已有介绍:

【GC系列】JVM堆内存分代模型及常见的垃圾回收器

通过这段日志可以看到最后通过几次FullGC都没办法清除,最终导致了OOM。

PS GC日志详解

先看这一句:

「[GC (Allocation Failure) [PSYoungGen: 7839K->368K(9216K)] 7839K->7544K(39936K), 0.0072850 secs] [Times: user=0.01 sys=0.02, real=0.01 secs]」

该句GC日志的含义:

「GC」:YGC,产生在年轻代(新生代)的GC。

「Allocation Failure」:产生GC的原因。

「PSYoungGen」:PS,新生代。

「7839K->368K(9216K)」:垃圾回收之前是7839K,回收之后是368K(也就是说回收了7839-368的空间大小),9216K是整个年轻代的堆大小。

「7839K->7544K(39936K)」:整个堆的空间大小变化。为什么总堆大小和年轻代的一样都是7839K,没有old区了吗?原因就是全被年轻代占用了。

「0.0072850 secs」:本次GC所耗时间

「[Times: user=0.01 sys=0.02, real=0.01 secs]」:user表示用户态耗时,sys表示内核态耗时,real表示实际耗时

一旦产生了内存溢出,GC日志把整个堆「heap dump」出来:

Heap
PSYoungGen      total 9728K, used 8533K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
  eden space 9216K, 92% used [0x00000000ff600000,0x00000000ffe55678,0x00000000fff00000)
  from space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
  to   space 512K, 0% used [0x00000000fff00000,0x00000000fff00000,0x00000000fff80000)
ParOldGen       total 51200K, used 50422K [0x00000000fc400000, 0x00000000ff600000, 0x00000000ff600000)
  object space 51200K, 98% used [0x00000000fc400000,0x00000000ff53d878,0x00000000ff600000)
Metaspace       used 2545K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 275K, capacity 386K, committed 512K, reserved 1048576K

这个信息已经很明确了,比如「PSYoungGen是新生代,eden是新生代中的eden区,from、to是两个survivor区,ParOldGen是老年代,Metaspace是元空间」

主要看这几个内存地址:

[0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)

[起始地址, 使用空间结束地址, 整体空间结束地址)

eden space 9216K, 92% used [0x00000000ff600000,0x00000000ffe55678,0x00000000fff00000):

表示eden区的空间的内存地址从0x00000000ff600000到0x00000000fff00000,总共9216K,已使用了92%。

用个图总结一下:【GC系列】JVM的常用GC参数及GC日志解析


首发公众号 「行百里er」,欢迎老铁们关注阅读指正。也可访问我的 「GitHub」 github.com/xblzer/JavaJourney


原文始发于微信公众号(行百里er):【GC系列】JVM的常用GC参数及GC日志解析