X

Oracle Solaris, Oarcle ハードウェア製品に関する情報

  • Sun
    February 23, 2010

DTrace で Java のアプリケーションを解析する

Guest Author


はじめに

本記事では DTrace で Java のプログラムを調査する方法をご紹介します。DTrace は Java の HotSpot VM に対応しており、HotSpot VM も DTrace に対応しています。DTrace と HotSpot VM 両方の機能を使う事で Java のプログラムも C や C++ で書かれたプログラムと同様の手順で解析する事が可能です。


jstack() アクション

まずは DTrace の Java 対応機能からご紹介します。DTrace には jstack() と言う Java 専用のアクションが用意されています。jstack() アクションはアプリケーションのスタックをダンプしたい時に使用します。同じ様にアプリケーションのスタックをダンプする ustack() というアクションもありますが jstack() は Java のメソッドのアドレスをメソッド名に変換する機能が付いています。その為、Java のプログラムを解析する場合は ustack() アクションの代わりに jstack() アクションを使用します。

リスト 1. は jstack() アクションの使用例です。少し長いですが、"# dtrace -x jstackstrsize=2048 -qn 'syscall::lwp_cond_wait:entry { @agg[jstack(10)] = count()} END{trunc(@agg, 3)}' -c 'java -jar dacapo-9.12-bach.jar h2' | ../dem/dem'" というコマンドを実行しています。全体としては、 Java のプログラムでロックが発生したらスタックをダンプしてロックの発生源を探るという処理を行っています。

まず jstackstrsize=2048 で jstack() アクションで格納する文字列の最大長を 2048bytes に設定しています。syscall::lwp_cond_wait:entry' の部分は lwp_cond_wait システムコールが呼び出されたら DTrace のスクリプトを実行する事を示しています。続く '{}' の中に実行する処理が記述されています。ここでは、まず @agg[] という集積体を作成しています。@agg[] のキーは jstack() アクションの呼び出しになっており、jstack() アクションの引数は 10 です。これはスタックフレームを 10 段分出力するという意味です。@agg[] の集積関数は count() です。count() は同じキーが何回発生したかをキー毎に集計する関数です。つまり、この @agg[] 集積体はスタックダンプの文字列をキーとし、スタックダンプの中身が同じだった回数を数え上げています。"END{trunc(@agg, 3)}" の部分はプログラム終了時に実行されます。trunc(@agg,3) は上位 3 エントリを残して集積体の中の情報を削除します。最後に -c オプションで DTrace スクリプトで解析する対象のプログラムを渡しています。今回は Java のサンプルプログラムとして DaCapo Benchmark を使用しました。"'java -jar dacapo-9.12-bach.jar h2'" の部分が DaCapo Benchmark の実行部分です。"../dem/dem" の部分は C++ のシンボル名を見易くする為のフィルタです。dem コマンドのソースはこの記事の一番最後に掲載してあります。

