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

メソッドトレース方法

メソッドの入り口と出口にログをしかけるために、java.util.logging.Loggerクラスのenteringとexitingメソッドが提供されています。

import java.util.logging.Logger;

public class MyBusiness {
    public int calc(int a, int b) {
        logger.entering(MyBusiness.class.getName(), "calc", new Object[] {a, b});
        int returnValue = 0;
        // returnValueの計算
        logger.exiting(MyBusiness.class.getName(), "calc", returnValue);
        return returnValue;
    }

    public static void main(String[] args) {
        MyBusiness business = new MyBusiness();
        int ret = business.calc(1000, 2000);
    }

    private static Logger logger = Logger.getLogger(MyBusiness.class.getName());
}

メソッドのトレースはレベルFINERであり、デフォルトでは出力されないので、ログ出力設定を記述したプロパティファイル(例:mylogging.properties)を1つ用意します。

handlers = java.util.logging.ConsoleHandler
.level = ALL
java.util.logging.ConsoleHandler.level = ALL

JavaVM起動オプションで指定します。

D:\work>java -Djava.util.logging.config.file=mylogging.properties MyBusiness
2007/05/05 12:45:01 MyBusiness calc
詳細レベル (中): ENTRY 1,000 2,000
2007/05/05 12:45:01 MyBusiness calc
詳細レベル (中): RETURN 0
D:\work>

可変長引数版がほしいところ

J2SE 5.0で可変長引数が導入されたので、enteringの第3引数は配列バージョンでなく可変長引数で指定できると便利ですが、java.util.loggingはJava2 1.4で追加されたため、このあたりが使いにくいところです。

複数のリターン箇所を持つメソッドでは

リターンが一箇所のときはよいですが、複数個所でリターンする場合、上記コードではトレース漏れが発生します。

public class MyBusiness {
        :
    public int calc(int a, int b) {
        logger.entering(MyBusiness.class.getName(), "calc", new Object[] {a, b});
        int returnValue = 0;
        // 処理１の記述
　　　　if (specificCase) {
            return returnValue;
        }
        // 処理２の記述
        logger.exiting(MyBusiness.class.getName(), "calc", returnValue);
        return returnValue;
    }
}

この場合、処理1のリターンがロギングのメソッドトレースから漏れてしまいます。
そこで、終了時に必ず実行したい処理を記述するイディオムであるtry-finally構文を使用します。

public class MyBusiness {
        :
    public int calc(int a, int b) {
        logger.entering(MyBusiness.class.getName(), "calc", new Object[] {a, b});
        int returnValue = 0;
        try {
            // 処理１の記述
　　    　　if (specificCase) {
                return returnValue;
            }
            // 処理２の記述
            return returnValue;
        } finally {
            logger.exiting(MyBusiness.class.getName(), "calc", returnValue);
        }
    }
}

例外発生時と正常リターン時とともにメソッドトレースをロギングする場合はちょっと悩ましいです。安直には以下のコードになります。

public class MyBusiness {
        :
    public int calc(int a, int b) throws MyBusinessException {
        logger.entering(MyBusiness.class.getName(), "calc", new Object[] {a, b});
        int returnValue = 0;
        try {
            // 処理１の記述
　　    　　if (specificCase) {
                return returnValue;
            }
            // 処理２の記述
            return returnValue;
        } catch (MyBusinessException e) {
            logger.throwing(MyBusiness.class.getName(), "calc", e);
            throw e;
        } finally {
            logger.exiting(MyBusiness.class.getName(), "calc", returnValue);
        }
    }
}

finally句は例外発生時でも必ず実行されるので、例外発生のロギングとメソッドのリターンのロギングが両方出力されてしまいます。

superやthisを呼び出したいコンストラクタでのトレースログ

コンストラクタ中で親クラスのコンストラクタや自身のオーバーロードされたコンストラクタを呼び出すには、コンストラクタの先頭文にsuperまたはthisを記述します。

本来はその先頭文より前にロギングを行いたいのですが、現在のJavaではコンパイルエラーとなってしまいます。

  //　コンパイルエラー
  public MyBusiness() {
      logger.entering(MyBusiness.class.getName(), "MyBusiness");
      super("mybusiness");
      logger.exiting(MyBusiness.class.getName(), "MyBusiness");
  }

この場合、順番を入れ替えるしかないのですが、そうすると呼び出しの入れ子関係がログ出力上崩れてしまいます。

  //　コンパイルはOKだが・・・
  public MyBusiness() {
      super("mybusiness");
      logger.entering(MyBusiness.class.getName(), "MyBusiness");
      logger.exiting(MyBusiness.class.getName(), "MyBusiness");
  }

アスペクト指向の力を借りる

ということで、ロギングの問題を解決するには、アスペクト指向の力を借りるのがよいようです。

AspectJでは、メソッドの呼び出し時、メソッドからのreturnによる復帰時、メソッドの例外による中断時に所定の処理を実行するよう仕掛けることができます。

torutkのブログ

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