Printing Java garbage collection time stamps
I’ve been spending a bunch of time lately looking at Java garbage collection (GC) performance & tuning. One of the old standby options for GC logging is:
-XX:+PrintGCTimeStamps
this option tells the JVM to print a time stamp in the front of each GC line that is the number of seconds since the Java process started. You end up with lines like:
1.449: [GC 76756K->5892K(504320K), 0.0226648 secs]
1.472: [Full GC 5892K->5752K(504320K), 0.1099638 secs]
4.276: [GC 137848K->14895K(504320K), 0.0333021 secs]
5.653: [GC 146991K->63707K(504320K), 0.0858191 secs]
38.536: [GC 195803K->77393K(636416K), 0.0683676 secs]
144.875: [GC 341585K->97580K(637440K), 0.1131954 secs]
While these are better than nothing, it can be a PITA to translate these to something useful, like say wall clock time, such as when you want to correlate a GC time to an external alarm.
Starting in Sun’s JDK version 1.6u4, there is another option that can be enabled that actually prints both the wall clock time as well as the seconds since process start. This is way more user-friendly. I suspect there is a extremely minute performance penalty to add this extra info, but I’d be shocked if it is actually perceptable. If anyone knows differently, please let me know. This option is:
-XX:+PrintGCDateStamps
If you have it enabled, the output looks like:
2009-09-02T23:02:07.151-0400: 1.463: [GC 79398K->5887K(504320K), 0.0236701 secs]
2009-09-02T23:02:07.175-0400: 1.486: [Full GC 5887K->5753K(504320K), 0.1095894 secs]
2009-09-02T23:02:10.028-0400: 4.339: [GC 137849K->14987K(504320K), 0.0345331 secs]
2009-09-02T23:04:31.707-0400: 146.018: [GC 147083K->23143K(504320K), 0.0455040 secs]
2009-09-02T23:14:28.502-0400: 742.813: [GC 155239K->28406K(504320K), 0.0912850 secs]
As you can see, this is much more easily digestable to humans. Since you still have the ‘seconds since program start’ info handy, you can continue to use scripts/programs to easily calculate the time deltas between GCs.
Some useful links I’ve found for Java tuning in general are:
- Resources from Matty’s presentation:
http://prefetch.net/blog/index.php/2008/02/05/java-performance-presentation/
- Java performance forum:
http://forums.java.net/jive/forum.jspa?forumID=60
- Jon Masamitsu’s blog: (the last post was over a year ago, starting to age, but some good material)
http://blogs.sun.com/jonthecollector/
- Garbage Collection Tuning in the Java HotSpot Virtual Machine presentation at Java One 2009
http://developers.sun.com/learning/javaoneonline/sessions/2009/pdf/TS-4887.pdf