JVM性能调优（2） —— 内存设置和查看GC日志

1）JVM内存分配有如下一些参数：

一般 -Xms 和 -Xmx 设置一样的大小，-XX:MetaspaceSize 和 -XX:MaxMetaspaceSize 设置一样的大小。-Xms 等价于 -XX:InitialHeapSize，-Xmx等价于-XX:MaxHeapSize；-Xmn等价于-XX:MaxNewSize。

2）在IDEA中可以按照如下方式设置JVM参数：

3）命令行启动时可以按照如下格式设置：

1）设置GC参数：

可以在启动时加上如下参数来查看GC日志：

例如，我在IDEA中添加了如下JVM启动参数：

启动程序之后打印出了如下的一些日志：

从第三行 CommandLine flags 可以得到如下的信息：

2）查看默认参数：

如果要查看JVM的默认参数，就可以通过给JVM加打印GC日志的参数，就可以在GC日志中看到JVM的默认参数了。

还可以在启动参数中添加 -XX:+PrintFlagsFinal 参数，将会打印系统的所有参数，就可以看到自己配置的参数或系统的默认参数了：

3）GC日志：

之后的日志就是每次垃圾回收时产生的日志，每行日志说明了这次GC的执行情况，例如第四行GC日志：

详细内容如下：

2020-09-25T13:00:41.631+0800：GC发生的时间点。

4.013：系统运行多久之后发生的GC，单位秒，这里就是系统运行 4.013 秒后发生了一次GC。

GC (Allocation Failure)：说明了触发GC的原因，这里是指对象分配失败导致的GC。

PSYoungGen：指触发的是年轻代的垃圾回收，使用的是 Parallel Scavenge 垃圾回收器。

419840K->20541K：对年轻代执行了一次GC，GC之前年轻代使用了 419840K，GC之后有 20541K 的对象活下来了。

(472064K)：年轻代可用空间是 472064K，即 461 M，为什么是461M呢？因为新生代大小为 512M，Eden 区占 409.6M，两块 Survivor 区各占 51.2M，所以年轻代的可用空间为 Eden+1个Survivor的大小，即460.8M，约为461M。

419840K->20573K：GC前整个堆内存使用了 419840K，GC之后堆内存使用了 20573K。

(996352K)：整个堆的大小是 996352K，即 973M，其实就是年轻代的 461M + 老年代的 512 M

0.0118345 secs：本次GC耗费的时间

Times: user=0.00 sys=0.00, real=0.01 secs：本次GC耗费的时间

4）JVM退出时的GC情况：

程序结束运行后，还会打印一些日志，就是第12行之后的日志，这部分展示的是当前堆内存的使用情况：

详细内容如下：

本文采用的JDK版本：

设置JVM GC格式日志的主要参数包括如下8个：

本文假设读者已经熟悉JVM 内存结构。

如果想开启GC日志的信息，可以通过设置如下的参数任一参数：

如果只设置 -XX:+PrintGC 那么打印的日志如下所示：

1、 GC 表示是一次YGC（Young GC）

2、 Allocation Failure 表示是失败的类型

3、 68896K->5080K 表示年轻代从68896K降为5080K

4、 256000K 表示整个堆的大小

5、 0.0041139 secs 表示这次GC总计所用的时间

在JDK 8中， -verbose:gc 是 -XX:+PrintGC 一个别称，日志格式等价与： -XX:+PrintGC ，。

不过在 JDK 9 中 -XX:+PrintGC被标记为 deprecated 。

-verbose:gc 是一个标准的选项， -XX:+PrintGC 是一个实验的选项，建议使用 -verbose:gc 替代 -XX:+PrintGC

参考： Difference between -XX:+PrintGC and -verbose:gc

1、 GC 表示是一次YGC（Young GC）

2、 Allocation Failure 表示是失败的类型

3、PSYoungGen 表示年轻代大小

4、 53248K->2176K 表示年轻代占用从 53248K 降为 2176K

5、 59392K 表示年轻带的大小

6、 58161K->7161K 表示整个堆占用从 53248K 降为 2176K

7、 256000K 表示整个堆的大小

8、 0.0039189 secs 表示这次GC总计所用的时间

9、 [Times: user=0.02 sys=0.01, real=0.00 secs] 分别表示，用户态占用时长，内核用时，真实用时。

时间保留两位小数，四舍五入。

