OpenJDK/SystemTapのデバッグが有効な5つの事例：Java on Linuxを鬼凄ネイティブデバッグ！（後篇）（1/3 ページ）

OpenJDKとSystemTapは実案件で大活躍！

　前回の「OpenJDK＋SystemTapでトラブル解析はここまでできる！」ではOpenJDKとSystemTapの概要と、これらの組み合わせでできることを簡単なサンプルを交えながら説明しました。今回は実戦で使える事例ということで、以下の5つを具体的なスクリプトを含めながら説明します。スクリプトやソースコードはこちらからダウンロードできます。

1. GC動作状況の取得
2. 特定メソッドのプロファイリング
3. 特定メソッド実行時のスタックトレース取得
4. エンドポイントとのコネクション（ソケット）確認
5. 競合するモニターオブジェクトの把握

　なお、今回のサンプルはすべて、以下の環境で動作を確認しています。

• OS：Red Hat Enterprise Linux Server release 6.1（Santiago）
• カーネル：kernel-2.6.32-131.0.15.el6.x86_64
• libc：glibc-2.12-1.25.el6.x86_64
• JDK：java-1.6.0-openjdk-1.6.0.0-1.39.1.9.8.el6_1.x86_64（※RHSA-2011:0856-1を適用）
• SystemTap：systemtap-1.4-6.el6.x86_64

プロセスアタッチ時の注意点

　ケーススタディの説明の前に、SystemTapでJavaアプリケーションの解析をする場合の注意点について記載します。

■ 動的アタッチ（すでに起動しているプロセスに対するアタッチ）の場合

　stapコマンド実行時に-xオプションを付加して、ターゲットプロセスのPIDを指定する必要があります。またターゲットプロセスに対して、stapコマンドでアタッチ後にシグナルを送信しておく必要があります。

　SystemTapはユーザープロセスの情報をプローブするために「uprobes」と呼ばれる仕組みを利用します。uprobesを用いたユーザー空間プローブは、プロセス内の（ネイティブレベルでの）全スレッドにプローブが設定されるまで有効になりません。

　この「プローブが設定されるタイミング」というのは、システムコールの発行やシグナル受信など、さまざまなものがありますが（※1）、Javaはネイティブレベルでのメインスレッド（PID = TIDのスレッド）が「pthread_join(3)」関数でスリープ状態となっているため、このタイミングを得ることができず、プローブポイントが有効になりません（※2）。

　そのため、stapコマンドでアタッチ後にターゲットプロセスに対してSIGQUITなどを送出し、ネイティブレベルのメインスレッドを動作させる必要があります。

■ あらかじめstapコマンドを起動しておく場合

　全てのプロセスにプローブを掛けることになるため、プローブ呼び出し元のプロセス名やPIDなどで、プローブポイント内の情報を確実に管理する必要があります。

　システムコールやライブラリ関数にプローブポイントを設定した場合、さまざまなプロセスからプローブポイントが大量に呼び出されてしまい、システムの高負荷状態やstapコマンドの異常終了、カーネルがクラッシュする可能性があります。

ケース1：GC動作状況の取得

　本ケースでは、GCログの出力を設定していない既存のjavaプロセスから、GCログライクな出力をオンデマンドで取得します。稼働中のプロセスでGC多発などのトラブルが発生し、開発側からGCログの提供が求められたときなどに便利です。

■ 取得する項目

　GC発生前後の各領域の使用量を取得し、GC種別（使用した不要オブジェクト回収機構）や処理時間をstapコマンドの標準出力に出力します。

• タイムスタンプ（※UNIXエポック（1970/1/1 00:00:00 UTC）からの経過時間）
• GC種別
• New世代使用量（Eden＋Survivor）
• Old世代使用量
• Permanent世代使用量
• 処理時間（マイクロ秒）

■ 使用するプローブ

• hotspot.mem_pool_gc_begin
• hotspot.mem_pool_gc_end

　GCの開始と終了をメモリプール（領域）単位でフックします。今回はそれぞれのプローブでメモリマネージャ名と各メモリプールの使用量を取得します。

　これらのプローブで使用可能な変数の情報源はJMXのMemoryPoolMXBeanインターフェイスと同一です。そのため、JConsoleやVisualVMなど、JMX経由でメモリの詳細情報を取得するときと同じものを、リアルタイムに得ることが可能になります。

　それぞれのプローブで使用可能な変数を表1に示します。mem_pool_gc_beginとmem_pool_gc_endでは取得できる項目が同じなので、GC発生前後での値の推移をそのまま比較できます。

■ 実装のポイント

　ここではスクリプト実装のポイントを説明します。スクリプト全体については「case1.stp」をダウンロードしてください。

● 【1】「ビフォーアフター」の記録場所の用意

　GCログは対象世代を「回収前の使用量→回収後の使用量」という形で記録します。これを実現するために、GC発生前後の各メモリプールの使用量を格納するためのグローバル変数を用意します。

