Spring Boot. Настройка профилирования времени выполнения

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

Т.к. речь шла о сервисе, который был написан довольно давно, и в него многие месяцы не вносились изменения, повинуясь принципу “работает - не трогай”, я решил постараться сделать это, не прикасаясь к самому коду сервиса.

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

В сети множество туториалов о предоставляемых Spring Boot средствах AOP логирования, один из которых был выбран за основу и немного доработан для удобства использования.

Входные данные: Java, Spring Boot 2.5.6., Maven 3.6.3.
Используемые зависимости:

<parent>  
    <groupId>org.springframework.boot</groupId>  
    <artifactId>spring-boot-starter-parent</artifactId>  
    <version>2.5.6</version>
</parent>

<dependency>  
    <groupId>org.springframework.boot</groupId>  
    <artifactId>spring-boot-starter-web</artifactId>  
</dependency>

<dependency>  
    <groupId>org.springframework.boot</groupId>  
    <artifactId>spring-boot-starter-aop</artifactId>  
</dependency>

Для примера сделаем простейший контроллер и пару сервисов:

package ru.alfastrah.profilingdemo.controller;  
  
import org.springframework.web.bind.annotation.GetMapping;  
import org.springframework.web.bind.annotation.RestController;  
import ru.alfastrah.profilingdemo.service.SomeService;  
  
@RestController  
public class SomeController {  
  
    private final SomeService service;  
  
    public SomeController(SomeService service) {  
        this.service = service;  
    }  
  
    @GetMapping(path = "/something")  
    public String doSomething() throws InterruptedException {  
        return service.doSomething();  
    }  
}

package ru.alfastrah.profilingdemo.service;  
  
import org.springframework.stereotype.Service;  
import java.util.concurrent.TimeUnit;  
  
@Service  
public class SomeService {  
  
    private final SomeAnotherService anotherService;  
  
    public SomeService(SomeAnotherService anotherService) {  
        this.anotherService = anotherService;  
    }  
  
    public String doSomething() throws InterruptedException {  
        TimeUnit.SECONDS.sleep(1);  
        String somethingElse = anotherService.doSomethingElse();  
        return "did something and " + somethingElse;  
    }  
}

Туториал содержал примерно такую конфигурацию для включения AOP профилирования:

package ru.alfastrah.profilingdemo;  
  
import org.aspectj.lang.annotation.Pointcut;  
import org.springframework.aop.Advisor;  
import org.springframework.aop.aspectj.AspectJExpressionPointcut;  
import org.springframework.aop.interceptor.PerformanceMonitorInterceptor;  
import org.springframework.aop.support.DefaultPointcutAdvisor;  
import org.springframework.context.annotation.Bean;  
import org.springframework.context.annotation.Configuration;  
import org.springframework.context.annotation.EnableAspectJAutoProxy;  
  
@Configuration  
@EnableAspectJAutoProxy  
public class ProfilingConfiguration {  
  
    @Pointcut("execution(public String ru.alfastrah.profilingdemo.service.SomeService.doSomething(..))")  
    public void monitor() { }  
  
    @Bean  
    public PerformanceMonitorInterceptor interceptor() {  
        return new PerformanceMonitorInterceptor();  
    }  
  
    @Bean  
    public Advisor performanceMonitorAdvisor() {  
        var pointcut = new AspectJExpressionPointcut();  
        pointcut.setExpression("ru.alfastrah.ProfilingConfiguration .monitor()");  
        return new DefaultPointcutAdvisor(pointcut, interceptor());  
    }  
}

Остается только выставить в конфигурации для PerformanceMonitorInterceptor уровень логирования в TRACE:

logging.level.org.springframework.aop.interceptor.PerformanceMonitorInterceptor=TRACE

И всё заработает, в логах мы увидим время выполнения метода doSomething:

o.s.a.i.PerformanceMonitorInterceptor : StopWatch 'ru.alfastrah.profilingdemo.service.SomeService.doSomething': running time = 3022447900 ns

В целом, цель достигнута, но есть несколько моментов, которые мне бы хотелось (на мой взгляд) улучшить.

Во-первых, смущает вывод времени в наносекундах. Такая точность в нашем случае ни к чему, а читать такие логи становится затруднительно. В данном случае используется готовая реализация AbstractMonitoringInterceptor - PerformanceMonitorInterceptor. Я не нашел способа изменить её поведение в этой части, поэтому пришлось сделать свою:

public class CustomPerformanceMonitorInterceptor extends AbstractMonitoringInterceptor {  
  