実行結果は "===== DaCapo 9.12 h2 PASSED in 7209 msec =====" まではアプリケーションの出力で、その下の行からが DTrace の出力です。まずスタックダンプが最大 10 行分とその発生回数が表示され、空白行を開けて次のスタックダンプと発生回数、更に空白行を開けてスタックダンプとその回数が表示されています。つまり、スタックダンプの中身とその発生回数が空白行区切りで三個表示さていることになります。一つ目のスタックダンプのスタックトップは libc.so.1`___lwp_cond_wait+0x15 となっており、これは lwp_cond_wait の呼び出しです。その下の libjvm.so で始まる行は Java VM のルーチンが積んだスタックです。9,10 行目の "org/h2" で始まる 2 行が Java のメソッド呼び出しです。"org/h2/command" は "org.h2.command" パッケージでしょうか。この様に C, C++, Java が入り乱れていて多少見辛いですが、"JdbcPreparedStatement.executeQuery()" という文字から、プリペアドステートメントの実行で条件変数待ちが発生している事が読み取れると思います。

 \*\*\* リスト 1. jstack() アクションの使用例 \*\*\*
# dtrace -x jstackstrsize=2048 -qn 'syscall::lwp_cond_wait:entry
{ @agg[jstack(10)] = count()} END{trunc(@agg, 3)}' \\
-c 'java -jar dacapo-9.12-bach.jar h2' | ../dem/dem
Using scaled threading model. 16 processors detected, 16 threads used to drive the workload, in a possible range of [1,4000]
===== DaCapo 9.12 h2 starting =====
....
Completed 4000 transactions
Stock level ............. 155 ( 3.9%)
Order status by name .... 108 ( 2.7%)
Order status by ID ...... 65 ( 1.6%)
Payment by name ......... 1050 (26.2%)
Payment by ID ........... 661 (16.5%)
Delivery schedule ....... 167 ( 4.2%)
New order ............... 1774 (44.4%)
New order rollback ...... 20 ( 0.5%)
Resetting database to initial state
===== DaCapo 9.12 h2 PASSED in 7209 msec ===== <-- ここまで DaCapo Benchmark の出力

libc.so.1`___lwp_cond_wait+0x15 <-- スタックトップ
libjvm.so`void os::PlatformEvent::park()+0xa9
libjvm.so`void ObjectMonitor::EnterI(Thread\*)+0x1d2
libjvm.so`void ObjectMonitor::enter(Thread\*)+0x2a2
libjvm.so`void ObjectSynchronizer::slow_enter(Handle,BasicLock\*,Thread\*)+0x106
libjvm.so`void ObjectSynchronizer::fast_enter(Handle,BasicLock\*,bool,Thread\*)+0x6c
libjvm.so`void InterpreterRuntime::monitorenter(JavaThread\*,BasicObjectLock\*)+0x19e
<couldn't find start>
org/h2/command/Command.executeQuery(IZ)Lorg/h2/result/ResultInterface;
org/h2/jdbc/JdbcPreparedStatement.executeQuery()Ljava/sql/ResultSet; <-- プリペアドステートメントの実行?
2262 <-- これが count() で集計された回数
libc.so.1`___lwp_cond_wait+0x15
libjvm.so`void os::PlatformEvent::park()+0xa9
libjvm.so`void ObjectMonitor::EnterI(Thread\*)+0x1d2
libjvm.so`void ObjectMonitor::enter(Thread\*)+0x2a2
libjvm.so`void ObjectSynchronizer::slow_enter(Handle,BasicLock\*,Thread\*)+0x106
libjvm.so`void ObjectSynchronizer::fast_enter(Handle,BasicLock\*,bool,Thread\*)+0x6c
libjvm.so`void SharedRuntime::complete_monitor_locking_C(oopDesc\*,BasicLock\*,JavaThread\*)+0x19b
_complete_monitor_locking_Java
5083
libc.so.1`___lwp_cond_wait+0x15
libjvm.so`void os::PlatformEvent::park()+0xa9
libjvm.so`void ObjectMonitor::EnterI(Thread\*)+0x1d2
libjvm.so`void ObjectMonitor::enter(Thread\*)+0x2a2
libjvm.so`void ObjectSynchronizer::slow_enter(Handle,BasicLock\*,Thread\*)+0x106
libjvm.so`void ObjectSynchronizer::fast_enter(Handle,BasicLock\*,bool,Thread\*)+0x6c
libjvm.so`void SharedRuntime::complete_monitor_locking_C(oopDesc\*,BasicLock\*,JavaThread\*)+0x19b
_complete_monitor_locking_Java
6557

先ほどの例で、もし jstack() が使えなかったらどうなるかもご覧頂きましょう。二つ目のスタックダンプでは Java のメソッド呼び出しが解析されずにアドレスだけが表示されています。これは Solaris のコマンドで言うと jstack コマンドの代わりに pstack コマンドを使用した場合と同じ様な状況です。これでは Java のプログラムとして解析する事は出来ません。Java のプログラムを解析する場合は jstack() アクションを使用してください。

 \*\*\* リスト 2. jstack() の代わりに ustack() を使用すると... \*\*\*
# dtrace -x jstackstrsize=2048 -qn 'syscall::lwp_cond_wait:entry
{ @agg[ustack(10)] = count()} END{trunc(@agg, 3)}'
-c 'java -jar dacapo-9.12-bach.jar h2' | ../dem/dem
Using scaled threading model. 16 processors detected, 16 threads used to drive
the workload, in a possible range of [1,4000]
===== DaCapo 9.12 h2 starting =====
....
Completed 4000 transactions
Stock level ............. 155 ( 3.9%)
Order status by name .... 108 ( 2.7%)
Order status by ID ...... 65 ( 1.6%)
Payment by name ......... 1050 (26.2%)
Payment by ID ........... 661 (16.5%)
Delivery schedule ....... 167 ( 4.2%)
New order ............... 1774 (44.4%)
New order rollback ...... 20 ( 0.5%)
Resetting database to initial state
===== DaCapo 9.12 h2 PASSED in 7287 msec =====

