Adding Timestamp to Java's GC messages in Tomcat 6

Question

I turned on Java's GC log options

-XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+PrintGCDetails

Which print out these messages to standard output (catalina.out):

314.884: [CMS-concurrent-mark-start]
315.014: [CMS-concurrent-mark: 0.129/0.129 secs] [Times: user=0.14 sys=0.00, real=0.13 secs]
315.014: [CMS-concurrent-preclean-start]
315.016: [CMS-concurrent-preclean: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
315.016: [CMS-concurrent-abortable-preclean-start]
332.055: [GC 332.055: [ParNew: 17128K->84K(19136K), 0.0017700 secs] 88000K->70956K(522176K) icms_dc=4 , 0.0018660 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
 CMS: abort preclean due to time 352.253: [CMS-concurrent-abortable-preclean: 0.023/37.237 secs] [Times: user=0.78 sys=0.02, real=37.23 secs]

How can I make these log lines appear with an actual timestamp (including date) instead of these numbers, which presumably mean "time since JVM started" ?

Answer 1

As far as I know this can't be done. According to sun documentation

The format is not guaranteed to be the same in later releases. In particular the output associated with -XX:+PrintGCDetails is almost guaranteed to change in that it represents the current needs of JVM developers.

Admittedly this is an old reference( for java 1.4!) but I could find nothing more current, and the last time our group went through gc tuning, a few months back, we saw nothing in the current docs specifically addressing formatting.

Answer 2

Check this blog entry about how to show human readable timestamps in GC log files.