Ведение журнала производительности Spring

1. Обзор

В этом руководстве мы рассмотрим несколько основных опций, предлагаемых Spring Framework для мониторинга производительности.

2. PerformanceMonitorInterceptor

В качестве простого решения для получения базовых функций мониторинга времени выполнения наших методов мы можем использовать класс PerformanceMonitorInterceptor из Spring AOP (аспектно-ориентированное программирование).

Spring AOP позволяет определять сквозные проблемы в приложениях, то есть код, который перехватывает выполнение одного или нескольких методов, чтобы добавить дополнительную функциональность.

Класс PerformanceMonitorInterceptor — это перехватчик, который можно связать с любым пользовательским методом, который будет выполняться одновременно. Этот класс использует экземпляр StopWatch для определения времени начала и окончания выполнения метода.

Давайте создадим простой класс 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, нам нужно определить pointcut и советник:

@Configuration
@EnableAspectJAutoProxy
@Aspect
public class AopConfiguration {
    
    @Pointcut(
      "execution(public String com.foreach.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.foreach.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();
    }
}

Pointcut содержит выражение, которое идентифицирует методы, которые мы хотим перехватить — в нашем случае это метод getFullName() класса PersonService .

После настройки bean- компонента performanceMonitorInterceptor() нам нужно связать перехватчик с pointcut. Это достигается с помощью советника, как показано в примере выше.

Наконец, аннотация @EnableAspectJAutoProxy включает поддержку AspectJ для наших bean-компонентов. Проще говоря, AspectJ — это библиотека, созданная для упрощения использования Spring AOP с помощью удобных аннотаций, таких как @Pointcut .

После создания конфигурации нам нужно установить уровень журнала класса перехватчика на TRACE , так как это уровень, на котором он регистрирует сообщения.

Например, используя 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.foreach.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!");
            }            
        }
    }
}

Необходимо выполнить те же шаги для связывания пользовательского перехватчика с одним или несколькими методами, что и в предыдущем разделе.

Давайте определим pointcut для метода getAge() класса PersonService и свяжем его с созданным нами перехватчиком:

@Pointcut("execution(public int com.foreach.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.foreach.performancemonitor.AopConfiguration.myMonitor()");
    return new DefaultPointcutAdvisor(pointcut, myPerformanceMonitorInterceptor());
}

Давайте установим уровень журнала INFO для пользовательского перехватчика:

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

Выполнение метода g etAge() привело к следующему результату:

2017-01-08 19:19:25 INFO PersonService:26 - 
  Method com.foreach.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.foreach.performancemonitor.PersonService.getAge execution lasted:50 ms
2017-01-08 19:19:25 INFO PersonService:34 - 
  Method com.foreach.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!

4. Вывод

В этом кратком руководстве мы представили простой мониторинг производительности в Spring.

Как всегда, полный исходный код этой статьи можно найти на Github .