Repositoryに定義した関数の実行時間とかをログに出力したくなった

今回は開発中にDBへアクセスしている関数やそれにかかわる関数の実行時間を知りたいというシーンがあり、確認したい関数全部に開始時刻をとって終了時刻をとって計算するコードを追加する。。。。などという面倒な実装はしたくなかったため、何かスマートな実装はないものかと考えました。

独自に定義したアノテーションが付与されている関数にだけ関心を持つAdviceを実装して実現する

まずはアノテーションを定義する

CheckLog.java

package com.example.app;

import java.lang.annotation.ElementType;
import java.long.annotation.Target;

// メソッドに付与するアノテーションを定義
@Target(ElementType.METHOD)
public @interface CheckLog {

}

Adviceの実装

AspectComponent.java

package com.example.app;

import org.aspectj.lang.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.ProceedingJoinPoint;
import org.springframework.stereotype.Component;

@Aspect
@Component
public class AspectComponent {
    
    @Around("@annotation(com.example.app.CheckLog)")
    public Object around(final ProceedingJoinPoint joinPoint) throws Throwable {
        String className = joinPont.getSignature().getDeclaringType().getSimpleName(); // クラス名
        String methodName = joinPoint.getSignature().getName(); // メソッド名

        long startTime = System.currentTimeMillis();
        Object retval = joinPoint.proceed();
        long endTime = System.currentTimeMillis();
        
        System.out.println("className={}, methodName={}, {}ms", className, methodName, startTime - endTime);
        return retval;
    }
}

重要なのがこの部分

@Around("@annotation(com.example.app.CheckLog)")

先ほど定義したアノテーションがついている関数の前後に、この後定義しているaroundメソッドの処理を適用するようにしています。
このポイントカット指定子を書き換えることで、あるクラスに定義されているメソッドすべてに適用するなどアドバイスのジョインポイントを変更することができます。

詳しくは以下の記事が参考になりました。

ここまでを追加すると、Repositoryで定義している関数に@CheckLogというアノテーションをつけるだけでその関数が呼ばれたときに実行時間を計測してログを出すことができます。

当然Serviceなどに定義した関数にもこのアノテーションは付けることができるので、SQLの実行にかかった時間以外にも計測することができます。

参考資料

蛇足

Stream apiを使ったツイートが上から下に流れないタイプのTwitterクライアントを開発しています。
ぜひ使ってみてください。