GroovyでGCログ解析: ちょっと扱いにくいフォーマットを処理するときのパターン

G* Advent Calendar 2013の12/7担当、@nobusue です。

今年は基本に返って、実務に役立つGroovyの利用方法をご紹介しようと思います。(というか実際に業務で使ったのですが。。。)

お題はGCログの解析です。
ここでご紹介するサンプルはOracle JDK7(HotSpot VM)が出力するGCログを想定していますが、仕組みはシンプルなので他のフォーマット(IBM JDK以外)にも多少アレンジすれば適用可能なはずです。

GCログを解析する場合、通常はGCViewerなどのツールを使うことが多いですが、それでは対応が難しい要件もたまにあります。
例えば、「GCログが100本くらい取ってあって、それらを解析して最適なヒープサイズを見積もる」というようなケースです。いちいちGUIツールで一つ一つ開いてられないですよね。。。

そこでGCログをスクリプトで処理してやろうか、と思うのですが、GCログには以下のようなちょっと困った特徴があります。

  1. 一行で無理矢理情報を階層化しているので、フィールドの分割が単純にいかない
  2. 設定しているGCアルゴリズムによってフォーマットがかなり変わる
  3. CPU負荷が高いとログが壊れてフォーマットが不正になる場合がある

特に3.が厄介で、こいつのせいでまともにパーサーを実装しようとすると例外処理が無駄に複雑になってしまいます。かといって、一行全体をパターンマッチングで処理しようとすると、ものすごく長大な正規表現が必要になり、デバッグに苦しむことになります。(というか実際苦しんだ。)

そこで、現実的なアプローチとして以下の戦略を採用します。

  • 一行を区切り文字でおおざっぱに分割する
  • 分割した各要素から、正規表現で必要な部分を取り出す

具体的なやり方は以下のようになります。

GCログ出力設定

まずは準備としてGCログを採取します。
JVMの起動時オプションに以下を追加してください。

 -Dverbose:gc -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps

これで、JVM起動時のカレントディレクトリに gc.log が出力されるようになります。(+PrintGCDateStampsはJDK6以降でないと使えないので、JDK5以前の方は+PrintGCTimeStampsに変更してくださいね。)
GCログの具体的な出力は以下のようになります。
マイナーGCの場合:

2013-12-07T17:33:31.668+0900: 19.047: [GC [PSYoungGen: 26476K->6407K(30208K)] 59443K->40152K(74240K), 0.0631133 secs] [Times: user=0.20 sys=0.00, real=0.06 secs] 

フルGCの場合:

2013-12-07T17:33:31.731+0900: 19.110: [Full GC [PSYoungGen: 6407K->0K(30208K)] [ParOldGen: 33744K->34259K(65024K)] 40152K->34259K(95232K) [PSPermGen: 40231K->39553K(65536K)], 0.1483206 secs] [Times: user=0.36 sys=0.00, real=0.15 secs] 

GCログの読み方の詳細についてはここでは触れません。こちらあたりが参考になると思います。

GCログの1行をおおざっぱに分割する

GCログのフォーマットを眺めてみると、以下のような構造になっています。

2013-12-07T17:33:31.668+0900: 19.047:
[GC
  [PSYoungGen: 26476K->6407K(30208K)]
  59443K->40152K(74240K),
  0.0631133 secs]
[Times: user=0.20 sys=0.00, real=0.06 secs] 

2013-12-07T17:33:31.731+0900: 19.110: 
[Full GC
  [PSYoungGen: 6407K->0K(30208K)]
  [ParOldGen: 33744K->34259K(65024K)]
  40152K->34259K(95232K)
  [PSPermGen: 40231K->39553K(65536K)],
  0.1483206 secs]
[Times: user=0.36 sys=0.00, real=0.15 secs] 

「Timesの部分は役に立たないので捨てる」という決断をすれば、1行を"["と"]"、および","で区切れば意味のある固まりに分割できることがわかります。
これをGroovyで実装すると以下のようになります。

def items = line.tokenize("[")*.tokenize("]").flatten()*.tokenize(",").flatten()*.trim()

flatten()が2回発生していますが、元のフォーマットが変態なせいですので我慢してください。
これで、「ヒープ領域ごとのMAXを取得する」という目的にかなり近づくことができました。

