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

[末永恭正，NTT OSSセンタ]

ケース4：エンドポイントとのコネクション（ソケット）確認

　本ケースでは、Apache Tomcat 7.0.21がacceptしたソケットに関してsrc側とdest側の情報（IPアドレス、ポート番号）および割り当てられたソケットファイルディスクリプタ（FD）番号を取得します。今回は、HotSpotのプローブポイントというよりは、SystemTap本来の機能であるシステムコールやカーネル関数のプローブをメインに使用します。

　アプリケーション、またはミドルウェアが接続しているエンドポイント情報を網羅的に確認するのに便利です。

■ 取得する項目

　ソケットのaccept時、close時に以下の情報を出力します。

• 発生日時
• スレッド名
• スレッドID（TID）
• FD番号
• エンドポイント情報（バインドアドレスとポート番号、src側dest側両方）

■ 使用するプローブ

• hotspot.thread_start
• hotspot.thread_end

　Javaスレッド名とTID（スレッドダンプでは「nid」で確認できます）のマッピングを取るために使用します。それぞれのプローブで使用可能な変数を表5に示します。

表5　hotspot.thread_*で使用可能な変数

変数名	内容
name	固定値（「thread_start」または「thread_end」）
thread_name	Javaスレッド名
id	java.lang.Thread#getId()で返される、スレッド識別子
native_id	TID（LWP ID）
is_daemon	デーモンスレッドか否か
probestr	プローブ呼び出し時の概要の文字列表現

• syscall.accept*
• kernel.function

　TomcatがWebクライアント（Webブラウザなど）との通信をacceptするのを、システムコールレベルでフックします。今回使用したカーネル（kernel-2.6.32-131.0.15.el6.x86_64）をビルドしたGCCに起因すると考えられる問題で、関数内のローカル変数から必要な情報を取得できないため、kernel.functionを使ってカーネル関数に直接プローブを掛けます。詳細については後述します。

• socket.close

　ソケットがクローズされるタイミングをカーネルレベルでフックします。

■ 実装のポイント

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

● 【1】スレッド名の記録

　TIDとそれに対応するJavaスレッドの名前を記録します。グローバル変数「thread_name_pool」を、TIDをキー、スレッド名を値とする連想配列として使用します。

global thread_name_pool;
probe begin{
printf("PID=%d probe start!\n", target());
}
probe hotspot.thread_start{
thread_name_pool[native_id] = thread_name;
}
probe hotspot.thread_stop{
delete thread_name_pool[native_id];
}

　Javaスレッド生成時に、そのスレッド名を記録し、スレッド消滅時に該当のエントリをthread_name_poolから削除します。

　ただし、メインスレッド（main()メソッドを実行するスレッド）、およびstapコマンドでプローブが有効になる前に生成されるスレッドに関してはスレッド名が取得されません（すでに当該スレッドが生成されているため）ので、ご注意ください。

● 【2】FD番号とエンドポイント情報の取得

　クライアントから新たな接続が受け入れられた（acceptされた）タイミングで、SystemTap本来の機能である、カーネル関数のプローブを利用してソケットに関する情報（src側とdest側それぞれのIPアドレスとポート番号およびFD番号）を取得し、表示します。

