Showing posts with label Micrometer. Show all posts
Showing posts with label Micrometer. Show all posts

Thursday, August 15, 2019

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