oinume journal

Scratchpad of what I learned

JVMのGCのログを-XX:+PrintGCDateStampsでhuman readableにする

English version

 

JVMGCのログ出すじゃないですか。んで、その時↓みたいに -XX:+PrintGCTimeStamps っていうオプションを指定するじゃないですか。

 

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 \

"

 

 

でもこれ、悲しいかな、JVM起動時の時間からの相対時間なんすよね... いやJVM起動した時間なんか調べるの面倒だし、いちいち相対時間から計算するの面倒だし、っていうあなたに -XX:+PrintGCDateStamps をオススメします。これを指定するとGCのログが絶対時間で出力される。(PrintGCDateStampsはJava6 u4から利用可能)

 

びふぉー(-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]

 

 

これで人間が読めるGCのログになりましたね。

 

[tmkm-amazon]4873113881[/tmkm-amazon]