libc.so.1`___lwp_cond_wait+0x15
libjvm.so`void os::PlatformEvent::park()+0xa9
libjvm.so`int ParkCommon(ParkEvent\*,long long)+0x56
libjvm.so`int Monitor::IWait(Thread\*,long long)+0x9d
libjvm.so`bool Monitor::wait(bool,long,bool)+0x7a
libjvm.so`GCTask\*GCTaskManager::get_task(unsigned)+0x67
libjvm.so`void GCTaskThread::run()+0x154
libjvm.so`java_start+0xf9
libc.so.1`_thrp_setup+0x9b
libc.so.1`_lwp_start
2302
libc.so.1`___lwp_cond_wait+0x15
libjvm.so`void os::PlatformEvent::park()+0xa9
libjvm.so`void ObjectMonitor::EnterI(Thread\*)+0x1d2
libjvm.so`void ObjectMonitor::enter(Thread\*)+0x2a2
libjvm.so`void ObjectSynchronizer::slow_enter(Handle,BasicLock\*,Thread\*)+0x106
libjvm.so`void ObjectSynchronizer::fast_enter(Handle,BasicLock\*,bool,Thread\*)+0x6c
libjvm.so`void InterpreterRuntime::monitorenter(JavaThread\*,BasicObjectLock\*)+0x19e
0xfb012b73 <-- これは何らかの Java のメソッドの呼び出し
0xfb002f27 <-- これは何らかの Java のメソッドの呼び出し
0xfb003403 <-- これは何らかの Java のメソッドの呼び出し
3533
libc.so.1`___lwp_cond_wait+0x15
libjvm.so`void os::PlatformEvent::park()+0xa9
libjvm.so`void ObjectMonitor::EnterI(Thread\*)+0x1d2
libjvm.so`void ObjectMonitor::enter(Thread\*)+0x2a2
libjvm.so`void ObjectSynchronizer::slow_enter(Handle,BasicLock\*,Thread\*)+0x106
libjvm.so`void ObjectSynchronizer::fast_enter(Handle,BasicLock\*,bool,Thread\*)+0x6c
libjvm.so`void SharedRuntime::complete_monitor_locking_C(oopDesc\*,BasicLock\*,JavaThread\*)+0x19b
0xfb04fc49 <-- これも何らかの Java のメソッドの呼び出し
14112


HotSpot プロバイダと HotSpot_JNI プロバイダ

続いて Java VM の側に実装されている DTrace 対応機能を見て頂きます。Java HotSpot VM には HotSpot プロバイダと HotSpot_JNI プロバイダの2 種類が組み込まれています。HotSpot プロバイダは Java VM の動きを解析する為のプロバイダで、HotSpot_JNI プロバイダは Java Native Interface に関するプロバイダです。この記事では HotSpot プロバイダの方を見て行きたいと思います。

HotSpot 用のプローブは全部で 500 個程用意されています。

 \*\*\* リスト 3. HotSpot VM に含まれるプローブの数 \*\*\*
# dtrace -ln 'hotspot\*:::' | wc -l
500

その内の大半は HotSpot_JNI プロバイダのプローブで、JNI に関連した調査に使用します。

 \*\*\* リスト 4. HotSpot_JNI プロバイダのプローブの数 \*\*\*
# dtrace -ln 'hotspot_jni\*:::' | wc -l
474

JNI を除いたプローブは 30 個弱あります。

 \*\*\* リスト 5. HotSpot プロバイダのプローブの数 \*\*\*
# dtrace -ln 'hotspot\*:::' | grep -v hotspot_jni | wc -l
27

HotSpot プロバイダには、クラスがロードされた時に発動するプローブやメソッドが呼び出された時に発動するプローブ、GC が開始した時に発動するプローブ、Java のオブジェクトがアロケートされた時に発動するプローブ、スレッドが起動した時に発動するプローブ等、Java のプログラムの解析に便利なプローブが沢山揃っています。リスト 6. は HotSpot プロバイダのプローブの一覧です。それぞれのプローブの機能はプローブ名を見て頂ければ直ぐ予想がつく様になっています。monitor-\* はスレッドの排他処理に関するプローブです。

 \*\*\* リスト 6. HotSpot プロバイダのプローブの一覧 \*\*\*
# dtrace -ln 'hotspot\*:::' | grep -v hotspot_jni | awk '{print $5}'
NAME
class-loaded
class-unloaded
compiled-method-load
compiled-method-unload
compiled-method-unload
gc-begin
gc-end
mem-pool-gc-begin
mem-pool-gc-end
method-compile-begin
method-compile-end
method-entry
method-return
monitor-contended-enter
monitor-contended-entered
monitor-contended-exit
monitor-notify
monitor-notifyAll
monitor-wait
monitor-waited
object-alloc
thread-start
thread-stop
vm-init-begin
vm-init-end
vm-shutdown


HotSpot プロバイダのサンプルスクリプト

今ご覧頂いた一覧の中にあるプローブを直に使って DTrace のスクリプトを書く事も可能ですが、幾つかサンプルスクリプトが用意されているのでそれらを見てみましょう。サンプルスクリプトは JDK をダウンロードして展開すると jdk/instances/jdk1.6.0/sample/dtrace/ に入っています。OpenSolaris では /usr/java/sample/dtrace/hotspot/ にインストールされています。簡単に試す事が出来ますので、是非実行してみてください。

 \*\*\* リスト 7. HotSpot プロバイダのサンプルスクリプトの一覧 \*\*\*
# ls jdk/instances/jdk1.6.0/sample/dtrace/hotspot
README.txt method_invocation_stat.d
class_loading_stat.d method_invocation_stat_filter.d
gc_time_stat.d method_invocation_tree.d
hotspot_calls_tree.d monitors.d
method_compile_stat.d object_allocation_stat.d


