spring-projects / spring-framework

Spring Framework
https://spring.io/projects/spring-framework
Apache License 2.0
56.3k stars 37.99k forks source link

Execution order of @Timed and @Transactional #33595

Open dkroehan opened 2 days ago

dkroehan commented 2 days ago

I use micrometer in a Spring Boot application to measure the execution time of a method. Given the following (Kotlin) method:

class MyClass(...) {

  @Timed(value = "my_timer")
  @Transactional
  fun doSomething() {
    // Some code that performs changes on the database
  }
}

I would expect that the @Timed annotation measures the total time that the method execution takes including the @Transactional handling. I compared it to measuring the time outside, as in the following example:

val start = System.nanoTime()
myClass.doSomething()
timer.record(System.nanoTime() - start, TimeUnit.NANOSECONDS)

Since the time measuring is different I did some debugging and found out that the underlying io.micrometer.core.aop.TimedAspect runs after the @Transactional processing, which means the order is as follows:

  1. Transaction start
  2. Time measurement starts
  3. Method body execution
  4. Time measurement stops
  5. Transaction commits

What I would like to achieve is the following order:

  1. Time measurement starts
  2. Transaction start
  3. Method body execution
  4. Transaction commits
  5. Time measurement stops

I already opened an issue at micrometer: https://github.com/micrometer-metrics/micrometer/issues/5235, but they pointed me to the spring-framework issue tracker.

I already tried to use @DeclarePrecedence like this + @EnableAspectJAutoProxy on the @SpringBootApplication class, but it had no effect.

@Aspect
@DeclarePrecedence("TimedAspect, *")
public class TimedAspectPrecedence {

}
quaff commented 2 days ago

You can try register your own TimedAspect bean with @Order(Ordered.HIGHEST_PRECEDENCE) to backoff auto configured bean.

see https://github.com/spring-projects/spring-boot/blob/eb7b6a776dd8b01849a0ea35d097b81f7eeec23e/spring-boot-project/spring-boot-actuator-autoconfigure/src/main/java/org/springframework/boot/actuate/autoconfigure/metrics/MetricsAspectsAutoConfiguration.java#L58

wilkinsona commented 1 day ago

While reviewing https://github.com/spring-projects/spring-boot/pull/42450, I formed the opinion that this is quite subjective and I suspect that users will be able to make compelling cases for either ordering. To fix this, I think we may have to make the ordering configurable so that the advice from the TimedAspect that Boot configures can be made to run before or after Framework's advice for @Transactional.

There's other advice that users may or may not want to be including in the timing such as Spring Security's advice for method-based security. Anything that we do here looks like it will require changes across multiple projects. As part of that, I wonder if it's worth considering support for some relative ordering so that we don't have to rely on magic numbers across those projects.