Context refresh may deadlock when using Prometheus Exemplars

[goafabric]

Description
I am experiencing a very strange problem,
thats not easy to reproduce.
However I was able to capture a Thread Dump via JProfile.

With the combination of :

• Spring Boot 3-RC1 (also latest Snapshot from 7th November)

• Jaeger Tracing inside Docker or Kubernetes

• Prometheus

• Zipkin

• Data JPA

The Application will occasionally deadlock during bootstrap.
Just after the initialization of "ServletWebServerApplicationContext"
Removing one of the Dependencies will remedy the situation.
The stacktrace below shows that the problem seems to occur when prometheus triggers the autoconfig of the tracer.
However this only happens when combined with JPA.
Full Stacktrace is attached as well as the gradle build file.

Unfortunately I was able to create a downsized application that is able to reproduce the error.
So that is all the information i can provide for now

Question
I also noticed, that the rebuild Micrometer Tracing behaves where differently from the old sleuth implementation.
The traces include a lot of low level information (e.g. Spring Security Filter Chain).
And I was also not able to get complete spans across multiple applications, just seperate ones.
Will there be a fix and/or updated documentation with the Release of 3.0 GA ?

Thanks in advance

Thread main:
  at org.springframework.util.function.SingletonSupplier.get() (line: 94)
  at org.springframework.util.function.SingletonSupplier.obtain() (line: 115)
  at org.springframework.boot.actuate.autoconfigure.tracing.exemplars.ExemplarsAutoConfiguration$LazyTracingSpanContextSupplier.currentSpan() (line: 85)
  at org.springframework.boot.actuate.autoconfigure.tracing.exemplars.ExemplarsAutoConfiguration$LazyTracingSpanContextSupplier.isSampled() (line: 80)
  at io.prometheus.client.exemplars.DefaultExemplarSampler.doSample(double, io.prometheus.client.exemplars.Exemplar) (line: 46)
  at io.prometheus.client.exemplars.DefaultExemplarSampler.sample(double, io.prometheus.client.exemplars.Exemplar) (line: 34)

thread-trace.zip
build.gradle.zip

[wilkinsona]

Thanks for the report. For a deadlock to occur, two or more threads much be involved. Looking at the thread dump, there only appears to be a single thread involved. There's also no information about the locks that are held which unfortunately makes it impossible to see what's going on. Can you please try reproducing the problem and, when it occurs, capture a thread dump using kill -3 and share the complete output?

[wilkinsona]

Question
I also noticed, that the rebuild Micrometer Tracing behaves where differently from the old sleuth implementation.

Spring Boot's issue tracker isn't really the right place for this. The Micrometer Slack would be better.

[goafabric]

@wilkinsona
will try to reproduce and deliver the kill -3 result
thank you

[goafabric]

does not seem to be reproduceable on my faster macbook pro
have to pickup my macbook air later and reverify there .... looks like a race condition

[goafabric]

Attached the kill -3 output.
Imo mostly tells the same story .. blocked inside SingletTonSupplier of SpanContextsSupplier .get()
Which has a call to synchronize ..
But I am not the expert here ...

Same code, runs with Spring Boot 2.x .. taking into account that a lot of transient libraries of Spring of Course have changed.

kill-dump.txt

[wilkinsona]

Thank you, @goafabric. This dump is much more useful as it shows the deadlock:

Found one Java-level deadlock:
=============================
"main":
  waiting to lock monitor 0x0000600001bb35a0 (object 0x0000000702e01130, a org.springframework.util.function.SingletonSupplier),
  which is held by "Notification Thread"

"Notification Thread":
  waiting to lock monitor 0x0000600001ba63c0 (object 0x0000000700801208, a java.util.concurrent.ConcurrentHashMap),
  which is held by "main"

