В процессе работы над одной из задач возникла необходимость промониторить время исполнения отдельных участков кода одного из микросервисов для того, чтобы отловить узкие места и попытаться эту ситуацию исправить.
Т.к. речь шла о сервисе, который был написан довольно давно, и в него многие месяцы не вносились изменения, повинуясь принципу “работает - не трогай”, я решил постараться сделать это, не прикасаясь к самому коду сервиса.
Для такой задачи самым очевидным решением видится использование 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
Спасибо за внимание!
Комментарии (13)
evseevvd
00.00.0000 00:00Так есть же micro benchmarks https://www.baeldung.com/java-microbenchmark-harness для спринга. В чем смысл своего велосипеда?
GekIn Автор
00.00.0000 00:00В заметке я уточнил, что хотелось иметь возможность включать\выключать функционал, а также выбирать участки кода для профилирования "на лету" с помощью конфиг файлов, без релизов и пересборки. В варианте по ссылке, насколько вижу, все равно придется навешивать аннотации в самом коде сервиса
evseevvd
00.00.0000 00:00с помощью конфиг файлов это не на лету это минимум рестарт пода/контейнера/сервиса, мерить benchmark как раз имеет смысл до того как придет баг с прода что все медленно. если уж и подрубать на лету то это MBean(JMX)
GekIn Автор
00.00.0000 00:00Да, согласен, не совсем "на лету", но всё же сильно быстрее и удобнее чем через код и релиз (во всяком случае в разрезе той задачи, что передо мной стояла). Спасибо, посмотрю в сторону JMX
zKey
00.00.0000 00:00Костыль. Есть много более подходящих решений этой задачи.
GekIn Автор
00.00.0000 00:00+1Возможно, буду благодарен, если поделитесь
yeap
00.00.0000 00:00+2Я бы еще предложить результаты профилирования вынести в метрики(prometheus), чтобы удобно находить медленные участки кода, настроить алертинг и построить графики.
Метрики времени выполнения + счетчики`{package=“ru.alfastrah.profilingdemo.service”,class=“SomeService”, method=“doSomething”}`
GekIn Автор
00.00.0000 00:00Согласен, удобная была бы доработка, но на тот момент это бы сильно вышло за пределы необходимого по задаче, т.к. суть была просто в обнаружении проблемного места, а не в каком-то перманентном мониторинге. В целом, если говорить о постоянном мониторинге, то у нас настроен prometheus|grafana по эндпойнтам сервиса, и этого хватает, чтобы реагировать на инциденты
LeshaRB
00.00.0000 00:00-1А почему не сделать через аннотации? Это ведь удобнее, чем прописывать пути в настройках
GekIn Автор
00.00.0000 00:00В статье отдельно отмечено, что я хотел иметь возможность выбирать путь именно через конфиги, чтобы не заниматься релизом и пересборкой каждый раз, когда потребуется промониторить другой участок кода
svp7093
Решение полезное, но есть одно "но". "Работает - не трогай" и AOP в жаве - это немножко несовместимые вещи. Вы, фактически, скрыто навешиваете кучу прокси-классов на уже работающий код. И вот эта орава классов может легко что-нибудь сломать и/или замедлить. Если уж вы всё равно пересобираете код и надо промониторить одну функцию - так и вставьте туда таймер. По крайней мере будете уверены, что ничего больше в байт-коде не изменилось.
GekIn Автор
Про навешивание прокси - согласен. Смысл как раз был в том, что пересобирать код придется один раз - во время добавления стартера с конфигурацией, а включать\выключать функционал прокси и выбирать какой кусок кода мониторить можно уже без релизов и пересборки