Dropwizard Metric Annotations @Timed not working

Question

I'm trying to automatically publish metrics to my MetricRegistry using annotations like @Timed (http://metrics.dropwizard.io/3.1.0/apidocs/com/codahale/metrics/annotation/package-summary.html).

This doesn't work out of the box. On searching for questions, I found Codahale Metrics: using @Timed metrics annotation in plain Java where it was mentioned that the only way for this to work would be by using aspectj. I added this to my project, but still do not see my metrics in my MetricRegistry.

This is my pom file. I added a librato library, which loads in com.codahale.metrics:metrics-annotation.

<dependency>
  <groupId>io.astefanutti.metrics.aspectj</groupId>
  <artifactId>metrics-aspectj</artifactId>
  <version>${metrics-aspectj.version}</version>
</dependency>
<dependency>
  <groupId>org.aspectj</groupId>
  <artifactId>aspectjrt</artifactId>
  <version>1.8.10</version>
</dependency>

  <plugin>
    <groupId>org.codehaus.mojo</groupId>
    <artifactId>aspectj-maven-plugin</artifactId>
    <version>1.7</version>
    <configuration>
      <showWeaveInfo>true</showWeaveInfo>
      <source>1.8</source>
      <target>1.8</target>
      <complianceLevel>1.8</complianceLevel>
      <encoding>UTF-8</encoding>
      <verbose>true</verbose>
      <aspectLibraries>
        <aspectLibrary>
          <groupId>io.astefanutti.metrics.aspectj</groupId>
          <artifactId>metrics-aspectj</artifactId>
        </aspectLibrary>
      </aspectLibraries>
    </configuration>
    <executions>
      <execution>
        <phase>process-sources</phase>
        <goals>
          <goal>compile</goal>
          <goal>test-compile</goal>
        </goals>
      </execution>
    </executions>
  </plugin>

<dependency>
  <groupId>com.librato.metrics</groupId>
  <artifactId>metrics-librato</artifactId>
  <version>${metrics-librato.version}</version>
</dependency>

This is how I'm trying to use the metrics

@Metrics(registry = "default") // this.metricRegistry is default
public class Foo {
    @Inject
    private MetricRegistry metricRegistry;
    ...

