20

I have an issue on a few servers with the GC log. It's filled with this:

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

Noticed this occurs on servers with a large memory given to the JVM: -Xms32G -Xmx48G. This might be a red herring though but thought to mention it.

Since these are low latency/high throughput apps analyzing the log is vital. But instead, it's full of those characters above.

We are using 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)

We use this to create the log:

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

Anyone seen this issue before? What might cause it?

bdem
  • 321
  • 1
  • 6
  • how did you create the gc log? do you use the `verbose:gc` flag or any other way ? – kucing_terbang Oct 07 '15 at 10:01
  • @kucing_terbang: yes, I updated the question with the info – bdem Oct 07 '15 at 11:56
  • 3
    `^@` is the Unix/Linux notation for Ctrl-@, ASCII 0. Typically zeroed memory as happens a lot in java. – Joop Eggen Oct 07 '15 at 12:26
  • Does this happen after you truncate the log file? – clstrfsck Oct 07 '15 at 12:30
  • Maybe [this old answer](http://stackoverflow.com/a/10499244/44522) helps:: "The solution was to just log GC to stdout and then append stdout to a file." – MicSim Oct 07 '15 at 12:48
  • @msandiford: the file is not truncated, it's just one file. – bdem Oct 07 '15 at 14:43
  • 1
    @bdem I meant is the file being truncated, perhaps by some log file rotation process? See also this question/answer: http://stackoverflow.com/questions/3822097/rolling-garbage-collector-logs-in-java – clstrfsck Oct 07 '15 at 20:57
  • @msandiford: nope, it's not – bdem Oct 08 '15 at 07:13
  • The output of -XX:+PrintGCDetails depends on the GC algorithm used. See https://blog.codecentric.de/en/2014/01/useful-jvm-flags-part-8-gc-logging/ In case you programmatically invoke the garbage collector or change the algorithm, try to disable (if this is easy) that functionality. – Spyros K Oct 14 '15 at 10:10
  • Do you see those characters also when you do a `tail -f` on the GC log file? – Krzysztof Krasoń Apr 09 '16 at 08:41
  • I would also be interested to understand from where these characters are coming from. FYI, i've seen the same issue on SOLARIS with JDK1.7 and for "small" JVM (like Xms/Xmx set up to ~3GB only) with -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps and -Xloggc:path_to_file. I'm just used to remove the first line (as these characters are only on the first line) from command line with a tail) – SRG Apr 01 '19 at 14:13

2 Answers2

6

TL;DR

Don't use logrotate (or any 3rd party rotation) to rotate JVM GC logs. It's behaviour does not play nicely with the way the JVM writes the GC log file. The JVM is capable of rotating it's own GC logs, using JVM flags:

  • -XX:+UseGCLogFileRotation Enables GC log file rotation
  • -XX:NumberOfGCLogFiles=5 Will tell the JVM to keep 5 rotated files
  • -XX:GCLogFileSize=20M Will tell the JVM to rotate when the file reaches 20M

The problem

For us, this was because logrotate and the JVM were both trying to write the file without a lock. JVM garbage collection logs appear to be special insofar as they're written directly from the JVM itself into the file. What happens is that the JVM keeps a handle to this file, and a location within it where it writes logs to.

^@ is actually just a null byte in your file. You can see this if you run hexdump -C your_gc.log. What causes these null bytes is the interesting part - logrotate truncating the file.

$ 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|

This only surfaced for us because we were using Logstash to monitor the GC log. Logstash was crashing with OutOfMemoryError every time logrotate ran, and from inspecting heap dumps, we noticed that logstash was trying to ship a HUGE (600MB in JVM internal memory) log line that looked like:

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

In this case, because logstash escapes the nulls to unicode (6 characters), and each character is represented as UTF-16 internally in the JVM, this means the on-heap encoding of this is a whopping factor of 12 larger than the null bytes on disk. So it takes a smaller log than you would expect to run out of memory.

This lead us to find the nulls in the garbage collection log, and where they came from:

1. JVM happily writing logs

*-------------------------*
^                         ^
JVM's file start          JVM's current location

2. logrotate has entered the game

                         **
\________________________/
^                    |    ^
JVM's file start     |    JVM's current location
                     |
                     logrotate copies contents elsewhere and truncates file
                     to zero-length

3. JVM keeps writing

*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
Will Faithfull
  • 1,868
  • 13
  • 20
0

If the text you are saving is encoded with UTF-16, it may append an "^@" in a regular text file. I've had this problem opening some encoded files in UNIX systems before.

MrPublic
  • 520
  • 5
  • 16