Накладные расходы из-за ведения журнала AOP
Я планирую регистрировать время выполнения всех методов REST API. Для этого я использую АОП следующим образом:
@Aspect
@Component
@Slf4j
@ConditionalOnExpression("${aspect.enabled:true}")
public class ExecutionTimeAdvice {
@Around("@annotation(TrackExecutionTime)")
public Object executionTime(ProceedingJoinPoint point) throws Throwable {
long startTime = System.currentTimeMillis();
Object object = point.proceed();
long endtime = System.currentTimeMillis();
log.info("Class Name: " + point.getSignature().getDeclaringTypeName() + ". Method Name: " + point.getSignature().getName() + ". Time taken for Execution is : " + (endtime - startTime) + "ms");
return object;
}
}
@Service
public class MessageService {
@TrackExecutionTime
@Override
public List<AlbumEntity> getMessage() {
return "Hello message";
}
}
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface TrackExecutionTime {}
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-aop</artifactId>
</dependency>
Но использование АОП приводит к снижению производительности. Существует задержка во времени ответа службы более 200 мс, т. е. накладные расходы на производительность.
Какие эффективные способы существуют для реализации регистрации времени выполнения? Могу ли я использовать AspectJ для большей эффективности? Или есть какие-нибудь альтернативы АОП? Можем ли мы использовать АОП более эффективно?
Я использую версию весенней загрузки 3.2.2.
Можете ли вы подтвердить свое утверждение доказательствами? Я измерил ваш аспект с помощью 1000 вызовов, войдя в консоль Spring Boot. Общее время выполнения пустого метода составило 80 мс, т.е. на порядки быстрее, чем 200 мс на вызов. Я думаю, вы либо измеряете не то, либо, возможно, синхронно регистрируетесь в очень медленной базе данных. Кроме того, почему вы вручную создаете сложное сообщение журнала, а не просто регистрируете точку соединения вместе со временем выполнения?
Но на самом деле log.info(point + " - execution time " + (System.currentTimeMillis() - startTime) + " ms") по-прежнему составляет 80 мс для 1000 вызовов в общей сложности. Ваше узкое место, конечно, не Spring AOP, это что-то другое, возможно, журналирование как таковое. Вы можете легко проверить это, временно добавив операторы синхронизации и регистрации в этот метод вручную. Разница во времени выполнения должна быть едва измеримой по сравнению с решением АОП. Переход от Spring AOP на основе прокси к собственному AspectJ также может ускорить процесс, но в данном случае проблема не в AOP.
Хорошо, я быстро измерил время выполнения для синхронизации и регистрации непосредственно в пустом методе и без аспекта. 40 мс (по сравнению с 80 мс у Spring AOP) на 1000 вызовов, т. е. накладные расходы AOP составляют 40 нс (наносекунд) на один вызов на моем старом ноутбуке 2017 года, вход в консоль IntelliJ IDEA и прокрутку. При использовании собственного AspectJ накладные расходы должны практически снизиться до нуля, но это оптимизация не той части приложения, если вы теряете 200 мс на вызов в другом месте, например. в самой конфигурации платформы ведения журнала. Это не исчезнет при входе в систему с использованием другой технологии.
Следуйте полученному ответу и проверьте, лучше ли он написанной вами собственной реализации. Это то, что я должен был дать в качестве ответа.
@krigaex .. Я планирую использовать AspectJ с плетением времени компиляции для версии Java 17. Я не могу найти подходящий плагин maven для компилятора аспекта. Можете ли вы предоставить несколько образцов того же самого?
Вы также вообще не отреагировали на мои комментарии, объяснив, что проблема не в АОП, если логирование занимает 200 мс вместо нескольких нс.
@krigaex .. Ранее я проводил тестирование производительности в двух разных центрах обработки данных. Итак, была огромная задержка ... Прямо сейчас тестировалось в том же центре обработки данных ... Теперь я вижу задержку от 4 до 5 мс. Итак, в моем случае задержка происходит не со стороны АОП, а с двумя разными центрами обработки данных. Спасибо большое за объяснение..
Я так и думал. В следующий раз, пожалуйста, сначала измерьте и сравните правильные вещи, прежде чем тратить время на оптимизацию неправильных вещей. Я рад, что вы узнали, в чем проблема.
Ответы 1
Если вы включите Micrometer, Prometheus и Spring Boot Actuator, вы можете уменьшить накладные расходы на 200+ мс. Я предполагаю, что накладные расходы в 200+ мс связаны с ведением журнала. В этой статье дается хорошее описание использования аннотации @Timed для измерения времени выполнения общедоступного метода. Информация о таймере, такая как максимальное и общее время выполнения и количество событий, отображается при достижении конечной точки привода/Promethius. Вы получите среднее значение из общего количества и количества событий.
Ведьминскую версию
spring-bootты используешь?