    @Metered(name = "meterName")
    public void bar() {
        Meter meter = metricRegistry.meter("manual");
        meter.mark();
        // this.metricRegistry does not contain "meterName" after the ConsoleReporter prints the metrics for "default"
        // this.metricRegistry contains "manual" after the ConsoleReporter prints the metrics for "default"
    }

I'm seeing this in my logs when I compile:

[INFO] Extending interface set for type 'Foo' (Foo.java) to include 'io.astefanutti.metrics.aspectj.Profiled' (MetricAspect.aj)
[INFO] Type 'Foo' (Foo.java) has intertyped field from 'io.astefanutti.metrics.aspectj.MetricAspect' (MetricAspect.aj:'java.util.Map<java.lang.String,io.astefanutti.metrics.aspectj.AnnotatedMetric<com.codahale.metrics.Gauge>> io.astefanutti.metrics.aspectj.Profiled.gauges')
[INFO] Type 'Foo' (Foo.java) has intertyped field from 'io.astefanutti.metrics.aspectj.MetricAspect' (MetricAspect.aj:'java.util.Map<java.lang.String,io.astefanutti.metrics.aspectj.AnnotatedMetric<com.codahale.metrics.Meter>> io.astefanutti.metrics.aspectj.Profiled.meters')
[INFO] Type 'Foo' (Foo.java) has intertyped field from 'io.astefanutti.metrics.aspectj.MetricAspect' (MetricAspect.aj:'java.util.Map<java.lang.String,io.astefanutti.metrics.aspectj.AnnotatedMetric<com.codahale.metrics.Timer>> io.astefanutti.metrics.aspectj.Profiled.timers')
[INFO] Join point 'staticinitialization(void Foo.<clinit>())' in Type 'Foo' (Foo.java:46) advised by after advice from 'io.astefanutti.metrics.aspectj.MetricStaticAspect' (metrics-aspectj-1.2.0.jar!MetricStaticAspect.class:41(from MetricStaticAspect.aj))
[INFO] Join point 'method-execution(void Foo.bar())' in Type 'Foo' (Foo.java:74) advised by around advice from 'io.astefanutti.metrics.aspectj.TimedAspect' (metrics-aspectj-1.2.0.jar!TimedAspect.class:26(from TimedAspect.aj))
[INFO] Join point 'method-execution(void Foo.bar())' in Type 'Foo' (Foo.java:74) advised by before advice from 'io.astefanutti.metrics.aspectj.MeteredAspect' (metrics-aspectj-1.2.0.jar!MeteredAspect.class:26(from MeteredAspect.aj))

It seems to indicate the annotated metrics I setup are working properly. However, I also see this in my logs too

[WARNING] advice defined in io.astefanutti.metrics.aspectj.TimedStaticAspect has not been applied [Xlint:adviceDidNotMatch]
    /Users/x/.m2/repository/io/astefanutti/metrics/aspectj/metrics-aspectj/1.2.0/metrics-aspectj-1.2.0.jar!io/astefanutti/metrics/aspectj/TimedStaticAspect.class:26

[WARNING] advice defined in io.astefanutti.metrics.aspectj.ExceptionMeteredAspect has not been applied [Xlint:adviceDidNotMatch]
    /Users/x/.m2/repository/io/astefanutti/metrics/aspectj/metrics-aspectj/1.2.0/metrics-aspectj-1.2.0.jar!io/astefanutti/metrics/aspectj/ExceptionMeteredAspect.class:26

[WARNING] advice defined in io.astefanutti.metrics.aspectj.ExceptionMeteredStaticAspect has not been applied [Xlint:adviceDidNotMatch]
    /Users/x/.m2/repository/io/astefanutti/metrics/aspectj/metrics-aspectj/1.2.0/metrics-aspectj-1.2.0.jar!io/astefanutti/metrics/aspectj/ExceptionMeteredStaticAspect.class:26

[WARNING] advice defined in io.astefanutti.metrics.aspectj.MeteredStaticAspect has not been applied [Xlint:adviceDidNotMatch]
    /Users/x/.m2/repository/io/astefanutti/metrics/aspectj/metrics-aspectj/1.2.0/metrics-aspectj-1.2.0.jar!io/astefanutti/metrics/aspectj/MeteredStaticAspect.class:26

[WARNING] advice defined in io.astefanutti.metrics.aspectj.TimedAspect has not been applied [Xlint:adviceDidNotMatch]
    /Users/x/.m2/repository/io/astefanutti/metrics/aspectj/metrics-aspectj/1.2.0/metrics-aspectj-1.2.0.jar!io/astefanutti/metrics/aspectj/TimedAspect.class:26

[WARNING] advice defined in io.astefanutti.metrics.aspectj.TimedStaticAspect has not been applied [Xlint:adviceDidNotMatch]
    /Users/x/.m2/repository/io/astefanutti/metrics/aspectj/metrics-aspectj/1.2.0/metrics-aspectj-1.2.0.jar!io/astefanutti/metrics/aspectj/TimedStaticAspect.class:26

[WARNING] advice defined in io.astefanutti.metrics.aspectj.MetricAspect has not been applied [Xlint:adviceDidNotMatch]
    /Users/x/.m2/repository/io/astefanutti/metrics/aspectj/metrics-aspectj/1.2.0/metrics-aspectj-1.2.0.jar!io/astefanutti/metrics/aspectj/MetricAspect.class:45

[WARNING] advice defined in io.astefanutti.metrics.aspectj.ExceptionMeteredAspect has not been applied [Xlint:adviceDidNotMatch]
    /Users/x/.m2/repository/io/astefanutti/metrics/aspectj/metrics-aspectj/1.2.0/metrics-aspectj-1.2.0.jar!io/astefanutti/metrics/aspectj/ExceptionMeteredAspect.class:26

[WARNING] advice defined in io.astefanutti.metrics.aspectj.MeteredAspect has not been applied [Xlint:adviceDidNotMatch]
    /Users/x/.m2/repository/io/astefanutti/metrics/aspectj/metrics-aspectj/1.2.0/metrics-aspectj-1.2.0.jar!io/astefanutti/metrics/aspectj/MeteredAspect.class:26

[WARNING] advice defined in io.astefanutti.metrics.aspectj.ExceptionMeteredStaticAspect has not been applied [Xlint:adviceDidNotMatch]
    /Users/x/.m2/repository/io/astefanutti/metrics/aspectj/metrics-aspectj/1.2.0/metrics-aspectj-1.2.0.jar!io/astefanutti/metrics/aspectj/ExceptionMeteredStaticAspect.class:26

[WARNING] advice defined in io.astefanutti.metrics.aspectj.MetricStaticAspect has not been applied [Xlint:adviceDidNotMatch]
    /Users/x/.m2/repository/io/astefanutti/metrics/aspectj/metrics-aspectj/1.2.0/metrics-aspectj-1.2.0.jar!io/astefanutti/metrics/aspectj/MetricStaticAspect.class:41

[WARNING] advice defined in io.astefanutti.metrics.aspectj.MeteredStaticAspect has not been applied [Xlint:adviceDidNotMatch]
    /Users/x/.m2/repository/io/astefanutti/metrics/aspectj/metrics-aspectj/1.2.0/metrics-aspectj-1.2.0.jar!io/astefanutti/metrics/aspectj/MeteredStaticAspect.class:26

Here is my app setup

@Override
public void run(AppConfiguration configuration, Environment environment) {

    ConsoleReporter reporter = ConsoleReporter.forRegistry(environment.metrics())
            .convertRatesTo(TimeUnit.SECONDS)
            .convertDurationsTo(TimeUnit.MILLISECONDS)
            .build();
    reporter.start(2, TimeUnit.MINUTES);
}

Answer 1

I just tried this out and it works well. Here is my entire setup:

pom.xml:

<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 http://maven.apache.org/maven-v4_0_0.xsd">
    <modelVersion>4.0.0</modelVersion>
    <groupId>com.mycompany.app</groupId>
    <artifactId>my-app</artifactId>
    <packaging>jar</packaging>
    <version>1.0-SNAPSHOT</version>
    <name>my-app</name>
    <url>http://maven.apache.org</url>


