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ログには以下のようなちょっと困った特徴があります。
- 一行で無理矢理情報を階層化しているので、フィールドの分割が単純にいかない
- 設定しているGCのアルゴリズムによってフォーマットがかなり変わる
- 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ログの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}
何をしているのか簡単に解説します。
サンプルコード
第一引数として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の便利さを感じていただくことができましたか?
次は@tyamaさんです!