Showing posts with label Spring Boot. Show all posts
Showing posts with label Spring Boot. Show all posts

Friday, August 16, 2019

Spring Aspects - Logging debugging information of service methods


Method Tracing Aspects

Following aspects enable method tracing by using Spring AOP. The following information will be gathered and logged:


  1. Types and values of input parameters
  2. Type and value of return object
  3. Types and details of exceptions





@Configuration
@Aspect
public class MethodTracingAspect {
  private static Logger logger = LoggerFactory.getLogger(MethodTracingAspect.class);

  @Autowired private LoggerCache loggerCache;

  @PostConstruct
  protected void init() {
    logger.warn("###-AOP-### DebuggableAspect initialized...");
  }

  @Before(
      "(com.yourcorp.common.aspect.CommonPointcut.servicePackageMethodDebugEnabled() "
          + "|| com.yourcorp.common.aspect.CommonPointcut.implPackageMethodDebugEnabled()) && "
          + "!com.yourcorp.common.aspect.CommonPointcut.nonTraceableAnnotationEnabled()")
  public void logDebugInformationMethodBeforeEntering(JoinPoint joinPoint) {
    final Logger mLogger = loggerCache.getLogger(joinPoint);
    mLogger.debug(
        "Entering class:{} - method : {} with input parameters {}",
        joinPoint.getTarget().getClass().getSimpleName(),
        joinPoint.getSignature().getName(),
        joinPoint.getArgs());
  }

  @AfterReturning(
    value =
        "(com.yourcorp.common.aspect.CommonPointcut.servicePackageMethodDebugEnabled() "
            + "|| com.yourcorp.common.aspect.CommonPointcut.implPackageMethodDebugEnabled()) && "
            + "!com.yourcorp.common.aspect.CommonPointcut.nonTraceableAnnotationEnabled()",
    returning = "result"
  )
  public void logDebugInformationMethodAfterReturning(JoinPoint joinPoint, Object result) {
    final Logger mLogger = loggerCache.getLogger(joinPoint);
    mLogger.debug(
        "Returning from class:{} - method : {} with return type: {} - value {}",
        joinPoint.getTarget().getClass().getSimpleName(),
        joinPoint.getSignature().getName(),
        ((MethodSignature) (joinPoint.getSignature())).getReturnType().getSimpleName(),
        result);
  }
}

@Configuration
@Aspect
public class ExceptionHandlingAspect {
  @Autowired private LoggerCache loggerCache;

  @AfterThrowing(
    value = "com.yourcorp.common.aspect.CommonPointcut.servicePackageMethodDebugEnabled()",
    throwing = "exception"
  )
  public void logRecoverableFailureException(
      JoinPoint joinPoint, RecoverableFailureException exception) {
    Logger logger = loggerCache.getLogger(joinPoint);
    logger.warn("\t " + exception.getFullMessage(), exception);
  }

  @AfterThrowing(
    value = "com.yourcorp.common.aspect.CommonPointcut.servicePackageMethodDebugEnabled()",
    throwing = "exception"
  )
  public void logUnRecoverableFailureException(
      JoinPoint joinPoint, UnRecoverableFailureException exception) {
    Logger logger = loggerCache.getLogger(joinPoint);
    logger.error("\t " + exception.getFullMessage(), exception);
  }
}



Common Pointcuts




import org.aspectj.lang.annotation.Pointcut;

/**
 * The pointcuts defined here are the service classes most likely logging, metrics and tracing
 * concerns will be the applied.
 */
@Aspect
public class CommonPointcut {

  // All method in service packages
  @Pointcut("execution(* com.yourcorp.app..service.*.*(..))")
  public void servicePackageMethodDebugEnabled() {
    // no implementation.
  }

  // All method in impl packages
  @Pointcut("execution(* com.yourcorp.app..impl..*.*(..))")
  public void implPackageMethodDebugEnabled() {
    // no implementation.
  }

  // Methods with @MethodDebuggingDisable
  @Pointcut("@annotation(com.yourcorp.app.common.aspect.debug.MethodDebuggingDisable))")
  public void nonTraceableAnnotationEnabled() {
    // no implementation.
  }
}



Custom Annotation



/**
 * If a method is very sensitive to
 */
@Target({ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
public @interface MethodTracingDisable {}


Logger Cache



/**
 * Cache logger according to type, the logger search operation is expensive.
 */
@Service
public class LoggerCacheImpl implements LoggerCache {
  private Map<Class<?>, Logger> loggerCache = new ConcurrentReferenceHashMap<>();

  @Override
  @MethodTracingDisable
  public Logger getLogger(JoinPoint joinPoint) {
    final Class<?> clazz = joinPoint.getTarget().getClass();
    return loggerCache.computeIfAbsent(clazz, e -> LoggerFactory.getLogger(e));
  }
}


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