はじめに
プログラムでログを出力する時、通常どのクラスのどのファイルが出力したのかを明らかにするためクラス名とメソッド名を指定します。たとえば次のリストはJ2SEのLoggerクラスを利用したログの例です。
public class Foo { public void bar(String[] args) { Logger.global.entering("Foo", "bar", args); ... Logger.global.exiting("Foo", "bar"); } ... }
しかし、なぜクラス名やメソッド名を文字列で記述しなければならないのでしょうか？ ソースファイルにはFooというクラス名もbarというメソッド名も書いてあります。また、C/C++には__FILE__マクロでソースファイル名をソースに埋め込むことができますが、なぜJavaにはそういった機能が無いのでしょうか？
Java仮想マシンはクラス、メソッドなどの情報を実行時に参照します。このため、実際にはこれらの情報をプログラムから利用することができます。たとえば、プログラムが実行中に例外をスローすると標準出力にスタックトレースが表示されます。この情報は実行中に仮想マシンが保持しているスタックフレームの内容です。本記事では、スタックフレーム情報からこれらの情報を取得する方法について説明します。
対象読者
本記事は、Javaプログラミング初級者を対象に、スタックフレームの意味、読み方とプログラムからの利用方法を説明します。
必要な環境
本記事のソースをビルド/実行する場合にはJ2SE 1.5を利用してください。記事で取り上げた範囲のソースについてはJ2SE 1.4でもビルド/実行可能ですが、添付のantビルドスクリプトではこれらのプログラムを区別していないため、ディレクトリツリーからソースファイルを削除しないとビルドができなくなりますのでご注意ください。
参考までに筆者が利用した本記事のテスト環境は以下のものです。
| OS | J2SE | Ant | JUnit | IDE |
| WindowsXP SP2 | 1.5.0_04 | 1.6.2 | 3.8.1 | NetBeans4.0J |
| Mac OS X 10.4.2 | 1.5.0_02 | 1.6.2 | 3.8.1 | - |
ファイル構成
サンプルファイルはzip形式で圧縮してあります。展開すると「trcp」というディレクトリを頂点としたディレクトリ階層ができます。すぐに実行できるようにコンパイル済みのクラスファイルも添付してあります。また、ソースファイルはすべてシフトJISでエンコードしています。
「trcp」ディレクトリ
- 「build.xml」
junit.homeプロパティの値は「junit.jar」が配置されたディレクトリ名に変更してください。以下のターゲットがあります。
- デフォルト（build）：「src」ディレクトリのプログラムをビルド
- junit：
MethodInfoTestとMethodInfo5Testをビルドして実行 - bench：
SpeedCheckをビルドして実行 - stack：
Bugをビルドして実行 - nodebug：
StackInfoとNoDebugInfoをビルドして実行
「trcp\src\com\example\sys」ディレクトリ
- 「StackInfo.java」
- 「MetohdInfo.java」
- 「MetohdInfo5.java」
StackTraceElementの内容を出力するプログラムThrowable#getStackTraceを利用してクラス名、メソッド名を取得するプログラムThread#getStackTraceを利用してクラス名、メソッド名を取得するプログラム「test\com\example\sys」ディレクトリ
- 「Bug.java」
- 「MetohdInfoTest.java」
- 「MetohdInfo5Test.java」
- 「SpeedCheck.java」
- 「NoDebugInfo.java」
MethodInfoクラスのユニットテストプログラムMethodInfo5クラスのユニットテストプログラム（J2SE 1.5以上が必要です。1.4しかインストールされていない場合には削除してください）MethodInfoとMethodInfo5の処理速度を比較するプログラム（J2SE 1.5以上が必要です。1.4しかインストールされていない場合には削除してください）StackTraceElementの内容を出力するプログラムNetBeans 4.0からの利用
メニューから［ファイル］→［新規プロジェクト］→［プロジェクト―既存のAntスクリプトを使用するJavaプロジェクト］を順に選択し［次へ］ボタンをクリックします。次に［場所］の［ブラウズ］ボタンをクリックし、ダイアログボックスを表示します。アーカイブを展開したディレクトリのtrcpディレクトリを選択し、［開く］をクリックします。この操作で、［構築スクリプト］［プロジェクトフォルダ］が自動的に設定されるため、残る［プロジェクト名］に適当な名前（trcpなど）を入力し、［次へ］をクリックしてください。
一般的なメニュー項目のうち、［プロジェクトをテスト］に「junit」を設定します。［次へ］をクリックし、［ソースパッケージフォルダ］に「src」と「test」を追加し、［次へ］をクリックして完了します。
以後、「build.xml」を右クリックすると表示されるショートカットメニューの［ターゲット実行］→［その他のターゲット］のクリックで、「build.xml」に定義されている各種ターゲットをNetBeans上で実行できるようになります。
解説
スタックとスタックフレーム
Java仮想マシンは個々のメソッドを呼び出すときにスタックを利用します。スタックはスレッド毎に割り当てられたメモリー上の領域でこの中にメソッド内で利用される変数、引数と呼び出し元メソッドの情報が格納されます。
図は、barが呼び出したbazの中からさらにbarを呼び出している状態を示したものです。
Java仮想マシンはメソッドが呼び出される都度、スタック上に新たなフレーム（枠）を作成します。このため、たとえば同じbarメソッドの変数aであっても、呼び出しが異なればスタック上の異なる領域が確保され、互いに影響することはありません。同様に、メソッド呼び出しの引数は、呼び出し元の変数とは異なる領域が割り当てられるため、呼び出し側の代入操作は呼び出し元には伝わりません。
void method1() { int a = 8; foo(a); System.out.println(a); // 8と出力 } void method2(int a) { a = 10; // このaはmethod1の変数aとは異なる }
なお、確保されたフレームは、メソッドからreturnやthrowによって呼び出し元へ戻る時点で解放されます。
例外発生時のスタックトレース
プログラムがスローした例外には、その例外を作成した時点のスタックフレームの情報が格納されます。この情報は、mainメソッドを抜けてjavaコマンドが拾った場合か、あるいはプログラムでキャッチしてprintStackTraceメソッドを呼び出すと標準出力に出力されます。
サンプルの「Bug.java」は、意図的に例外をスローするプログラムです。なお、他のリストと異なりこのリストには行番号を振っています。
1:package com.example.sys; 2:public class Bug { 3: void foo(String s) { 4: bar(s); 5: } 6: static void bar(String s) { 7: baz(s); 8: } 9: static void baz(String s) { 10: System.out.println(s.length()); 11: } 12: public static void main(String[] args) { 13: new Bug().foo(null); 14: } 15:}
このプログラムを実行すると以下の出力を得ます。
>java -cp build/classes com.example.sys.Bug
Exception in thread "main" java.lang.NullPointerException
at com.example.sys.Bug.baz(Bug.java:10)
at com.example.sys.Bug.bar(Bug.java:7)
at com.example.sys.Bug.foo(Bug.java:4)
at com.example.sys.Bug.main(Bug.java:13)
この出力を順番に説明すると次のようになります。
- 1行目：
java.lang.NullPointerExceptionクラスの例外（Exception）が「main」スレッドで発生 - 2行目：「Bug.java」の10行目の
Bugクラスのbazメソッドで発生 - 3行目：「Bug.java」の7行目の
Bugクラスのbarメソッドからの呼び出し - 4行目：「Bug.java」の4行目の
Bugクラスのfooメソッドからの呼び出し - 5行目：「Bug.java」の13行目の
Bugクラスのmainメソッドからの呼び出し
NullPointerExceptionですので、オブジェクトがあると思ってアクセスしたらnullだったという意味になります。ここで1行目の例外についての情報を除いた2行目以降がスタックフレームの情報で、呼び出しの末端から順に呼び出し元へ向かって出力されます。
なお、見ての通り、メソッド名とクラス名の区切りには良く利用される「#」ではなく、staticメソッドかインスタンスメソッドかの区別なく「.」が使われます。また、コンストラクタについては「<init>」という文字列が利用されます。
この例外情報の2行目（最初のスタックフレーム情報）から「Bug.java」の10行目を見ると、
System.out.println(s.length());
という記述があります。System.out.printlnについてはnullになる余地がないことから、s.length()という呼び出しのsがnullだと推測できます。そのsは引数として与えられていることがbazメソッドのメソッド宣言部（9行目）でわかります。それではそのsという引数を与えたのはどこでしょうか？ 同様に例外情報の3行目を見るとbarメソッド（7行目）だということがわかります。このように順に例外情報をたどることで、5行目のmainメソッドの呼び出し（13行目）の
new Bug().foo(null);
にたどり着くことができるでしょう。
もちろん、本物の例外ではこのように単純に原因がわかるとは限りません。しかし、引数やその時点のインスタンス変数などに依存しない単純なバグであれば、どのクラスのどのメソッドの何行目かという情報によって容易に原因を突き止めることができるでしょう。
なお、ファイル名と行番号をスタックトレースに含めるためにはjavacのデバッグオプションをデフォルト（無指定）以上にする必要があります。「-g:none」を指定すると
at com.example.sys.Bug.baz(Unknown Source)
のように、ファイル名と行番号は出力されなくなります。
行番号はメソッド上の例外となった位置を特定するのに重要ですので、クラスファイルを可能な限り小さくしたいであるとか、難読化の一環として情報を減らしたいといった特別な理由がない限り、デバッグ情報は無効化しないほうが良いと思います。
プログラムからのスタック情報取得
ここまでの説明をお読みになれば、プログラムから実行中のメソッドとクラスの名前を取得するには、スタックトレースを利用すれば良さそうだということがおわかりになると思います。少なくてもExceptionクラスのprintStackTraceメソッドを呼び出すとこれらの情報が取得できるからです。
しかし、J2SE1.3までは本当にStreamを用意してprintStackTraceを呼び出さない限り、スタックフレームの情報は取得できませんでした。
幸いなことにJ2SE 1.4では、Throwable（Exceptionのスーパークラス）に、StackTraceElementクラス（スタックフレームの情報を整理したオブジェクト）の配列を取得できるgetStackTraceというメソッドが追加されたため、手軽にプログラムから扱えるようになりました。ただし、手軽に扱えるのは良いのですが、パフォーマンス上の呼び出しペナルティが大きいことには留意したほうが良いでしょう。パフォーマンスについては簡単なテストプログラムを用意してあるので、本記事でも後で触れます。
StackTraceElementクラスの内容を表示するプログラムを以下に示します。
package com.example.sys; public class StackInfo { public static void main(String[] args) { Throwable t = new Throwable(); StackTraceElement[] ste = t.getStackTrace(); System.out.println("class=" + ste[0].getClassName()); System.out.println("method=" + ste[0].getMethodName()); System.out.println("file=" + ste[0].getFileName()); System.out.println("line=" + ste[0].getLineNumber()); } }
スタックトレースを得るには実際に例外をスローする必要はなく、単にThrowableクラスのインスタンスを生成するだけです。これによりThrowableオブジェクトを生成した時点のクラス名、メソッド名、ファイル名、行番号を配列の第1要素としたStackTraceElement配列が得られます。
このプログラムを実行すると以下の結果が得られます。
>java -cp build\classes com.example.sys.StackInfo class=com.example.sys.StackInfo method=main file=StackInfo.java line=4
なお、デバッグ情報の出力を無効して実行すると次の結果となります。
>java -cp build\classes com.example.sys.NoDebugInfo class=com.example.sys.NoDebugInfo method=main file=null line=-1
ここで呼び出しているNoDebugInfoは、最初の「StackInfo.java」と同一内容で単にクラス名を変えただけのクラスです。添付のantビルドスクリプトのnodebugターゲットでデバッグ情報無しでビルドできるように別の名前にしてあります。
このように、デバッグ情報付きコンパイルを無効にするとファイル名には「null」、行番号には「-1」が返ります。
スタックトレース情報を使いやすくする
「StackInfo.java」を見てのように、プログラムからスタックトレース情報を利用するのは手軽です。しかし、実際に本記事の最初に例としたLogger#enteringなどに与えるにはそれなりに手数がかかるため、より簡単に使えるようにまとめたのが次の「MethodInfo.java」です。
package com.example.sys; /* * 現在のメソッドに関連する情報を取得する。 */ public class MethodInfo { static final StackTraceElement NULL_STACKTRACEELEMENT = new StackTraceElement("", "", "", 0); StackTraceElement[] stack; int startIndex; /** * メソッド情報オブジェクトを生成する。 */ public MethodInfo() { stack = new Throwable().getStackTrace(); for (int i = 0; i < stack.length; i++) { if ("<init>".equals(stack[i].getMethodName())) { startIndex = i + 1; break; } } assert stack != null; } /** * 現在のメソッド名を取得する。 * @return メソッド名。取得できない場合は空文字列 */ public String getCurrentName() { assert stack != null; return getStack(startIndex).getMethodName(); } /** * 現在のメソッドを呼び出したメソッド名を取得する。 * @return メソッド名。取得できない場合は空文字列 */ public String getCallerName() { assert stack != null; return getStack(startIndex + 1).getMethodName(); } /** * 現在のメソッドを実装したクラス名を取得する。 * @return クラス名。取得できない場合は空文字列 */ public String getCurrentClassName() { assert stack != null; return extractClassName(getStack(startIndex) .getClassName()); } /** * 現在のメソッドを呼び出したクラスの名前を取得する。 * @return クラス名。取得できない場合は空文字列 */ public String getCallerClassName() { assert stack != null; return extractClassName(getStack(startIndex + 1) .getClassName()); } StackTraceElement getStack(int index) { return (stack.length > index) ? stack[index] : NULL_STACKTRACEELEMENT; } static String extractClassName(String name) { int n = name.lastIndexOf('.'); if (n < 0) { return name; } return name.substring(n + 1); } }
MethodInfoクラスは次のような利用方法を想定しています。
public class Foo { public void bar(String[] args) { MethodInfo mi = new MethodInfo(); Logger.global.entering(mi.getCurrentClassName(), mi.getCurrentName(), args); ... Logger.global.exiting(mi.getCurrentClassName(), mi.getCurrentName()); } ... }
単純なプログラムなので特に説明が必要なコードは無いと思いますが、3点だけ解説します。
コンストラクタの処理
コンストラクタでは、Throwableのインスタンスを生成し、スタックフレーム情報を取り出した後、先頭の要素のインデックスを求めています。これは、2つの意味があります。
1つは、実際にMethodInfoクラスのcurrent（現時点の）メソッドに相当するのは、このコンストラクタを呼び出したメソッドだということから、MethodInfoのコンストラクタの1つ上のスタックフレームを探索するためです。
2つ目の理由は少し複雑な大人の事情です。考えてみなくてもすぐわかりますが、1の理由であれば、単に
startIndex = 1;
とすれば済む話です。先頭の0がコンストラクタなのだから当然の話ですね。それなのになぜ配列をたどってメソッド名が「<init>」のものを探しているかというと、本記事執筆時に想定していたのは、J2SE 1.5で導入されたThread#getStackTraceメソッドを利用した場合との共通処理だったのが理由です。Thread#getStackTraceは配列の先頭が呼び出し時点のメソッドの情報ではなく、Threadクラスの内部メソッドとなっていたため、実装に依存せずに先頭を探すためには、コンストラクタを示す<init>を検索に利用するのが確実だと考えたからです。これによってJ2SE 1.4用とJ2SE 1.5で共通のクラスを利用することを考えていたのです（Thread#getStackTraceはJ2SE1.4には存在しないため、リフレクションを利用した呼び出しによって使い分けるという考えでした）。なぜ、それがMethodInfoというThrowable#getStackTraceを利用するクラスとMethodInfo5というThread#getStackTraceを利用するクラスの2つに完全に分離してあるかというと……その理由は後で説明します。なお、本記事では掲載しませんが「MethodInfo5.java」もアーカイブには格納されているので興味があれば参照してください。
getStackメソッド
スタックトレースは実は常に取得できるわけではありません。ホットスポットコンパイラによる最適化が進むと、スタックフレームの作成が省略されることがあるからです。
そのため、サーバーサイドで実行されるプログラムのログ用に利用するには多少の危険があります。このプログラムをデバッグ以外の目的に利用すると、メソッド名などの情報を失う危険性があることは留意してください。
このことは、コンストラクタで求めたstartIndexが実は配列の最後の要素を越えていたりする可能性がゼロではないことを意味します。特に呼び出し側の情報を取得するには1を加算して求めています。また、getStackTraceメソッドの戻り値が0要素の配列の可能性もあり得るということです。
このため、配列のインデックス値が配列に実在する要素を指しているか確認する必要があります。getStackメソッドでは、実在しない要素を参照していると判断した場合、NULL_STACKTRACEELEMENTというダミーのStackTraceElementを返します。このオブジェクトはクラスの先頭で定義しているように空文字列と行番号0を持ったStackTraceElementです。
もし、配列の要素が存在しなかった場合にnullを返送するとどうなるでしょうか？ たとえばgetCurrentNameメソッドは次のような実装になるでしょう。
StackTraceElement elm = getStack(startIndex); if (elm == null) { return ""; } else { return elm.getMethodName(); }
このnullかどうかのチェックは、getCallerName、getCurrentClassNameなど他のすべての処理に必要になります。しかし、やりたいことは単に対応するStackTraceElementが存在しなければ空文字列を返すことです。
こういう場合には、呼び出した側（たとえばgetCurrentNameメソッド）にnullかどうか判定させるのではなく、条件判断した側（getStackメソッド）があらかじめ呼び出した側の処理に適応した結果を返すべきです。そうすれば、条件判断がソースコード上1ヶ所で済み、実行時にも呼び出し側と呼ばれた側の計2回、条件判断するのではなく呼ばれた側の1回で済むため効率的です。ちなみにこのように直接nullを利用する代わりにnullだった場合の動作を実行する特殊なオブジェクトを利用するパターンをNULLオブジェクトパターンと呼びます。
extractClassName
既に何度か実行例を見ているのでおわかりだと思いますが、StackTraceElementのgetClassNameで取得できるクラス名はパッケージ名が付いたものです。ほとんどの場合、同一クラス名を利用することは無いと思いますので、ここではパッケージ名を削除しています。
スタックトレース取得の問題点
スタックトレースの取得はパフォーマンスに影響を与えます。
SpeedCheckクラスはMethodInfo（Throwable#getStackTrace）およびMethodInfo5（Thread#getStackTrace）それぞれを与えられた回数分繰り返し実行し、呼び出しに必要な時間を計測するプログラムです。
このプログラムをPentiumM 1.7GHzのWindowsXPのJ2SE 1.5で動作した結果を参考までに以下に示します。
>java -cp build/classes com.example.sys.SpeedCheck 100000 経過時間(Throwable):1102, 1tick=0.01102 経過時間(Thread):4486, 1tick=0.04486 経過時間(Throwable):1052, 1tick=0.01052 経過時間(Thread):4356, 1tick=0.04356 経過時間(Throwable):1082, 1tick=0.01082 経過時間(Thread):4356, 1tick=0.04356
スタックが深くなると両者の差が縮まる傾向が見られますが、単純に比較すると4倍以上Thread#getStackTraceのほうが遅いという結果が得られました。また、1回の呼び出しに高速なほうのThrowable#getStackTraceでも約10マイクロ秒が必要です。当初の予測では、インスタンス生成が必要なThrowable#getStackTraceより、staticメソッドの連鎖で呼び出しが可能なThread#getStackTraceのほうが効率的だと考えていたため、この結果はちょっと驚きです。もっともJ2SEの実装は最初に実装されたバージョンはチューニングされていず、版を追って効率化されることが多いため、Thread#getStackTraceも今後のバージョンでは変わることが想像できます。そのため、ここで示した結果を固定的に考えるべきではありません。
ここで示された10マイクロ秒という速度が早いか遅いかは使い方と考え方によって決まります。たとえばLog4J（Apacheプロジェクトのロギングユーティリティ）では、ログ取得に必要な時間を21マイクロ秒（SimpleLayout時）、あるいは37マイクロ秒（TTCCLayout時）と具体的な数値を示して利用時の負荷を明らかにしています。なぜそのような記述が必要かというと、ログはプログラムがユーザー要件を実現するための機能そのものではないからです。ログはプログラムの保守や障害時の調査のために無くてはならないものですがそれはあくまでもシステム要件であり、ユーザー要件の実現という観点だけから見ればむしろ実行効率を落とす悪者です（「システムの都合」ということですね）。そのため、ログに関する実行コストは低ければ低いほど良いことになります。
この観点からは、実際のロギングのコストが約20マイクロ秒で済むのに対して、クラス名とメソッド名の記述を省略するために10マイクロ秒も費やすのは望ましいこととは言えないでしょう。直接文字列でクラス名やメソッド名を指定すればコストは0で済むからです。
一方、たかだか10マイクロ秒ならば、仮にWebアプリケーションが1リクエスト処理するのに100メソッド呼び出しが必要だとしても合計1ミリ秒に過ぎないので、クライアントにとっては全く影響ないと考えることもできます。
ただ、どちらにしてもログを無効化しているのに呼び出しが行われるのは望ましくはありません。MethodInfoクラスのgetCaller*メソッドは、そのような場合にロギングの有無を判定するメソッドを間に挟む利用方法を想定して実装されています。
具体的には次のような利用方法です。
public class Foo { public void bar(String[] args) { startLog(Level.DEBUG, args); ... } void startLog(Level level, Object args) { if (Logger.global.isLoggable(level)) { MethodInfo mi = new MethodInfo(); Logger.global.entering(mi.getCallerClassName(), mi.getCallerName(), args); } } ...
startLogメソッドの中でMethodInfoのインスタンスを生成していますが、ここで取得したいクラス名/メソッド名はstartLogではなく、それを呼び出したメソッド（この例ではbar）です。そのため、現在のスタックフレームの更に1つ上のクラス名とメソッド名を取得するメソッドを利用します。
まとめ
スタックの取得はそれなりに実行効率に影響する処理ですが、利用箇所を心得て使う限りは、非常に便利に実行時の情報を取得することができます。障害発生時のログ取得メソッドを共通化するような場合には、特に呼び出し側でクラス名やメソッド名を用意する必要がないことや、呼び出し頻度が少ないことから（障害発生頻度が高ければそちらのほうが余程問題ですね）、有効に利用できると思います。
また、プログラムにバグがあれば例外とスタックトレースが出力されます。その意味で、スタックトレースは最も重要なプログラマーの友です。もしスタックトレースが出力されていても読まないでいたら、それは大きな損失です。最初に説明したようにスタックトレースを読むことは、アルファベットが並んでいることを除けばそんなに難しいものではありません。むしろ例外の発生箇所をきちんと把握するのに十分な情報が含まれていることから、これなしにデバッグするほうが、よほど難しいと言っても良いでしょう。
これらの情報を使いこなして上手にプログラミングをしましょう。