    <dependencies>

        <dependency>
            <groupId>io.astefanutti.metrics.aspectj</groupId>
            <artifactId>metrics-aspectj</artifactId>
            <version>1.2.0</version>
        </dependency>

    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.codehaus.mojo</groupId>
                <artifactId>aspectj-maven-plugin</artifactId>
                <configuration>
                    <aspectLibraries>
                        <aspectLibrary>
                            <groupId>io.astefanutti.metrics.aspectj</groupId>
                            <artifactId>metrics-aspectj</artifactId>
                        </aspectLibrary>
                    </aspectLibraries>
                    <complianceLevel>1.8</complianceLevel>
                    <source>1.8</source>
                    <target>1.8</target>
                </configuration>
                <executions>
                    <execution>
                        <goals>
                            <goal>compile</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-assembly-plugin</artifactId>
                <version>2.4.1</version>
                <configuration>
                    <!-- get all project dependencies -->
                    <descriptorRefs>
                        <descriptorRef>jar-with-dependencies</descriptorRef>
                    </descriptorRefs>
                    <!-- MainClass in mainfest make a executable jar -->
                    <archive>
                        <manifest>
                            <mainClass>com.mkyong.core.utils.App</mainClass>
                        </manifest>
                    </archive>

                </configuration>
                <executions>
                    <execution>
                        <id>make-assembly</id>
                        <!-- bind to the packaging phase -->
                        <phase>package</phase>
                        <goals>
                            <goal>single</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>
        </plugins>
    </build>

</project>

Note that I need to add the aspectj-maven-plugin. I am also adding an assembly plugin for testing later. This is not really necessary, I just didn't want to go hunting for dependencies on my local box.

My timed class:

package com.mycompany.app;

import java.util.concurrent.ThreadLocalRandom;

import com.codahale.metrics.annotation.Timed;

import io.astefanutti.metrics.aspectj.Metrics;
@Metrics(registry = "someMetrics")
public class TimedClass {

    @Timed(name = "test")
    public void doSomething() {
        try {
            Thread.sleep(200L);
        } catch (InterruptedException e) {
        }
        System.out.println("Done");
    }