　また、タイムスタンプやGC処理時間の基準となる時刻、および「どのメモリプールに関する情報を取得したか？」を記録する変数も併せて用意します。今回、表2に示すグローバル変数を用意しました。これらの変数はメモリマネージャ名をキーに持つ連想配列として使用します。

● 【2】確認対象のメモリプールの特定

　mem_pool_gc_*で取得できるメモリプールは、さまざまな種類が存在します。また、メモリプール名もGCアルゴリズムによって異なります。例えばOld領域の場合、シリアルGCでは「Tenured Gen」、パラレルGCでは「PS Old Gen」となります。

● 【3】hotspot.mem_pool_gc_beginプローブ

　mem_pool_gc_beginプローブでは、GC開始前の各世代の使用量を取得します。

　変数「pool」で渡されるメモリプール名はコラムで説明したとおり、GCアルゴリズムによって異なります。そのため、SystemTapの関数である「isinstr()」を使って、このプローブが対象とするメモリプールがどの世代のものなのか特定します。

　使用量は変数「used」より取得し、メモリマネージャ名（変数「manager」）と世代名（Eden／Survivor／Old／Perm）の2つをキーにもつ連想配列（グローバル変数「BeforeUsage」）の値に設定します。

probe hotspot.mem_pool_gc_begin{
GCStartTime[manager] = gettimeofday_us();
MemPoolFlags[manager] = 0;
if(isinstr(pool, "Eden"))
BeforeUsage[manager, "Eden"] = used;
else if(isinstr(pool, "Survivor"))
BeforeUsage[manager, "Survivor"] = used;
else if((isinstr(pool, "Tenured") || isinstr(pool, "Old")))
BeforeUsage[manager, "Old"] = used;
else if(isinstr(pool, "Perm"))
BeforeUsage[manager, "Perm"] = used;
}

　併せて、GC開始時間を「gettimeofday_us()」を用いてマイクロ秒単位で取得し、MemPoolFlagsをゼロクリアします。

● 【4】hotspot.mem_pool_gc_endプローブ

　mem_pool_gc_endプローブでは、GC終了後の各世代の使用量を取得します。使用量の取得は【3】と同様に行います。mem_pool_gc_*はメモリプール単位で呼び出されるため、すべてのメモリプール情報を一括して表示する場合は、自分がそれまでどのメモリプールを処理したかを記録しておく必要があります。その記録にグローバル変数MemPoolFlagsを使用します。

　MemPoolFlagsはメモリマネージャ名をキーにもつ連想配列で、値には処理したメモリプールを表すビットを立てます。今回は下位ビットから順にEden、Survivor、Old、Permとしました。

probe hotspot.mem_pool_gc_end{
if(isinstr(pool, "Eden")){
AfterUsage[manager, "Eden"] = used;
MemPoolFlags[manager] |= 1;
}
else if(isinstr(pool, "Survivor")){
AfterUsage[manager, "Survivor"] = used;
MemPoolFlags[manager] |= 2;
}
else if((isinstr(pool, "Tenured") || isinstr(pool,"Old"))){
AfterUsage[manager, "Old"] = used;
MemPoolFlags[manager] |= 4;
}
else if(isinstr(pool, "Perm")){
AfterUsage[manager, "Perm"] = used;
MemPoolFlags[manager] |= 8;
}
if(MemPoolFlags[manager] == 15){
now_time = gettimeofday_us();
printf("%d %s: New: %dKB->%dKB, Old: %dKB->%dKB, Perm: %dKB->%dKB, Time: %dus\n",
now_time / 1000, manager,
(BeforeUsage[manager, "Eden"] + BeforeUsage[manager, "Survivor"]) / 1024,
(AfterUsage[manager, "Eden"] + AfterUsage[manager, "Survivor"]) / 1024,
BeforeUsage[manager, "Old"] / 1024, AfterUsage[manager, "Old"] / 1024,
BeforeUsage[manager, "Perm"] / 1024, AfterUsage[manager, "Perm"] / 1024,
now_time - GCStartTime[manager]);
}
}

　すべてのビットが立った（1ビット目から4ビット目まで：10進数で合計15）になった時点でGCログライクな出力を「printf()」を用いて出力します。printf()はC言語のprintf()同様、フォーマット文字列を受け付ける仕様になっています。

■ 実行例

　ケース1のスクリプト実行例を図1に示します。これは、わざとメモリリークを起こすJavaプログラムに動的にアタッチしてログを取得したものです。

図1　ケース1のスクリプト実行例

　冒頭の「PID=」で始まる文字列は、スクリプト開始時に呼び出されるbeginプローブで出力しています。stapコマンドのコンソール出力に用いるターゲットPIDの取得には「target()」を使用しています。プロセスアタッチ時の注意点で説明したターゲットプロセスへのシグナル送信タイミングは、このbeginプローブによるメッセージ出力後です。