contention from MetricUtil.getMetricID() when using Metrics using annotations

[vasanth-bhat]

Repeated the tests used for overhead measurement of metric annotation with the fix from #1581 from helidon-1.x branch. With that fix there is about the tests showed 20% improvement in Avg RT.

repeated config lookup for "mp.metrics.appName" and "mp.metrics.tags", These are originating from creation of instances of org.eclipse.microprofile.metrics.MetricID, which is done for every metric update operation when using annotation

This is happening from the below stack

at io.helidon.microprofile.config.MpConfig.getOptionalValue(MpConfig.java:240)
at org.eclipse.microprofile.metrics.MetricID.(MetricID.java:124)
at io.helidon.microprofile.metrics.MetricUtil.getMetricID(MetricUtil.java:60)
at io.helidon.microprofile.metrics.InterceptorBase.called(InterceptorBase.java:133)
at io.helidon.microprofile.metrics.InterceptorBase.aroundMethod(InterceptorBase.java:114)

Environment Details

• Helidon Version: 1.4.5-SNAPSHOT
• Helidon MP
• JDK version: Java 8
• OS: Oracle Linux 7

[vasanth-bhat]

From the thread dumps taken during the load we see that most threads on two stacks,

1. some of them BLOCKED in ConcurrentHashMap.computeIfAbsent() below.

java.lang.Thread.State: BLOCKED (on object monitor)
at java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1674)

• waiting to lock <0x0000000414f33ea0> (a java.util.concurrent.ConcurrentHashMap$Node)
  at io.helidon.config.ConfigFactory.config(ConfigFactory.java:138)
  at io.helidon.config.AbstractConfigImpl.get(AbstractConfigImpl.java:134)
  at io.helidon.config.Config.get(Config.java:573)
  at io.helidon.microprofile.config.MpConfig.lambda$findValue$4(MpConfig.java:166)
  at io.helidon.microprofile.config.MpConfig$$Lambda$345/2073299099.get(Unknown Source)
  at java.util.Optional.orElseGet(Optional.java:267)
  at io.helidon.microprofile.config.MpConfig.findValue(MpConfig.java:166)
  at io.helidon.microprofile.config.MpConfig.getValue(MpConfig.java:113)
  at io.helidon.microprofile.config.MpConfig.getOptionalValue(MpConfig.java:240)
  at org.eclipse.microprofile.metrics.MetricID.(MetricID.java:124)
  at io.helidon.microprofile.metrics.MetricUtil.getMetricID(MetricUtil.java:60)
  at io.helidon.microprofile.metrics.InterceptorBase.called(InterceptorBase.java:133)
  at io.helidon.microprofile.metrics.InterceptorBase.aroundMethod(InterceptorBase.java:114)
  at sun.reflect.GeneratedMethodAccessor32.invoke(Unknown Source)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:498)
  at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
  at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
  at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
  at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
  at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
  at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)

2. Others in RUNNABLE creating instances of io.helidon.config.MissingValueException(). This exception is thrown repeatedly as the lookup did not find values for "mp.metrics.appName" and "mp.metrics.tags"

java.lang.Thread.State: RUNNABLE
at java.lang.Throwable.fillInStackTrace(Native Method)
at java.lang.Throwable.fillInStackTrace(Throwable.java:784)

• locked <0x00000006cf069e68> (a io.helidon.config.MissingValueException)
  at java.lang.Throwable.(Throwable.java:266)
  at java.lang.Exception.(Exception.java:66)
  at java.lang.RuntimeException.(RuntimeException.java:62)
  at io.helidon.config.ConfigException.(ConfigException.java:32)
  at io.helidon.config.MissingValueException.(MissingValueException.java:34)
  at io.helidon.config.MissingValueException.create(MissingValueException.java:44)
  at io.helidon.config.ConfigValue.lambda$get$0(ConfigValue.java:109)
  at io.helidon.config.ConfigValue$$Lambda$346/2090991873.get(Unknown Source)
  at java.util.Optional.orElseThrow(Optional.java:290)
  at io.helidon.config.ConfigValue.get(ConfigValue.java:109)
  at io.helidon.microprofile.config.MpConfig.lambda$findValue$4(MpConfig.java:166)
  at io.helidon.microprofile.config.MpConfig$$Lambda$345/2073299099.get(Unknown Source)
  at java.util.Optional.orElseGet(Optional.java:267)
  at io.helidon.microprofile.config.MpConfig.findValue(MpConfig.java:166)
  at io.helidon.microprofile.config.MpConfig.getValue(MpConfig.java:113)
  at io.helidon.microprofile.config.MpConfig.getOptionalValue(MpConfig.java:240)
  at org.eclipse.microprofile.metrics.MetricID.(MetricID.java:120)
  at io.helidon.microprofile.metrics.MetricUtil.getMetricID(MetricUtil.java:60)
  at io.helidon.microprofile.metrics.InterceptorBase.called(InterceptorBase.java:133)
  at io.helidon.microprofile.metrics.InterceptorBase.aroundMethod(InterceptorBase.java:114)
  at sun.reflect.GeneratedMethodAccessor32.invoke(Unknown Source)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:498)
  at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
  at org.jboss.weld.interceptor.proxy.NonTerminalAroundInvokeInvocationContext.proceedInternal(NonTerminalAroundInvokeInvocationContext.java:66)
  at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78)
  at io.helidon.microprofile.metrics.InterceptorCounted.prepareAndInvoke(InterceptorCounted.java:52)
  at io.helidon.microprofile.metrics.InterceptorCounted.prepareAndInvoke(InterceptorCounted.java:31)
  at io.helidon.microprofile.metrics.InterceptorBase.called(InterceptorBase.java:143)
  at io.helidon.microprofile.metrics.InterceptorBase.aroundMethod(InterceptorBase.java:114)
  at sun.reflect.GeneratedMethodAccessor32.invoke(Unknown Source)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:498)
  at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
  at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
  at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
  at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
  at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
  at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)

