Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Performance issue reporting EhCache metrics with a large cache #1584

Closed
sthallapalli opened this issue Sep 12, 2019 · 12 comments
Closed

Performance issue reporting EhCache metrics with a large cache #1584

sthallapalli opened this issue Sep 12, 2019 · 12 comments

Comments

@sthallapalli
Copy link

sthallapalli commented Sep 12, 2019

Spring Boot 2.0.x
EhCache: 2.10.6
micrometer: 1.0.8

Message : java.lang.reflect.InvocationTargetException ############
java.lang.RuntimeException: java.lang.reflect.InvocationTargetException
	at org.terracotta.statistics.PassThroughStatistic.value(PassThroughStatistic.java:65)
	at net.sf.ehcache.statistics.extended.AbstractStatistic.value(AbstractStatistic.java:57)
	at net.sf.ehcache.statistics.extended.SemiExpiringStatistic.value(SemiExpiringStatistic.java:33)
	at net.sf.ehcache.statistics.StatisticsGateway.getLocalHeapSizeInBytes(StatisticsGateway.java:327)
	at io.micrometer.core.instrument.internal.DefaultGauge.value(DefaultGauge.java:40)
	at io.micrometer.prometheus.PrometheusMeterRegistry.lambda$newGauge$3(PrometheusMeterRegistry.java:230)
	at io.micrometer.prometheus.MicrometerCollector.collect(MicrometerCollector.java:92)
	at io.prometheus.client.CollectorRegistry$MetricFamilySamplesEnumeration.findNextElement(CollectorRegistry.java:183)
	at io.prometheus.client.CollectorRegistry$MetricFamilySamplesEnumeration.nextElement(CollectorRegistry.java:216)
	at io.prometheus.client.CollectorRegistry$MetricFamilySamplesEnumeration.nextElement(CollectorRegistry.java:137)
	at io.prometheus.client.exporter.common.TextFormat.write004(TextFormat.java:22)
	at org.springframework.boot.actuate.metrics.export.prometheus.PrometheusScrapeEndpoint.scrape(PrometheusScrapeEndpoint.java:50)
	at sun.reflect.GeneratedMethodAccessor452.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:246)
	at org.springframework.boot.actuate.endpoint.invoke.reflect.ReflectiveOperationInvoker.invoke(ReflectiveOperationInvoker.java:76)
	at org.springframework.boot.actuate.endpoint.annotation.AbstractDiscoveredOperation.invoke(AbstractDiscoveredOperation.java:61)
	at org.springframework.boot.actuate.endpoint.web.servlet.AbstractWebMvcEndpointHandlerMapping$ServletWebOperationAdapter.handle(AbstractWebMvcEndpointHandlerMapping.java:274)
	at org.springframework.boot.actuate.endpoint.web.servlet.AbstractWebMvcEndpointHandlerMapping$OperationHandler.handle(AbstractWebMvcEndpointHandlerMapping.java:330)
	at sun.reflect.GeneratedMethodAccessor231.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:209)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:136)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:102)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:891)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:797)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:991)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:925)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:981)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:873)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:858)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:90)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:320)
	at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:127)
	at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:91)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
	at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:119)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
	at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
	at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
	at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:170)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
	at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
	at org.springframework.security.oauth2.provider.authentication.OAuth2AuthenticationProcessingFilter.doFilter(OAuth2AuthenticationProcessingFilter.java:176)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
	at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
	at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:74)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
	at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
	at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:215)
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:178)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:357)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:270)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.security.oauth2.client.filter.OAuth2ClientContextFilter.doFilter(OAuth2ClientContextFilter.java:60)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:109)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:93)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.cloud.sleuth.instrument.web.ExceptionLoggingFilter.doFilter(ExceptionLoggingFilter.java:48)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at brave.servlet.TracingFilter.doFilter(TracingFilter.java:86)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:117)
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:106)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:493)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:800)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:806)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1498)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.reflect.InvocationTargetException: null
	at sun.reflect.GeneratedMethodAccessor453.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.terracotta.statistics.StatisticsManager$MethodCallable.call(StatisticsManager.java:113)
	at org.terracotta.statistics.PassThroughStatistic.value(PassThroughStatistic.java:63)
	... 119 common frames omitted
Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded
	at java.util.Arrays.copyOf(Arrays.java:3332)
	at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:124)
	at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:448)
	at java.lang.StringBuilder.append(StringBuilder.java:136)
	at ch.qos.logback.core.pattern.FormattingConverter.write(FormattingConverter.java:39)
	at ch.qos.logback.core.pattern.PatternLayoutBase.writeLoopOnConverters(PatternLayoutBase.java:115)
	at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:141)
	at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:39)
	at ch.qos.logback.core.encoder.LayoutWrappingEncoder.encode(LayoutWrappingEncoder.java:115)
	at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:230)
	at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
	at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
	at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:398)
	at ch.qos.logback.classic.Logger.warn(Logger.java:696)
	at net.sf.ehcache.pool.impl.DefaultSizeOfEngine.sizeOf(DefaultSizeOfEngine.java:196)
	at net.sf.ehcache.store.MemoryStore.getInMemorySizeInBytes(MemoryStore.java:802)
	at sun.reflect.GeneratedMethodAccessor453.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.terracotta.statistics.StatisticsManager$MethodCallable.call(StatisticsManager.java:113)
	at org.terracotta.statistics.PassThroughStatistic.value(PassThroughStatistic.java:63)
	at net.sf.ehcache.statistics.extended.AbstractStatistic.value(AbstractStatistic.java:57)
	at net.sf.ehcache.statistics.extended.SemiExpiringStatistic.value(SemiExpiringStatistic.java:33)
	at net.sf.ehcache.statistics.StatisticsGateway.getLocalHeapSizeInBytes(StatisticsGateway.java:327)
	at io.micrometer.core.instrument.binder.cache.EhCache2Metrics$$Lambda$962/969440066.applyAsDouble(Unknown Source)
	at io.micrometer.core.instrument.internal.DefaultGauge.value(DefaultGauge.java:40)
	at io.micrometer.prometheus.PrometheusMeterRegistry.lambda$newGauge$3(PrometheusMeterRegistry.java:230)