如果加上 -XX:+PrintGCTimeStamps 那么日志仅仅比1.1介绍的最前面多了一个时间戳： 1.963 ， 表示从JVM启动到打印GC时刻用了1.963秒。

如果加上 -XX:+PrintGCDateStamps 那么日志仅仅比1.1介绍的最前面多了一个日期时间： 2019-03-05T16:56:15.108+0800 ， 表示打印GC的时刻的时间是 2019-03-05T16:56:15.108+0800 。+0800表示是东8区。

这个参数开启后，

使用如下参数 -verbose:gc -XX:+PrintHeapAtGC -Xmn64M -Xms256M -Xmx256M

打印日志如下：

由此可以看出在，打印如下日志前后

详细打印出了日志信息

invocations 表示GC的次数，每次GC增加一次，每次GC前后的invocations相等

1、 Heap before GC invocations=1 表示是第1次GC调用之前的堆内存状况

2、 {Heap before GC invocations=1 (full 0): 表示是第1次GC调用之后的堆内存状况

如果使用该参数 -Xloggc 则默认开启如下两个参数

如果启动参数如下： -Xloggc:gc.log -Xmn64M -Xms256M -Xmx256M 则日志格式如下所示

gc.log 也可以指定绝对的路径。

在gc.log最前面还会默认打印系统的JDK版本与启动的参数

此设置 -XX:+PrintReferenceGC可以打印出SoftReference，WeakReference，FinalReference，PhantomReference，JNI Weak Reference几种引用的数量，以及清理所用的时长，该参数在进行YGC调优时可以排上用场。

具体可以参考占小狼的一篇实战： 一次 Young GC 的优化实践（FinalReference 相关）

CMS日志分为两个STW(stop the world)

分别是 init remark （1） 与 remark （7）两个阶段。一般耗时比YGC长约10倍（个人经验）。

（1）、 [GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs][Times: user=0.01 sys=0.00, real=0.01 secs]

会STO(Stop The World)，这时候的老年代容量为 32768K， 在使用到 19498K 时开始初始化标记。耗时短。

（2）、 [CMS-concurrent-mark-start]

并发标记阶段开始

（3）、 [CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

并发标记阶段花费时间。

（4）、 [CMS-concurrent-preclean-start]

并发预清理阶段，也是与用户线程并发执行。虚拟机查找在执行并发标记阶段新进入老年代的对象(可能会有一些对象从 新生代 晋升到老年代， 或者有一些对象被分配到老年代)。通过重新扫描，减少下一个阶段”重新标记”的工作，因为下一个阶段会Stop The World。

（5）、 [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

并发预清理阶段花费时间。

（6）、 [CMS-concurrent-abortable-preclean-start] CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs][Times: user=0.57 sys=0.00, real=5.09 secs]

并发可中止预清理阶段，运行在并行预清理和重新标记之间，直到获得所期望的eden空间占用率。增加这个阶段是为了避免在重新标记阶段后紧跟着发生一次垃圾清除

（7）、 [GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)][Rescan (parallel) , 0.0021918 secs][weak refs processing, 0.0000245 secs][class unloading, 0.0044098 secs][scrub symbol table, 0.0029752 secs][scrub string table, 0.0006820 secs][1 CMS-remark: 19498K(32768K)] 36316K(62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

会STW(Stop The World)，收集阶段，这个阶段会标记老年代全部的存活对象，包括那些在并发标记阶段更改的或者新创建的引用对象

（8）、 [CMS-concurrent-sweep-start]

并发清理阶段开始，与用户线程并发执行。

（9）、 [CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

并发清理阶段结束，所用的时间。

（10）、 [CMS-concurrent-reset-start]

开始并发重置。在这个阶段，与CMS相关数据结构被重新初始化，这样下一个周期可以正常进行。

（11）、 [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

并发重置所用结束，所用的时间。

参考：

Geek-Yan : JVM 学习笔记(四) CMS GC日志详解

设置JVM GC 性能的有如下参数

新生代大小官网推荐的大小是 3/8 , 如果设置太小，比如 1/10会 导致 Minor GC 与 Major GC 次数增多。

其中n的大小为区间为[0,15],如果高于15，JDK7 会默认15，JDK 8会启动报错

发生在CMS GC运行期间，详情参考：

JVM 调优 —— GC 长时间停顿问题及解决方法

GC的悲观策略

发生在Minor GC期间

---