[vasanth-bhat]

Just to understand if the contention is sue to parameers "mp.metrics.appName" and "mp.metrics.tags" parameters missing from configuration , added the below configuration to microprofile-config.properties

mp.metrics.tags=app=compute,container=helidon
mp.metrics.appName=compute

This did help avoid creation of io.helidon.config.MissingValueException() during metric update.
However there was not much improvement in the overall performance.

[vasanth-bhat]

These repeated lookups for "mp.metrics.appName" and "mp.metrics.tags" are originating from the constructor for org.eclipse.microprofile.metrics.MetricID.

For every metric update one new instance of MetricID is created, during which these lookups happen. These instances of MetricID don't seem to get cached and thus adding overhead.

public MetricID(String name, Tag... tags) {
this.name = name;
Config config = ConfigProvider.getConfig();
Optional globalTags = config.getOptionalValue(GLOBAL_TAGS_VARIABLE, String.class);
globalTags.ifPresent(this::parseGlobalTags)
Optional applicationName = config.getOptionalValue(APPLICATION_NAME_VARIABLE, String.class);
applicationName.ifPresent(appName -> {
if(!appName.isEmpty()) {
addTag(new Tag(APPLICATION_NAME_TAG, appName));
}
});
addTags(tags);
}

[vasanth-bhat]

Just to understand the overhead from the continuous lookup,
modified the implementation of io.helidon.microprofile.config.MpConfig.getOptionalValue() as below to avoid repeated config lookups for "mp.metrics.tags" & "mp.metrics.appName" to return fixed values.

public <T> Optional<T> getOptionalValue(String propertyName, Class<T> propertyType) {
    if (propertyName != null) {
         if (propertyName.equalsIgnoreCase("mp.metrics.appName") ) {
            return (Optional<T>) Optional.of("compute");
         } else if (propertyName.equalsIgnoreCase("mp.metrics.tags")) {
            return (Optional<T>) Optional.of("app=compute,container=helidon");
         }
    }
    try {

        return Optional.of(getValue(propertyName, propertyType));
    }

    .......
}

and re-ran the same tests.
with this we see 40% improvement in average RT.

[vasanth-bhat]

creating new instances of " org.eclipse.microprofile.metrics.MetricID" for every metric update operation seems to be root cause for this contention.

Would it be feasible to avoid this new instance creation every invocation, instances MetricID of cached in the implementation of io.helidon.microprofile.metrics.MetricUtil.getMetricID()?
Doing so would avoid bulk of these overheads.

[spericas]

@vasanth-bhat Thanks for the analysis. Are you interested in providing a PR for this?

[vasanth-bhat]

The change i did is just to understand the performance impact of avoiding the repetitive config lookups and not the real solution.
The right solution would be to avoid repetitive creation of instances of io.helidon.microprofile.metrics.MetricUtil.MetricID every time the metric is updated.

[spericas]

The change i did is just to understand the performance impact of avoiding the repetitive config lookups and not the real solution.
The right solution would be to avoid repetitive creation of instances of io.helidon.microprofile.metrics.MetricUtil.MetricID every time the metric is updated.

Of course, I thought you may have gone further and explore the use of a cache.

[vasanth-bhat]

No, I haven't

[olotenko]

1. The config issue. If the keys are meant to be optional, configuration should have negative caching - remember the value is missing, instead of always jumping into computeIfAbsent (and failing)

2. Creation of MetricID. It seems instead of looking up the metric all the time, it should be possible to attach a Metric directly to the method or some other mechanism for InterceptorBase to get the Metric directly.

But maybe there are some intentional design decisions? It looks like the Metric instance is always different, which is quite unexpected.

Adding a print statement to interceptorBase.called:

INSTALL NEW io.helidon.metrics.HelidonTimer@51aa10db for MetricID{name='timedSleep', tags=[]}
INSTALL NEW io.helidon.metrics.HelidonTimer@51aa10fb for MetricID{name='timedSleep', tags=[]}
INSTALL NEW io.helidon.metrics.HelidonTimer@51aa111b for MetricID{name='timedSleep', tags=[]}

[tjquinno]

Given that the metric ID creation seems to be the worse problem, that's where we're looking currently. The negative caching idea might be suitable for a separate issue on the config component.

There are a few possible solutions to the metrics ID issue, each with varying impact on the code. We're working on that now.

[tjquinno]

Undoing the auto-close of this issue until the 1.x PR can be merged. Currently it's waiting for the grpc cert fix so the pipeline can pass.

[tjquinno]

Fixed in 1.x and 2.x

[vasanth-bhat]

Repeated the test updated Helidon from 1.x branch (1.4.5-SNAPSHOT) that includes fixes for issues #1595, #1570 & #1571

With the fixes, we no longer have the significant overhead that we used to have when using metrics via Annotations.
Now the overall performance for use of metrics via annotation is similar to that using metrics via APIs. These tests showed ~ 3x (300%) improvement in Averge RT for use Counter and Timer via annotations, when compared to earlier tests done on 1.4.4

Thanks for the excellent fix

[tjquinno]

Thanks for testing again and sharing your results.