Java GC 日志充满了奇怪的字符

Question

我在一些服务器上遇到 GC 日志问题。它充满了这个:

^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@

注意到这发生在为 JVM 提供大内存的服务器上:-Xms32G -Xmx48G。虽然这可能是一个转移注意力的问题，但还是想提一下。

由于这些是低延迟/高吞吐量的应用程序，因此分析日志至关重要。但相反，它充满了上面的那些字符。

我们正在使用 Java 8:

java version "1.8.0_40"
Java(TM) SE Runtime Environment (build 1.8.0_40-b26)
Java HotSpot(TM) 64-Bit Server VM (build 25.40-b25, mixed mode)

我们用它来创建日志:

-verbose:gc
-Xloggc:/path/to/gc.log
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps

有人以前见过这个问题吗？可能是什么原因导致的？

Answer 1

长话短说

不要使用 logrotate(或任何第 3 方轮换)来轮换 JVM GC 日志。它的行为不适合 JVM 写入 GC 日志文件的方式。 JVM 能够使用 JVM 标志轮转它自己的 GC 日志:

• -XX:+UseGCLogFileRotation 启用 GC 日志文件轮换
• -XX:NumberOfGCLogFiles=5 将告诉 JVM 保留 5 个旋转文件
• -XX:GCLogFileSize=20M 当文件达到 20M 时会告诉 JVM 旋转

问题

对我们来说，这是因为 logrotate 和 JVM 都试图在没有锁定的情况下写入文件。 JVM 垃圾收集日志看起来很特别，因为它们直接从 JVM 本身写入文件。发生的情况是，JVM 保留了该文件的句柄，以及其中写入日志的位置。

^@ 实际上只是您文件中的一个空字节。如果您运行 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 日志。每次 logrotate 运行时，Logstash 都会因 OutOfMemoryError 而崩溃，并且通过检查堆转储，我们注意到 logstash 正在尝试发送一个巨大的(JVM 内部内存中为 600MB)日志行看起来像:

{ "message": "\u0000\u0000\u0000...

在这种情况下，因为 logstash 将空值转义为 unicode(6 个字符)，并且每个字符在 JVM 内部表示为 UTF-16，这意味着堆上编码比磁盘上的空字节。因此，它需要的日志比您预期的要耗尽内存的日志要小。

这让我们找到垃圾收集日志中的空值，以及它们来自哪里:

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