春のパフォーマンスログ - 開発者ドキュメント

1. 概要

このチュートリアルでは、Springフレームワークがパフォーマンス監視のために提供するいくつかの基本的なオプションを調べます。

2. PerformanceMonitorInterceptor

メソッドの実行時間の基本的な監視機能を取得するための簡単なソリューションである、Spring AOP（アスペクト指向プログラミング）のPerformanceMonitorInterceptorクラスを利用できます。

Spring AOPを使用すると、アプリケーションで横断的関心事を定義できます。つまり、機能を追加するために、1つ以上のメソッドの実行をインターセプトするコードを定義できます。

PerformanceMonitorInterceptor クラスは、同時に実行される任意のカスタムメソッドに関連付けることができるインターセプターです。このクラスは、 StopWatch インスタンスを使用して、メソッド実行の開始時刻と終了時刻を決定します。

監視する2つのメソッドを使用して、単純なPersonクラスとPersonServiceクラスを作成しましょう。

public class Person {
    private String lastName;
    private String firstName;
    private LocalDate dateOfBirth;

    // standard constructors, getters, setters
}

public class PersonService {
    
    public String getFullName(Person person){
        return person.getLastName()+" "+person.getFirstName();
    }
    
    public int getAge(Person person){
        Period p = Period.between(person.getDateOfBirth(), LocalDate.now());
        return p.getYears();
    }
}

Springモニタリングインターセプターを利用するには、ポイントカットとアドバイザーを定義する必要があります。

@Configuration
@EnableAspectJAutoProxy
@Aspect
public class AopConfiguration {
    
    @Pointcut(
      "execution(public String com.baeldung.performancemonitor.PersonService.getFullName(..))"
    )
    public void monitor() { }
    
    @Bean
    public PerformanceMonitorInterceptor performanceMonitorInterceptor() {
        return new PerformanceMonitorInterceptor(true);
    }

    @Bean
    public Advisor performanceMonitorAdvisor() {
        AspectJExpressionPointcut pointcut = new AspectJExpressionPointcut();
        pointcut.setExpression("com.baeldung.performancemonitor.AopConfiguration.monitor()");
        return new DefaultPointcutAdvisor(pointcut, performanceMonitorInterceptor());
    }
    
    @Bean
    public Person person(){
        return new Person("John","Smith", LocalDate.of(1980, Month.JANUARY, 12));
    }
 
    @Bean
    public PersonService personService(){
        return new PersonService();
    }
}

ポイントカットには、インターセプトするメソッド（この場合は、 PersonServiceクラスのgetFullName（）メソッド）を識別する式が含まれています。

performanceMonitorInterceptor（） Beanを構成した後、インターセプターをポイントカットに関連付ける必要があります。これは、上記の例に示すように、アドバイザーを通じて実現されます。

最後に、 @EnableAspectJAutoProxy アノテーションは、BeanのAspectJサポートを有効にします。簡単に言えば、AspectJは、@Pointcutのような便利なアノテーションを使用してSpringAOPを簡単に使用できるようにするために作成されたライブラリです。

構成を作成した後、インターセプタークラスのログレベルを設定する必要があります。これはメッセージをログに記録するレベルであるためです。

たとえば、Jog4jを使用すると、log4j.propertiesファイルを介してこれを実現できます。

log4j.logger.org.springframework.aop.interceptor.PerformanceMonitorInterceptor=TRACE, stdout

getAge（）メソッドを実行するたびに、コンソールログにTRACEメッセージが表示されます。

2017-01-08 19:19:25 TRACE 
  PersonService:66 - StopWatch 
  'com.baeldung.performancemonitor.PersonService.getFullName': 
  running time (millis) = 10

3. カスタムパフォーマンスモニタリングインターセプター

パフォーマンス監視の実行方法をさらに制御したい場合は、独自のカスタムインターセプターを実装できます。

このために、 AbstractMonitoringInterceptor クラスを拡張し、 invokeUnderTrace（）メソッドをオーバーライドして、メソッドの開始、終了、期間、およびメソッドの実行が続く場合の警告をログに記録しましょう。 10ミリ秒以上：

public class MyPerformanceMonitorInterceptor extends AbstractMonitoringInterceptor {
    
    public MyPerformanceMonitorInterceptor() {
    }

    public MyPerformanceMonitorInterceptor(boolean useDynamicLogger) {
            setUseDynamicLogger(useDynamicLogger);
    }

    @Override
    protected Object invokeUnderTrace(MethodInvocation invocation, Log log) 
      throws Throwable {
        String name = createInvocationTraceName(invocation);
        long start = System.currentTimeMillis();
        log.info("Method " + name + " execution started at:" + new Date());
        try {
            return invocation.proceed();
        }
        finally {
            long end = System.currentTimeMillis();
            long time = end - start;
            log.info("Method "+name+" execution lasted:"+time+" ms");
            log.info("Method "+name+" execution ended at:"+new Date());
            
            if (time > 10){
                log.warn("Method execution longer than 10 ms!");
            }            
        }
    }
}

カスタムインターセプターを1つ以上のメソッドに関連付けるための前のセクションと同じ手順に従う必要があります。

PersonServiceのgetAge（）メソッドのポイントカットを定義し、作成したインターセプターに関連付けましょう。

@Pointcut("execution(public int com.baeldung.performancemonitor.PersonService.getAge(..))")
public void myMonitor() { }
    
@Bean
public MyPerformanceMonitorInterceptor myPerformanceMonitorInterceptor() {
    return new MyPerformanceMonitorInterceptor(true);
}
    
@Bean
public Advisor myPerformanceMonitorAdvisor() {
    AspectJExpressionPointcut pointcut = new AspectJExpressionPointcut();
    pointcut.setExpression("com.baeldung.performancemonitor.AopConfiguration.myMonitor()");
    return new DefaultPointcutAdvisor(pointcut, myPerformanceMonitorInterceptor());
}

カスタムインターセプターのログレベルをINFOに設定しましょう。

log4j.logger.com.baeldung.performancemonitor.MyPerformanceMonitorInterceptor=INFO, stdout

g etAge（）メソッドを実行すると、次の出力が生成されました。

2017-01-08 19:19:25 INFO PersonService:26 - 
  Method com.baeldung.performancemonitor.PersonService.getAge 
  execution started at:Sun Jan 08 19:19:25 EET 2017
2017-01-08 19:19:25 INFO PersonService:33 - 
  Method com.baeldung.performancemonitor.PersonService.getAge execution lasted:50 ms
2017-01-08 19:19:25 INFO PersonService:34 - 
  Method com.baeldung.performancemonitor.PersonService.getAge 
  execution ended at:Sun Jan 08 19:19:25 EET 2017
2017-01-08 19:19:25 WARN PersonService:37 - 
  Method execution longer than 10 ms!