How to measure service methods using spring boot 2 and micrometer

Question

I started my first project on Spring Boot 2 (RC1). Thanks to the already good documentation this has not been to hard coming from Spring Boot 1.x.

However now that I want to integrate metrics I'm stumbeling. As far as I was able to find currently there is only documentation for the metrics shipped by default. But I'd like to also measure service level execution time as well as the time used in dynamodb.

EDIT I'm looking for a solution using Micrometer, the library used in the new actuator library shipped with spring-boot 2.

Is there any guide on how this should be done? From this I read that there is no easy annotation based solution for arbitrary spring beans yet. Could s.o. give me an example / link to documentation on how a method like below could be metered?

@Service
@Timed
public class MyService {
    public void doSomething() {
        ...;
    }
}

Answer 1

Based on this this documentation, you only need to set management.observations.annotations.enabled=true in properties when using Spring Actuator and Micrometer and there's no need to define TimedAspect bean anymore.

Also don't forget that: (from XII)

@Timed works only on public methods called by another class. A good explanation is this one https://stackoverflow.com/a/3429757/2468241

Answer 2

Here's a little sample which should get you going. There's more variants to Timer.record() which aren't shown here. (Also: Field injection only used for brevity.) You don't have to put the called methods name into a tag. You can also make it part of the metric name itself. Just wanted to show what you could do.

Update 2018-03-12: As of Micrometer 1.0.0 a TimedAspect has been introduced so that you can also use the @Timed annotation. For now you need to register the Bean yourself. (You need to be cautious though when you have custom @Timed annotations on your Spring-MVC or Jersey resources.) This was already mentioned by Michal Stepan in a follow-up answer.

package io.github.mweirauch.micrometered.eval;

import java.util.concurrent.TimeUnit;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.EnableAspectJAutoProxy;
import org.springframework.scheduling.annotation.Scheduled;
import org.springframework.stereotype.Service;

import io.micrometer.core.annotation.Timed;
import io.micrometer.core.aop.TimedAspect;
import io.micrometer.core.instrument.MeterRegistry;
import io.micrometer.core.instrument.Timer;
import io.micrometer.core.instrument.Timer.Sample;

@Configuration
@EnableAspectJAutoProxy
public class TimingStuff {

    @Service
    static class MyService {

        @Autowired
        private MeterRegistry registry;

        public void helloManual() {
            // you can keep a ref to this; ok to call multiple times, though
            Timer timer = Timer.builder("myservice").tag("method", "manual").register(registry);

            // manually do the timing calculation
            long start = System.nanoTime();
            doSomething();
            timer.record(System.nanoTime() - start, TimeUnit.NANOSECONDS);
        }

        public void helloSupplier() {
            Timer timer = Timer.builder("myservice").tag("method", "supplier").register(registry);

            // execution of the method is timed internally
            timer.record(() -> doSomething());
        }

        public void helloSample() {
            Timer timer = Timer.builder("myservice").tag("method", "sample").register(registry);

            // records time taken between Sample creation and registering the
            // stop() with the given Timer
            Sample sample = Timer.start(registry);
            doSomething();
            sample.stop(timer);
        }

        // TimedAspect adds "class" and "method" tags
        @Timed(value = "myservice.aspect")
        public void helloAspect() {
            doSomething();
        }

        private void doSomething() {
            try {
                Thread.sleep(50);
            } catch (InterruptedException e) {
                //
            }
        }

    }

    @Autowired
    private MyService myService;

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

    @Scheduled(fixedRate = 1000)
    public void postConstruct() {
        myService.helloManual();
        myService.helloSupplier();
        myService.helloSample();
        myService.helloAspect();
    }

}

In case you go for Prometheus, you'd end up with something like that:

# HELP myservice_seconds  
# TYPE myservice_seconds summary
myservice_seconds_count{application="micrometered",method="manual",} 4.0
myservice_seconds_sum{application="micrometered",method="manual",} 0.200378014
myservice_seconds_max{application="micrometered",method="manual",} 0.050115291
myservice_seconds_count{application="micrometered",method="supplier",} 4.0
myservice_seconds_sum{application="micrometered",method="supplier",} 0.200393455
myservice_seconds_max{application="micrometered",method="supplier",} 0.05011635
myservice_seconds_count{application="micrometered",method="sample",} 4.0
myservice_seconds_sum{application="micrometered",method="sample",} 0.200527005
myservice_seconds_max{application="micrometered",method="sample",} 0.050250191
# HELP myservice_aspect_seconds  
# TYPE myservice_aspect_seconds summary
myservice_aspect_seconds_count{application="micrometered",class="io.github.mweirauch.micrometered.eval.TimingStuff$MyService",method="helloAspect",} 4.0
myservice_aspect_seconds_sum{application="micrometered",class="io.github.mweirauch.micrometered.eval.TimingStuff$MyService",method="helloAspect",} 0.201824272
myservice_aspect_seconds_max{application="micrometered",class="io.github.mweirauch.micrometered.eval.TimingStuff$MyService",method="helloAspect",} 0.051014296

Answer 3

@io.micrometer.core.annotation.Timed annotation seems to be out of order for custom calls due to reduction of scope, at it is mentioned in link in your question.

You need to manually setup an Aspect:

@Configuration
@EnableAspectJAutoProxy
public class AutoTimingConfiguration {
    @Bean
    public TimedAspect timedAspect(MeterRegistry registry) {
        return new TimedAspect(registry);
        }
}

This way method like this:

@Timed("GET_CARS")
public List<Car> getCars(){
        return Lists.newArrayList();
}

will result in GET_CARS metric in /actuator/metrics (default) endpoint.