JVM学习6815K->6424K (19456K) 表示「GC 前 Java 堆已使用容量 -> GC 后 Java

GC日志如何看

¹0.080: ²[GC ³(Allocation Failure) 0.080: ⁴[DefNew: ⁵6815K->280K(9216K),⁶ 0.0043690 secs] ⁷6815K->6424K(19456K), ⁸0.0044111 secs]⁹ [Times: user=0.00 sys=0.01, real=0.01 secs]

以上是发生 Minor GC 的 GC 是日志，如果发生 Full GC 呢，格式如下

¹0.088: ²[Full GC ³(Allocation Failure) 0.088: ⁴[Tenured: ⁵0K->210K(10240K), ⁶0.0009420 secs] ⁷4603K->210K(19456K), [Metaspace: 2630K->2630K(1056768K)], ⁸0.0009700 secs]⁹ [Times: user=0.01 sys=0.00, real=0.02 secs]

两者格式其实差不多，一起来看看，主要以本例触发的 Minor GC 来讲解，以上日志中标的每一个数字与以下序号一一对应

开头的 0.080，0.088 代表了 GC 发生的时间，这个数字的含义是从 Java 虚拟机启动以来经过的秒数
[GC 或者 [Full GC 说明了这次垃圾收集的停顿类型，注意不是用来区分新生代 GC 还是老年化 GC 的，如果有 Full，说明这次 GC 是发生了 Stop The World 的，如果是调用 System.gc () 所触发的收集，这里会显示 [Full GC（System）
之后的 Allocation Failure 代表了触发 GC 的原因，在这个程序中我们设置了新生代的大小为 10M（-Xmn10M），Eden:S0:S1 = 8：1：1（-XX:SurvivorRatio=8），也就是说 Eden 区占了 8M, 当分配 allocation4 时，由于将要分配的总大小为 10M, 超过了 Eden 区，所以此时会发生 GC
接下来的 [DefNew，[Tenured，[Metaspace 表示 GC 发生的区域，这里显示的区域名与使用的 GC 收集器是密切相关的，在此例中由于新生代我们使用了 Serial 收集器，此收集器新生代名为「Default New Generation」，所以显示的是 [DefNew，如果是 ParNew 收集器，新生代名称就会变为 [ParNew`，意为「Parallel New Generation」, 如果采用「Parallel Scavenge」收集器，则配套的新生代名称为「PSYoungGen」, 老年代与新生代一样，名称也是由收集器决定的
再往后 6815K->280K(9216K) 表示「GC 前该内存区域已使用容量 -> GC 后该内存区域已使用容量（该内存区域总容量）」
0.0043690 secs 表示该块内存区域 GC 所占用的时间，单位是秒
6815K->6424K (19456K) 表示「GC 前 Java 堆已使用容量 -> GC 后 Java 堆已使用容量（java 堆总容量）」。
0.0044111 secs 表示整个 GC 执行时间，注意和 6 中 0.0043690 secs 的区别，后者专指相关区域所花的 GC 时间，而前者指的 GC 的整体堆内存变化所花时间（新生代与老生代的的内存整理），所以前者是肯定大于后者的！
最后一个 [Times: user=0.01 sys=0.00, real=0.02 secs] 这里的 user, sys 和 real 与 Linux 的 time 命令所输出的时间一致，分别代表用户态消耗的 CPU 时间，内核态消耗的 CPU 时间，和操作从开始到结束所经过的墙钟时间，墙钟时间包括各种非运算的等待耗时，例如等待磁盘 I/O，等待线程阻塞，而 CPU 时间不包括这些耗时，但当系统有多 CPU 或者多核的话，多线程操作会叠加这些 CPU 时间，所以 user 或 sys 时间是可能超过 real 时间的。

启动参数

首先环境是java8，所以用的是cms收集器

-Xmx52m

-Xmn16m

-Xss256k

-XX:+PrintGC

-XX:+PrintGCDetails

-XX:+UseConcMarkSweepGC

-Xloggc:E:\gcLog\gc02142.log

分析方法1

使用jvisualvm，可以可视化看到堆，可以dump。看对象数目

分析方法2

分析gc02142.log

299.303: [GC (Allocation Failure) 299.303: [ParNew: 13543K->414K(14784K), 0.0015689 secs] 47206K->34116K(51648K), 0.0016169 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

299.552: [GC (Allocation Failure) 299.552: [ParNew: 13592K->347K(14784K), 0.0012870 secs] 47295K->34088K(51648K), 0.0013334 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

299.795: [GC (Allocation Failure) 299.795: [ParNew: 13531K->422K(14784K), 0.0013714 secs] 47272K->34203K(51648K), 0.0014180 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

300.019: [GC (Allocation Failure) 300.019: [ParNew: 13606K->357K(14784K), 0.0010670 secs] 47387K->34176K(51648K), 0.0011187 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

300.260: [GC (Allocation Failure) 300.260: [ParNew: 13541K->410K(14784K), 0.0011748 secs] 47360K->34269K(51648K), 0.0012216 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

300.497: [GC (Allocation Failure) 300.497: [ParNew: 13594K->432K(14784K), 0.0012819 secs] 47453K->34330K(51648K), 0.0013310 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

300.736: [GC (Allocation Failure) 300.736: [ParNew: 13616K->358K(14784K), 0.0013124 secs] 47514K->34294K(51648K), 0.0014030 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

300.738: [GC (CMS Initial Mark) [1 CMS-initial-mark: 33936K(36864K)] 34328K(51648K), 0.0005368 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

300.739: [CMS-concurrent-mark-start]

300.750: [CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.05 sys=0.01, real=0.01 secs]

300.750: [CMS-concurrent-preclean-start]

300.750: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

300.751: [GC (CMS Final Remark) [YG occupancy: 1179 K (14784 K)]300.751: [Rescan (parallel) , 0.0009191 secs]300.752: [weak refs processing, 0.0000635 secs]300.752: [class unloading, 0.0031517 secs]300.755: [scrub symbol table, 0.0052226 secs]300.760: [scrub string table, 0.0002986 secs][1 CMS-remark: 33936K(36864K)] 35116K(51648K), 0.0097836 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

300.761: [CMS-concurrent-sweep-start]

300.770: [CMS-concurrent-sweep: 0.009/0.009 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

300.770: [CMS-concurrent-reset-start]

300.770: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

300.997: [GC (Allocation Failure) 300.997: [ParNew: 13542K->425K(14784K), 0.0013179 secs] 29216K->16138K(51648K), 0.0013634 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

301.220: [GC (Allocation Failure) 301.220: [ParNew: 13609K->365K(14784K), 0.0012578 secs] 29322K->16117K(51648K), 0.0013159 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

301.450: [GC (Allocation Failure) 301.451: [ParNew: 13549K->425K(14784K), 0.0010929 secs] 29301K->16217K(51648K), 0.0012134 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]

301.693: [GC (Allocation Failure) 301.693: [ParNew: 13609K->366K(14784K), 0.0012695 secs] 29401K->16197K(51648K), 0.0013247 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

301.954: [GC (Allocation Failure) 301.954: [ParNew: 13550K->388K(14784K), 0.0010705 secs] 29381K->16257K(51648K), 0.0011212 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

302.172: [GC (Allocation Failure) 302.172: [ParNew: 13572K->442K(14784K), 0.0014375 secs] 29441K->16351K(51648K), 0.0015138 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

302.399: [GC (Allocation Failure) 302.399: [ParNew: 13626K->364K(14784K), 0.0013103 secs] 29535K->16312K(51648K), 0.0013558 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

302.656: [GC (Allocation Failure) 302.656: [ParNew: 13548K->416K(14784K), 0.0012516 secs] 29496K->16405K(51648K), 0.0013040 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

302.913: [GC (Allocation Failure) 302.913: [ParNew: 13594K->355K(14784K), 0.0011384 secs] 29583K->16383K(51648K), 0.0011860 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

303.155: [GC (Allocation Failure) 303.155: [ParNew: 13539K->424K(14784K), 0.0013714 secs] 29567K->16491K(51648K), 0.0014278 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

绝大多数都是GC (Allocation Failure)

当新生代的 Eden 区满的时候触发 Minor GC。存活下来的对象，则会被送到 Survivor 区

Survivor 中的对象可以升级到 old gen

CMS收集器的CMS-concurrent收集

定时去检查 old gen 的使用量，当使用量超过了触发比例就会启动一次 CMS GC，对 old gen 做回收。

full GC 全收集

一些策略思想

1. 采用 JVM 的默认值，然后进行压测分析 GC 日志。观察在不同情况下 GC 的回收情况

2. 如果我们看到频繁发生 Minor GC，而频繁 GC 效率又不高，说明我们的对象并没有那么快被回收，这时候我们可以适当调大年轻代大小，然后观察。

3. 如果每次 concurrent GC 年老代内存占用率没有下来，有可能是内存泄漏，需要排查代码。如果 concurrent GC 后内存占用率下来了，说明不是内存泄漏，可以考虑调大老年代。

值得一看

tech.meituan.com/2017/12/29/…