各スクリプトの説明


  • class_loading_stat.d はロードされたクラス数とアンロードされたクラス数をクラス毎に出力するスクリプトです。デフォルトでは 10 秒毎に出力を行います。このスクリプトは HotSpot プロバイダの hotspot:::class-loaded と hotspot:::class-unloaded プローブを利用しています。

  • gc_time_stad.d は一定時間毎にガベージコレクションに掛かった時間を出力するスクリプトです。出力はヒープ内のエリア毎に行われます。デフォルトでは 10 秒間隔で出力されますが、出力間隔を指定する事も可能です。このスクリプトは HotSpot プロバイダの hotspot:::gc-begin と hotspot:::gc-end, hotspot:::mem-pool-gc-begin, hotspot:::mem-pool-gc-end の各プローブを利用しています。

  • hotspot_calls_tree.d は class-loaded, class-unloaded, compiled-method-load, compiled-method-unload, monitor-notify, monitor-notifyAll, vm-init-begin, vm-init-end, gc-begin, gc-end, mem-pool-gc-begin, mem-pool-gc-end, thread-start, thread-stop, method-compile-begin, method-compile-end, monitor-contended-enter, monitor-contended-exit, monitor-wait, monitor-waited の各プローブの発生をトレースして、それをコールフローとして表示します。hotspot_calls_tree.d を実行する際は JavaVM に ExtendedDTraceProbes フラグを設定する必要があります。ExtendedDTraceProbes フラグについては後ほど改めて取り上げます。

  • method_compile_stat.d はコンパイルされたメソッドのリストをコンパイルに掛かった時間でソートして出力します。デフォルトでは 60 秒毎に、最もコンパイルに時間が掛かったメソッドのトップ 25 と、最もコンパイルに時間が掛からなかったメソッドのトップ 25 を表示します。このスクリプトは method-compile-begin, method-compile-end, compiled-method-load, compiled-method-unload プローブを利用しています。

  • method_invocation_stat.d は Java の実行時に呼び出されたシステムコール、JNI のイベント、Java のメソッド、クラス、パッケージを、呼び出された回数でソートして出力します。HotSpot プロバイダの method-entry プローブ、HotSpot_JNI プロバイダのプローブからプローブ名が -entry で終わる物を利用しています。method_invocation_stat.d を実行する際は JavaVM に ExtendedDTraceProbes フラグを設定する必要があります。

  • method_invocation_stat_filter.d は Java のメソッド呼び出しをメソッド毎にカウントするスクリプトです。特定のパッケージ、クラス、メソッドのみを集計する事が出来ます。method_invocation_stat_filter.d は method-entry プローブを利用しています。method_invocation_stat_filter.d を実行する際は JavaVM に ExtendedDTraceProbes フラグを設定する必要があります。

  • method_invocation_tree.d は Java のメソッドのコールフローを出力します。このスクリプトは HotSpot プロバイダの method-entry, method-return プローブを主に使用しています。method_invocation_tree.d を実行する際は JavaVM に +ExtendedDTraceProbes フラグを設定する必要があります。

  • monitors.d はスレッドの開始と終了、モニターへの侵入をトレースします。このスクリプトは HotSpot プロバイダの thread-start, thread-stop, monitor-contended-enter, monitor-contended-entered プローブを利用しています。monitors.d を実行する際は JavaVM に +ExtendedDTraceProbes フラグを設定する必要があります。

  • object_allocation_stat.d は Java のオブジェクトのアロケーションをトレースします。デフォルトでは 60 秒毎に、アロケーションされた総バイト数が最も多かったオブジェクトのトップ 25 とアロケーションされた回数が最も多かったオブジェクトのトップ 25 を出力します。object_allocation_stat.d を実行する際は JavaVM に +ExtendedDTraceProbes フラグを設定する必要があります。


スクリプトの実行例

以下は method_invocation_stat_filter.d を実行した結果です。解析対象の Java のプログラムは先ほどと同じ DaCapo Benchmark です。引数でフィルターを指定し、org.h2.engine.Database クラスだけを調査する様にしています。解析結果は isReconnectNeeded() メソッドが 8878365 回で、一番多く呼び出されている事が分かります。

 \*\*\* リスト 8. method_compile_stat.d の実行例 \*\*\*
