@Timed not working despite registering TimedAspect explicitly - spring boot 2.1

Question

I need to measure method-metrics using micrometer @Timed annotation. As it doesn't work on arbitrary methods; i added the configuration of @TimedAspect explicitly in my spring config. Have referred to this post for exact config Note: have tried adding a separate config class JUST for this, as well as including the TimedAspect bean as part of my existing configuration bean

How to measure service methods using spring boot 2 and micrometer

Yet, it unfortunately doesn't work. The Bean is registred and the invocation from config class goes thru successfully on startup. Found this while debugging. However, the code in the @Around never seems to execute. No error is thrown; and im able to view the default 'system' metrics on the /metrics and /prometheus endpoint.

Note: This is AFTER getting the 'method' to be invoked several times by executing a business flow. I'm aware that it probably doesn't show up in the metrics if the method isn't invoked at all

Versions: spring-boot 2.1.1, spring 5.3, micrometer 1.1.4, actuator 2.1

Tried everything going by the below posts:

How to measure service methods using spring boot 2 and micrometer

https://github.com/izeye/sample-micrometer-spring-boot/tree/timed-annotation

https://github.com/micrometer-metrics/micrometer/issues/361

Update: So, the issue seems to be ONLY when the Timed is on an abstract method, which is called via another method. Was able to reproduce it via a simple example. Refer to the @Timed("say_hello_example") annotation. It simply gets ignored and doesnt show up when i hit the prometheus endpoint.

Code: Abstract Class

public abstract class AbstractUtil {
    public abstract void sayhello();

    public void sayhellowithtimed(String passedVar) {
        System.out.println("Passed var =>"+passedVar);
        System.out.println("Calling abstract sayhello....");
        sayhello();

    }
}

Impl Class

@Component
@Scope("prototype")
public class ExampleUtil extends AbstractUtil  {

    public static final String HELLO = "HELLO";

    @Timed("dirwatcher_handler")
    public void handleDirectoryWatcherChange(WatchEvent event){
        System.out.println("Event kind:" + event.kind() + ". File affected: " + event.context());
    }

    @Timed("say_hello_example")
    @Override
    public void sayhello() {
        System.out.println(HELLO);
        try {
            Thread.sleep(1000);
        }
        catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

A simple DirWatcher implementation class...

package com.example;
            
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.boot.context.event.ApplicationStartedEvent;
import org.springframework.context.ApplicationListener;
import org.springframework.context.annotation.Scope;
import org.springframework.context.event.ContextRefreshedEvent;
import org.springframework.stereotype.Component;
            
import java.io.IOException;
import java.nio.file.*;
            
@Component
@Scope("prototype")
public class StartDirWatcher implements ApplicationListener<ApplicationStartedEvent> {
            
    @Value("${directory.path:/apps}")
    public String directoryPath;
            
    @Autowired
    private ExampleUtil util;
            
    private void monitorDirectoryForChanges() throws IOException, InterruptedException {
        WatchService watchService = FileSystems.getDefault().newWatchService();
        Path path = Paths.get(directoryPath);
        path.register(
            watchService,
            StandardWatchEventKinds.ENTRY_CREATE,
            StandardWatchEventKinds.ENTRY_DELETE,
            StandardWatchEventKinds.ENTRY_MODIFY);
        WatchKey key;
        while ((key = watchService.take()) != null) {
            for (WatchEvent<?> event : key.pollEvents()) {
                util.handleDirectoryWatcherChange(event);
                util.sayhellowithtimed("GOD_OF_SMALL_THINGS_onAPPEvent");
            }
            key.reset();
        }
    }
            
    @Override
    public void onApplicationEvent(ApplicationStartedEvent applicationStartedEvent) {
        try {
            monitorDirectoryForChanges();
        } catch (Throwable e) {
            System.err.println("ERROR!! "+e.getMessage());
            e.printStackTrace();
        }
    }
}

The Spring Boot Application Class

package com.example;

import io.micrometer.core.aop.TimedAspect;
import io.micrometer.core.instrument.MeterRegistry;
import io.micrometer.prometheus.PrometheusMeterRegistry;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.actuate.autoconfigure.metrics.MeterRegistryCustomizer;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.ComponentScan;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.EnableAspectJAutoProxy;

@EnableAspectJAutoProxy
@ComponentScan
@Configuration
@SpringBootApplication
public class ExampleStarter{

    @Bean
    MeterRegistryCustomizer<PrometheusMeterRegistry> metricsCommonTags() {
        return registry -> registry.config().commonTags("app.name", "example.app");
    }
    @Bean
    TimedAspect timedAspect(MeterRegistry reg) {
        return new TimedAspect(reg);
    }

    public static void main(String[] args) {
        SpringApplication.run(ExampleStarter.class, args);
    }

}

The main pom.xml file

<?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 http://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>

<groupId>com.metrics.timed.example</groupId>
<artifactId>example-app</artifactId>
<version>1.0-SNAPSHOT</version>
<build>
    <plugins>
        <plugin>
            <groupId>org.apache.maven.plugins</groupId>
            <artifactId>maven-compiler-plugin</artifactId>
            <configuration>
                <source>1.8</source>
                <target>1.8</target>
            </configuration>
        </plugin>
    </plugins>
</build>
<dependencies>
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-web</artifactId>
        <version>2.1.1.RELEASE</version>
    </dependency>

    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-actuator</artifactId>
        <version>2.1.1.RELEASE</version>
    </dependency>
    <dependency>
    <groupId>io.micrometer</groupId>
    <artifactId>micrometer-registry-prometheus</artifactId>
    <version>1.1.2</version>
</dependency>
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-aop</artifactId>
        <version>2.1.1.RELEASE</version>
    </dependency>
</dependencies>

Welcome to SO and thanks for your detailed description in prose. The only thing that is missing is code, ideally an MCVE. Nobody can compile, run and debug your prose. Show the code, please, and I mean your own code, not lots of examples you linked to but neither of which is your code. Thank you. — kriegaex
Spring AOP is implemented using proxies (by default). Hence only method calls into the object will be intercepted and have AOP applied. In this case the timing aspect. However you are callin the sayhello method internally (from within the proxy) and as such won't be timed as it doesn't pass through the proxy. — M. Deinum
@M. Deinum - is there any way around this to make it work. What i basically need to do, is add this timing annotation on methods which are part of frameworks which are extended in our runtimes (example: spring batch) — Rahul

makson makson · Accepted Answer · 2020-05-13T08:33:59

I use spring boot 2.2.6.RELEASE and this MetricConfig works for me

@Configuration
public class MetricConfig {

  @Bean
  MeterRegistryCustomizer<MeterRegistry> metricsCommonTags() {
    return registry -> registry.config().commonTags("application", "my app");
  }

  @Bean
  TimedAspect timedAspect(MeterRegistry registry) {
    return new TimedAspect(registry);
  }

}

In application.yml

management:
  endpoints:
    web:
      exposure:
        include: ["health", "prometheus"]
  endpoint:
    beans:
      cache:
        time-to-live: 10s

@Timed not working despite registering TimedAspect explicitly - spring boot 2.1

1 Answers