GC日志格式

本文是JVM层GC调优(上)的后续,在上一篇文章中,我们介绍了JVM的内存结构、常见的垃圾回收算法以及垃圾收集器和不同收集器中的一些GC调优参数。所以通过上文,我们也对GC相关的内容有了一定的了解。

但是光知道一些调优参数是没用的,我们需要能够从GC的日志中去分析可以调优的地方,这样才能使用这些参数去进行相应的调整,所以本小节将介绍一下不同收集器的GC日志格式。

我们这里以Tomcat为例,首先需要在Tomcat的catalina.sh脚本文件中加入打印GC日志的相关参数,如下:




参数说明:

· -XX:+PrintGCDetails 打印GC的详细信息

· -XX:+PrintGCTimeStamps、-XX:+PrintGCDateStamps 打印GC的时间

· -Xloggc:$CATALINA_HOME/logs/gc.log 指定GC日志文件所存放的路径

· -XX:+PrintHeapAtGC 在GC发生的前后打印堆信息

· -XX:+PrintTenuringDistribution 打印对象的年龄信息

默认情况下,JDK1.8使用的是Parallel GC,以下是我们设置了参数后,所输出的日志格式片段如下:



{



注:如果默认不是使用Parallel GC的话,可以加上这个参数启用:-XX:+UseParallelGC。我们主要关注GC的详细信息,所以我就截取这一部分进行一个简单的说明:



2018



知道了如何去查看Parallel GC的日志格式后,我们再来看看CMS GC的日志格式。同样的,到catalina.sh中配置启用CMS GC,如下示例:



[



启用CMS GC后,所输出的日志格式片段如下:



{



同样的,我们主要关注GC的详细信息,所以我就截取这一部分进行一个简单的说明:



2018



然后还有老年代的GC信息,以下这个片段是CMS GC特有的日志信息格式,也就是完整的一次Full GC过程:



2018



接下来就是G1的日志格式,G1在JDK1.8后被广泛使用,所以是需要好好了解一下它的日志格式的。同样的,需要先到catalina.sh中配置启用G1,如下示例:



[



启用C1 GC后,所输出的日志格式片段如下,可以看到与之前的的日志格式区别就比较大了,因为G1的垃圾回收过程也比较复杂:



{



同样的,我们主要关注GC的详细信息,所以我就截取这一部分进行一个简单的说明:



2018



我们也知道,G1收集器里还有一个全局并发标记(global concurrent marking)概念,触发时其日志格式如下,与CMS的标记过程有些类似,这里截取出来做一个简单的说明:



2018



... 略 ...



2018



可视化工具分析GC日志

在上一小节中,我们已经了解了常用的几种垃圾收集器的GC日志格式。俗话说:工欲善其事,必先利其器。在进行GC调优之前我们需要先学习如何使用可视化的GC日志分析工具,去分析GC的日志格式,以此来得知该收集器的响应时间和吞吐量是多少,然后才能针对这两个点去进行调优。这里要介绍的工具是:

在线工具:http://gceasy.io/

GCViewer

首先我们来看在线的工具,在浏览器上访问http://gceasy.io/,然后上传一个GC日志文件,我这里上传的是 Parallel GC 收集器的日志文件:




java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_调优


稍等一会后,该工具就可以帮我们分析出如下这些可视化的图表及表格数据:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_java日志打印太大会导致堆栈溢出吗_02


往下拉我们还可以看到交互图:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_调优_03


以及各种GC时的状态信息:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_G1_04


触发GC的原因也做了一个统计:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_java gc日志乱码_05


在页面的最上端,还可以下载本次分析的结果报告:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_java gc日志乱码_06


其他类型的垃圾收集器也是类似的,所以这里也不再演示了,毕竟都是图形化操作的,图表数据也很直观,而且在报告中也已经对各个点进行了说明。

所以接下来我们看看GCViewer的使用,这是一款开源的、用Java编写的客户端工具,GitHub地址如下:

https://github.com/chewiebug/GCViewer

下载压缩包即可,下载好后进行解压,使用cmd进入解压后的目录,然后使用maven命令对其进行编译打包:

D:GCViewGCViewer-develop>mvn clean package -Dmaven.test.skip

第一次打包的过程稍微有些慢,打包成功后,可以在target目录下看到一个jar包,双击这个jar包即可运行:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_java日志打印太大会导致堆栈溢出吗_07


打开后主界面如下:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_java gc日志乱码_08


同样的,打开一个GC日志文件,我这里仍然使用Parallel GC的日志文件作为演示:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_window下tomcat 按天生成日志_09


打开后,可以看到一个概览的图表:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_G1_10


从Summary选项卡中查看吞吐量:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_java日志打印太大会导致堆栈溢出吗_11


停顿时间则在Pause选项卡里:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_java日志打印太大会导致堆栈溢出吗_12


Memory选项卡里自然就是查看内存相关的统计信息了:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_window下tomcat 按天生成日志_13


查看触发GC的原因在Event Detail选项卡里:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_G1_14


关于GCViewer就介绍到这,详细的说明可以参考官方的文档。

Parallel GC调优

GC调优无外乎以下三个步骤:

打印GC日志

根据日志得到关键性能指标

分析GC原因,调整JVM参数

Parallel GC调优的指导原则:

除非确定,否则不要设置最大堆内存

优先设置吞吐量目标

如果吞吐量目标达不到,调大最大内存,不能让OS使用Swap,如果仍然达不到,降低目标

如果吞吐量能达到,但GC时间太长,则设置停顿时间的目标

现在我们来简单的实战一把GC调优,同样的,还是以Tomcat为例,使用Parallel GC。首先设置一些初始参数:


[


重启Tomcat完成后,把GC日志下载到本地,然后使用上一小节所介绍到的可视化工具进行分析,首先要关注的是吞吐量和停顿时间的数据,在下图中可以看到最大停顿时间有点长:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_调优_15


我们再看看各种GC的状态信息,发现Full GC发生了三次,所以才导致最大停顿时间有点长:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_window下tomcat 按天生成日志_16


然后我们看看触发GC的原因,可以看到是Metaspace区域分配内存失败导致的:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_window下tomcat 按天生成日志_17


所以就可以得知是Metaspace区域的内存有点小了,仅仅是启动的过程就发生了三次Full GC,那么我们就需要给Metaspace区域调大些内存。其实在页面顶端,该工具也很智能的提示了我们需要调整的地方:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_window下tomcat 按天生成日志_18


我这里的Metaspace区域内存大小默认为34M,所以我先给它调到64M看看。调优是一个不断重复尝试的过程,至于需要尝试多少次完全取决于经验和运气了。在之前的初始化参数中,加入如下参数:


[


再次将日志文件上传到可视化工具中进行分析,可以发现最大停顿时间明显变短了:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_调优_19


那么除此之外我们还可以做哪些调优呢?在本小节的开头我们也说了,当使用Parallel GC的时候,我们可以设置吞吐量目标和停顿时间目标,让它去自动进行调整。在之前的参数中,加入如下参数:


[


再次将日志文件上传到可视化工具中进行分析,发现停顿时间变化并不大,吞吐量反而还降低了一些,实际上这点差距是很小的,毕竟这只是一个Tomcat启动过程中的GC日志:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_window下tomcat 按天生成日志_20


但是我们会发现,调整了一些参数后,Full GC的次数是少了,但是Young GC的次数仍然没有降下来,虽然不可以随便修改堆的大小,但我们可以稍微修改动态扩容增量的参数。在之前的参数中,加入如下参数:


[


再次将日志文件上传到可视化工具中进行分析,可以看到,稍微比之前好了那么一些,Young GC比之前减少了两次:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_调优_21


关于Parallel GC的调优就先介绍到这,实际上调优都是需要经验来积累的,不是一蹴而就的,所以这里也只是给出一些调优的步骤、方式而已。

G1调优

在上一小节中,我们介绍了Parallel GC的调优,而在本小节中,将介绍一下G1收集器的调优。G1 GC的最佳实践:

年轻代大小:避免使用-Xmn、-XX:NewRatio等显式设置Young区大小,会覆盖暂停时间目标

暂停时间目标:暂停时间不要太严苛,其吞吐量目标是90%的应用程序时间和10%的垃圾回收时间,太严苛会直接影响到吞吐量

同样的,我们先不设置任何调优参数,只是设置一些初始参数,然后再来做对比,也是以Tomcat为例(之前Parallel GC相关的参数要去掉),如下:


[


和之前一样,重启Tomcat完成后,把GC日志下载到本地,然后上传到工具上进行分析,可以看到使用了G1后,停顿时间明显小了很多,但吞吐量变化不大,因为G1是停顿时间优先的收集器:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_java gc日志乱码_22


从触发GC的原因可以看到,Metaspace区域发生了一次GC,并且Young GC的次数也比较多:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_java gc日志乱码_23


同样的,在页面顶端,该工具也提示了我们可以调整Metaspace区域的大小:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_java日志打印太大会导致堆栈溢出吗_24


那我们就和之前一样,调大Metaspace区域看看:


[


再次将日志文件上传到可视化工具中进行分析,可以看到吞吐量上去了一些:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_java日志打印太大会导致堆栈溢出吗_25


而且也没有再发生Full GC了:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_G1_26


但是从上图中可以看到Young GC的次数依然很多,我们可以试着将堆的大小调大一些看看。如下:


[


再次将日志文件上传到可视化工具中进行分析,可以看到吞吐量和停顿时间却变长了一些:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_G1_27


但是Young GC的次数明显少了很多:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_java日志打印太大会导致堆栈溢出吗_28


我们都知道G1是停顿时间优先的收集器,所以我们可以设置一个停顿时间目标,让G1自己自动调整去达到这个目标。如下:


[


再次将日志文件上传到可视化工具中进行分析,结果是吞吐量上去了一些,但停顿时间却变长了一些:


java日志打印太大会导致堆栈溢出吗 java 打印gc日志 影响性能_调优_29


因为这个Tomcat里面也没有跑什么实际的应用,所以调优的变化并不是很大,但是也是有那么一些差别的。G1收集器的调优参数无非也就这几个,更多的是要对日志进行分析以及经验的积累,才能得出高效的调优方式。