torutkのブログ

ソフトウェア・エンジニアのブログ

JavaロギングAPI考：AspectJで効果的なメソッドトレース

Java

id:torutk:20070505のロギングでの問題点をAspectJで解決してみようと実験します。

まず、MyBusinessクラスからロギングAPIの呼び出しを削除します。横断的関心事であるロギングはアスペクトとして別モジュールに記述するからです。

public class MyBusiness {
    public int calc(int a, int b) throws MyBusinessException {
        int returnValue = 0;
        // 処理1
        if (isSpecificCase) {
            throw new MyBusinessException();
        }
        // 処理2
        return returnValue;
    }
    private boolean isSpecificCase = false;
}

AspectJ言語でMyBusinessクラスのメソッドトレース・ログを記述します。

import java.util.logging.Logger;
import org.aspectj.lang.Signature;

aspect Trace {
    pointcut atTrace():
        execution(* MyBusiness.*(..)) ||
        execution(MyBusiness.new(..));

    before(): atTrace() {
	Signature sig = thisJoinPoint.getSignature();
        logger.entering(sig.getDeclaringType().getName(), sig.getName(),
			thisJoinPoint.getArgs());
    }

    after() returning(Object o): atTrace() {
	Signature sig = thisJoinPoint.getSignature();
        logger.exiting(sig.getDeclaringType().getName(), sig.getName(), o);
    }

    after() throwing(Exception e): atTrace() {
	Signature sig = thisJoinPoint.getSignature();
        logger.throwing(sig.getDeclaringType().getName(), sig.getName(), e);
    }

    Logger logger = Logger.getLogger(MyBusiness.class.getName());
}
ポイントカットの定義

AspectJでは、アスペクトを織り込む（ウィービング）場所をpointcutで定義します。ここでは、以下の2つの場所を定義しています。
(1)MyBusinessクラスの任意の名前、任意の戻り値型、任意の引数のメソッドの実行(execution)
(2)MyBusinessクラスの任意の引数のコンストラクタの実行(execution)

任意の名前、任意の戻り値型は、ワイルドカード（'*'）で示します。一方、任意の引数は、'..'で示します。

ポイントカットの事前に実行するアドバイスの定義

pointcutで定義した場所に処理が到達したときに最初に実行したい内容をbeforeアドバイスで定義します。ここでは、JavaロギングAPIのLogger.enteringメソッドを実行します。enteringメソッドの引数で渡すクラス名、メソッド名、引数の配列を取り出すために、thisJoinPointという暗黙の変数と、Signatureオブジェクトを使用しています。
これは、JavaのリフレクションAPIと類似の概念です。

(1)クラス名：この単純なサンプルではMyBusinessクラスに決めうちでもいいのですが、ここでは汎用的にクラス名を取り出しています。thisJoinPointからSignatureオブジェクトを取得し(getSignature）、そこから型を取り出し（getDeclaringType）、その名前を取り出しています（getName）。
(2)メソッド名：Signatureオブジェクトからメソッド名を取り出しています（getName）。
(3)引数の配列：thisJoinPointから引数配列を取り出しています（getArgs）。

ポイントカットの事後に実行するアドバイスの定義（return）

pointcutで定義した場所から例外ではなく正常にリターンした直後に実行したい内容をafter - returningアドバイスで定義します。ここでは、JavaロギングAPIのLogger.exitingメソッドを実行します。
exitingメソッドは引数にクラス名、メソッド名、戻り値を取ります。このうち
クラス名、メソッド名はbeforeアドバイスと同様thisJoinPointという暗黙の変数と、Signatureオブジェクトを使用します。
戻り値を取得するには、returningのパラメータとして戻り値型を宣言する必要があります。ただしメソッドトレースの対象メソッドは戻り値型がばらばらなため、ここではObject型で宣言しています。Javaのプリミティブ型はObject型ではありませんが、AspectJ(1.5.3)ではうまく捉えられています（仕様？実装依存？）。

ポイントカットの事後に実行するアドバイスの定義（例外）

pointcutで定義した場所から例外で終了する直後に実行したい内容をafter - throwingアドバイスで定義します。ここでは、JavaロギングAPIのLogger.throwingメソッドを実行します。
throwingメソッドは引数にクラス名、メソッド名、例外オブジェクトを取ります。このうちクラス名、メソッド名はbeforeアドバイスと同様thisJoinPointという暗黙の変数と、Signatureオブジェクトを使用します。
例外オブジェクトを取得するには、after-throwingのパラメータとして例外型を宣言する必要があります。例外の型はメソッドによってばらばらなため、ここではException型で宣言しています（Throwable型の方がよいかも）。

AspectJを使ったトレースの例題のコンパイルと実行

D:\work> ajc MyBusiness.java MyBusinessException.java Trace.aj
D:\work> java -Djava.util.logging.config.file=mylogging.properties MyBusiness
2007/05/06 8:02:33 MyBusiness calc
詳細レベル (中): ENTRY 1,000 2,000
2007/05/06 8:02:33 MyBusiness calc
詳細レベル (中): RETURN 3,150
2007/05/06 8:02:33 MyBusiness calc
詳細レベル (中): ENTRY 1,234 5,678
2007/05/06 8:02:33 MyBusiness calc
詳細レベル (中): THROW
MyBusinessException
at MyBusiness.calc(MyBusiness.java:13)
at MyBusiness.main(MyBusiness.java:24)