# /usr/java/sample/dtrace/hotspot/method_invocation_stat_filter.d \\
-c 'java -server -XX:+ExtendedDTraceProbes -jar ./dacapo-9.12-bach.jar h2 -s small' \\
'"c"' '"org/h2/engine/Database"'
BEGIN hotspot method invocation tracing
Using scaled threading model. 16 processors detected, 16 threads used to drive the workload, in a possible range of [1,400]
===== DaCapo 9.12 h2 starting =====
Completed 400 transactions
Stock level ............. 12 ( 3.0%)
Order status by name .... 11 ( 2.8%)
Order status by ID ...... 5 ( 1.3%)
Payment by name ......... 107 (26.8%)
Payment by ID ........... 64 (16.0%)
Delivery schedule ....... 18 ( 4.5%)
New order ............... 179 (44.8%)
New order rollback ...... 4 ( 1.0%)
Resetting database to initial state
===== DaCapo 9.12 h2 PASSED in 794614 msec =====
Top packages calls:
11777555 org/h2/engine
Top class calls:
11777555 org/h2/engine/Database
Top method calls:
1 org/h2/engine/Database:<init>:(Ljava/lang/String;Lorg/h2/engine/ConnectionInfo;Ljava/lang/String;)V
1 org/h2/engine/Database:closeFiles:()V
1 org/h2/engine/Database:closeOpenFilesAndUnlock:(Z)V
1 org/h2/engine/Database:getAllUsers:()Lorg/h2/util/ObjectArray;
1 org/h2/engine/Database:isClosing:()Z
1 org/h2/engine/Database:isMultiThreaded:()Z
1 org/h2/engine/Database:open:(II)V
1 org/h2/engine/Database:openDatabase:(IIZ)V
1 org/h2/engine/Database:opened:()V
1 org/h2/engine/Database:parseDatabaseShortName:()Ljava/lang/String;
1 org/h2/engine/Database:recompileInvalidViews:(Lorg/h2/engine/Session;)V
1 org/h2/engine/Database:reconnectModified:(Z)Z
1 org/h2/engine/Database:removeUnusedStorages:(Lorg/h2/engine/Session;)V
1 org/h2/engine/Database:setMasterUser:(Lorg/h2/engine/User;)V
1 org/h2/engine/Database:stopServer:()V
1 org/h2/engine/Database:stopWriter:()V
2 org/h2/engine/Database:close:(Z)V
2 org/h2/engine/Database:getAllSchemaObjects:(I)Lorg/h2/util/ObjectArray;
2 org/h2/engine/Database:getOptimizeReuseResults:()Z
3 org/h2/engine/Database:getAllTablesAndViews:()Lorg/h2/util/ObjectArray;
6 org/h2/engine/Database:addDefaultSetting:(Lorg/h2/engine/Session;ILjava/lang/String;I)V
8 org/h2/engine/Database:addDatabaseObject:(Lorg/h2/engine/Session;Lorg/h2/engine/DbObject;)V
8 org/h2/engine/Database:getMap:(I)Ljava/util/HashMap;
16 org/h2/engine/Database:checkMetaFree:(Lorg/h2/engine/Session;I)V
16 org/h2/engine/Database:findUser:(Ljava/lang/String;)Lorg/h2/engine/User;
16 org/h2/engine/Database:removeMeta:(Lorg/h2/engine/Session;I)V
16 org/h2/engine/Database:update:(Lorg/h2/engine/Session;Lorg/h2/engine/DbObject;)V
16 org/h2/engine/Database:validateFilePasswordHash:(Ljava/lang/String;[B)Z
17 org/h2/engine/Database:createSession:(Lorg/h2/engine/User;)Lorg/h2/engine/Session;
18 org/h2/engine/Database:removeSession:(Lorg/h2/engine/Session;)V
19 org/h2/engine/Database:getNextModificationMetaId:()J
28 org/h2/engine/Database:addMetaData:(I)V
51 org/h2/engine/Database:addSchemaObject:(Lorg/h2/engine/Session;Lorg/h2/schema/SchemaObject;)V
58 org/h2/engine/Database:allocateObjectId:(ZZ)I
75 org/h2/engine/Database:addMeta:(Lorg/h2/engine/Session;Lorg/h2/engine/DbObject;)V
92 org/h2/engine/Database:setLockMode:(I)V
122 org/h2/engine/Database:findSetting:(Ljava/lang/String;)Lorg/h2/engine/Setting;
139 org/h2/engine/Database:exceptionThrown:(Ljava/sql/SQLException;Ljava/lang/String;)V
141 org/h2/engine/Database:findUserDataType:(Ljava/lang/String;)Lorg/h2/engine/UserDataType;
141 org/h2/engine/Database:getIgnoreCase:()Z
325 org/h2/engine/Database:getAllowLiterals:()I
530 org/h2/engine/Database:getSchema:(Ljava/lang/String;)Lorg/h2/schema/Schema;
571 org/h2/engine/Database:compareTypeSave:(Lorg/h2/value/Value;Lorg/h2/value/Value;)I
634 org/h2/engine/Database:findSchema:(Ljava/lang/String;)Lorg/h2/schema/Schema;
1132 org/h2/engine/Database:compare:(Lorg/h2/value/Value;Lorg/h2/value/Value;)I
2737 org/h2/engine/Database:getSessionCount:()I
140531 org/h2/engine/Database:checkWritingAllowed:()V
142095 org/h2/engine/Database:beforeWriting:()Z
143800 org/h2/engine/Database:getNextModificationDataId:()J
146273 org/h2/engine/Database:getModificationMetaId:()J
147141 org/h2/engine/Database:afterWriting:()V
148024 org/h2/engine/Database:checkPowerOff:()V
153730 org/h2/engine/Database:getTrace:(Ljava/lang/String;)Lorg/h2/message/Trace;
238987 org/h2/engine/Database:getModificationDataId:()J
259850 org/h2/engine/Database:setProgress:(ILjava/lang/String;II)V
1371802 org/h2/engine/Database:areEqual:(Lorg/h2/value/Value;Lorg/h2/value/Value;)Z
8878365 org/h2/engine/Database:isReconnectNeeded:()Z
=======================================
JAVA_CALLS: 11777515
Run time: 3415371293436

END of hotspot method invocation tracing


HotSpot プロバイダを使用する際の注意点

次に HotSpot プロバイダを使用する際の注意点を解説します。注意する必要があるのは Java VM の ExtendedDTraceProbes フラグ、DTrace のゼロ・プローブ・エラー、特定のプローブでの argN 変数の扱い方の 3 つです。


ExtendedDTraceProbes フラグ

ExtendedDTraceProbes フラグは Java VM のオプションです。HotSpot プロバイダのプローブの内、オーバーヘッドが大きく、アプリケーションの実行に影響する物を使用する際にこのフラグを有効にする必要があります。ExtendedDTraceProbes フラグが必要なプローブは monitor-\* プローブ、method-entry, method-return, object-alloc プローブです。デフォルトはこのフラグは有効になっていません。ExtendedDTraceProbes フラグの設定方法は二種類あります。一つは Java VM の起動時に設定する方法、もう一つは jinfo コマンドを使用する方法です。

ExtendedDTraceProbes フラグは Java VM の起動時に設定する事が出来ます。

 \*\*\* リスト 9. ExtendedDTraceProbes フラグを付けて Java VM を起動する \*\*\*
# java -XX:+ExtendedDTraceProbes [ other options ]

既に起動している Java VM に大しては jinfo コマンドを使用して、'jinfo -flag +ExtendedDTraceProbes <PID>' の様にフラグを設定する事が可能です。

 \*\*\* リスト 10. jinfo コマンドで ExtendedDTraceProbes フラグを設定する \*\*\*
# /usr/java/bin/jps
760 Bootstrap
2290 Jps
2289 jar
# /usr/java/bin/jinfo -flag ExtendedDTraceProbes 2289
-XX:-ExtendedDTraceProbes <-- デフォルトではフラグは設定されていません
# /usr/java/bin/jinfo -flag +ExtendedDTraceProbes 2289
# /usr/java/bin/jinfo -flag ExtendedDTraceProbes 2289
-XX:+ExtendedDTraceProbes <-- フラグが設定されました
# /usr/java/bin/jinfo -flag -ExtendedDTraceProbes 2289
# /usr/java/bin/jinfo -flag ExtendedDTraceProbes 2289
-XX:-ExtendedDTraceProbes <-- フラグが無効になりました


ゼロ・プローブ・エラー

DTrace では dtrace コマンドの -c オプションで実行するコマンドを指定して解析を行う事が良くあります。しかし Java のアプリケーションを引数にして実行を開始しようとするとエラーが発生する場合があります。これは DTrace が実行を開始した時点では Java VM は完全に起動しておらず、HotSpot プロバイダのプローブが一つも用意されていない事に起因します。これを回避する為 dtrace コマンドには -Z オプションが用意されています。-Z オプションはスクリプト開始時にマッチするプローブの数がゼロでもエラーにせず、トレースを開始するという意味のオプションです。リスト 11. は -Z オプションを付けていなかった為にエラーが発生する例です。

 \*\*\* リスト 11. ゼロ・プローブ・エラー \*\*\*
# dtrace -n 'hostpot$target:::class-loaded' -c 'java -jar dacapo-9.12-bach.jar h2'
dtrace: invalid probe specifier hostpot$target:::class-loaded: probe
description hostpot2247:::class-loaded does not match any probes

dtrace コマンドに -Z オプションを付ければエラーは回避出来ます。Java のプログラムを引数にして dtrace コマンドを実行する場合は -Z オプションを忘れない様にしてください。

 \*\*\* リスト 12. -Z オプションでゼロ・プローブ・エラーを回避 \*\*\*
# dtrace -Zn 'hostpot$target:::class-loaded' -c 'java -jar dacapo-9.12-bach.jar h2'
dtrace: description 'hostpot$target:::class-loaded' matched 0 probes
...


method-entry プローブを使用する場合の注意点

method-entry プローブを使用したスクリプトを素直に書くと出力が混じってしまい、解析が出来ません。

 \*\*\* リスト 13. DTrace の出力にゴミが混じってしまう例 \*\*\*
# dtrace -b 256m -Zqn 'hotspot$target:::method-entry
{ @agg[stringof(copyin(arg1, arg2)), stringof(copyin(arg3, arg4))] = count() }
tick-1sec { trunc(@agg, 3); printa(@agg); trunc(@agg) }'
-c 'java -XX:+ExtendedDTraceProbes -jar dacapo-9.12-bach.jar h2'
...
org/h2/expression/ParameterckParcheckSetetaIdquiredntInternal26_50g
checkSetetaIdquiredntInternal26_50g 4354
org/h2/util/ObjectArrayeterckParcheckSetetaIdquiredntInternal26_50g
getckParcheckSetetaIdquiredntInternal26_50g 4354
sun/misc/Unsaferrent/atomic/AtomicLong/OcompareAndSetmIntring24_50g
compareAndSwapLongLong/OcompareAndSetmIntring24_50g 6208
org/h2/expression/ParameterckParcheckSetetaIdquiredntInternal26_50gbleWarehouse
checkSetetaIdquiredntInternal26_50gbleWarehouse 3808
org/h2/util/ObjectArrayeterckParcheckSetetaIdquiredntInternal26_50gbleWarehouse
getckParcheckSetetaIdquiredntInternal26_50gbleWarehouse 3808
sun/misc/Unsaferrent/atomic/AtomicLong/OcompareAndSetmIntring24_50gbleWarehouse
compareAndSwapLongLong/OcompareAndSetmIntring24_50gbleWarehouse 5442
org/h2/expression/ParameterckParcheckSetetaIdquiredntInternal26_50g
checkSetetaIdquiredntInternal26_50g 3864
org/h2/util/ObjectArrayeterckParcheckSetetaIdquiredntInternal26_50g
getckParcheckSetetaIdquiredntInternal26_50g 3864
sun/misc/Unsaferrent/atomic/AtomicLong/OcompareAndSetmIntring24_50g
compareAndSwapLongLong/OcompareAndSetmIntring24_50g 5518

この問題を回避する為に stringof() で文字列に変換する前に、手動で文字の配列を作成します。具体的には以下の様なスクリプトを作成します。ここでは arg1, arg3 変数を copyin() したデータをそのまま stringof() に渡さず、先に (char \*) にキャストし、文字列の終端に自分でヌル文字を入れています。ひと手間掛かりますが、これで問題は解決出来ます。

 \*\*\* リスト 14. method-entry プローブを使用する際の回避策 \*\*\*
# cat mentry.d
#!/usr/sbin/dtrace -Zqs
hotspot$target:::method-entry
{
self->class = (char \*) copyin(arg1, arg2 + 1);
self->class[arg2] = '\\0';
self->method = (char \*) copyin(arg3, arg4 + 1);
self->method[arg4] = '\\0';
@agg[stringof(self->class), stringof(self->method)] = count()
}
tick-1sec
{
trunc(@agg, 3);
printa("%@d\\t\\t%s . %s\\n", @agg);
printf("\\n");
clear(@agg)
}

回避策を組み込んだ場合の出力結果は以下の通り、文字は重なり合っていません。これで解析を行う事が可能になりました。

 \*\*\* リスト 15. 回避策を講じた場合の出力例 \*\*\*
# ./mentry.d -c 'java -XX:+ExtendedDTraceProbes -jar dacapo-9.12-bach.jar h2'
...
25697 java/util/concurrent/atomic/AtomicLong . get
25697 sun/misc/Unsafe . compareAndSwapLong
25698 java/util/Random . next
31307 java/util/concurrent/atomic/AtomicLong . compareAndSet
31307 java/util/concurrent/atomic/AtomicLong . get
31307 sun/misc/Unsafe . compareAndSwapLong
11716 org/h2/util/ObjectArray . get
16041 java/lang/Object . <init>
21066 java/lang/Character . digit


object-alloc プローブを使用する場合の注意点

method-entry と同じ様に、objec-alloc プローブでも stringof() で直接文字列に変換すると、処理が追いつかずに出力がおかしくなります。

 \*\*\* リスト 16. object-alloc プローブで出力が乱れる例 \*\*\*
# dtrace -b 256m -Zqn 'hotspot$target:::object-alloc
{ @agg[stringof(copyin(arg1, arg2))] = count()}
tick-1sec {trunc(@agg, 3); printa(@agg); clear(@agg)}' \\
-c 'java -XX:+ExtendedDTraceProbes -jar dacapo-9.12-bach.jar h2'
...
java/math/BigDecimaldergFixederrrayIterator 20826
org/h2/value/ValueStringFixederrrayIterator 25735
org/h2/value/ValueStringFixedtArrayIteratorndomdUpdater$AtomicReferenceFieldUpdaterImpl 28359
java/lang/StringBuildergFixedtArrayIterator 14000
[Cva/lang/StringBuildergFixedtArrayIterator 21000
org/h2/value/ValueStringFixedtArrayIterator 146923
java/lang/StringBuildergFixederrrayIterator 21420
[Cva/lang/StringBuildergFixederrrayIterator 32130
java/math/BigDecimaldergFixederrrayIterator 48143
org/h2/value/ValueStringampedKCS11teeermIZE_ARGSte;cry;reamolcReferenceFieldUpdaterImpl 11784
java/math/MutableBigIntegerederrrayIterator 11980
java/math/BigDecimaldergFixederrrayIterator 15178

先ほどと同様に、この様なスクリプトを作成すれば回避可能です。

 \*\*\* リスト 17. 回避策 \*\*\*
# cat oalloc.d
#!/usr/sbin/dtrace -Zqs
hotspot$target:::object-alloc
{
self->class = (char \*) copyin(arg1, arg2 + 1);
self->class[arg2] = '\\0';
@agg[stringof(self->class)] = count();
}
tick-1sec
{
trunc(@agg, 3);
printa(@agg);
trunc(@agg)
}

(それなりに)分かり易い表記になったと思います。クラス名の '[L' や '[C' については http://java.sun.com/docs/books/jvms/second_edition/html/ClassFile.doc.html#84645 をご覧下さい。

 \*\*\* リスト 18. 回避策を講じた場合の出力 \*\*\*
# ./oalloc.d -c 'java -XX:+ExtendedDTraceProbes -jar dacapo-9.12-bach.jar h2'
...
[C 31555
org/h2/value/ValueStringFixed 74362
org/h2/value/ValueString 81814
org/h2/value/ValueString 46835
java/math/BigDecimal 47985
[C 59466
org/h2/value/ValueShort 26387
[C 56711
java/math/BigDecimal 56935


おわりに

DTrace で Java のプログラムを解析する際に便利な jstack() アクションと HotSpot プロバイダの使い方をご紹介しました。jstack() アクションでは syscall プロバイダと併せて使用した場合の例を、HotSpot プロバイダではサンプルスクリプトのご紹介と、HotSpot プロバイダを使用する際の注意点をご説明しました。DTrace が Java のアプリケーションの解析にも便利に使える事がご理解頂けたと思います。是非お手元でも実際にお試し頂ければと思います。

なお、DTrace は Java だけでなく JavaScript, PHP, Python, Ruby, Perl 等の言語でも使用する事が可能です。JavaScript, PHP, Python, Ruby のプロバイダは既に OpenSolaris にも組み込まれておりますので、是非インストールして試してみてください。


参考文献


おまけ


DTrace で Clojure のプログラムを解析する

Java VM の上で動くプログラムであれば Java 以外の言語でも解析対象とする事が出来ます。以下は Clojure を解析する例です。

Clojure の REPL から次の様な関数を定義するとします。

 \*\*\* リスト 19. Clojure を起動して REPL で関数を定義する \*\*\*
# java -XX:+ExtendedDTraceProbes -jar clojure.jar
Clojure 1.1.0
user=> (defn foo [] (pr "foo"))
#'user/foo
user=> \^D

Clojure が起動したら、関数を定義する前に、別の端末エミュレータから以下のコマンドを実行しておきます。ここで実行している dtrace コマンドは Clojure で関数を定義した時にアロケートされるオブジェクトのサイズの総和を出力します。

 \*\*\* リスト 20. HotSpot プロバイダのプローブを利用して調査を行う \*\*\*
# /usr/java/bin/jps <-- Clojure のプロセスを探す
761 Bootstrap
6275 jar
6276 Jps
# dtrace -qn 'hotspot$target:::object-alloc { @sz = sum(arg3) }
tick-5sec { printa("%@d\\n", @sz); trunc(@sz)}' -p 6275
597768

出力結果を見ると、全部で 597768 bytes のオブジェクトがアロケートされた事が分かります。小さな関数の定義で 600KB ほどメモリを消費しました。この時、どんなオブジェクトが生成されているかも DTrace で簡単に調べる事が出来ます。

 \*\*\* リスト 21. どんなオブジェクトが生成されているかを調べるスクリプト \*\*\*
# dtrace -qn 'hotspot$target:::object-alloc { self->m = (char \*) copyin(arg1, arg2+1);
self->m[arg2] = '\\0'; @agg[stringof(self->m)] = count()}
tick-5sec {trunc(@agg, 5); printa(@agg);
trunc(@agg,0)}' -p 6275

[B 205
java/lang/reflect/Method 238
[Ljava/lang/Object; 337
java/lang/String 821
[C 1267

左がアロケートされたオブジェクト、右がオブジェクトの個数です。最も多くアロケートされたオブジェクトはキャラクター型の配列で、1267 個アロケートされています。この様に、DTrace を使用すれば、発想次第で様々な情報を取り出す事が出来ます。非常に便利なツールだと思います。


dem コマンドについて

dem コマンドは C++ のシンボル名を読み易く加工する為にでっち上げたコマンドです。Sun Studio がインストールされた環境では c++filt というコマンドを代わりに使用出来ますので、なるべくそちらをお使い下さい。

 \*\*\* リスト 22. dem コマンドのソースコード \*\*\*
# cat dem.c
// gcc dem.c -ldemangle -o dem
#include <demangle.h>
#include <stdio.h>
#define LEN 1024
char input[LEN];
char mangled[LEN];
char output[LEN];
int main() {
while(fgets(input, LEN, stdin)) {
int i, start;
i = 0;
while((input[i] != '`') && (input[i] != NULL)) {
i++;
}
write(1, input, i + 1);
if(input[i] == NULL)
continue;
start = ++i;
while((input[i] != '+') && (input[i] != NULL)) {
i++;
}
bcopy(&input[start], mangled, i - start);
mangled[i-start] = NULL;
cplus_demangle(mangled, output, LEN);
write(1, output, strlen(output));
if(input[i] != NULL)
write(1, &input[i], strlen(input) - i);
}
}

Be the first to comment

Comments ( 0 )
Please enter your name.Please provide a valid email address.Please enter a comment.CAPTCHA challenge response provided was incorrect. Please try again.