oinume journal

Scratchpad of what I learned

Top > Java > Make Javas VM's GC log human readable with -XX:+PrintGCDateStamps

Make Javas VM's GC log human readable with -XX:+PrintGCDateStamps

Java in English

I use Java VM's option -XX:+PrintGCTimeStamps in order to output time in GC log of Java VM , Just like this.

TODAY=`date "+%Y%m%d-%H%M%S"`

JAVA_OPTS="-server -Xms512m -Xmx512m -Xmn256m -XX:PermSize=256m -XX:MaxPermSize=256m \
 -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:+UseParNewGC \
 -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=32 -XX:TargetSurvivorRatio=85 \
 -verbose:gc -Xloggc:/usr/local/tomcat/logs/gc.log.$TODAY \
 -XX:+PrintGCDetails \
 -XX:+PrintGCTimeStamps \
 -DJENKINS_HOME=/var/lib/jenkins \
"

But, the output is relative time from starting time of Java VM. So it's difficult to read. However, we have an another option -XX:+PrintGCDateStamps !! It is an option to output absolute time!! (Available from Java6 u6)

-XX:+PrintGCTimeStamps

63.156: [CMS-concurrent-mark-start]
64.175: [CMS-concurrent-mark: 0.844/1.019 secs] [Times: user=2.59 sys=0.21, real=1.02 secs] 
64.176: [CMS-concurrent-preclean-start]
64.197: [CMS-concurrent-preclean: 0.019/0.021 secs] [Times: user=0.05 sys=0.01, real=0.03 secs] 
64.197: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 69.246: [CMS-concurrent-abortable-preclean: 4.756/5.049 secs] [Times: user=12.37 sys=0.75, real=5.04 secs] 
69.248: [GC[YG occupancy: 235103 K (235968 K)]69.248: [Rescan (parallel) , 0.2130820 secs]69.461: [weak refs processing, 0.0017410 secs] [1 CMS-remark: 138712K(262144K)] 373816K(498112K), 0.2149850 secs] [Times: user=0.61 sys=0.00, real=0.21 secs] 
69.466: [CMS-concurrent-sweep-start]
69.468: [GC 69.468: [ParNew: 235968K->26176K(235968K), 0.0955880 secs] 374601K->174167K(498112K), 0.0957410 secs]

-XX:+PrintGCDateStamps

2013-01-20T13:20:43.395+0900: 0.847: [Full GC (System) 0.847: [CMS: 0K->1757K(262144K), 0.0502300 secs] 16808K->1757K(498112K), [CMS Perm : 10054K->10045K(262144K)], 0.0503520 secs] [Times: user=0.09 sys=0.00, real=0.05 secs] 
2013-01-20T13:20:47.952+0900: 5.404: [GC 5.404: [ParNew: 209792K->1976K(235968K), 0.0304360 secs] 211549K->3733K(498112K), 0.0305290 secs] [Times: user=0.05 sys=0.00, real=0.03 secs] 
2013-01-20T13:20:53.692+0900: 11.144: [GC 11.144: [ParNew: 211768K->3713K(235968K), 0.0192760 secs] 213525K->5470K(498112K), 0.0193720 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 
2013-01-20T13:21:02.932+0900: 20.383: [GC 20.383: [ParNew: 213505K->21672K(235968K), 0.0812540 secs] 215262K->23429K(498112K), 0.0813650 secs] [Times: user=0.13 sys=0.03, real=0.08 secs] 
2013-01-20T13:21:07.448+0900: 24.899: [GC 24.900: [ParNew: 231464K->26176K(235968K), 0.1677760 secs] 233221K->38711K(498112K), 0.1678730 secs] [Times: user=0.32 sys=0.05, real=0.17 secs] 
2013-01-20T13:21:12.021+0900: 29.473: [GC 29.473: [ParNew: 235968K->26176K(235968K), 0.2173720 secs] 248503K->57677K(498112K), 0.2175440 secs] [Times: user=0.62 sys=0.00, real=0.22 secs] 
2013-01-20T13:21:16.168+0900: 33.620: [GC 33.620: [ParNew: 235968K->26176K(235968K), 0.0859270 secs] 267469K->59042K(498112K), 0.0860640 secs]

-XX:+PrintGCDateStamps is a great option for humans.

Effective Java (Java Series)

Effective Java (Java Series)