Java stack information for the threads listed above:
===================================================
"main":
	at org.springframework.util.function.SingletonSupplier.get(SingletonSupplier.java:94)
	- waiting to lock <0x0000000702e01130> (a org.springframework.util.function.SingletonSupplier)
	at org.springframework.util.function.SingletonSupplier.obtain(SingletonSupplier.java:115)
	at org.springframework.boot.actuate.autoconfigure.tracing.exemplars.ExemplarsAutoConfiguration$LazyTracingSpanContextSupplier.currentSpan(ExemplarsAutoConfiguration.java:85)
	at org.springframework.boot.actuate.autoconfigure.tracing.exemplars.ExemplarsAutoConfiguration$LazyTracingSpanContextSupplier.isSampled(ExemplarsAutoConfiguration.java:80)
	at io.prometheus.client.exemplars.DefaultExemplarSampler.doSample(DefaultExemplarSampler.java:46)
	at io.prometheus.client.exemplars.DefaultExemplarSampler.sample(DefaultExemplarSampler.java:34)
	at io.micrometer.prometheus.PrometheusCounter.updateExemplar(PrometheusCounter.java:79)
	at io.micrometer.prometheus.PrometheusCounter.increment(PrometheusCounter.java:58)
	at io.micrometer.core.instrument.Counter.increment(Counter.java:38)
	at io.micrometer.core.instrument.binder.logging.MetricsTurboFilter.decide(LogbackMetrics.java:199)
	at ch.qos.logback.classic.spi.TurboFilterList.getTurboFilterChainDecision(TurboFilterList.java:49)
	at ch.qos.logback.classic.LoggerContext.getTurboFilterChainDecision_0_3OrMore(LoggerContext.java:251)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:375)
	at ch.qos.logback.classic.Logger.info(Logger.java:584)
	at org.flywaydb.core.internal.logging.slf4j.Slf4jLog.info(Slf4jLog.java:37)
	at org.flywaydb.core.internal.logging.multi.MultiLogger.info(MultiLogger.java:52)
	at org.flywaydb.core.internal.logging.EvolvingLog.info(EvolvingLog.java:58)
	at org.flywaydb.core.internal.license.VersionPrinter.printVersionOnly(VersionPrinter.java:56)
	at org.flywaydb.core.internal.license.VersionPrinter.printVersion(VersionPrinter.java:49)
	at org.flywaydb.core.FlywayExecutor.execute(FlywayExecutor.java:121)
	at org.flywaydb.core.Flyway.migrate(Flyway.java:128)
	at org.springframework.boot.autoconfigure.flyway.FlywayMigrationInitializer.afterPropertiesSet(FlywayMigrationInitializer.java:66)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1799)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1749)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:599)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:521)
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:326)
	at org.springframework.beans.factory.support.AbstractBeanFactory$$Lambda$280/0x0000000800db79c8.getObject(Unknown Source)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
	- locked <0x0000000700801208> (a java.util.concurrent.ConcurrentHashMap)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:324)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:200)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:313)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:200)
	at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1131)
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:906)
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:584)
	- locked <0x000000070089bae8> (a java.lang.Object)
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:146)
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:730)
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:432)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:308)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1302)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1291)
	at org.goafabric.personservice.Application.main(Application.java:19)
"Notification Thread":
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.getSingletonFactoryBeanForTypeCheck(AbstractAutowireCapableBeanFactory.java:972)
	- waiting to lock <0x0000000700801208> (a java.util.concurrent.ConcurrentHashMap)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.getTypeForFactoryBean(AbstractAutowireCapableBeanFactory.java:891)
	at org.springframework.beans.factory.support.AbstractBeanFactory.isTypeMatch(AbstractBeanFactory.java:619)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.doGetBeanNamesForType(DefaultListableBeanFactory.java:572)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBeanNamesForType(DefaultListableBeanFactory.java:531)
	at org.springframework.beans.factory.BeanFactoryUtils.beanNamesForTypeIncludingAncestors(BeanFactoryUtils.java:260)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.findAutowireCandidates(DefaultListableBeanFactory.java:1539)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.doResolveDependency(DefaultListableBeanFactory.java:1338)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory$DependencyObjectProvider.getObject(DefaultListableBeanFactory.java:1972)
	at org.springframework.boot.actuate.autoconfigure.tracing.exemplars.ExemplarsAutoConfiguration$LazyTracingSpanContextSupplier$$Lambda$733/0x0000000801137ac0.get(Unknown Source)
	at org.springframework.util.function.SingletonSupplier.get(SingletonSupplier.java:97)
	- locked <0x0000000702e01130> (a org.springframework.util.function.SingletonSupplier)
	at org.springframework.util.function.SingletonSupplier.obtain(SingletonSupplier.java:115)
	at org.springframework.boot.actuate.autoconfigure.tracing.exemplars.ExemplarsAutoConfiguration$LazyTracingSpanContextSupplier.currentSpan(ExemplarsAutoConfiguration.java:85)
	at org.springframework.boot.actuate.autoconfigure.tracing.exemplars.ExemplarsAutoConfiguration$LazyTracingSpanContextSupplier.isSampled(ExemplarsAutoConfiguration.java:80)
	at io.prometheus.client.exemplars.DefaultExemplarSampler.doSample(DefaultExemplarSampler.java:46)
	at io.prometheus.client.exemplars.DefaultExemplarSampler.sample(DefaultExemplarSampler.java:34)
	at io.micrometer.prometheus.PrometheusCounter.updateExemplar(PrometheusCounter.java:79)
	at io.micrometer.prometheus.PrometheusCounter.increment(PrometheusCounter.java:58)
	at io.micrometer.core.instrument.binder.jvm.JvmGcMetrics$GcMetricsNotificationListener.countPoolSizeDelta(JvmGcMetrics.java:223)
	at io.micrometer.core.instrument.binder.jvm.JvmGcMetrics$GcMetricsNotificationListener.handleNotification(JvmGcMetrics.java:191)
	at sun.management.NotificationEmitterSupport.sendNotification(java.management@17.0.2/NotificationEmitterSupport.java:155)
	at com.sun.management.internal.GarbageCollectorExtImpl.createGCNotification(jdk.management@17.0.2/GarbageCollectorExtImpl.java:115)

Found 1 deadlock.

This deadlock is the same as reported in spring-projects/spring-framework#23501. I'm not sure what, if anything, we can do about it in Boot.