global sock_alloc_progress;
global fd_table;
：
probe syscall.accept{
sock_alloc_progress[tid()] = 0;
}
probe kernel.function("sock_alloc").return{
if($return != 0)
sock_alloc_progress[tid()] = $return;
}
probe syscall.accept.return{
sock = sock_alloc_progress[tid()];
delete sock_alloc_progress[tid()];
if((sock == 0) || ($return sk;
fd_index = sprintf("%s:%d -> %s:%d",
ip_ntop(__ip_sock_saddr(sk)), tcpmib_local_port(sk),
ip_ntop(__ip_sock_daddr(sk)), tcpmib_remote_port(sk));
printf("%s: accept \"%s\"(TID=%d): fd=%d, %s\n", tz_ctime(gettimeofday_s()),
thread_name_pool[tid()], tid(), $return, fd_index);
fd_table[fd_index] = $return;
}

　「java.net.ServerSocket#acept()」などのJDKのソケットI/Oをつかさどる関数は、最終的にJNIを通してプラットフォームAPIが呼び出されます。今回は、Tomcatにつなぎに来たクライアントの情報を得ることが目的なので、プローブを掛けるポイントとしてはaccept(2)が適しています。

　本来SystemTapはDWARF情報をたどって関数内のローカル変数を参照できますが、プローブ対象のバイナリ（今回の場合はカーネル）をコンパイルしたGCCによっては、これに必要なDWARF情報が欠落してしまい、ローカル変数にアクセスできないことがあります。

コラム　DWARFに関するGCCの既知の問題

これは既知の問題として認識されており、以下のサイトにまとめられています。詳細については、そちらをご確認ください。

TipContextVariables - Systemtap Wiki

なお、今回対象としたカーネルのdebuginfoに含まれるvmlinuxの.commentセクションをダンプしてみると、ビルドに使用したGCCは4.4.4で、上記に記載されているコンパイルオプションによる回避策で対応できないバージョンのようです。

　今回のカーネルも、この問題に当たっているようで、必要なソケット情報（struct sock）にアクセスできないため、回避策として以下のポイントで情報を取得しています。

• function.returnプローブ

　カーネル関数sock_alloc()の戻りにプローブを掛けます。この関数はacceptしたコネクションとの通信を行うための情報を格納する構造体（struct socket）を作成し、戻り値とします。変数$returnを取得し、TIDをキーに持つ連想配列「sock_alloc_progress」に格納します。

• syscall.acceptプローブ

　sock_alloc_progresの、TIDをキーに持つエントリをゼロクリアします。

• syscall.accept.returnプローブ

　取得したソケット情報（struct socket）からネットワーク層に関する情報を保持する構造体メンバ（sk: struct sock）を取得し、そこからsrc側とdest側のIPアドレスとポート番号を出力します。「ip_ntop()」はIPアドレスを文字列表現に変換する関数、「tcpmib_local_port()」「tcpmib_remote_port()」はsrc側とdest側のポート番号を抽出する関数としてそれぞれ定義されていますが、「__ip_sock_saddr()」「__ip_sock_daddr()」はSystemTapの内部関数です。

　「tcpmib_local_addr()」などのSystemTap提供関数を使用すると、戻り値のIPアドレスの整数表現がホストバイトオーダーに変換されます。x86系CPUはリトルエンディアンなので、IPアドレスがホストバイトオーダーに変換されてしまうと、ip_ntop()で出力されるアドレスが「1.0.0.127」のように反転してしまいます。そのため、「tcp.recvmsg」プローブで使用されている、これらの内部関数を流用します。

　accept(2)の結果得られる、アプリケーション（今回の場合はHotSpot VM）が使用するFD番号は連想配列「fd_table」に格納します。連想配列のキー値には、コンソール出力を行うために生成した文字列（src側IPアドレス:ポート -> dest側IPアドレス:ポート）を使用します。

　クライアントからの接続をacceptした時刻を表示するのに、tz_ctime()を使用しています。これはタイムゾーンを意識した時刻の文字列化を行う関数です。

● 【3】socket.closeプローブ

　最後にソケットクローズの検知です。ソケットがクローズしたタイミングでacceptと同等の内容を出力します。

probe socket.close{
fd_index = sprintf("%s:%d -> %s:%d",
ip_ntop(ip_sock_saddr($sock->sk)), tcpmib_local_port($sock->sk),
ip_ntop(ip_sock_daddr($sock->sk)), tcpmib_remote_port($sock->sk));
fd = fd_table[fd_index];
if(fd == 0) next;
delete fd_table[fd_index];
printf("%s: close from \"%s\"(TID=%d): fd=%d, %s\n", tz_ctime(gettimeofday_s()),
thread_name_pool[tid()], tid(), fd, fd_index);
}

■ 実行例

　ケース4のスクリプト実行例を図4に示します。これは、Tomcatの8080番ポートに対してローカルからcurlコマンドでリクエストを発行したときと、別マシンからIEでアクセスした時を示しています。

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

　このソケット情報は「Tomcatから見たsrcとdest」となるため、src側がTomcat、dest側がクライアントを示しています。

ケース5：競合するモニターオブジェクトの把握

　本ケースでは、別のスレッドによって獲得されているモニターオブジェクトの待ち行列に入ったスレッドと、そのモニターを獲得するまでの待ち時間を取得します。マルチスレッドアプリケーションの動作が遅いとき、排他制御に疑いがあるときの確認に便利です。

■ 取得する項目

　競合状態のモニターオブジェクトの待ち行列に入ったとき、およびそれを獲得したタイミングで以下の情報を取得します。

• スレッド名
• TID
• モニターオブジェクトのクラス名
• モニターオブジェクトのID（ネイティブ仮想メモリアドレス）
• 待ち行列に入っていた時間（マイクロ秒：モニター獲得時のみ出力）

■ 使用するプローブ

• hotspot.thread_start
• hotspot.thread_stop

　Javaスレッド名とスレッドIDのマッピングを取るために使用します。取得方法に関してはケース4と同様です。プローブポイントの説明については表 を参照してください。

• hotspot.monitor_contended_enter
• hotspot.monitor_contended_entered

　競合状態のモニターオブジェクトに入った（待ち行列に入った）とき、および競合状態のモニターを獲得したとき（クリティカルセクションに入ったとき）に呼び出されるプローブです。JVMTIで用意されている、「MonitorContendedEnter」イベントおよび「MonitorContendedEntered」イベントと同じタイミングで呼び出されます。使用できるプローブを表6に示します。

表6　hotspot.monitor_contended_*で使用可能な変数

変数名	内容
name	固定値（「monitor_contended_enter」または「monitor_contended_entered」）
thread_id	java.lang.Thread#getId()で返される、スレッド識別子
id	モニターオブジェクトの仮想メモリ上のアドレス
class	モニターオブジェクトのクラス名
probestr	プローブ呼び出し時の概要の文字列表現

■ 実装のポイント

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

　今回のポイントは「monitor_contended_enter」が呼び出された瞬間を待ち行列に入った時間として、計測開始地点とし、monitor_contended_enteredで待ち時間を表示するところです。待ち行列に入った時間は連想配列「waited_time」に、スレッドIDをキーにマイクロ秒単位で保存します。

probe hotspot.monitor_contended_enter{
printf("monitor contended! thread: %s (TID=%d), monitor: %s (0x%x)\n",
thread_name_pool[thread_id], tid(), class, id);
waited_time[thread_id] = gettimeofday_us();
}
probe hotspot.monitor_contended_entered{
printf("monitor entered! thread: %s (TID=%d), monitor: %s (0x%x), wait: %dus\n",
thread_name_pool[thread_id], tid(), class, id,
gettimeofday_us() - waited_time[thread_id]);
delete waited_time[thread_id];
}

　monitor_contended_*ではTIDを取得できないため、連想配列「thread_name_pool」のキー値にはスレッドIDを使用し、TIDの表示には「tid()」を使用しています。

■ 実行例

　ケース5のスクリプト実行例を図5に示します。前編でも記載したように、モニター関連のプローブでは、ターゲットのjavaコマンドに対してもオプションを付加する必要があります。今回は「-XX:+DTraceMonitorProbes」を付加しています。

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

原因がアプリかプラットフォームか見極めるために

　今回は、Javaを用いたシステム開発やトラブルシューティングの過程で取得したくなりそうな情報を、OpenJDKとSystemTapの組み合わせで得る方法について具体的なスクリプトを交えながら説明しました。

　何か障害が発生したとき、OS側のエンジニアからは「アプリケーションが悪い」といわれ、アプリケーション側のエンジニアからは「プラットフォームが悪い」といわれ、問題を解決するためにどこから手をつければいいのか検討がつかなくなってしまうケースがあると思います。そのようなときにOpenJDKとSystemTapを組み合わせて使用することで、OSからJavaVM、アプリケーションレイヤに至るまで包括的に見ることで、各レイヤに特化したデバッグでは見えなかった原因が見えてくることがあります。

　本特集は「上（アプリケーション）からがダメなら下（OS）から手を出してみよう」をテーマに執筆してきました。これをきっかけに、1人でも多くのJavaプログラマが低いレイヤにも興味をもっていただければ幸いです。

「Java on Linuxを鬼凄ネイティブデバッグ！」バックナンバー

• OpenJDK/SystemTapのデバッグが有効な5つの事例
• OpenJDK＋SystemTapでトラブル解析はここまでできる！