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; 博士

不要使用logrotate（或任何第三方轮换）来轮换 JVM GC 日志。它的行为与 JVM 写入 GC 日志文件的方式并不一致。JVM 能够使用 JVM 标志轮换它自己的 GC 日志：

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

问题

对我们来说，这是因为logrotateJVM 都试图在没有锁定的情况下写入文件。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 日志。LogstashOutOfMemoryError每次logrotate运行都会崩溃，通过检查堆转储，我们注意到 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 系统中打开一些编码文件时遇到过这个问题。