Java虚拟机之 XX:+UseGCLogFileRotation 解析

通常，在生产环境中，我们需要借助 GC Log 来实时检测我们的微服务基于 Java 虚拟机层面活动状态，涉及年轻代、年老代以及全局的垃圾回收 ，只有基于上述方案，我们才能够快速的定位、分析微服务在某一时刻、时间段所呈现的活动轨迹及事件，以便高效解决业务问题。此篇文章来自笔者早期博客，依据实际的项目场景进行总结整理的。因技术群里有朋友在问此方面领域的问题，故再次将其呈现出来。

首先，我们来看一下在实际的生产环境中，应用服务中是如何开启日志打印相关开关，具体示例可参考如下所示：

JAVA_OPTS="-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:/data/logs/adminMana/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=3 -XX:GCLogFileSize=512k"

上述参数为 JDK 9 之前，尤其是 JDK 6/8 的通用型 GC Log 启用参数，针对 JDK 9 之后，以 JDK 11 为例，可尝试通过以下命令行参数启用，具体如下所示：

-Xlog:gc*,gc+ref=debug,gc+age=trace,gc+heap=debug:file=gc%p%t.log:tags,uptime,time:filecount=10,filesize=10m

本文暂不解析 JDK 11 版本的相关日志规范及相关案例，后续文章将会给出。现在针对 JDK 9 之前版本的核心日志参数进行简要解析，以让大家能够了解下相关参数的作用及场景特点，具体如下：

1、-XX:+PrintGCDetails

此参数主要定义GC Log 的详细信息。

2、-XX:+PrintGCTimeStamps

此参数主要定义GC Log 的时间戳信息，通常以“基准时间”形式打印。

3、-Xloggc:/data/logs/adminMana/gc.log

此参数主要定义GC Log 的存储路径以及所输出的文件名称。

4、-XX:+UseGCLogFileRotation

此参数主要定义GC Log 的滚动功能，需要进行开启或关闭，其通常基于第3条的

-Xloggc 参数展开。

5、-XX:NumberOfGCLogFiles=3

此参数主要定义滚动日志文件的个数，此参数值必须大于等于1，对应的日志文件

命名策略为：<filename>.0、<filename>.1、 ... 、 <filename>.n-1等，其中 n 是

该参数的值。

6、-XX:GCLogFileSize=512k

此参数主要定义滚动日志文件的大小，必须大于 8k，当前写日志文件大小超过该

参数值时，日志将写入下一个文件，依次类推。

具体，我们来看一下简单的 GC Log 输出的示例，如下所示：

[administrator@JavaLangOutOfMemory cpu ]% less devopsDemo.log.0.current 
Java HotSpot(TM) 64-Bit Server VM (25.271-b09) for bsd-amd64 JRE (1.8.0_271-b09), built on Sep 16 2020 16:54:38 by "java_re" with gcc 4.2.1 Compatible Apple LLVM 10.0.0 (clang-1000.11.45.5)
Memory: 4k page, physical 4194304k(27404k free)

/proc/meminfo:

CommandLine flags: -XX:GCLogFileSize=524288 -XX:InitialHeapSize=67108864 -XX:MaxHeapSize=1073741824 -XX:NumberOfGCLogFiles=3 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:+UseParallelGC 
Heap
 PSYoungGen      total 18944K, used 1311K [0x00000007aab00000, 0x00000007ac000000, 0x00000007c0000000)
  eden space 16384K, 8% used [0x00000007aab00000,0x00000007aac47cb0,0x00000007abb00000)
  from space 2560K, 0% used [0x00000007abd80000,0x00000007abd80000,0x00000007ac000000)
  to   space 2560K, 0% used [0x00000007abb00000,0x00000007abb00000,0x00000007abd80000)
 ParOldGen       total 44032K, used 0K [0x0000000780000000, 0x0000000782b00000, 0x00000007aab00000)
  object space 44032K, 0% used [0x0000000780000000,0x0000000780000000,0x0000000782b00000)
 Metaspace       used 2731K, capacity 4490K, committed 4864K, reserved 1056768K
  class space    used 291K, capacity 386K, committed 512K, reserved 1048576K

上面的 GC 垃圾回收策略基于 JDK 1.8 ，采用默认指定的策略，从上述的简要的 GC Log ，我们可以看出当前的 Java 虚拟机基础环境信息、启动参数以及各个代的相关活动情况。

通常，在我们开启 GC Log 文件后，日志文件的大小以及数量的分割有时候往往需要给予更多的关注，毕竟，无论从管理角度、信息完整性角度、友好性及其他相关联角度，都需要综合性考虑。因此，基于 -XX:+UseGCLogFileRotation 参数所定义的日志滚动功能，在大多数公司也应用，然而，在实际的生产环境中是否推荐呢？这也是本文所需要探讨的另一方面内容。

