Javaメソッドトレース

“ソフトウェアの二大ボトルネック ”で2種類のボトルネックがあることを述べました。

Javaアプリケーションについて前者のボトルネックを見つける1つの手法として、“メソッドトレース”があります。具体的には、メソッドの入口と出口に次のようなログ出力のコードを埋め込み、ログからメソッドの実行時間を知るという手法です。(ちなみに精密な性能測定を行う場合は、System.currentTimeMillis()よりもSystem.nanoTime()がお勧め)

System.out.println("a: start: "+System.nanoTime());

小さなアプリケーションならメソッドが少なく、上記コードをゴリゴリ手書きすればよいです。しかし巨大なアプリケーションになると手書きする箇所が膨大になり、現実的ではありません。

そのようなときには、Spring FrameworkなどにあるAOP(Aspect Oriented Programming)機能が役に立ちそうです。AOPを使ってバイトコードにログ出力のコードを埋め込ませ、メソッドトレースを実現するというものです。
 
しかし私はSpring Frameworkをまだ試したことがありません。が、次を使用してメソッドトレースを実現しました。

1. Java SE 5.0で追加されたjava.lang.instrumentパッケージ
2. Javassist

java.lang.instrumentパッケージは、平たく言うと次を提供してくれています。

• アプリケーションのmainメソッドを呼ぶ前に、エージェントのpremainメソッドを呼ぶ仕組み
• アプリケーションの実行に必要なクラスをJava VMが定義する前にクラスファイルを変換する機会

ClassFileTransformerの実装クラスを作って、premainメソッドを持つエージェントでInstrumentation#addTransformer()を使ってClassFileTransformerの実装クラスを登録するだけでよいのです。ところがクラスファイルを変換するAPIはJava SEには含まれていないのです。

そこで必要となるのが、バイトコードを変換するAPIであるjavassistです。バイトコードを変換するAPIとして、他にBCELもありますが、私はjavassistを選択しました。ClassFileTransformerの実装クラスからjavaassistを使ってバイトコードを変換し、ログを出力するコードを埋め込ませるだけです。具体的な作り方は記載しませんが、意外と簡単そうでしょう？

私はこうしてメソッドトレース機能を作り、さらに別途、メソッドトレース機能が出力するログを解析するプログラムも作って、処理時間が長いメソッドを特定できるようになり、巨大なJavaアプリケーションのボトルネック箇所をいくつか見つけることができました。

市販のプロファイラツールは高価だし、自分の思うようなデータを出力してくれない可能性もありますから、メソッドトレース機能を2、3日間で自作したのですが、このメソッドトレース機能は意外と応用範囲が広かったのです。ボトルネック箇所の特定だけでなく、メソッドの呼び出しシーケンス分析や、メソッド実行網羅率の採取などにも活用することができ、非常に便利なツールになっています。