TL;DR
不要使用(或任何第三方轮换)来轮换 JVM GC 日志。它的行为与JVM写入GC日志文件的方式不符。JVM 能够使用 JVM 标志轮换它自己的 GC 日志:logrotate
-
-XX:+UseGCLogFileRotation
启用 GC 日志文件轮换
-
-XX:NumberOfGCLogFiles=5
将告诉 JVM 保留 5 个旋转文件
-
-XX:GCLogFileSize=20M
将告诉JVM在文件达到20M时旋转
问题
对我们来说,这是因为JVM都在尝试在没有锁定的情况下写入文件。JVM垃圾回收日志看起来很特殊,因为它们直接从JVM本身写入文件。发生的情况是,JVM 保留了此文件的句柄,以及其中写入日志的位置。logrotate
^@
实际上只是文件中的一个空字节。如果运行 ,则可以看到此内容。导致这些空字节的原因是有趣的部分 - 截断文件。hexdump -C your_gc.log
logrotate
$ hexdump -C gc.log | head -3
00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
061ca010 00 00 00 00 00 00 00 32 30 32 30 2d 30 37 2d 30 |.......2020-07-0|
这对我们来说只是因为我们使用Logstash来监视GC日志。Logstash 每次运行时都会崩溃,通过检查堆转储,我们注意到 logstash 试图发布一个巨大的日志行(JVM 内存中为 600MB),如下所示:OutOfMemoryError
logrotate
{ "message": "\u0000\u0000\u0000...
在这种情况下,由于 logstash 将 null 转义为 unicode(6 个字符),并且每个字符在 JVM 内部表示为 UTF-16,这意味着 this 的堆上编码比磁盘上的空字节大 12 倍。因此,它需要的日志比您预期的内存不足要小。
这导致我们在垃圾回收日志中找到空值,以及它们的来源:
1. JVM愉快地写入日志
*-------------------------*
^ ^
JVM's file start JVM's current location
2.已进入游戏logrotate
**
\________________________/
^ | ^
JVM's file start | JVM's current location
|
logrotate copies contents elsewhere and truncates file
to zero-length
3. JVM 不断写入
*xxxxxxxxxxxxxxxxxxxxxxxxx-*
\________________________/^^
^ | |JVM's current location
JVM's file start | JVM writes new log
|
File is now zero-length, but JVM still tries to write
to the end, so everything before it's pointer is
filled in with zeros