    @Timed(name = "test-random")
    public void doSomething2() {
        try {
            Thread.sleep(ThreadLocalRandom.current().nextLong(100L));
        } catch (InterruptedException e) {
        }
        System.out.println("Done");
    }
}

And the app:

package com.mycompany.app;

import java.util.concurrent.TimeUnit;

import com.codahale.metrics.ConsoleReporter;
import com.codahale.metrics.MetricRegistry;
import com.codahale.metrics.SharedMetricRegistries;
public class App {

    public static void main(String[] args) throws InterruptedException {
        MetricRegistry metrics =
                SharedMetricRegistries.getOrCreate("someMetrics");

        ConsoleReporter.forRegistry(metrics)
        .convertRatesTo(TimeUnit.SECONDS)
        .convertDurationsTo(TimeUnit.MILLISECONDS)
        .build()
        .start(1, TimeUnit.SECONDS);

        TimedClass c = new TimedClass();
        for(int i = 0; i < 10; i++) {
            c.doSomething();
            c.doSomething2();
        }
        c.doSomething();
        Thread.sleep(1010L);
    }
}

What happens here is that while compiling the maven plugin for aspect will find the annotations you use and apply the aspects.

In your case (and mine) for example this one from the metrics-aspect source:

final aspect TimedAspect {

    pointcut timed(Profiled object) : execution(@Timed !static * (@Metrics Profiled+).*(..)) && this(object);

    Object around(Profiled object) : timed(object) {
        String methodSignature = ((MethodSignature) thisJoinPointStaticPart.getSignature()).getMethod().toString();
        Timer timer = object.timers.get(methodSignature).getMetric();
        Timer.Context context = timer.time();
        try {
            return proceed(object);
        } finally {
            context.stop();
        }
    }
}

All the above does is to say:

Any method that is non static and has a @Timed annotation should be executed within the "around" method.

Now, you may compile and package that by doing:

mvn clean install package

This will print a bunch of warning for non-applied aspects, but that is perfectly fine (we are not actually using them).

Further, you now have a fat-jar containing your application and you can execute it to see if what we did worked:

java -cp target/my-app-1.0-SNAPSHOT-jar-with-dependencies.jar com.mycompany.app.App

Which will print:

artur@pdb-ct ~/dev/repo/my-app $ java -cp target/my-app-1.0-SNAPSHOT-jar-with-dependencies.jar com.mycompany.app.App
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
Done
Done
Done
Done
Done
Done
Done
Done
04/01/18 15:10:42 ==============================================================

-- Timers ----------------------------------------------------------------------
com.mycompany.app.TimedClass.test
             count = 4
         mean rate = 4.11 calls/second
     1-minute rate = 0.00 calls/second
     5-minute rate = 0.00 calls/second
    15-minute rate = 0.00 calls/second
               min = 200.21 milliseconds
               max = 200.37 milliseconds
              mean = 200.29 milliseconds
            stddev = 0.06 milliseconds
            median = 200.25 milliseconds
              75% <= 200.32 milliseconds
              95% <= 200.37 milliseconds
              98% <= 200.37 milliseconds
              99% <= 200.37 milliseconds
            99.9% <= 200.37 milliseconds
com.mycompany.app.TimedClass.test-random
             count = 4
         mean rate = 4.10 calls/second
     1-minute rate = 0.00 calls/second
     5-minute rate = 0.00 calls/second
    15-minute rate = 0.00 calls/second
               min = 20.41 milliseconds
               max = 32.28 milliseconds
              mean = 26.07 milliseconds
            stddev = 4.56 milliseconds
            median = 28.26 milliseconds
              75% <= 32.28 milliseconds
              95% <= 32.28 milliseconds
              98% <= 32.28 milliseconds
              99% <= 32.28 milliseconds
            99.9% <= 32.28 milliseconds


Done
Done
Done
Done
Done
Done
Done
04/01/18 15:10:43 ==============================================================

-- Timers ----------------------------------------------------------------------
com.mycompany.app.TimedClass.test
             count = 8
         mean rate = 4.06 calls/second
     1-minute rate = 0.00 calls/second
     5-minute rate = 0.00 calls/second
    15-minute rate = 0.00 calls/second
               min = 200.16 milliseconds
               max = 200.37 milliseconds
              mean = 200.25 milliseconds
            stddev = 0.06 milliseconds
            median = 200.25 milliseconds
              75% <= 200.26 milliseconds
              95% <= 200.37 milliseconds
              98% <= 200.37 milliseconds
              99% <= 200.37 milliseconds
            99.9% <= 200.37 milliseconds
com.mycompany.app.TimedClass.test-random
             count = 7
         mean rate = 3.55 calls/second
     1-minute rate = 0.00 calls/second
     5-minute rate = 0.00 calls/second
    15-minute rate = 0.00 calls/second
               min = 20.41 milliseconds
               max = 97.20 milliseconds
              mean = 43.68 milliseconds
            stddev = 28.17 milliseconds
            median = 28.26 milliseconds
              75% <= 76.30 milliseconds
              95% <= 97.20 milliseconds
              98% <= 97.20 milliseconds
              99% <= 97.20 milliseconds
            99.9% <= 97.20 milliseconds


Done
Done
Done
Done
Done
Done
04/01/18 15:10:44 ==============================================================

-- Timers ----------------------------------------------------------------------
com.mycompany.app.TimedClass.test
             count = 11
         mean rate = 3.70 calls/second
     1-minute rate = 0.00 calls/second
     5-minute rate = 0.00 calls/second
    15-minute rate = 0.00 calls/second
               min = 200.13 milliseconds
               max = 200.37 milliseconds
              mean = 200.23 milliseconds
            stddev = 0.07 milliseconds
            median = 200.21 milliseconds
              75% <= 200.26 milliseconds
              95% <= 200.37 milliseconds
              98% <= 200.37 milliseconds
              99% <= 200.37 milliseconds
            99.9% <= 200.37 milliseconds
com.mycompany.app.TimedClass.test-random
             count = 10
         mean rate = 3.37 calls/second
     1-minute rate = 0.00 calls/second
     5-minute rate = 0.00 calls/second
    15-minute rate = 0.00 calls/second
               min = 15.19 milliseconds
               max = 97.20 milliseconds
              mean = 48.90 milliseconds
            stddev = 30.99 milliseconds
            median = 32.28 milliseconds
              75% <= 76.30 milliseconds
              95% <= 97.20 milliseconds
              98% <= 97.20 milliseconds
              99% <= 97.20 milliseconds
            99.9% <= 97.20 milliseconds

Few points:

This does not work within Eclipse. You will have to install an extension to get that to work (I have not tried that), see here:

https://github.com/astefanutti/metrics-aspectj/blob/master/README.md

And for instructions on how to use AJDT:

https://www.ibm.com/developerworks/library/j-ajdt/

The reason is (vague because I have not spend too much time on this) that the aspects are applied at compile time, not at runtime. Eclipse uses its own compiler when run within the IDE, so it just executes your code. The maven plugin inside your pom file however is what applies the aspects when compiling your code.

I hope that helps,

P.S. forgive my naming/packaging - i used the default maven generator

-- Artur

Follow up:

To add your dropwizard metrics you can just add it to the shared one if you want to use the above solution. For example:

