Garbage collector log (loggc) file rotation with l

Question

I came across a weird issue when using JVM garbage collection log option with Linux logrotate command. When rotation is executed, it fills NUL ( ^@ ) values the first line of the file given as argument to the JVM.

Let say this is the java call (Test.class is located in /home/test/) :

java -Xloggc:/home/test/test.log -cp /home/test/ Test

The configuration of logrotate for this file is as follow :

/home/test/test.log {
   rotate 56
   missingok
   notifempty
   copytruncate
   nocreate
   nomail
}

I also have a crontab entry logging every minute for testing purposes :

*/1 * * * * /usr/sbin/logrotate -f /etc/logrotate.d/gcLog

I came to the conclusion that JVM writes in append mode and keeps some kind of offset used to write next line in the related file, even if the file is truncated by logrotate (I may be wrong).

My next idea was to try and redirect the stdout to test.log file. I used this java call and kept the same configuration for logrotate and cron:

java -verbose:gc -cp /home/test/ Test > /home/test/test.log

Once again, when test.log is truncated by logrotate, the new created file is filled with NUL (^@) values on the first line.

No need to say that I didn't find anything helpful using google. I found another question on stackoverflow kind of related, but I couldn't manage to setup Java Script Wrapper, so this doesn't work.

Did anybody come across this issue ? Any idea why is this happening ? Better, any workaround or solution ? I need to try and pipe the call to the application to a some script reading the output and maybe look at the way Tomcat logs and rotate stdout in catalina.out (here some help will be really appreciated as well)

Answer 1

We had the same problem at our place running Jboss7 and Java6, we were getting NULLs in the GC file and they just kept growing.

Solution was to just log GC to stdout and then append stdout to a file:

Simple example:

java -verbose:gc >> console.log

Apparently using append (>>) gets rid of the Java "pointer" to a position in the file. With the added bonus of not having the GC logs reset per server restart so we can have some stats over time.

At least the IBM PMAT tool has no problem parsing the sysout with GC output.

The simplest solution is sometimes the best :)

Though I wish Java would support rotating of GC logs, as I see someone's been discussing before: http://mail.openjdk.java.net/pipermail/hotspot-runtime-dev/2011-April/002061.html

Answer 2

instead of java -verbose:gc >> console.log can I do: java -Xloggc:logs/gc.log >> console.log so the output will be saved in a file and then also rotate to console.log?

Answer 3

To explain the null's, Java maintains an internal reference counting the position for indentation, and as you move the file out of the way it causes null characters to be written to the log.

I've seen tampering with the GC log files to cause the system to crash, the abort caused while it writes to the log file is ignored (see the code here http://pastebin.com/HWkNv3PM) causing the JVM to continue ignoring the error.

As the file is reopened, I believe the position counter isn't being reset.

As for other ideas on how to roll the log files - see also: Rolling garbage collector logs in java

Answer 4

A simple workaround could be to change the Java call I used in my question:

java -Xloggc:/home/test/test.log -cp /home/test/ Test

to

java -verbose:gc -cp /home/test/ Test | tee -a /home/test/test/log

Configuration of logrotate and cron could stay the same (even if cron period should be increased).

See my commentary under the question for a link giving more details about logrotate and file handlers in Linux. See also brainzzy's explanations on Java behavior.