在 JDK 9 之后的版本中悲雳，啟動(dòng)參數(shù)有一些變化蚀浆，繼續(xù)使用原來(lái)的參數(shù)配置可能會(huì)在啟動(dòng)時(shí)報(bào)錯(cuò)缀程。不過(guò)也不用擔(dān)心搜吧，如果碰到，一般都可以從錯(cuò)誤提示中找到對(duì)應(yīng)的處置措施和解決方案杨凑。
例如 JDK 11 版本中打印 info 級(jí)別 GC 日志的啟動(dòng)腳本：
# JDK 11 環(huán)境赎败，輸出 info 級(jí)別的 GC 日志
java -Xms512m -Xmx512m
-Xlog:gc*=info:file=gc.log:time:filecount=0
demo.jvm0204.GCLogAnalysis
從 JDK 9 開(kāi)始，可以使用命令 java -Xlog:help 來(lái)查看當(dāng)前 JVM 支持的日志參數(shù)蠢甲，本文不進(jìn)行詳細(xì)的介紹僵刮，有興趣的同學(xué)可以查看 JEP 158: Unified JVM Logging 和 JEP 271: Unified GC Logging。
另外鹦牛，JMX 技術(shù)提供了 GC 事件的通知機(jī)制搞糕，監(jiān)聽(tīng) GC 事件的示例程序我們會(huì)在《應(yīng)對(duì)容器時(shí)代面臨的挑戰(zhàn)》這一章節(jié)中給出。
但很多情況下 JMX 通知事件中報(bào)告的 GC 數(shù)據(jù)并不完全曼追，只是一個(gè)粗略的統(tǒng)計(jì)匯總窍仰。
GC 日志才是我們了解 JVM 和垃圾收集器最可靠和全面的信息，因?yàn)槔锩姘撕芏嗉?xì)節(jié)礼殊。再次強(qiáng)調(diào)驹吮，分析 GC 日志是一項(xiàng)很有價(jià)值的技能，能幫助我們更好地排查性能問(wèn)題晶伦。
下面我們通過(guò)實(shí)際操作來(lái)分析和解讀 GC 日志碟狞。
Serial GC 日志解讀
關(guān)于串行垃圾收集器的介紹，請(qǐng)參考前面的文章：《常見(jiàn) GC 算法介紹》婚陪。
首先族沃，為了打開(kāi) GC 日志記錄，我們使用下面的 JVM 啟動(dòng)參數(shù)如下：
# 請(qǐng)注意命令行啟動(dòng)時(shí)沒(méi)有換行泌参，此處是手工排版
java -XX:+UseSerialGC
-Xms512m -Xmx512m
-Xloggc:gc.demo.log
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
demo.jvm0204.GCLogAnalysis
讓我們看看 Serial GC 的垃圾收集日志脆淹，并從中提取信息。
啟用串行垃圾收集器沽一，程序執(zhí)行后輸出的 GC 日志類(lèi)似這樣（為了方便大家閱讀盖溺，已手工折行）：
Java HotSpot(TM) 64-Bit Server VM (25.162-b12) ......
Memory: 4k page，physical 16777216k(1551624k free)
CommandLine flags:
-XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912
-XX:+PrintGC -XX:+PrintGCDateStamps
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps
-XX:+UseCompressedClassPointers -XX:+UseCompressedOops
-XX:+UseSerialGC
2019-12-15T15:18:36.592-0800: 0.420:
[GC (Allocation Failure)
2019-12-15T15:18:36.592-0800: 0.420:
[DefNew: 139776K->17472K(157248K)铣缠，0.0364555 secs]
139776K->47032K(506816K)烘嘱，
0.0365665 secs]
[Times: user=0.02 sys=0.01，real=0.03 secs]
......
2019-12-15T15:18:37.081-0800: 0.908:
[GC (Allocation Failure)
2019-12-15T15:18:37.081-0800: 0.908:
[DefNew: 156152K->156152K(157248K)攘残，0.0000331 secs]
2019-12-15T15:18:37.081-0800: 0.908:
[Tenured: 299394K->225431K(349568K)拙友，0.0539242 secs]
455546K->225431K(506816K)为狸，
[Metaspace: 3431K->3431K(1056768K)]歼郭，
0.0540948 secs]
[Times: user=0.05 sys=0.00，real=0.05 secs]
日志的第一行是 JVM 版本信息辐棒，第二行往后到第一個(gè)時(shí)間戳之間的部分，展示了內(nèi)存分頁(yè)谈况、物理內(nèi)存大小陷虎，命令行參數(shù)等信息，這部分前面介紹過(guò)鲫竞，不在累述。
仔細(xì)觀(guān)察逼蒙，我們發(fā)現(xiàn)在這段日志中發(fā)生了兩次 GC 事件从绘，其中一次清理的是年輕代，另一次清理的是整個(gè)堆內(nèi)存是牢。讓我們先來(lái)分析前一次年輕代 GC 事件僵井。
Minor GC 日志分析
這次年輕代 GC 事件對(duì)應(yīng)的日志內(nèi)容：
2019-12-15T15:18:36.592-0800: 0.420:
[GC (Allocation Failure)
2019-12-15T15:18:36.592-0800: 0.420:
[DefNew: 139776K->17472K(157248K)，0.0364555 secs]
139776K->47032K(506816K)驳棱，
0.0365665 secs]
[Times: user=0.02 sys=0.01批什，real=0.03 secs]
從中可以解讀出這些信息：
