SpringBoot AOP でメソッドの実行時間を計測する

エキサイト株式会社メディア開発の佐々木です。

SpringBoot/AOPでメソッドの実行時間を計測します。計測は重要です。

依存関係の解消

Gradleで依存関係を解消します。

dependencies {
     ...
     implementation "org.springframework.boot:spring-boot-starter-aop"   // これを追加
     ...
}

マーカーアノテーション

マーカーアノテーションを作成しておきます。計測したいメソッドにマーカーアノテーションをつけるだけで計測対象になるので、とても便利です。

/**
 * メソッドの実行速度を計測する用のマーカアノテーション.
 * 実際の計測は {@link jp.co.excite.web.aop.LatencyMonitorAop} で実行.
 */
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
@Documented
public @interface LatencyMonitor {

}

RetensionPolicy が大事で、 RUNTIME をつけないと実行時に動作しないので気をつけてください。

AOPを設定

AOPを下記のように定義します。今回は@Aroundを使います。これはメソッドの開始と終了のときに処理を差し込むことができるAOPになります。

@Aspect // AOPであることを明示
@Component
@Slf4j
public class LatencyMonitorAop {

    @Around("@annotation(jp.co.excite.web.aop.LatencyMonitor)")
    public Object monitor(ProceedingJoinPoint joinPoint) throws Throwable {
        long start = System.currentTimeMillis();  // メソッド開始前のシステム時刻
        Object proceed = joinPoint.proceed();     // メソッド実行
        long end = System.currentTimeMillis();   // メソッド終了後のシステム時刻
        log.info("{} {}   method latency: {} ms."    // メソッドの実行時間の出力
                , joinPoint.getTarget().getClass().getName()
                , joinPoint.getSignature().getName()
                , end - start);
        return proceed;  // メソッドの内容を返却
    }
}

開始時と終了時にシステム時刻をとっておき差分をとります。

メソッドに付与

計測したいメソッドにはじめに定義したマーカーアノテーションをつけるだけです。

@Controller
@RequestMapping
public class RootController {

    @GetMapping("fast")
    @LatencyMonitor // アノテーションをつけるだけ
    public String fast(){
        return "index";
    }

    @GetMapping("slow")
    @LatencyMonitor  // アノテーションをつけるだけ
    public String slow() throws InterruptedException {

        Thread.sleep(2000);

        return "index";
    }
}

実行ログです。

2021-05-13 00:45:07.245  INFO 17967 --- [nio-8080-exec-4] jp.co.excite.web.aop.LatencyMonitorAop   : jp.co.excite.web.controller.RootController fast   method latency: 0 ms.
2021-05-13 00:45:11.836  INFO 17967 --- [nio-8080-exec-5] jp.co.excite.web.aop.LatencyMonitorAop   : jp.co.excite.web.controller.RootController slow   method latency: 2004 ms.

それぞれ、計測されています。

最後に

SpringAOPを使ってメソッドの中身を変更せずに、実行時間を計測する機能を作ってみました。AOPはとても便利ですが、どこで何が行われてるかわからなくなるので、マーカーアノテーション等をトリガーにした作りにするのがよさそうです。AOPは補助的な処理にとても向いてると思うので、これも拡張していければと思います。

エキサイトではフロントエンジニア、バックエンドエンジニア、アプリエンジニアを随時募集しております。長期インターンも歓迎していますので、興味があれば連絡いただければと思います。