パターンマッチングで必要な部分を抜き出す

この前の作業で、

[PSYoungGen: 6407K->0K(30208K)]

みたいな文字列を切り出すことはできました。じゃあ、ここから"(30208K)"の数字部分だけ取り出すにはどうすればよいでしょうか?
良い子の皆さんは既にお分かりだと思いますが、正規表現を使うのが一番手っ取り早くお手軽だと思います。でも、いざ使うとなると、サンプルとか少なくて意外に悩みませんか?
こういう場合、私はいつも次のようにしています。

def s = "[PSYoungGen: 6407K->0K(30208K)]"
def max = s.find( /PSYoungGen:.*\((\d+)K\)/ ) {all,m0 -> return m0}

何をしているのか簡単に解説します。

  1. find(/正規表現(正規表現)/)で文字列のマッチを行います。括弧で囲んでいる部分が、切り出したい文字列に相当する部分です。(バックリファレンス)
  2. findの最後の引数にクロージャを渡すと、クロージャの第1引数にはマッチした文字列全体、第2引数以降にはバックリファレンスで指定した文字列が渡されます。
  3. 欲しいのはバックリファレンスの1つめ、すなわちクロージャの第2引数なので、これをそのままreturnで返します。加工が必要ならここでやることもできます。

サンプルコード

第一引数としてGCログのファイル名を渡すと、

Young Max: 41472K
Old Max  : 65024K
Total Max: 95744K
Perm Max : 65536K
Total GC pause time: 0.3325945 sec

みたいな感じで、ヒープの各領域のMAXを表示するサンプルがこちらになります。(フルGCが発生していないとOld/Permは取得できないので"0K"になります。そういう仕様なのでご了承ください。)

def srcFile = new File(args[0])

def youngMax=0, oldMax=0, totalMax=0, permMax=0
def totalPause=0.0

srcFile.eachLine{ line ->
  if( line =~ /^\d\d\d\d-\d\d-\d\dT/) {
    def gcinfo = parseGC(line)
    //println gcinfo
    try{
   	ym = gcinfo.ym.toInteger()
   	tm = gcinfo.tm.toInteger()
   	pt = gcinfo.pt.toDouble()
    } catch(e) { return }
   youngMax = (ym > youngMax) ? ym : youngMax
   totalMax = (tm > totalMax) ? tm : totalMax
   totalPause += pt
   if( line.contains("[Full GC")) {
   try{
   	om = gcinfo.om.toInteger()
   	pm = gcinfo.pm.toInteger()
   } catch(e) { return }
    	oldMax = (om > oldMax) ? om : oldMax
    	permMax = (pm > permMax) ? pm : permMax
   } 
 }
}
println "Young Max: ${youngMax}K"
println "Old Max  : ${oldMax}K"
println "Total Max: ${totalMax}K"
println "Perm Max : ${permMax}K"
println "Total GC pause time: ${totalPause} sec"

def Map parseGC(line) {
    def items = line.tokenize("[")*.tokenize("]")
               .flatten()*.tokenize(",").flatten()*.trim()
    //println items
    def m = [:]
    items.each{
        switch(it) {
	    case ~/PSYoungGen:.*/:
	        m.ym = it.find( /PSYoungGen:.*\((\d+)K\)/ ) {all,m0 -> return m0}
		break
	    case ~/ParOldGen:.*/:
		m.om = it.find( /ParOldGen:.*\((\d+)K\)/ ) {all,m0 -> return m0}
	        break
	    case ~/PSPermGen:.*/:
	 	m.pm = it.find( /PSPermGen:.*\((\d+)K\)/ ) {all,m0 -> return m0}
		break
	    case ~/\d+K->\d+K\(\d+K\)/:
		m.tm = it.find( /\d+K->\d+K\((\d+)K\)/ ) {all,m0 -> return m0}
		break
	    case ~/\d*\.\d*\s+secs/:
		m.pt = it.find( /(\d*\.\d*)\s+secs/ ) {all,m0 -> return m0}
	}
   }
   return m
}

以上です。
Groovyの便利さを感じていただくことができましたか?

次は@さんです!