@shakuzen
Copy link
Member

It will be hard to diagnose what the cause of the OOM error is without more information. Can you check a heap dump when the OOM occurs? If it is related to Micrometer, the most likely cause is that unique metrics are being created with high cardinality (unbounded). If that's the cause, we'd want to see what metric there are a lot of. Perhaps check the Prometheus endpoint before an OOM happens to see if there is any metric with many many different labels.

@checketts
Copy link
Contributor

In a project I helped with, we weren't hitting OOM errors, but we were seeing that the way that ehcache checks it size and local memory usage were both inefficient. We had to turn it off by:

#Disable cache.size metrics for ehcache since they are so big, it is expensive to compute
management.metrics.enable.cache.size: false
# cache.local metrics is related to the size of the cache in memory, also expensive
management.metrics.enable.cache.local: false

We weren't able to work around it with Micrometer because the calls to ehcache themselves (StatisticsGateway.getLocalHeapSizeInBytes for example) itself just wasn't efficient.

Alternatively you could watch the metrics that are being reported and before the OOM and limit the cache size to that amount. I would have made that approach on the aforementioned project, but instead they had opted to increase their memory usage and keep their caches as they were.

@checketts checketts changed the title OutOfMemoryError using EhCache and Micrometer with Prometheus on SptingBoot 2 OutOfMemoryError using EhCache and Micrometer with Prometheus on SpringBoot 2 Sep 27, 2019
@shakuzen
Copy link
Member

We weren't able to work around it with Micrometer because the calls to ehcache themselves (StatisticsGateway.getLocalHeapSizeInBytes for example) itself just wasn't efficient.

Would a MeterFilter that denies those metrics work?

If those two metrics are generally problematic, maybe we should not register those metrics by default. What do you think?
Also, is there an open issue in EHCache regarding the inefficiency of these methods? Maybe there is an alternative we could use or they could improve it.

@checketts
Copy link
Contributor

If those two metrics are generally problematic, maybe we should not register those metrics by default. What do you think?

Since this is the first issue opened in this regard, I don't think they are generally problematic. We could add at try/catch to EhCache2Metrics that could encourage the user to disable the metric at that time (if it is causing them errors).

The project I saw where they ran into this were a little oblivious to how much they were caching and how large the objects were.

I hadn't checked for an issue against EhCache, since I've largely been migrating to Caffeine for in-memory caches going forward.

@mnowotnik
Copy link

mnowotnik commented Oct 6, 2020

I also experience this problem in a large Spring web application. We've disabled metrics for the time being because calls by prometheus to scrape endpoint end up lasting longer and longer to the point where there are tens of threads occupied by calls to scrape endpoint stuck inside StatisticsGateway#getLocalHeapSizeInBytes method. Application ends up using all available memory and CPU resources and crashes.

@jens-krogsboll
Copy link

We are also having this issue with a big Spring web application with a huge amount of cache.

I ended here in my search for a way to disable just the cache or ehcache binding. Will @shakuzen idea with a MeterFilter be an option?

@mnowotnik
Copy link

We are also having this issue with a big Spring web application with a huge amount of cache.

I ended here in my search for a way to disable just the cache or ehcache binding. Will @shakuzen idea with a MeterFilter be an option?

You can simply exclude Spring autoconfiguration: org.springframework.boot.actuate.autoconfigure.metrics.cache.CacheMetricsAutoConfiguration; and it completely solves the problem. Notice, however, that this autoconfig is responsible for multiple cache metrics:
ehcache,hazelcast,jcache,caffeine.

@jens-krogsboll
Copy link

Thanks @mnowotnik :-)

I experimented a bit and also found that using just one of @checketts suggested settings seem to disable exactly the metric that causes the problem:

management.metrics.enable.cache.local: false

@mnowotnik
Copy link

mnowotnik commented Oct 12, 2020

Thanks @mnowotnik :-)

I experimented a bit and also found that using just one of @checketts suggested settings seem to disable exactly the metric that causes the problem:

management.metrics.enable.cache.local: false

Glad it works for you.
Tried that and didn't work for me (unless I made a typo). Also, I couldn't find docs for that property on the web, so I went the excluding autoconfig route.

EDIT*:
it seems those properties are assigned here:

@ConfigurationProperties("management.metrics")
public class MetricsProperties {
	/**
	 * Whether meter IDs starting with the specified name should be enabled. The longest
	 * match wins, the key `all` can also be used to configure all meters.
	 */
	private final Map<String, Boolean> enable = new LinkedHashMap<>();
}

@shakuzen shakuzen changed the title OutOfMemoryError using EhCache and Micrometer with Prometheus on SpringBoot 2 Performance issue reporting EhCache metrics with a large cache Oct 13, 2020
@marcingrzejszczak
Copy link
Contributor

Is it still a problem with the latest versions?

@marcingrzejszczak marcingrzejszczak added the waiting for feedback We need additional information before we can continue label Dec 19, 2023
Copy link

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

Copy link

github-actions bot commented Jan 5, 2024

Closing due to lack of requested feedback. If you would like us to look at this issue, please provide the requested information and we will re-open.

@github-actions github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale Jan 5, 2024
@jonatan-ivanov jonatan-ivanov removed waiting for feedback We need additional information before we can continue feedback-reminder labels Jan 8, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

7 participants