阅读分析虚拟机和垃圾收集器的日志是处理Java虚拟机内存问题必备的基础技能，为进行GC调优提供数据分析支持。

一、JDK统一日志格式
垃圾收集器日志是一系列人为设定的规则，多少有点随开发者编码时的心情而定，没有任何的“业界标准”可言，换句话说，每个收集器的日志格式都可能不一样。除此以外还有一个麻烦，在JDK 9以前，HotSpot并没有提供统一的日志处理框架，虚拟机各个功能模块的日志开关分布在不同的参数上，日志级别、循环日志大小、输出格式、重定向等设置在不同功能上都要单独解决。直到JDK 9，这种混乱不堪的局面才终于消失，HotSpot所有功能的日志都收归到了-Xlog参数上，这个参数的能力也相应被极大拓展了。

Xlog选项支持的参数如下：

• -Xlog 使用info级别启用JVM日志（-Xlog等价于-Xlog:all=info:stdout:uptime,level,tags）
• -Xlog:help：打印Xlog帮助文档
• -Xlog:disable：关闭所有日志记录并清除日志记录框架的所有配置，包括警告和错误的默认配置
• -Xlog[:option]：按照命令行上出现的顺序应用多个参数。同一输出的多个参数按其给定顺序覆盖。option的格式为：

-Xlog[:[what][:[output][:[decorators][:output-options[,...]]]]]

1、what：选择器，由标签（Tag）和日志级别（Level）共同组成。格式：tag1[+tag2...][*][=level][,...] 。除非用*指定了通配符，否则只有匹配了指定tag的日志消息才会被匹配。

（1）标签Tag：可理解为虚拟机中某个功能模块的名字，它告诉日志框架用户希望得到虚拟机哪些功能的日志输出。垃圾收集器的标签名称为“gc”，全部支持的功能模块标签名如下：（如指定为all，则表示下面所有标签的组合）

add、age、alloc、annotation、aot、arguments、attach、barrier、biasedlocking、blocks、bot、breakpoint、bytecode、census、class、classhisto、cleanup、compaction、comparator、constraints、constantpool、coops、cpu、cset、data、defaultmethods、dump、ergo、event、exceptions、exit、fingerprint、freelist、gc、hashtables、heap、humongous、ihop、iklass、init、itables、jfr、jni、jvmti、liveness、load、loader、logging、mark、marking、metadata、metaspace、method、mmu、modules、monitorinflation、monitormismatch、nmethod、normalize、objecttagging、obsolete、oopmap、os、pagesize、parser、patch、path、phases、plab、preorder、promotion、protectiondomain、purge、redefine、ref、refine、region、remset、resolve、safepoint、scavenge、scrub、setting、stackmap、stacktrace、stackwalk、start、startuptime、state、stats、stringdedup、stringtable、subclass、survivor、sweep、system、task、thread、time、timer、tlab、unload、update、verification、verify、vmoperation、vtables、workgang、

（2）日志级别：从低到高有Trace， Debug， Info， Warning， Error， Off六种级别， 日志级别决定了输出信息的详细程度，默认级别为Info，HotSpot的日志规则与Log4j、SLF4j这类Java日志框架大体上是一致的。

2、output：设置输出类型。默认为stdout。
-Xlog 支持以下类型的输出：

• stdout ：将输出发送到标准输出；
• stderr ：将输出发送到stderr；
• file=filename：将输出发送到文本文件。你还可以让文件按照文件大小轮换，例如每记录10M就轮换，只保留5个文件等。默认情况下，最多保留5个20M的文件。可使用 filesize=10M, filecount=5 格式去指定文件大小和保留的文件数。

3、decorators：装饰器,用来装饰消息，记录与消息有关的信息。使用一系列自定义的装饰器去配置output，来要求每行日志输出都附加上额外的内容。可以为每个output配置一组自定义的装饰器，输出顺序和定义的顺序相同。缺省的装饰器为uptime、level和tags。
支持附加在日志行上的信息包括：

