Java GC日志充满了奇怪的字符TL;DR问题

2022-09-02 10:57:20

我在几台带有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

以前有人见过这个问题吗?什么可能导致它?


答案 1

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.loglogrotate

$ 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),如下所示:OutOfMemoryErrorlogrotate

{ "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

答案 2

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