ケース2：特定メソッドのプロファイリング
本ケースでは、Javaメソッドの実行時間を計測します。今回は実行状態の「Main.java」にSystemTapでアタッチし、同じ鍵で、同じ文字列を暗号化したときの実行コストを「AES」「Blowfish「DESede（3DES）」の3つの暗号アルゴリズムで比較します。
なお、「Main.java」はサンプルの「case2」フォルダに入っています。
仕組み的には、すべてのJavaメソッドを対象にできますが、この場合はhprofではできない、特定のメソッドに限定した実行時間計測を行います。
■ 取得する項目
プロファイル対象とするJavaメソッドの入りと戻りにプローブを掛け、実行時間をナノ秒単位で取得します。
- 対象メソッドに入った回数
- 対象メソッドの最大実行時間（ナノ秒）
- 対象メソッドの累積実行時間（ミリ秒）
■ 使用するプローブ
- begin
SystemTapのスクリプトが開始されるときに呼び出されるプローブです。今回はグローバル変数を初期化する目的で使用します。
- end
SystemTapのスクリプトが終了するときに呼び出されるプローブです。今回は、このプローブで、それまでに取得したプロファイルデータをstapコマンドの標準出力に出力します。
- hotspot.method_entry
- hotspot.method_return
Javaメソッドの入りと戻りをフックします。今回はメソッド名とシグネチャからプロファイル対象メソッドか否かを判断し、対象メソッドであれば「method_entry」「method_return」それぞれのプローブが呼び出された時間差を実行時間として記録します。
それぞれのプローブで使用可能な変数を表3に示します。「method_entry」「method_return」では取得できる項目が同一です。
| 変数名 | 内容 |
|---|---|
| name | 固定値（「method_entry」または「method_return」） |
| thread_id | java.lang.Thread#getId()で返される、スレッド識別子 |
| class | 対象メソッドを提供するクラス名 |
| method | 対象メソッド名 |
| sig | 対象メソッドのシグネチャ |
| probestr | プローブ呼び出し時の概要の文字列表現 |
■ 実装のポイント
ここではスクリプト実装のポイントを説明します。スクリプト全体についてはcase2.stpをダウンロードしてください。
● 【1】プロファイル情報の記録場所と初期化
プロファイル対象とするメソッドの最大実行時間と累積実行時間を保持するための連想配列をグローバル変数で用意します。また、メソッド実行回数および、その時点でプロファイリング中のメソッド情報を保持するための連想配列も併せて用意します。今回は、表4に示すグローバル変数を用意しました。
| 変数名 | 目的 |
|---|---|
| elapsedTimes | プロファイル情報の保持 |
| method_entry_count | プロファイル対象メソッドの実行回数 |
| current | 実行中のプロファイル対象メソッドの開始時間を保持 |
初期化コードは以下のようになります。連想配列のエントリ初期化は共通化できるので、「CounterInit」という、引数にプロファイル対象クラス名を持つ関数に切り出してbeginプローブから呼び出すようにしました。
elapsedTimesはプロファイル対象クラス名と区分（最大値：max、累積：acc）の2つをキーに持ちます。method_entry_countはプロファイル対象クラス名のみをキーに持ちます。
function CounterInit(cryptoKlass:string){
elapsedTimes[cryptoKlass, "max"] = -1;
elapsedTimes[cryptoKlass, "acc"] = -1;
method_entry_count[cryptoKlass] = 0;
}
probe begin{
CounterInit("com/sun/crypto/provider/AESCipher");
CounterInit("com/sun/crypto/provider/BlowfishCipher");
CounterInit("com/sun/crypto/provider/DESedeCipher");
printf("PID=%d probe start!\n", target());
}
CounterInitの引数に与えているFQCNが今回測定対象の暗号アルゴリズムを実装するSPI（Service Provider Interface）クラスです。
● 【2】メソッドのプロファイル
今回プロファイルするプログラムは「javax.crypto.Cipher#doFinal(byte[])」で暗号化を行います。今回は暗号化コストをアルゴリズム別に見ていくため、この先のメソッドでプロファイルを掛けます。
probe hotspot.method_entry{
if((method == "engineDoFinal") && (sig == "([BII)[B")){
current[thread_id] = gettimeofday_ns();
method_entry_count[class]++;
}
}
probe hotspot.method_return{
if((method == "engineDoFinal") && (sig == "([BII)[B")){
real = gettimeofday_ns() - current[thread_id];
elapsedTimes[class, "acc"] += real;
if(real > elapsedTimes[class, "max"])
elapsedTimes[class, "max"] = real;
delete current[thread_id];
}
}
暗号化自体はCipherクラスのSPIが提供する「engineDoFinal()」というメソッドで実行されます。ただし、このメソッドはオーバーロードされているので、メソッド名だけではなくシグネチャも確認対象にしています。
時間はSystemTapの関数である「gettimeofday_ns()」を用いて、ナノ秒単位で取得します。開始時刻を格納する連想配列「current」は、そのプローブを呼び出したスレッドIDをキーに持ちます。スレッドIDは変数「thread_id」から取得します。currentの値はmethod_return時に「delete」句で連想配列のエントリそのものを削除します（多くのスレッドが生成と破棄を繰り返すアプリケーションの場合、メモリリソースが枯渇する可能性があるため）。
■ 実行例
ケース2のスクリプト実行例を図2に示します。前編でも記載したように、Javaメソッド関連のプローブでは、ターゲットのjavaコマンドに対してもオプションを付加する必要があります。今回は「-XX:+DTraceMethodProbes」を付加しています。
コラム CPU時間の取得
さらに本格的なプロファイリングをするためにCPU時間が必要な場合があります。SystemTapでは「task_utime()」「task_stime()」といった関数が用意されており、CPU時間を細かく取得することが可能です。
他にも、ユーザープロセスに関するさまざまな情報がSystemTapの関数を通して簡単に取得できます。どのような項目が取得できるかについては、SystemTapのリファレンスをご覧ください。
ケース3：特定メソッド実行時のスタックトレース取得
本ケースでは、特定のメソッドがどのような経緯（コールスタック）で呼び出されたか、スタックトレースを取得します。
フレームワークやミドルウェアの提供する特定のメソッドを呼び出した経緯を調査したいときなど、ソースコードに手を加えることが難しい確認を簡単に行うのに便利です。
■ 取得する項目
特定のメソッドが呼び出されたタイミングで、そのスレッドのJavaスタックトレースをstapコマンドの標準出力に出力します。今回はApache Tomcat 7.0.21デフォルトのindex.jspにアクセスしたときのスタックトレースを取得します。
■ 使用するプローブ
- hotspot.method_entry
Javaメソッドの入りにフックを掛け、スタックトレース取得対象メソッドである場合はスタックトレースを出力します。プローブポイントの説明については表3を参照してください。
■ 実装のポイント
ここではスクリプト実装のポイントを説明します。スクリプト全体についてはcase3.stpをダウンロードしてください。
今回のポイントは、スタックトレースの表示に「$JAVA_HOME/tapset/jstack.stp」の提供する、print_jstack()関数を使用することです。この関数はJDKに付属するjstackコマンドの機能限定版で、プローブポイントを呼び出したスレッドのスタックトレースをstapコマンドの標準出力に出力します。
probe hotspot.method_entry{
if((class == "org/apache/jsp/index_jsp") && (method == "_jspService")){ // 【1】
// 【2】始まり
if(!vm_inited){
Universe_methodKlassObj = $_methodKlassObj;
Universe_collectedHeap = $_collectedHeap;
HeapWordSize = $HeapWordSize;
CodeCache_heap = $_heap;
sp_register = "rsp";
fp_register = "rbp";
pc_register = "rip";
ptr_size = 8;
ptr_mask = 0xFFFFFFFFFFFFFFFF;
constantPoolOopDesc_size = 56;
HeapBlock_Header_size = 2 * ptr_size;
oopDesc_size = 2 * ptr_size;
vm_inited = 1;
}
// 【2】終わり
print_jstack();
print("\n");
}
}
【1】の部分では、Tomcatのインデックスページ「index.jsp」が呼び出されたときに動作する、Jasperが生成するクラスとメソッドを指定しています。
【2】の部分ではprint_jstack()を動作させるための基本的な情報を「jstack.stp」で宣言されているグローバル変数に格納しています。
jstack.stpでは、hotspot.vm_init_endプローブ（HotSpot VMの初期化が終了したときに呼び出されるプローブ）を使用して、これらの値を設定しています。しかし、既存プロセスにアタッチする場合は、VMの初期化が終了した後になるため、これらの値が設定されるタイミングがありません。
従って、CPUのレジスタ名やJavaヒープ開始アドレスなど、print_jstack()を動かすために必要な最小限の情報をjstack.stpから抜き出し、method_entryで設定するようにします（「vm_inited」という変数はjstack.stpの中で宣言されており、VMの初期化が完了したか（＝必要なグローバル変数の設定が終わったか）を示すフラグです）。
■ 実行例
ケース3のスクリプト実行例を図3に示します。ケース2同様、ターゲットのjavaコマンドに対してもオプションを付加する必要があります。今回は「-XX:+DTraceMethodProbes」を「$CATALINA_BASE/bin/setenv.sh」内で、$CATALINA_OPTSに追加しています。
コラム 他にも使えるjstack系関数
今回は「print_jstack()」でJavaレベルのスタックトレースを出力しましたが、他にも「print_jstack_full()」という関数があります。これはjstackコマンドの-mオプション同様、ネイティブフレームも出力します（出力結果はデマングルされません）。
他にもスタックトレースを文字列として返す「jstack()」や、取得するフレーム数を指定する「jstack_n()」など、いくつかの関数が存在します。どのようなものが存在するのか、一度jstack.stpをのぞいてみてください。
Copyright © ITmedia, Inc. All Rights Reserved.