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

TL;DR

不要使用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，这意味着它的堆上编码是 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

Answer 2

如果您保存的文本使用 UTF-16 编码，它可能会在常规文本文件中附加一个“^@”。我以前在 UNIX 系统中打开一些编码文件时遇到过这个问题。