  @Override  
  protected Object invokeUnderTrace(MethodInvocation invocation, Log logger) throws Throwable {  
        String name = this.createInvocationTraceName(invocation);  
        var stopWatch = new StopWatch(name);  
        stopWatch.start(name);  
  
        Object result;  
        try {  
            result = invocation.proceed();  
        } finally {  
            stopWatch.stop();  
            this.writeToLog(logger, String.format("Profiling: %s. Running time: %f sec", name, stopWatch.getTotalTimeSeconds()));  
        }  
  
        return result;  
    }  
}

Добавляем наш интерсептор в конфигурацию, попутно избавляясь от излишнего объявления его в качестве бина:

@Bean  
public Advisor performanceMonitorAdvisor() {  
    var pointcut = new AspectJExpressionPointcut();  
    pointcut.setExpression("ru.alfastrah.profilingdemo.ProfilingConfiguration.monitor()");  
    return new DefaultPointcutAdvisor(pointcut, new CustomPerformanceMonitorInterceptor());  
} 

И не забываем изменить в конфигурации уровень логирования для своей реализации:

logging.level.ru.alfastrah.profilingdemo.config.CustomPerformanceMonitorInterceptor=TRACE

И получаем гораздо более читабельные логи:

.p.c.CustomPerformanceMonitorInterceptor : Profiling: ru.alfastrah.profilingdemo.service.SomeService.doSomething. Running time: 3,018584 sec

Во-вторых, мы избежали внесения изменений в код сервисов, но выбор метода для профилирования по-прежнему происходит через код в конфигурационном классе, что влечет за собой соответствующие трудности, если потребуется изменить эту настройку - ревью, мердж, релиз и т.п. Мне бы хотелось иметь возможность выбирать методы для профилирования в конфигурационном файле, который будет находиться в конфиг-сервере и подтягиваться "на лету". По этой же причине мною не был использован вариант конфигурации с помощью аннотаций над самими классами\методами, которые мы хотим профилировать. Безусловно, у варианта с конфигурацией в файле, а не через аннотации, есть свои недостатки. К примеру, придется следить за изменениями в названиях пакетов, классов, методов. Но у меня не было цели написать какой-то постоянный мониторинг работы сервиса, а нужен был легкий инструмент для определения конкретной проблемной точки, после чего профилирование можно отключить, не оставив за собой никаких следов в коде.

Итак, для того, чтобы перейти на настройку через конфигурационный файл, избавимся от аннотации Pointcut и воспользуемся внедрением значения через Value:

  @Value("${profiling.pointcuts}")  
  private String pointcuts;  
  
  @Bean  
  public Advisor performanceMonitorAdvisor() {  
        var pointcut = new AspectJExpressionPointcut();  
        pointcut.setExpression(pointcuts);  
        return new DefaultPointcutAdvisor(pointcut, new CustomPerformanceMonitorInterceptor());  
    }

В конфигурационном файле пропишем expression (подробнее о которых можно почитать в документации):

profiling.pointcuts=execution(public * ru.alfastrah.profilingdemo.service.SomeService.doSomething(..))

Если нам нужно логировать несколько методов, то добавим их через || :

profiling.pointcuts=execution(public * ru.alfastrah.profilingdemo.service.SomeService.doSomething(..)) || \  
execution(public * ru.alfastrah.profilingdemo.service.SomeAnotherService.doSomethingElse(..))

либо можно указать путь к целому пакету:

profiling.pointcuts=execution(public * ru.alfastrah.profilingdemo..*(..))

Уже лучше, вносить изменения можно через конфигурационный файл, код остается неизменным, но теперь смущает сложность написания всех этих execution-ов, куча скобок, звездочек и т.п. - легко ошибиться, да и читается так себе.

Учитывая, что для логирования нам вряд ли понадобятся все возможности pointcut expressions, немного упростим конфигурацию - добавим в конфиг класс метод для составления выражения из обычного пути к пакету\классу\методу:

@Value("${profiling.pointcuts}")  
private List<String> pointcuts;  
  
@Bean  
public Advisor performanceMonitorAdvisor() {  
    var pointcut = new AspectJExpressionPointcut();  
    pointcut.setExpression(formExpressions());  
    return new DefaultPointcutAdvisor(pointcut, new CustomPerformanceMonitorInterceptor());  
}  
  
private String formExpressions() {  
    return pointcuts  
            .stream()  
            .map(this::formExpression)  
            .collect(Collectors.joining(" || "));  
}
  
private String formExpression(String pointcut) {  
    return pointcut.endsWith(")") ? execForMethod(pointcut) : execForPackageClass(pointcut);  
}  
  
