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

» 2011年11月10日 00時00分 公開
[末永恭正，NTT OSSセンタ]

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などを送出し、ネイティブレベルのメインスレッドを動作させる必要があります。

・※1 プローブポイントが登録されるタイミング
SystemTapのソースコードには「uprobes.txt」というテキストファイルが含まれており、そこにuprobesについての説明が記載されています。プローブポイントの登録や削除のタイミングに関しては「1. Concepts: Uprobes, Return Probes」に、一例として以下の記載があります

You can establish Utrace callbacks to register and/or unregister probes when aparticular process forks, clones a thread, execs, enters a system call, receives a signal,exits, etc.


上記中の「Utrace」とは、uprobesが使用する、Linuxカーネルのユーザープロセストレース機能です。utraceとuprobesのかかわりについては「1.2 The Role of Utrace」をご覧ください

・※2 マルチスレッドアプリケーションでの既知の問題
SystemTapのBugzillaには、マルチスレッドアプリケーションにアタッチできない問題として、上記のバグが登録されています。この登録者はアプリケーションにGDBをアタッチする（SIGTRAPをトラップさせる）ことで本事象のワークアラウンドとしているようです。しかし、uprobes.txtの「4.4 User's Callback for Delayed Registrations」には以下の内容が仕様として記述されているため、バグとはいいづらい状況です

the [un]registration operation is delayed until all handlers associated with that handler's probepoint have been run.


■ あらかじめ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発生前後での値の推移をそのまま比較できます。

表1　hotspot.mem_pool_gc_*で使用可能な変数
変数名 内容
name 固定値（「mem_pool_gc_begin」または「mem_pool_gc_end」）
manager メモリマネージャ名（「Copy」「ConcurrentMarkSweep」など、オブジェクト回収を行う機構名）
pool 対象のメモリプール名
initial 初期サイズ
used 使用量
committed その時点での使用可能量
max 最大使用可能量
probestr プローブ呼び出し時の概要の文字列表現

コラム　hotspot.gc_begin／hotspot.gc_endプローブの問題点

OpenJDKで利用可能なプローブであるhotspot.gc_beginとhotspot.gc_endでフックできるポイントのほとんどは、JVMTIの「GarbageCollectionStart」「GarbageCollectionFinish」イベントと同一です（今回調査対象としたOpenJDKでは、例外としてG1GCの一部はJVMTIでのみフック可能です）。

JVMTIの仕様によると、イベントの発生条件は「すべてのスレッドが処理を停止する（Stop-The-World: STW）コレクションだけがレポートされる」とあります。

この「STWになるGC」というのが難点で、CMSをはじめとした一部の「STWに（極力）ならないGC」ではGCの開始と終了をフックできません。これはJVMTIだけではなく、同じ個所でフックを掛けるSystemTapの静的プローブポイントにも通じます。

上記の理由および、「hotspot.gc_*」を使用しても、そのままでは各メモリプールの使用量を簡単に取得できないことから、本ケースではhotspot.mem_pool_gc_*を用いることにしています。


コラム　hotspot.mem_pool_gc_*が呼び出されるタイミング

HotSpot VMはC++で記述されており、hotspot.mem_pool_gc_*プローブはTraceMemoryManagerStatsクラスのコンストラクタ・デストラクタを経由して、それぞれ呼び出されます。TraceMemoryManagerStatsおよび、その派生クラスは各種GC発生時に、GC発生回数やGC処理時間などを収集する目的で使用されます。


■ 実装のポイント

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

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

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

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

表2　ケース1で使用するグローバル変数
変数名 目的
BeforeUsage GC前の各領域（Eden／Survivor／Old／Permanent）の使用量
AfterUsage GC後の各領域（Eden／Survivor／Old／Permanent）の使用量
GCStartTime GC開始時間をUNIXエポックからのマイクロ秒で記録
MemPoolFlags 使用量を記録したメモリプールを表すフラグ

コラム　各種連想配列でメモリマネージャをキーに持つ理由

CMSのようなコンカレントGCの場合、メジャーコレクションが実行されている最中にマイナーコレクションが開始することがあります。この場合も、mem_pool_gc_*はそれぞれのGCで呼び出されることになるため、今回のケースでは各種GCを個別に把握するためにメモリマネージャ名をキーにもつ連想配列でデータを保持します。


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

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

コラム　メモリプールの名前

メモリプールで使用される名前はHotSpot VMのソースコード内で定義されています。VMは初期化時に「hotspot/src/share/vm/services/memoryService.cpp」の中の、「MemoryService::add__memory_pool()」という関数を呼び出します。呼び出される関数は使用するGCアルゴリズムに応じたものが選択され、それらの中で適切なプール名が与えられます。プール名に、どのような文字列が割り当てられるのか確認したい場合は、memoryService.cppの中を覗いてみてください。

「Garbage-First GC（-XX:+UseG1GC）」で使用するメモリプールは例外で、「hotspot/src/share/vm/services/g1MemoryPool.cpp」に初期化コードが入っています。G1GCを使用する際はこちらのソースコードを参照してください。


● 【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のスクリプト実行例 図1　ケース1のスクリプト実行例

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

　　　　　　 1|2|3 次のページへ

Copyright © ITmedia, Inc. All Rights Reserved.

スポンサーからのお知らせPR

注目のテーマ

Microsoft ＆ Windows最前線2025
AI for エンジニアリング
ローコード／ノーコード セントラル by ＠IT - ITエンジニアがビジネスの中心で活躍する組織へ
Cloud Native Central by ＠IT - スケーラブルな能力を組織に
システム開発ノウハウ 【発注ナビ】PR
あなたにおすすめの記事PR

@ITについて

RSSについて

アイティメディアIDについて

メールマガジン登録

＠ITのメールマガジンは、 もちろん、すべて無料です。ぜひメールマガジンをご購読ください。