其实，从生产落地场景来说，现在的日志采集、管理及存储框架比较成熟，比如，通过 Agent 将其存储至第三方系统，更有利于对其进行管理与维护。本文着重从应用日志处理角度，基于此参数 -XX:+UseGCLogFileRotation 的相关设置所引入的缺陷以及解决方案。那么，会带来哪些问题呢？具体如下：

1、内容丢失问题

正如上述参数所描述的场景那样，假设，在我的微服务启动参数中显性定义了以下参数：-XX:+UseGCLogFileRotation、-XX:NumberOfGCLogFiles=3 以及 -XX:GCLogFileSize=20M ，即意味着我们设置了3个文件，应用程序运行一段时间过后就会生成3个日志文件，假如最先定义的是admin-gc.log.0，最近的是admin-gc.log.3，当admin-gc.log.3到达20M以后，日志会重新写入到admin-gc.log.0，admin-gc.log.0之前的内容会被清空掉，从而使得之前的信息不够完整。

2、可读性差

还是基于上述相同场景，日志目录已生成3个日志文件：admin-gc.log.0 到 admin-gc.log.3，若此时因各种原因进行JVM重启操作，此时 GC Log 会重新从 admin- gc.log.0 开始写入，但是 admin-gc.log.1、admin-gc.log.2、admin-gc.log.3这里面的日志依然为之前旧的日志，新旧日志就混合写入，导致格式模糊，可读性较差，影响用户体验。因此，若要解决这个问题，在重启服务器之前我们需要把老的日志全部迁移到其他目录，以避免重启后日志重新写入问题，影响日志的可读性。

3、不易分析

基于上述策略，若我们将 GC Log 进行分割后，生成的文件数量较多，通过日志分析平台（例如：类似GC Viewer及相关平台）进行解析时，往往需要导入多份文件，同时，由于各个文件（ admin-gc.log.1、admin-gc.log.2、admin-gc.log.3、...）内容之间可能存在时间间断，故上传至分析平台的文件不够完整，导致分析出来的结果参考性意义不大，从而很难为具体的业务场景需求提供优化建议。

4、难以维护

基于上述参数定义的场景，当前应用服务运行期间的活动日志文件的后缀名会被标记为 .current，假设，应用服务在某一时刻活动所生成的日志文件是 admin-gc.log.3，那么此时，其对应的活动日志文件名会被命名为 admin-gc.log.3.current，如果我们要把不同机器上的 GC Log 文件都集中传送至某一共享主机上去的话，通常我们会借助各种日志同步工具或命令行，例如：Rsyslog 等类似工具，然而，基于此种策略下的命名方式对 类似 Rsyslog 工具来说效率较为低下，影响数据的实时同步。

综上4点所述为基于 -XX:+UseGCLogFileRotation 参数在 GC Log 分析、存储时所带来的弊端，当然，也有其他潜在的问题，本文暂不讨论。那么，针对如上问题，是否有较好的建议或意见呢？答案：当然有。而且很多，在这里，我们简要介绍 2 种参考方案，具体如下所示：

1、对接至第三方日志系统

若我们不对 GC Log 文件进行滚动操作，让其以原生态模式进行日志输出，然后将其转储至第三方日志系统，依据第三方日志系统定义的日志规范。即使我们的应用服务因各种原因进行重启操作，也不会影响 GC Log 的写入，从而避免数据的丢失。

2、增加时间戳

若我们想实现 GC Log 文件的切割，我们可以尝试在 GC Log 的文件后缀加上时间戳，当 JVM 重启以后，会生成新的日志文件，新的日志也不会覆盖老的日志，只需要在日志文件名中添加 %t的后缀即可，具体如下示例所示：

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/data/logs/admin-gc-%t.log

“%t” 将会在文件名添加时间戳后缀，其生成的通用格式为 YYYY-MM-DD_HH-MM-SS，例如：“admin-gc-2016-01-01_02-13-04.log” 。基于此种策略，我们就轻而易举地避免了基于 -XX:+UseGCLogFileRotation 参数带来的所有的困扰。当然，撇开应用服务本身的特性，如果基于日志切割，目前成熟的方案有很多种，无论是基于哪种，终极目标无非是性能损耗小、易分析、易维护，大家有兴趣的话，可以实践其他方案。

至此，关于 Java 虚拟中 XX:+UseGCLogFileRotation 参数的相关解析本文到此为止，大家有什么疑问、想法及建议，欢迎留言沟通。