private String execForMethod(String pointcut) {  
    return String.format("execution(public * %s(..))", pointcut.replace("()", ""));  
}  
  
private String execForPackageClass(String pointcut) {  
    return String.format("execution(public * %s..*(..))", pointcut);  
}

Теперь в конфигурационном файле можно просто указывать путь к пакету\классу\методу в виде списка:

profiling.pointcuts=ru.alfastrah.profilingdemo.service.SomeService.doSomething(), \  
 ru.alfastrah.profilingdemo.service.SomeAnotherService, \  
 ru.alfastrah.profilingdemo.controller 

Попробуем запустить сервис и увидим, что все три способа (с указанием пакета, класса, метода) работают:

.a.p.CustomPerformanceMonitorInterceptor : Profiling: ru.alfastrah.profilingdemo.service.SomeAnotherService.doSomethingElse. Running time: 2,010053 sec
.a.p.CustomPerformanceMonitorInterceptor : Profiling: ru.alfastrah.profilingdemo.service.SomeService.doSomething. Running time: 3,015384 sec
.a.p.CustomPerformanceMonitorInterceptor : Profiling: ru.alfastrah.profilingdemo.controller.SomeController.doSomething. Running time: 3,018843 sec

В-третьих, хотелось дать возможность коллегам и себе легко добавлять конфигурацию в существующие\новые модули с минимальными усилиями и дублированием кода. Для этого превратим нашу конфигурацию в spring-starter.

Создадим новый проект (или модуль) для стартера, pom файл которого будет выглядеть следующим образом:

<?xml version="1.0" encoding="UTF-8"?>  
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"  
  xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">  
    <modelVersion>4.0.0</modelVersion>  
    <parent>  
        <groupId>org.springframework.boot</groupId>  
        <artifactId>spring-boot-starter-parent</artifactId>  
        <version>2.5.6</version>  
        <relativePath/> <!-- lookup parent from repository -->  
  </parent>  
    <groupId>ru.alfastrah</groupId>  
    <artifactId>profiling-demo-starter</artifactId>  
    <version>0.0.1-SNAPSHOT</version>  
    <name>profiling-demo-starter</name>  
    <description>profiling-demo-starter</description>  
    <properties>  
        <java.version>11</java.version>  
    </properties>  
    <dependencies>  
        <dependency>  
            <groupId>org.springframework.boot</groupId>  
            <artifactId>spring-boot-starter</artifactId>  
        </dependency>  
  
    </dependencies>  
  
</project>

Перенесем в стартер ProfilingConfiguration и CustomPerformanceMonitorInterceptor, а также пропишем автоконфиг в файле resources/META-INF/spring.factories:

org.springframework.boot.autoconfigure.EnableAutoConfiguration=ru.alfastrah.profilingdemostarter.ProfilingConfiguration

В целом, этого достаточно для того, чтобы стартер можно было использовать, но хотелось бы еще иметь возможность отключать функционал профилирования, когда он перестает быть нужен. Для этого можно было бы использовать аннотацию ConditionalOnProperty с value, указывающим на наличие конфига profiling.pointcuts. Но в таком варианте приложение упадет с исключением на старте при попытке настроить бин Advisor в случае, если в profiling.pointcuts будет пустая строка, а мне не хотелось бы, чтобы приложение падало из-за забытой настройки профилирования. Поэтому было решено использовать такую настройку с применением Spring Expression Language:

@Configuration  
@EnableAspectJAutoProxy  
@ConditionalOnExpression("T(org.springframework.util.StringUtils).hasText('${profiling.pointcuts:}')")  
public class ProfilingConfiguration {
  ...
}

В таком варианте бин с настройками профилирования будет создан, только если присутствует конфиг profiling.pointcuts, и он содержит какой-либо текст.

В итоге у нас получился стартер, который позволит легко добавить и гибко настроить логирование времени выполнения в любой сервис, не затрагивая его код. Всё, что от нас требуется, - лишь добавить зависимость:

<dependency>  
    <groupId>ru.alfastrah</groupId>  
    <artifactId>profiling-demo-starter</artifactId>  
    <version>0.0.1-SNAPSHOT</version>  
</dependency>

И прописать настройки в конфигурационном файле:

logging.level.ru.alfastrah.profilingdemostarter.CustomPerformanceMonitorInterceptor=TRACE

profiling.pointcuts=ru.alfastrah.profilingdemo.service.SomeService.doSomething(), \  
 ru.alfastrah.profilingdemo.service.SomeAnotherService, \  
 ru.alfastrah.profilingdemo.controller

Спасибо за внимание!