• time or t ：ISO-8601格式的当前日期时间；
• utctime or utc ：UTC格式的当前日期时间；
• uptime or u ：JVM启动了多久，以秒或毫秒为单位。例如6.567s；
• timemillis or tm： 相当于 System.currentTimeMillis()；
• uptimemillis or um ：JVM启动以来的毫秒数；
• timenanos or tn ：相当于 System.nanoTime()；
• uptimenanos or un： JVM启动以来的纳秒数；
• hostname or hn ：主机名；
• pid or p ：进程号；
• tid or ti ：线程号；
• level or l ：与日志消息关联的级别；
• tags or tg ：与日志消息关联的标签集；

如果不指定， 默认值是uptime、 level、 tags这三个， 此时日志输出类似于以下形式：

[3.080s][info][gc,cpu] GC(5) User=0.03s Sys=0.00s Real=0.01s

4、output-options：设置Xlog的日志输出output选项，格式：

filecount=file-count filesize=file size with optional K, M or G suffix

5、使用示例

# 示例1：使用info级别记录所有信息到stdout，装饰器使用uptime、level及tags
# 等价于-Xlog:all=info:stdout:uptime,levels,tags
-Xlog

# 示例2：以info级别打印使用了gc标签的日志到stdout
-Xlog:gc

# 示例3：使用默认装饰器，info级别，将使用gc或safepoint标签的消息记录到stdout。
# 如果某个日志同时标签了gc及safepoint，不会被记录，逗号表示或
-Xlog:gc,safepoint

# 示例4：使用默认装饰器，debug级别，打印同时带有gc和ref标签的日志。
# 仅使用gc或ref的日志不会被记录，加号表示同时
-Xlog:gc+ref=debug

# 示例5：不使用装饰器，使用debug级别，将带有gc标签的日志记录到gc.txt中
-Xlog:gc=debug:file=gc.txt:none

# 示例6：以trace级别记录所有带有gc标签的日志到gctrace.txt文件集中，该文件集中的文件最大1M，保留5个文件；使用的装饰器是uptimemillis、pid
-Xlog:gc=trace:file=gctrace.txt:uptimemillis,pids:filecount=5,filesize=1024

# 示例7：使用trace级别，记录至少带有gc及meta标签的日志到gcmetatrace.txt，同时关闭带有class的日志。某个消息如果同时带有gc、meta及class，将不会被记录，因为class标签被关闭了。
-Xlog:gc+meta*=trace,class*=off:file=gcmetatrace.txt

6、为运行中的 JVM 上配置日志记录
jdk9及其以上版本：可以使用 jcmd 和 VM.log在JVM上配置VM日志记录。所有java命令配置VM日志记录时提供的所有配置选项都可使用，但是需要通过 output、output_options、what 和 decorators 参数指定，下面是一个 jcmd 的使用示例：

jcmd <pid> VM.log output="file=heap.log" output_options="filecount=5,filesize=10m" what="heap=info" decorators="time,level"

二、旧式GC日志和Xlog的对照

通用的获取GC日志JVM参数（其他参数根据需要添加）：

＃jdk6-8:
-XX:+PrintGCDetails -XX:+PrintGCCause -XX:+PrintGCDateStamps -Xloggc:./gc.log
＃jdk9及以上版本：
-Xlog:gc*:file=./gc.log

三、GC日志分析工具

1、基础命令工具-jstat：虚拟机统计信息监视工具（JVM Statistics Monitoring Tool）

用于监视虚拟机各种运行状态信息的命令行工具。 它可以显示本地或者远程虚拟机进程中的类加载、内存、垃圾收集、即时编译等运行时数据， 在没有GUI图形界面、只提供了纯文本控制台环境的服务器上， 它将是运行期定位虚拟机性能问题的常用工具。

2、可视化工具-VisualGC

VisualGC可以作为VisualVM插件使用。一般用于开发、测试阶段，生产环境一般不会放开JMX端口。

 注意：

（1） Visual GC插件不支持通过JMX方式连接远端jvm，要通过另一个方式jstatd方式进行连接,否则显示"不受此JVM支持"。

（2）如果VM参数设置-XX:+UseParallelGC 或者 -XX:+AggressiveHeap，直方图Histogram会显示"不受此JVM支持"。

3、GCViewer

GCViewer是一个离线分析Java GC日志可视化小工具。生产项目上线初期调优、业务高峰期、故障等可以打印GC日志下载后离线分析，比看纯文本要直观一些。

GCViewer是一个jar包，可以直接启动：java -jar gcviewer-1.36.jar  ，然后导入GC日志文件。

