Wildfly 8でメソッドの実行時間を取るインタセプターを作る

メソッドの実行時間を取りたいなぁというとき、メソッドの最初と最後でSystem.currentTimeMillis()してその差をログに出す、なんてことをよくやるわけですが（プロファイラ使えばそもそもそんなことやらなくていいんでしょうが）、直接メソッド内に処理を書くのもアレなので、インタセプターとして実装してみました。

アノテーションの定義

@ElapsedTimeというアノテーションをメソッドに付けるとログが出るようにします。

@InterceptorBinding
@Target({ ElementType.METHOD, ElementType.TYPE })
@Retention(RetentionPolicy.RUNTIME)
@Priority(Interceptor.Priority.APPLICATION + 20)
public @interface ElapsedTime {

}

実装

実装は至って単純で、最初に書いた通りです。

@Interceptor
@Dependent
@ElapsedTime
public class ElapsedTimeInterceptor implements Serializable {
    private static final long serialVersionUID = 1L;

    @AroundInvoke
    public Object invoke(InvocationContext ic) throws Exception {
        Logger log = Logger
                .getLogger(ic.getTarget().getClass().getSuperclass());
        String methodName = ic.getMethod().getName();

        long begin = System.currentTimeMillis();
        Object result = ic.proceed();
        long end = System.currentTimeMillis();

        log.infof("METHOD=%s ELAPSEDTIME=%d msec", methodName, (end - begin));

        return result;
    }
}

getLoggerでgetSuperClassしてるのは、インジェクションされるクラスの実態は内部的に作られた元のクラスを継承したプロキシクラス（？）になるからです。逆にインジェクションされていないと期待値と違うかも。

あとはメソッドに@ElapsedTimeを付けて実行…と思ったらこれだけでは効かないようです。

beans.xml

ちゃんと定義しないとダメっぽい。

<?xml version="1.0"?>
<beans xmlns="http://xmlns.jcp.org/xml/ns/javaee" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/javaee http://xmlns.jcp.org/xml/ns/javaee/beans_1_1.xsd"
    version="1.1" bean-discovery-mode="all">

    <interceptors>
        <class>com.github.chanko.cdi.ElapsedTimeInterceptor</class>
    </interceptors>
</beans>

これでメソッド実行時に経過時間をログに出してくれます。
beans.xmlへの定義が必須っぽいので、アノテーションは必要なところに書いておいて、開発時だけbeans.xmlで有効化し、本番リリース時は無効にする、なんてこともできそうな気がする。