Spring 2.0によるDBアプリケーションの作成

番外編 Spring AOPによるロギングの実装

最終更新日:2007/07/24

目次

Spring IDE 2.0

Spring IDE 2.0 リリース

これまでの連載ではSpring IDE 2.0のMileStoneビルドを使っていましたが、Spring IDE 2.0が2007/06/27に正式リリースされました。多くのバグフィックスがなされているようですので、MileStoneビルドからアップグレードするとよいでしょう。

Spring IDE 2.0をインストールするには、Eclpseのソフトウェア更新でSpring IDEのUpdateサイト(http://springide.org/updatesite)へアクセスします。下図はSpring IDE 2.0のモジュールを選択している画面です。

尚、Spring IDE 2.0はEclipse 3.3にも対応しているので、Eclipse 3.3 + Spring IDE 2.0という構成でも問題ありません。

Bean定義ファイルのテンプレート

Spring IDE 2.0ではBean定義ファイルのテンプレートを作成できるようになりました。メニューからファイル>新規>その他>Spring>Spring Bean Definitionを選択します(下図)。

すると下図のようにBean定義ファイルで使用する名前空間を選択する画面が出てくるので、必要な名前空間を選択するとSchemaLocationまで生成されたXMLファイルが作られます。

ただ、この手順でBean定義ファイルを作った場合は一つ注意する点があります。上の画像でも表示されていますが、aopとtx名前空間のXMLスキーマファイルの名前がXXX-2.1xsdになっています。これはSpring 2.1向けのXMLスキーマですので、Spring 2.0で実行するとエラーが発生します。Spring 2.0を使っている場合は、上記の手順でテンプレートを作成した後にXMLファイルを開き、手作業でXXX-2.1.xsdをXXX-2.0.xsdに変更して下さい。

Spring AOPの概要

@AspectJのサポート

Spring 2.0のAOPはAspectJと統合されました。これによって、

ようになっています。そのためAspectJの知識があれば予備知識をあまり必要とせずにSpring AOPを使うことができます。従来のXMLベースの記述もサポートしているので、アノテーションでAOPを記述するか、XMLで記述するか選択できます。アノテーションで記述する場合はJava5が必須です。

ただしAspectJのすべての機能をサポートしているわけではありません。実際Spring AOPがサポートしているJoin Pointは"method execution"のみです。それ以上のことが必要であれば、AspectJを直接利用するといったことが必要ですが、大抵の場合はSpring AOPが備えている機能で十分でしょう。

尚、Spring AOPの実行にはAspectJのライブラリが必要ですが、AspectJのコンパイラやWeaverは必要としないので、AspectJを使う場合のようにコンパイルやWeavingをビルドプロセスに組み込む必要はありません。

Spring AOPの適用範囲

Spring AOPの適用範囲はSpringが管理するBeanのみです。そのため、Springが管理しないクラスはSpring AOPの適用対象外です。Spring管理下かどうかに関わらずAOPを使用したい場合は、AspectJのようなAOPをサポートするツールを直接使用して下さい。

アノテーションベースとXMLベースのどちらを使うか?

Javaのバージョンが1.4以前ならば選択の余地が無く、XMLベースのアプローチを採用することになります。

Java5に対応している場合は、双方のメリットデメリットを考慮して決めることになるでしょう。XMLベースのアプローチではソースコードの変更無しに(つまりコンパイル無しに)Pointcutを変更できることが一つのメリットです。

アノテーションベースのアプローチでは、Pointcutをアノテーションで記述するため、Pointcutの変更にはソースコードの変更が必要になりますが、PointcutとAdviceを同じ場所に記述できるので、PointcutとAdviceの対応がわかりやすくなります。またPointcutをモジュールとして扱うことができる(複数のPointcutを合わせたPointcutの定義ができる)ので、Pointcutの記述が柔軟にできるというメリットもあります。

今回はアノテーションベースのアプローチを採用することにします。

アノテーションベースのAOP

ビルドパスにAOPライブラリを追加

ここからは実際にアノテーションベースのAOPを作っていきますが、その前にSpringプロジェクトのビルドパスにAspectJ及びASMのライブラリを追加します。

次の5つのファイルをビルドパスに加えてください。

アノテーションベースのAOPを有効にする

アノテーションベースのアプローチを採用する場合は、Bean定義ファイルに以下の1行が必要です。

<aop:aspectj-autoproxy/>

Aspect作成の前に忘れずに加えておきましょう。

アスペクトの宣言

ではPointcutとAdviceを記述するためのAspectを作成します。通常のJavaクラスを作成し(パッケージは何でもOKですが、わかりやすくするためにAspect用のパッケージを作るとよいでしょう)、クラス宣言に@Aspectアノテーションを追加します。アスペクトの宣言としてはこれだけです。

package aspect;
import org.aspectj.lang.annotation.Aspect;

@Aspect

public class SimpleLoggingAspect {

}

Pointcutの宣言

次に作成したAspectクラスにPointcutの宣言を加えます。

@Pointcut("execution(* service.*.*(..))")
public void businessService() {}

Pointcutの宣言には@Pointcutアノテーションを使います。アノテーションの引数にはAspectJのPointcut記法でPointcutを記述します。上の例ではserviceパッケージのすべてのメソッド実行を対象としています。

空のメソッド"businessService"が宣言されていますが、これは後にAdviceでPointcutを参照するために使用する識別子のようなものです。このようにPointcutを独立して宣言することもできますし、AdviceでPointcutを直接記述することもできます(後述)。

サポートされているPointcut Designators

以下はSpring AOPでサポートされているPointcut Designatorsです。AspectJと比べて少ないですが、ほとんどの場合はこれらだけで十分だと思います。

Pointcut Designators 説明
execution メソッド実行
within 型やパッケージを制限する
this 指定のインタフェースを実装するProxyオブジェクトに制限する(主にadvice内で参照する変数宣言のために使用する)
target 指定のインタフェースを実装するターゲットオブジェクトに制限する(主にadvice内で参照する変数宣言のために使用する)
args 引数の数と型にマッチするメソッドに制限する(主にadvice内で参照する変数宣言のために使用する)
@target 指定のアノテーションを持つターゲットオブジェクトに制限する
@args 引数が指定のアノテーションを含んでいる場合に制限する
@within 指定のアノテーションがクラス宣言に含まれているターゲットオブジェクトに制限する
@annotation 指定のアノテーションを含んでいるメソッドに制限する

主なPointcut Designatorsの使用例 説明
execution(* com.xyz.service.*.*(..)) serviceパッケージの全てのメソッド実行
within(com.xyz.service..*) service及びそのサブパッケージ内のJoin Point
this(proxyObject) インタフェースを実装するProxyオブジェクト
target(targetObject) インタフェースを実装するターゲットオブジェクト
args(name) 一つの引数を持つメソッド実行

Adviceの宣言

Adviceの宣言は、実行させたい処理をJavaのメソッドとして記述し、@Beforeや@Afterなどのアノテーションを付与します。

/**
 * serviceパッケージに属するクラスのメソッド呼び出し前にログを出力する。
 */
@Before("aspect.SimpleLoggingAspect.businessService()")
public void logBeforeExecution() {
  System.out.println("START");
}

アノテーションの引数にはPointcutを指定します。今回は既にaspectパッケージのSimpleLoggingAspectクラスで、"businessService"というPointcutを宣言しているので、引数にはそのPointcutを指し示す値(パッケージ名 + クラス名 + Pointcut名)を与えます。

または以下のように引数に直接Pointcutを記述することもできます。この場合は先の例のようにPointcutを独立して宣言する必要はありません。ただ、同じPointcutを別のAdviceで再利用したい場合は、独立したPointcutを宣言しておくとよいでしょう。

/**
 * serviceパッケージに属するクラスのメソッド呼び出し前にログを出力する。
 */
@Before("execution(* service.*.*(..))")
public void logBeforeExecution() {
  System.out.println("START");
}

Advice一覧

以下は使用できるAdviceの一覧です。

Advice 説明
@Before メソッド実行前に呼び出される
@AfterReturning メソッドが正常終了した後に呼び出される(メソッド実行で例外がスローされた場合は呼び出されない)
@AfterThrowing メソッド実行で例外がスローされた後に呼び出される
@After メソッドの実行結果に関わらず、メソッド実行後に呼び出される
@Around メソッド実行の代わりに呼び出される

Bean定義ファイルへの登録

さて、Aspectの作成が終わったら、Bean定義ファイルへ作成したAspectを登録します。登録にはその他のBeanと同じようにbeanタグを使います。

<!-- AOP -->
<aop:aspectj-autoproxy />
<bean id="simpleLoggingAspect" class="aspect.SimpleLoggingAspect"/>

上記の例ではid="simpleLoggingAspect"としてidを付与していますが、これは省略可能です。とにかくbeanタグを使ってBean定義ファイルにAspectを登録するだけで、Spring AOPにAspectとして認識されます。

Aspectを登録すると、Bean定義ファイルやソースエディタの左端に矢印のアイコンが表示されます。これはAspectを示すアイコンで、例えばソースエディタの矢印アイコンにマウスポインタを合わせると、どんなAdviceが適用されるのかがわかるようになっています。

Bean定義ファイル

Aspect

Serviceクラス(Aspect適用対象)

シンプルなロギングアスペクトの作成

メソッド実行ログを出力するAspectの作成

それでは簡単な例として、以下のAspectを作成することにします。

メソッド呼び出し前後でログ出力を行う必要があるので、Adviceは@Beforeと@AfterReturningを使うことにします。

クラス名、メソッド名の取得

出力する内容にクラス名とメソッド名が含まれているので、これらの情報を取得する必要があります。このためにJoinPointというクラスを使います。Spring AOPの各AdviceではJoinPoint型の引数を取ることができ(省略も可能です)、このJoinPointクラスからJoinPointに関する様々な情報を取得できます。

以下はJoinPointからクラス名とメソッド名を取得するコードです。

@Before("aspect.SimpleLoggingAspect.businessService()")
public void logBeforeExecution(JoinPoint jp) {
  String cName = jp.getTarget().getClass().getName(); // クラス名
  String mName = jp.getSignature().getName(); // メソッド名

Aspectの実装

上記の要件を満たす最終的なAspectは以下のようになりました。尚、Import文は省略してあります。

package aspect;

@Aspect
public class SimpleLoggingAspect {

    @Pointcut("execution(public * service.*.*(..))")
    public void businessService() {}

    /**
     * serviceパッケージに属するpublicメソッド呼び出し前にログを出力する。<br/>
     * 【フォーマット】 クラス名 メソッド名 START
     */
    @Before("aspect.SimpleLoggingAspect.businessService()")
    public void logBeforeExecution(JoinPoint jp) {
        System.out.println(getLogMessage(jp, "START"));
    }

    /**
     * serviceパッケージに属するpublicメソッド呼び出し後にログを出力する。<br/>
     * 【フォーマット】 クラス名 メソッド名 END
     */
    @AfterReturning("aspect.SimpleLoggingAspect.businessService()")
    public void logAfterExecution(JoinPoint jp) {
        System.out.println(getLogMessage(jp, "END"));
    }

    private String getLogMessage(JoinPoint jp, String msg) {
        String cName = jp.getTarget().getClass().getName(); // クラス名
        String mName = jp.getSignature().getName(); // メソッド名
        return cName + " " + mName + " " + msg;
    }
}

テスト実行

以下はBumonServiceTestを実行した結果です。期待通りのログが標準出力へ出力されました。

service.BumonService registBumon START
service.BumonService registBumon END
service.BumonService getBumon START
service.BumonService getBumon END
service.BumonService removeBumon START
service.BumonService removeBumon END
service.BumonService registBumon START
service.BumonService registBumon END
service.BumonService registBumon START
service.BumonService registBumon END
service.BumonService getAllBumon START
service.BumonService getAllBumon END
service.BumonService removeBumon START
service.BumonService removeBumon END
service.BumonService removeBumon START
service.BumonService removeBumon END

実用的なロギングアスペクトの作成

メソッド実行の詳細ログを出力するAspectの作成

上記のシンプルなロギングアスペクトに次の仕様を加え、ある程度実用的なロギングアスペクトを作成することにします。

ReflectionToStringBuilder

Beanの内容をわかりやすく出力するには、commons.langのReflectionToStringBuilderを使うと便利です($SPRING_HOME/lib/jakarta-commons/commons-lang.jarをビルドパスに追加する必要があります)。各BeanでtoString()メソッドをオーバーライドし、以下のように実装するだけです。

public String toString() {
  return ReflectionToStringBuilder.toString(this, ToStringStyle.SHORT_PREFIX_STYLE);
}

これでtoString()を呼び出すと、例えばBumonクラスなら

Bumon[cdBumon=000001,nmBumon=ESC]

こんな文字列が返されます。Beanのフィールドをリフレクションで拾ってくれるので、toString()の実装として非常に便利です。

メソッド実行時間の取得

メソッドの実行時間を計る場合は、Around Adviceを使う必要があります。Aroundはメソッド実行の代わりに呼び出されるAdviceで、その中で本来呼び出すはずだったメソッドを呼び出すことができます(全く別の処理を行うようにすることも可能です)。任意のタイミングで任意の処理を実行できるので、メソッド呼び出し前後に時間を測定するコードを書くことで実行時間を計れます。

Around Adviceでは他のAdviceと異なり、第1引数がProceedingJoinPoint型でなければなりません。このProceedingJoinPointに対して、proceed()メソッドを呼び出すと、本来呼び出すはずだったメソッドが実行されます。

実行時間を取得する場合は例えば以下のようにします。System.currentTimeMillis()をメソッド実行前後に呼び出して差分を計算しているだけです。

@Around("aspect.LoggingAspect.businessService()")
public Object logAroundExecution(ProceedingJoinPoint pjp) throws Throwable {
  ・・・
  long beforeTime = System.currentTimeMillis();
  Object retVal = pjp.proceed();
  long afterTime = System.currentTimeMillis();
  long execTime = afterTime - beforeTime; // 実行時間の取得
  ・・・
}

引数の取得

引数の取得はProceedingJoinPointに対して、getArgs()メソッドを呼び出すだけです。これはJoinPointを使用する場合でも同じです。

Object[] args = pjp.getArgs();

戻り値の取得

戻り値はProceedingJoinPoint#proceed()の呼び出し結果です。実際に呼び出されるメソッドが戻り値を返しているのであればその値が返され、戻り値を返さないのであればnullが返されます。

Object retVal = pjp.proceed();

Log4jの使用

まず$SPRING_HOME/lib/log4j/log4j-1.2.14.jarをビルドパスに加えます。

最初にLoggerの宣言を行います。Aspectクラスに以下のようにLoggerを加え、

private static Logger logger = Logger.getLogger(LoggingAspect.class);

Around Advice内にログ出力コードを記述します。

// 呼び出し前ログ出力
StringBuilder beforeSB = ・・・;
・・・
logger.debug(beforeSB.toString());

また、以下のファイルをlog4j.xmlという名前で作成し、プロジェクトのソースフォルダへ配置して下さい。ソースフォルダへ配置するのは、log4j.xmlを編集すると自動的にクラス出力フォルダへlog4j.xmlのコピーが配置されるため、log4j.xmlの反映の手間が省けるからです。

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

    <appender name="FILE"
        class="org.apache.log4j.RollingFileAppender">
        <param name="File" value="log/trace.log" />
        <param name="Append" value="false" />
        <param name="MaxFileSize" value="1MB" />
        <param name="MaxBackupIndex" value="10" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d %-5p %m%n" />
        </layout>
    </appender>

    <appender name="STDOUT" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%m%n" />
        </layout>
    </appender>

    <logger name="aspect.LoggingAspect">
        <level value="debug" />
        <appender-ref ref="STDOUT" />
        <appender-ref ref="FILE" />
    </logger>

</log4j:configuration>

Aspectの実装

最終的なAspectは以下のようになりました。尚、以下で使われているStringBuilderクラスはJava5で追加されたStringBufferの非同期版です。StringBufferでも結果は同じです。

package aspect;

@Aspect
public class LoggingAspect {

    private static Logger logger = Logger.getLogger(LoggingAspect.class);

    @Pointcut("execution(* service.*.*(..))")
    public void businessService() {}

    /**
     * serviceパッケージに属するクラスのpublicメソッド呼び出し前後に
     * ログを出力する。
     * <p>
     * クラス名 メソッド名 START [パラメータ1, パラメータ2, ...] 
     * クラス名 メソッド名 END 実行時間(ms) [戻り値]
     */
    @Around("aspect.LoggingAspect.businessService()")
    public Object logAroundExecution(ProceedingJoinPoint pjp) 
      throws Throwable {
        String cName = pjp.getTarget().getClass().getName();
        String mName = pjp.getSignature().getName();
        Object[] args = pjp.getArgs();

        // 呼び出し前ログ出力
        StringBuilder beforeSB = createSB(cName, mName);
        beforeSB.append(" START ");
        for (Object arg : args) {
            beforeSB.append(arg);
            beforeSB.append(", ");
        }
        if (beforeSB.lastIndexOf(", ") == beforeSB.length() - 2) {
            beforeSB.delete(beforeSB.length() - 2, beforeSB.length());
        }
        logger.debug(beforeSB.toString());

        long beforeTime = System.currentTimeMillis();
        Object retVal = pjp.proceed();
        long afterTime = System.currentTimeMillis();
        long execTime = afterTime - beforeTime;

        // 呼び出し後ログ出力
        StringBuilder afterSB = createSB(cName, mName);
        afterSB.append(" END ");
        afterSB.append(execTime);
        afterSB.append("(ms) ");
        if (retVal != null) {
            afterSB.append(retVal);
        }
        logger.debug(afterSB.toString());

        return retVal;
    }

    private StringBuilder createSB(String cName, String mName) {
        StringBuilder sb = new StringBuilder();
        sb.append(cName);
        sb.append(" ");
        sb.append(mName);
        sb.append("()");
        return sb;
    }
}

テスト実行

BumonServiceTestを実行すると、コンソールに以下のように出力されました。ログファイルには日付付きで出力されています。ちょっと見にくいですが、メソッドの引数や戻り値の確認がSpring AOPで簡単にできるようになりました。

service.BumonService registBumon() START Bumon[cdBumon=000001,nmBumon=ESC]
service.BumonService registBumon() END 594(ms) 
service.BumonService getBumon() START 000001
service.BumonService getBumon() END 31(ms) Bumon[cdBumon=000001,nmBumon=ESC]
service.BumonService removeBumon() START 000001
service.BumonService removeBumon() END 78(ms) 
service.BumonService registBumon() START Bumon[cdBumon=000001,nmBumon=ESC]
service.BumonService registBumon() END 140(ms) 
service.BumonService registBumon() START Bumon[cdBumon=000002,nmBumon=OSK]
service.BumonService registBumon() END 78(ms) 
service.BumonService getAllBumon() START 
service.BumonService getAllBumon() END 0(ms) [Bumon[cdBumon=000001,nmBumon=ESC], 
Bumon[cdBumon=000002,nmBumon=OSK]]
service.BumonService removeBumon() START 000001
service.BumonService removeBumon() END 172(ms) 
service.BumonService removeBumon() START 000002
service.BumonService removeBumon() END 47(ms) 

今回のまとめ

今回はSpring AOPを使ってロギングアスペクトを実装する方法について紹介しました。AspectJと比べてコンパイルやWeavingが必要なく、手軽に導入しやすくなっています。デバッグやプロファイリングにも応用できるでしょう。本稿がSpring AOPの理解の手助けになれば幸いです。

今回までに作成したファイルはここからダウンロードできます。

Spring 2.0 トップへ

資料室へ戻る


Copyright (c) 2007 OKI Software Co., Ltd.