左侧是图表面板，右侧是数据面板。
3.1 Chart选项卡

显示了一系列线条

• Full GC线：黑色垂直线；
• Inc GC线：增量GC的青色垂直线；
• GC Times Line:显示各个GC耗时长短的绿线
• GC Times Rectangles:
  • 黑色矩形：每次FullGC的耗时；
  • 蓝色矩形：每次初始标记事件耗时；
  • 橙色矩形：每次重新标记事件耗时；
  • 红色矩形：每次vm操作事件处耗时（“应用程序已停止…”）；
  • 灰色矩形：每次“正常”GC处耗时；
  • 浅灰色矩形：每次增量GC处耗时；
• Total Heap：显示堆大小的红色区域；
• Tenured Generation:显示老年代大小品红色区域（未配置PrintGCDetails则不可用）；
• Young Generation:显示新生代大小橙色区域（未配置PrintGCDetails则不可用）；
• Used Heap:显示已用堆大小的蓝线；
• Initial mark level:显示“初始标记”事件时堆使用情况的黄线（仅当gc算法使用并发收集时可用，CMS和G1就是这样）；
• Concurrent collections：并发收集周期的每个开始（并发标记开始）的青色垂直线和每个结束（CMS并发重置/G1：并发清理结束）的粉红色垂直线；

3.2 Event details选项卡

 用于展示GC事件详情

• Gc pauses：显示所有STW停顿时间统计（最小耗时、最大耗时、平均耗时、标准偏差、总耗时，总占比），按照GC原因分组统计，不仅仅指FullGC停顿；
• Full gc pauses：FullGC停顿时间统计；
• VM operations overhead (safepoint pauses)：
  • 仅当gc日志是使用选项-XX:+PrintGCApplicationStoppedTime写入时，才会显示此区域。为了理解该指标的含义，了解安全点是很重要的（参见例如。http://blog.ragozin.info/2012/10/safepoints-in-hotspot-jvm.html)。
  • 如果GCViewer发现gc日志行如下：

  • 2017-03-29T14:37:12.812+0200: 8.832: [GC (Allocation Failure)[PSYoungGen: 29146K->3457K(29184K)] 78228K->52539K(116736K), 0.0009340 secs][Times: user=0.00 sys=0.00, real=0.00 secs]
    2017-03-29T14:37:12.813+0200: 8.833: Total time for which application threads were stopped: 0.0010682 seconds, Stopping threads took: 0.0000155 seconds

• GCViewer将在“Gc停顿”区域和该区域报告一个事件。“Total time…”报告的停顿时长为0.0001342s（0.0010682（安全点停顿的持续时间）- 0.0009340（gc停顿的持续日期）），因此GCViewer仅计算gc暂停之上的整个安全点所需的额外开销。
• Concurrent GCs：如果gc算法使用了并发收集周期，则包含有关这些周期的信息。此处报告的时间是在应用程序线程运行时花费的。可以在这里阅读，并发gc操作需要多长时间才能完成。

3.3 Parser选项卡

显示了解析器的输出。如果在解析过程或其他输出过程中出现警告，可以在那里进行检查。

 3.4 Data Panel面板

GCViewer提供了一些指标来帮助解释图表。请注意，一些基于平均值的指标与它们的标准差一起显示。如果与平均值相比，标准偏差明显较大，则这些值将变灰，表明实际值远小于或大于平均值。

（1）Summary 摘要

• Footprint：分配的最大内存量；
• Max heap after conc GC：并发gc后堆最大使用量；
• Max tenured after conc GC：并发gc后老年代最大使用量；
• Max heap after full GC：FullGC后堆最大使用量。指示活动对象的最大大小，可以帮助确定堆大小；
• Freed Memory：已释放的内存总量；
• Freed Mem/Min：每分钟释放的内存量；
• Total Time：为收集时间数据（仅当日志中存在时间戳时）；
• Acc Pauses：GC导致的所有停顿的总和；
• Throughput：吞吐量，应用程序不忙于GC的时间百分比；
• Full GC Performance：FullGC性能，请注意，所有包含老年代收集或标有“Full GC”的收集都被视为Full GC；
• GC Performance：GC性能，新生代收集的性能。

（2）Memory 内存

