CLOVER🍀

That was when it all began.

GCログに日付/時刻を出力させる

GCログの小ネタです。

GCログのオプションとして、「-XX:+PrintGCTimeStamps」、「-XX:+PrintGCDetails」、「-XX:+PrintGC」(PrintGCDetailsを指定すれば、無くてもOK)は有名だと思いますが

$ java -XX:+PrintGCTimeStamps -XX:+PrintGCDetails Monitor 
0.290: [GC [PSYoungGen: 15808K->2612K(18432K)] 15808K->8830K(60672K), 0.0472900 secs] [Times: user=0.06 sys=0.02, real=0.05 secs] 
0.355: [GC [PSYoungGen: 18420K->2593K(34240K)] 24638K->18138K(76480K), 0.0549070 secs] [Times: user=0.04 sys=0.02, real=0.05 secs] 
0.461: [GC [PSYoungGen: 34209K->2618K(34240K)] 49754K->26035K(76480K), 0.0498510 secs] [Times: user=0.05 sys=0.02, real=0.05 secs] 
0.548: [GC [PSYoungGen: 34234K->2618K(65856K)] 57651K->38116K(108096K), 0.0591100 secs] [Times: user=0.04 sys=0.04, real=0.06 secs] 
0.608: [Full GC [PSYoungGen: 2618K->0K(65856K)] [ParOldGen: 35498K->14305K(47424K)] 38116K->14305K(113280K) [PSPermGen: 2361K->2359K(21248K)], 0.1662370 secs] [Times: user=0.19 sys=0.02, real=0.17 secs] 

のように、出力されるタイムスタンプはJavaVMの起動からの経過時間となります。

0.290: 〜
0.355: 〜

これだと、後から見るには少々厳しいですよね。

そんな時は、「-XX:+PrintGCTimeStamps」フラグを「-XX:+PrintGCDateStamps」フラグに変更してあげます。すると、

$ java -XX:+PrintGCDateStamps -XX:+PrintGCDetails Monitor 
2012-06-24T00:43:13.519+0900: [GC [PSYoungGen: 15808K->2612K(18432K)] 15808K->8582K(60672K), 0.0403160 secs] [Times: user=0.05 sys=0.01, real=0.04 secs] 
2012-06-24T00:43:13.575+0900: [GC [PSYoungGen: 18420K->2609K(34240K)] 24390K->22483K(76480K), 0.0872630 secs] [Times: user=0.08 sys=0.01, real=0.09 secs] 
2012-06-24T00:43:13.725+0900: [GC [PSYoungGen: 34177K->2610K(34240K)] 54051K->22492K(76480K), 0.0163150 secs] [Times: user=0.02 sys=0.01, real=0.02 secs] 
2012-06-24T00:43:13.776+0900: [GC [PSYoungGen: 34226K->2607K(65856K)] 54108K->34711K(108096K), 0.0598400 secs] [Times: user=0.05 sys=0.04, real=0.06 secs] 
2012-06-24T00:43:13.837+0900: [Full GC [PSYoungGen: 2607K->0K(65856K)] [ParOldGen: 32104K->14076K(54336K)] 34711K->14076K(120192K) [PSPermGen: 2361K->2359K(21248K)], 0.1636650 secs] [Times: user=0.19 sys=0.01, real=0.17 secs]

出力されるのがJavaVMからの経過時間ではなくて、ログ出力時の時刻となります。これで、少しはGCログが見やすくなるかな?