Contention from io.helidon.metrics.Registry.getSortedMetrics()

[vasanth-bhat]

We some tests to understand the overhead of using metrics via both programmatic API's as well as annotations.
While didn't see much overhead while using programmatic API (MetricRegistry.counter, MetricRegistry.timer etc.) , we do see overhead while using annotations @timed , @ Counted etc.

The primarily contention is coming from the the implementation of synchronized method io.helidon.metrics.Registry.getSortedMetrics() , which is performing a sort using TreeMap. From the thread dumps, we see that most threads are BLOCKED on this method waiting for the monitor. The code path seems to end up sorting , all of them while holding the monitor.

private synchronized SortedMap<String, V> getSortedMetrics(MetricFilter filter, Class metricClass) {
Map<String, V> collected = allMetrics.entrySet()
.stream()
.filter(it -> metricClass.isAssignableFrom(it.getValue().getClass()))
.filter(it -> filter.matches(it.getKey(), it.getValue()))
.collect(Collectors.toMap(Map.Entry::getKey, it -> metricClass.cast(it.getValue())));
return new TreeMap<>(collected);
}

[vasanth-bhat]

Sample Stack for the Counter

java.lang.Thread.State: BLOCKED (on object monitor)
at io.helidon.metrics.Registry.getSortedMetrics(Registry.java:850)
- waiting to lock <0x0000000414ff4b50> (a io.helidon.metrics.Registry)
at io.helidon.metrics.Registry.getCounters(Registry.java:302)
at io.helidon.metrics.Registry.getCounters(Registry.java:297)
at io.helidon.microprofile.metrics.InterceptorCounted$$Lambda$1051/2102703721.apply(Unknown Source)
at io.helidon.microprofile.metrics.InterceptorBase.called(InterceptorBase.java:136)
at io.helidon.microprofile.metrics.InterceptorBase.aroundMethod(InterceptorBase.java:114)
at sun.reflect.GeneratedMethodAccessor33.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]

Sample Stack for the Timer

java.lang.Thread.State: BLOCKED (on object monitor)
at io.helidon.metrics.Registry.getSortedMetrics(Registry.java:850)
- waiting to lock <0x0000000414ff4b50> (a io.helidon.metrics.Registry)
at io.helidon.metrics.Registry.getTimers(Registry.java:332)
at io.helidon.metrics.Registry.getTimers(Registry.java:327)
at io.helidon.microprofile.metrics.InterceptorTimed$$Lambda$1055/325898573.apply(Unknown Source)
at io.helidon.microprofile.metrics.InterceptorBase.called(InterceptorBase.java:136)
at io.helidon.microprofile.metrics.InterceptorBase.aroundMethod(InterceptorBase.java:114)
at sun.reflect.GeneratedMethodAccessor33.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.GeneratedMethodAccessor33.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]

Version of Helidon                : v1.4.4
Whether you are writing a Helidon SE or MP application  :  Helidon MP
OS  : Linux 
Steps to reproduce :   
 Sample end point , that  updates 20+ metrics  on methods of a Injected Bean class. 

 Load test for 25+ concurrent users that invokes the end point

[spericas]

Fixed by PR #1581 (and #1575 in master).

[vasanth-bhat]

I have basic question .

Why there is a need for sort, for each attempt to update the metric? We don't seem to have it when we use the Counter via the API ( counter=MetricRegistry.counter("name") , counter.inc() )

This is now created as a separate issue
#1591

[vasanth-bhat]

Repeated the same tests with the fix from #1581 from helidon-1.x branch. With the fix there is about the tests showed 20% improvement in Avg RT.
However we are seeing the contention coming from the 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 through annotations.

Created the new issue #1595 for tracking this