13

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)

Pabluez
  • 2,653
  • 3
  • 19
  • 29
Hyb
  • 163
  • 1
  • 2
  • 9
  • My work around would be to make less garbage, less GCs and shorter logs which don't need to be rotated. ;) – Peter Lawrey Dec 02 '11 at 10:03
  • I agree with that. It's not my boss' point of view however. – Hyb Dec 02 '11 at 11:02
  • At the very least, he/she could make sure you have plenty of disk space for logging so it doesn't need to be rotated. A TB doesn't cost that must these days. – Peter Lawrey Dec 02 '11 at 11:05
  • 1
    I found exactly why this is happening. It's due to some bourn shell limitations [link]http://www.in-ulm.de/~mascheck/bourne/common.html (tl;dr complete explanation is in there) Workaround is simple when this java call is done: `java -verbose:gc -cp /home/test/ Test | tee -a /home/test/test/log` an keeping the configuration of logrotate and cron. – Hyb Dec 02 '11 at 14:51
  • @Hyb, once you find this working with the above settings/configs that you posted, feel free to add this as an answer to this question :) would help someone like you in future. – peakit Jan 01 '12 at 09:24
  • As [answered here](http://stackoverflow.com/a/12277309/350692) it is now possible to configure the HotSpot JVM to rotate GC logs. – Johan Kaving Sep 05 '12 at 08:14
  • note these nulls are really the empty space in a sparse file, they do not take up disk space. – Jason Pyeron Nov 12 '14 at 16:03

4 Answers4

6

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

Stian Lund
  • 193
  • 2
  • 12
  • Indeed, I didn't think about that. It's easier than using the Tee solution :) – Hyb Aug 02 '12 at 07:43
  • Good solution using append to avoid the issue with logrotate. Note that this is related to https://serverfault.com/a/522687/379420 – sfgeorge Nov 09 '18 at 16:42
4

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

Community
  • 1
  • 1
Dan Hardiker
  • 3,013
  • 16
  • 19
3

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.

Community
  • 1
  • 1
Hyb
  • 163
  • 1
  • 2
  • 9
0

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?

Sarit
  • 101
  • 1
  • 3
  • 6
  • You would need to pipe output to tee if you wanted to have two files. Otherwise java would just log to gc.log. – Stian Lund Sep 27 '13 at 23:26