A Micrometer Aspect to collect count and timer of method execution

The Aspect could be used in a Spring Boot based application, any method that is labeled with Micrometer's @Timed annotation will be intercepted, the following metrics will be collected against the method:

1. Elapsed time of method execution
2. Total count of method execution
3. Success count of method execution
4. Failure count of method execution

The Micrometer meters are cached so that they could be re-used for the same method.

Aspect

package com.yourcorp.common.statistics; import com.yourcorp.common.common.aspect.util.StatisticsCache; import io.micrometer.core.instrument.Clock; import io.micrometer.core.instrument.MeterRegistry; import io.micrometer.core.instrument.Timer; import java.util.concurrent.TimeUnit; import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.annotation.Around; import org.aspectj.lang.annotation.Aspect; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.context.annotation.Configuration; @Configuration @Aspect public class TimedAndCountedAspect {   private static final Logger LOGGER = LoggerFactory.getLogger(TimedAndCountedAspect.class);   private final MeterRegistry registry;   private final StatisticsCache staticticsCache;   private final TimeSampler timeSampler = new TimeSampler();   public TimedAndCountedAspect(MeterRegistry registry, StatisticsCache statisticsCache) {     this.registry = registry;     this.staticticsCache = statisticsCache;   }   @Around("execution (@io.micrometer.core.annotation.Timed * *.*(..))")   public Object timedMethod(ProceedingJoinPoint pjp) throws Throwable {     final Timer.Sample sample = Timer.start(registry);     timeSampler.setStart(Clock.SYSTEM.monotonicTime());     try {       final Object result = pjp.proceed();       staticticsCache.getExecutionCounter(pjp, "successCount", registry).increment();       return result;     } catch (Exception ex) {       staticticsCache.getExecutionCounter(pjp, "failCount", registry).increment();       throw ex;     } finally {       staticticsCache.getExecutionCounter(pjp, "totalCount", registry).increment();       try {         Timer timer = this.staticticsCache.getExecutionTimer(pjp, registry);         sample.stop(timer);       } catch (Exception e) {         // ignoring on purpose       }       timeSampler.setEnd(Clock.SYSTEM.monotonicTime());       if (LOGGER.isDebugEnabled()) {       LOGGER.debug(           "successCount:{}",           staticticsCache.getExecutionCounter(pjp, "successCount", registry).count());       LOGGER.debug(           "failCount:{}", staticticsCache.getExecutionCounter(pjp, "failCount", registry).count());       LOGGER.debug(           "totalCount:{}",           staticticsCache.getExecutionCounter(pjp, "totalCount", registry).count());       LOGGER.debug("timer Count:{}", this.staticticsCache.getExecutionTimer(pjp, registry).count());       LOGGER.debug(           "timer totalTime:{}",           this.staticticsCache.getExecutionTimer(pjp, registry).totalTime(TimeUnit.MILLISECONDS));       LOGGER.debug(           "timer max:{}",           this.staticticsCache.getExecutionTimer(pjp, registry).max(TimeUnit.MILLISECONDS));       LOGGER.debug(           "timer mean:{}",           this.staticticsCache.getExecutionTimer(pjp, registry).mean(TimeUnit.MILLISECONDS));       LOGGER.debug(           "gauge eclapsed time:{}",           this.staticticsCache.getElaspedTimeGauge(pjp, timeSampler, registry).value());       }     }   }   public static class TimeSampler {     private long start;     private long end;     public void setStart(long start) {       this.start = start;     }     public void setEnd(long end) {       this.end = end;     }     public double calculateEclapsedTime() {       return this.end - this.start;     }     @Override     public String toString() {       return "TimeSample [start=" + start + ", end=" + end + "]";     }   } }

MeterCache

Inside the class, the meters are built first then cached.

package com.yourcorp.common.aspect.util.impl; import com.yourcorp.common.aspect.util.StatisticsCache; import com.yourcorp.common.statistics.TimedAndCountedAspect.TimeSampler; import io.micrometer.core.annotation.Timed; import io.micrometer.core.instrument.Counter; import io.micrometer.core.instrument.Gauge; import io.micrometer.core.instrument.MeterRegistry; import io.micrometer.core.instrument.Tag; import io.micrometer.core.instrument.Tags; import io.micrometer.core.instrument.Timer; import java.lang.annotation.Annotation; import java.lang.reflect.Method; import java.time.Duration; import java.util.Map; import java.util.function.Function; import javax.validation.constraints.NotNull; import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.reflect.MethodSignature; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Service; import org.springframework.util.ConcurrentReferenceHashMap; import org.springframework.validation.annotation.Validated; @Service @Validated public class StatisticsCacheImpl implements StatisticsCache {   private static final Logger LOGGER = LoggerFactory.getLogger(StatisticsCacheImpl.class);   private Map<String, Counter> counterCache = new ConcurrentReferenceHashMap<>();   private Map<String, Gauge> gaugeCache = new ConcurrentReferenceHashMap<>();   private Map<String, Timer> timerCache = new ConcurrentReferenceHashMap<>();   @Override   public Counter getExecutionCounter(       @NotNull ProceedingJoinPoint pjp,       @NotNull String counterType,       @NotNull MeterRegistry meterRegistry) {     final Timed timed = this.getTimed(pjp);     final Function<ProceedingJoinPoint, Iterable<Tag>> tagsBasedOnJoinPoint =         this.getTagsReteivingFunction();     return counterCache.computeIfAbsent(         getKey(pjp, counterType),         key ->             Counter.builder(key)                 .description(timed.description().isEmpty() ? null : timed.description())                 .tags(timed.extraTags())                 .tags(tagsBasedOnJoinPoint.apply(pjp))                 .register(meterRegistry));   }   @Override   public Timer getExecutionTimer(       @NotNull ProceedingJoinPoint pjp, @NotNull @NotNull MeterRegistry meterRegistry) {     final Timed timed = getTimed(pjp);     final Function<ProceedingJoinPoint, Iterable<Tag>> tagsBasedOnJoinPoint =         this.getTagsReteivingFunction();     return timerCache.computeIfAbsent(         getKey(pjp, "timer"),         key ->             Timer.builder(key)                 .description(timed.description().isEmpty() ? null : timed.description())                 .tags(timed.extraTags())                 .tags(tagsBasedOnJoinPoint.apply(pjp))                 .publishPercentileHistogram(timed.histogram())                 .publishPercentiles(timed.percentiles().length == 0 ? null : timed.percentiles())                 .distributionStatisticExpiry(Duration.ofHours(1))                 .register(meterRegistry));   }   private Timed getTimed(ProceedingJoinPoint pjp) {     Method method = ((MethodSignature) pjp.getSignature()).getMethod();     Timed timed = method.getAnnotation(Timed.class);     if (timed == null) {       try {         method = pjp.getTarget().getClass().getMethod(method.getName(), method.getParameterTypes());       } catch (NoSuchMethodException | SecurityException e) {         LOGGER.warn("failed to retrieve method information.", e);       }       timed = method.getAnnotation(Timed.class);       if (timed == null) {         timed =             new Timed() {               @Override               public Class<? extends Annotation> annotationType() {                 return Timed.class;               }               @Override               public String value() {                 return null;               }               @Override               public String[] extraTags() {                 return null;               }               @Override               public boolean longTask() {                 return false;               }               @Override               public double[] percentiles() {                 return null;               }               @Override               public boolean histogram() {                 return false;               }               @Override               public String description() {                 return null;               }             };       }     }     return timed;   }   private Function<ProceedingJoinPoint, Iterable<Tag>> getTagsReteivingFunction() {     return pjp ->         Tags.of(             "class",             pjp.getStaticPart().getSignature().getDeclaringTypeName(),             "method",             pjp.getStaticPart().getSignature().getName());   }   @Override   public Gauge getElaspedTimeGauge(       @NotNull ProceedingJoinPoint pjp,       @NotNull TimeSampler timeSampler,       @NotNull MeterRegistry meterRegistry) {     final Timed timed = getTimed(pjp);     final Function<ProceedingJoinPoint, Iterable<Tag>> tagsBasedOnJoinPoint =         this.getTagsReteivingFunction();     return gaugeCache.computeIfAbsent(         getKey(pjp, "gauge"),         key ->             Gauge.builder(key, timeSampler::calculateEclapsedTime)                 .description(timed.description().isEmpty() ? null : timed.description())                 .tags(timed.extraTags())                 .tags(tagsBasedOnJoinPoint.apply(pjp))                 .register(meterRegistry));   }   private String getKey(ProceedingJoinPoint pjp, String suffix) {     final String className = pjp.getStaticPart().getSignature().getDeclaringTypeName();     final String methodName = pjp.getStaticPart().getSignature().getName();     return className + "." + methodName + "." + suffix;   }   @Override   public void clear() {     this.counterCache.forEach((k, v) -> v.close());     this.counterCache.clear();     this.gaugeCache.forEach((k, v) -> v.close());     this.gaugeCache.clear();     this.timerCache.forEach((k, v) -> v.close());     this.timerCache.clear();   } }

Metrics Logging

Collected metrics could be logged into local log files by retrieving the Micrometer rate aggregations from MBean server. Spring Actuator module is required for automatic MBean server setup.

package com.yourcorp.common.statistics.jvm.impl; import java.lang.management.ManagementFactory; import java.util.Arrays; import java.util.List; import java.util.regex.Pattern; import javax.annotation.PostConstruct; import javax.management.AttributeNotFoundException; import javax.management.InstanceNotFoundException; import javax.management.MBeanException; import javax.management.MBeanServer; import javax.management.MalformedObjectNameException; import javax.management.ObjectName; import javax.management.ReflectionException; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.beans.factory.annotation.Value; import org.springframework.stereotype.Service; @Service public class MBeanAttributeLoggingManager {   private static final Logger LOGGER = LoggerFactory.getLogger(MBeanAttributeLoggingManager.class);   @Value("#{'${mbean.shortterm.attributes}'.split(',')}")   private List<String> mbeanShorttermAttributes;   @Value("#{'${mbean.midterm.attributes}'.split(',')}")   private List<String> mbeanMidtermAttributes;   @Value("#{'${mbean.longterm.attributes}'.split(',')}")   private List<String> mbeanLongtermAttributes;   @PostConstruct   private void init() {     LOGGER.debug("mbeanShorttermAttributes:{}", mbeanShorttermAttributes);   }   public void logShorttermAttributes() {     this.logMBeanInfo(mbeanShorttermAttributes);   }   public void logMidtermAttributes() {     this.logMBeanInfo(mbeanMidtermAttributes);   }   public void logLongtermAttributes() {     this.logMBeanInfo(mbeanLongtermAttributes);   }   private void logMBeanInfo(List<String> attributes) {     final MBeanServer mBeanServer = ManagementFactory.getPlatformMBeanServer();     for (String attribute : attributes) {       LOGGER.info("attribute:{}", attribute);       String[] nameTokens = attribute.split(Pattern.quote("|"));       LOGGER.info("nameTokens:{}", Arrays.asList(nameTokens));       ObjectName mxBeanName = null;       try {         mxBeanName = new ObjectName(nameTokens[0]);       } catch (MalformedObjectNameException e) {         LOGGER.warn("failed to create ObjectName:" + nameTokens[0], e);       }       try {         Object attributeValue = null;         attributeValue = mBeanServer.getAttribute(mxBeanName, nameTokens[1]);         LOGGER.info("*** *** *** mbean{}:{}", attribute, attributeValue);       } catch (InstanceNotFoundException           | AttributeNotFoundException           | ReflectionException           | MBeanException e) {         LOGGER.info("failed to retrieve MBean attribute:" + attribute, e);       }     }   } }

application.properties

object.name.common.prefix=com.yourcorp.metrics:name=DelayedServiceDoWithDelay object.name.common.tags=.region.phoenix.stack.dev object.name.DelayedServiceDoWithDelayFailCount=${object.name.common.prefix}FailCount${object.name.common.tags} object.name.DelayedServiceDoWithDelayGauge=${object.name.common.prefix}Gauge${object.name.common.tags} object.name.DelayedServiceDoWithDelaySuccessCount=${object.name.common.prefix}SuccessCount${object.name.common.tags} object.name.DelayedServiceDoWithDelayTimer=${object.name.common.prefix}Timer${object.name.common.tags} object.name.DelayedServiceDoWithDelayTotalCount=${object.name.common.prefix}TotalCount${object.name.common.tags} mbean.shortterm.attributes=${object.name.DelayedServiceDoWithDelayTimer}|Mean\   ,${object.name.DelayedServiceDoWithDelayTimer}|Max\   ,${object.name.DelayedServiceDoWithDelayTimer}|Min\   ,${object.name.DelayedServiceDoWithDelayTimer}|StdDev\   ,${object.name.DelayedServiceDoWithDelayTimer}|Max\   ,${object.name.DelayedServiceDoWithDelayTimer}|50thPercentile\   ,${object.name.DelayedServiceDoWithDelayTimer}|95thPercentile\   ,${object.name.DelayedServiceDoWithDelayTimer}|99thPercentile\   ,${object.name.DelayedServiceDoWithDelayGauge}|Value\   ,${object.name.DelayedServiceDoWithDelayTotalCount}|Count\   ,${object.name.DelayedServiceDoWithDelayTotalCount}|OneMinuteRate\   ,${object.name.DelayedServiceDoWithDelaySuccessCount}|Count\   ,${object.name.DelayedServiceDoWithDelaySuccessCount}|OneMinuteRate\   ,${object.name.DelayedServiceDoWithDelayFailCount}|Count\   ,${object.name.DelayedServiceDoWithDelayFailCount}|OneMinuteRate   mbean.midterm.attributes=${object.name.DelayedServiceDoWithDelayTimer}|FiveMinuteRate\   ,${object.name.DelayedServiceDoWithDelayTotalCount}|FiveMinuteRate\   ,${object.name.DelayedServiceDoWithDelaySuccessCount}|FiveMinuteRate\   ,${object.name.DelayedServiceDoWithDelayFailCount}|FiveMinuteRate mbean.longterm.attributes=${object.name.DelayedServiceDoWithDelayTimer}|FifteenMinuteRate\   ,${object.name.DelayedServiceDoWithDelayTotalCount}|FifteenMinuteRate\   ,${object.name.DelayedServiceDoWithDelaySuccessCount}|FifteenMinuteRate\   ,${object.name.DelayedServiceDoWithDelayFailCount}|FifteenMinuteRate