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:
- Elapsed time of method execution
- Total count of method execution
- Success count of method execution
- 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
|