        MetricRegistry myCustomRegistry = new MetricRegistry();
        SharedMetricRegistries.add("my-metric-registry", myCustomRegistry);

In your case, this would come from environment().metrics() or similar.

Answer 2

The problem you're facing is that the MetricRegistry instance used by the AspectJ advice is different from the instance you are using for your manual metering test and your ConsoleReporter.

Since your question doesn't specify where the @Inject-ed MetricRegistry instance comes from, I can only speculate that it's the same instance you are using with the ConsoleReporter, but that is most probably a different instance from the "default" registry used by the AspectJ advice. The one used by the AspectJ advice is obtained with

SharedMetricRegistries.getOrCreate("default");

In order to solve your issue, you should either:

• make sure that the @Inject-ed MetricRegistry instance and the one returned by environment.metrics() is the same as SharedMetricRegistries.getOrCreate("default"), by using your preferred dependency injection framework's way of using factory methods (@Bean for Spring, @Produces for CDI).

• use an EL expression in the Foo class @Metrics annotation's registry value like this:

  @Metrics(registry = "${this.metricRegistry}")
  

  provide a getter for the referenced metricRegistry property above:

  public MetricRegistry getMetricRegistry() {
      return this.metricRegistry;
  }
  

  and make sure you have the required EL library in you project:

  <dependency>
      <groupId>org.glassfish</groupId>
      <artifactId>javax.el</artifactId>
      <version>3.0.1-b09</version>
  </dependency>