• Total heap (usage / alloc max)：总堆（使用量/分配最大值），总堆中的最大内存使用量/分配量（最后一个与Summary中的“footprint”相同）；
• Tenured heap (usage / alloc max)：老年代堆（使用/分配最大值）：老年代使用空间中的最大内存使用/分配；
• Young heap (usage / alloc max)：新生代堆（使用/分配最大值）：新生代使用空间中的最大内存使用/分配；
• Perm heap (usage / alloc max)：元数据区（使用/分配最大值）：元数据使用空间中的最大内存使用/分配；
• Max tenured after conc GC：请参阅“摘要”部分；
• Avg tenured after conc GC：并发GC后老年代平均大小；
• Max heap after conc GC：请参阅“摘要”部分；
• Avg heap after conc GC：并发GC后堆平均大小；
• Max heap after full GC：请参阅“摘要”部分；
• Avg after full GC：FullGC后平均堆消耗；
• Avg after GC：新生代GC后平均堆消耗；
• Freed Memory：已释放的内存总量；
• Freed by full GC：FullGC收集释放的内存量；
• Freed by GC:：新生代GC收集释放的内存量；
• Avg freed full GC：FullGC收集释放的平均内存量；
• Avg freed GC：新生代GC收集释放的平均内存量；
• Avg rel inc after FGC：FullGC之间内存消耗的平均相对增长。这是FullGC后的内存消耗与下一次FullGC后内存消耗之间的平均差值。
• Avg rel inc after GC：新生代GC之间内存消耗的平均相对增长。这是新生代GC后的内存消耗与下一次新生代GC的内存占用之间的平均差值。这可以用作新生代GC中幸存的内存量的指标，并且必须移动到幸存空间或老年代生成。添加到“Avg freed GC”中的这个值可以让您了解新生代的规模，以防您没有打开PrintGCDetails。
• Slope full GC：FullGC后内存消耗的回归线的斜率。这可以用作应用程序不可或缺的内存消耗（基本占用空间）增加的指标
• Slope GC：FullGC之间的新生代GC后内存消耗的回归线斜率的平均值。也就是说，如果有两个Full GC，并且中间有许多次YoungGC，则GCViewer将计算YoungGC到第一个完整集合的斜率，然后计算第一个和第二个Full GC之间的YoungGC的斜率。然后，它将计算加权平均值（每个斜率将根据计算的测量点数量进行加权）。
• initiatingOccFraction (avg / max)：CMS GC在老年代被填补之前就开始了。当CMS GC启动（初始标记）时，InitiatingOccupancyFraction告诉您老年代的平均/最大使用率（%）。此值可以使用-XX:CMSInitatingOccupancyFraction=手动设置。
• avg promotion：平均晋升，晋升是指新生代GC时从新生代晋升到老年代的对象的大小。平均提升显示每个新生代从年轻提升到老年代的平均内存量（仅适用于PrintGCDetails）；
• total promotion：总晋升，Total promotion显示文件中所有YoungGC从年轻提升为老年代使用的内存总量（仅适用于PrintGCDetails）。

（3）Pause

• Acc Pauses：由于任何GC导致的所有暂停的总和；
• Number of Pauses：停顿次数，由于任何类型的GC而导致的所有停顿的计数；
• Avg Pause：平均暂停时间：
• Min / max Pause：最小/最大停顿时长：
• Avg pause interval：任何类型的两次停顿之间的平均间隔；
• Min / max pause interval：任何类型的两次停顿之间的最小/最大间隔；

------------------------------------------------------------------------------------

• Acc full GC:由于FullGC而导致的所有暂停的总和；
• Number of full GC pauses：由于FullGC而导致的暂停次数；
• Acc GC：所有FullGC停顿时长的总和；
• Avg full GC：FullGC停顿的平均时长；
• Min / max full GC pause：最短/最长的FullGC停顿；
• Min / max full GC pause interval:两次FullGC停顿之间的最小/最大间隔；

------------------------------------------------------------------------------------

• Acc GC：由于YounGC导致的所有耗时；
• Number of GC pauses：YounGC次数；
• Avg GC：YounGC平均耗时；
• Min / max GC pause：最短/最长的YounGC耗时；

备注：GCViewer本身功能有一些局限性，有些展示可能存在错误，不能完全依赖这个工具展示信息。

其他：

GCViewer

VisualGC

 GCEasy