Micrometer TimedAspect doesn't intercept calls to methods annotated with @Timed

Viewed 1238

I am trying to use Micrometer to record execution time in my Java application. This is related to my other question about used @Timed annotation.

I have a class CountedObject that has the following 2 methods:

@Measured
@Timed(value = "timer1")
public void measuredFunction() {
    try {
        int sleepTime = new Random().nextInt(3) + 1;
        Thread.sleep(sleepTime * 1000L);
    } catch (InterruptedException e) {}
}

@Timed(value = "timer2")
public void timedFunction() {
    try {
        int sleepTime = new Random().nextInt(3) + 1;
        Thread.sleep(sleepTime * 1000L);
    } catch (InterruptedException e) {}
}

I have defined a custom annotation @Measured

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface Measured {
    
}

And a MeasuredAspect to intercept calls to methods annotated with my @Measured annotation:

@Aspect
public class MeasuredAspect {
    @Around("execution(* *(..)) && @annotation(Measured)")
    public Object around(ProceedingJoinPoint pjp) throws Throwable {
        return AppMetrics.getInstance().handle(pjp);

    }
}

In my AppMetrics class I initialize an instance of micrometer's TimedAspect and in the handle(ProceedingJoinPoint pjp) method pass the ProceedingJoinPoint pjp to the TimedAspect instance.

public class AppMetrics {
    private static final AppMetrics instance = new AppMetrics();
    
    private MeterRegistry registry;
    private TimedAspect timedAspect;
    
    public static AppMetrics getInstance() {
        return instance;
    }
    
    private AppMetrics() {
        this.registry = new SimpleMeterRegistry();
        this.timedAspect = new TimedAspect(registry);
    }
    
    public Object handle(ProceedingJoinPoint pjp) throws Throwable {
        return timedAspect.timedMethod(pjp);
    }
}

In my application main, I create an object of CountedObject and invoke measuredFunction() and timedFunction() then I check my registry.getMeters(); only timer1 used by the measuredFunction() [which is annotated by both @Measured and @Timed] is found, while the timer2 that should be used by timedFunction() [annotated only by @Timed] doesn't exist.

I am using eclipse with AspectJ Development Tools Plugin and my project is a Gradle project with AspectJ capability. I am using id "io.freefair.aspectj" version "5.1.1" plugin in my Gradle plugins. This is a basic java application not a Spring app.

What configurations needs to be done or what code changes are required so that micrometer TimedAspect can intercept my method calls directly [i.e timedFunction() should be timed and timer2 should be found in the registry] without the need of my custom annotation?

2 Answers

I created an example project for you:

https://github.com/kriegaex/SO_AJ_MicrometerTimed_67803726

Quoting the read-me (sorry, but answers only containing links are frowned upon on StackOverflow):


In https://github.com/micrometer-metrics/micrometer/issues/1149 and on StackOverflow, an FAQ about Micrometer's @Timed annotation is, why it works with Spring AOP, but not when using Micrometer as an aspect library for native AspectJ in the context of compile-time weaving (CTW), e.g. with AspectJ Maven Plugin. It can be made to work with load-time weaving (LTW) when providing an aop.xml pointing to TimedAspect, but in a CTW the aspect never kicks in.

The reason is that the aspect has been compiled with Javac, not with the AspectJ compiler (AJC), which is necessary to "finish" the Java class, i.e. to enhance its byte code in order to be a full AspectJ aspect. The LTW agent does that on the fly during class-loading, but in a CTW context you need to explicitly tell AJC to do post-compile weaving (a.k.a. binary weaving) on the Micrometer library, producing newly woven class files. This is done by putting Micrometer on AJC's inpath in order to make sure that its class files are being transformed and written to the target directory. The inpath in AspectJ Maven is configured via <weaveDependencies>. There are at least two ways to do this:

  • You can either create your own woven version of the library in a separate Maven module and then use that module instead of Micrometer. In that case, you need to exclude the original Micrometer library in the consuming module, in order to make sure that the unwoven class files are not on the classpath anymore and accidentally used.

  • The way shown here in this example project is a single-module approach, building an executable uber JAR with Maven Shade. The Micrometer class files are not a re-usable library like in the first approach, but it is nice for demonstration purposes, because we can just run the sample application and check its output:

$ mvn clean package

...
[INFO] --- aspectj-maven-plugin:1.12.6:compile (default) @ SO_AJ_MicrometerTimed_67803726 ---
[INFO] Showing AJC message detail for messages of types: [error, warning, fail]
[INFO] Join point 'method-execution(void de.scrum_master.app.Application.doSomething())' in Type 'de.scrum_master.app.Application' (Application.java:23) advised by around advice from 'io.micrometer.core.aop.TimedAspect' (micrometer-core-1.7.0.jar!TimedAspect.class(from TimedAspect.java))
...
[INFO] --- maven-shade-plugin:3.2.4:shade (default) @ SO_AJ_MicrometerTimed_67803726 ---
[INFO] Including org.hdrhistogram:HdrHistogram:jar:2.1.12 in the shaded jar.
[INFO] Including org.latencyutils:LatencyUtils:jar:2.0.3 in the shaded jar.
[INFO] Including org.aspectj:aspectjrt:jar:1.9.6 in the shaded jar.
[INFO] Excluding io.micrometer:micrometer-core:jar:1.7.0 from the shaded jar.
[INFO] Replacing original artifact with shaded artifact.
[INFO] Replacing C:\Users\me\java-src\SO_AJ_MicrometerTimed_67803726\target\SO_AJ_MicrometerTimed_67803726-1.0-SNAPSHOT.jar with C:\Users\me\java-src\SO_AJ_MicrometerTimed_67803726\target\SO_AJ_MicrometerTimed_67803726-1.0-SNAPSHOT-shaded.jar
[INFO] Dependency-reduced POM written at: C:\Users\me\java-src\SO_AJ_MicrometerTimed_67803726\target\dependency-reduced-pom.xml
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------

$ java -jar target/SO_AJ_MicrometerTimed_67803726-1.0-SNAPSHOT.jar

Juni 05, 2021 1:12:27 PM io.micrometer.core.instrument.push.PushMeterRegistry start
INFO: publishing metrics for LoggingMeterRegistry every 1m
Juni 05, 2021 1:13:00 PM io.micrometer.core.instrument.logging.LoggingMeterRegistry lambda$publish$5
INFO: method.timed{class=de.scrum_master.app.Application,exception=none,method=doSomething} throughput=0.166667/s mean=0.11842469s max=0.2146482s

Please specifically note those log lines (line breaks inserted for better readability):

Join point 'method-execution(void de.scrum_master.app.Application.doSomething())'
  in Type 'de.scrum_master.app.Application' (Application.java:23)
  advised by around advice from 'io.micrometer.core.aop.TimedAspect'
  (micrometer-core-1.7.0.jar!TimedAspect.class(from TimedAspect.java))

The above is proof that the @Timed annotation actually causes Micrometer's TimedAspect to be woven into our application code. And here are the measurements created by the aspect for the sample application:

method.timed
  {class=de.scrum_master.app.Application,exception=none,method=doSomething}
  throughput=0.166667/s mean=0.11842469s max=0.2146482s

I'm not sure what do you expect from this:

public Object handle(ProceedingJoinPoint pjp) throws Throwable {
    return timedAspect.timedMethod(pjp);
}

If I understand this correctly, it does nothing. There are guides that you can follow to set-up AspectJ properly for your project. After it is done TimedAspect should work, you don't need MeasuredAspect or @Measured just set up AspectJ.

Related