Problem
When using Spring Boot 3.4.0 combined with Spring WebMVC, virtual threads, and lazy bean initialization, accessing /actuator/health during the application launch results in a pinned virtual thread.
This is a regression from Spring Boot 3.3.6 where this issue does not occur.
Sample App
This issue is demonstrated in https://github.com/chrisgleissner/spring-boot-3.4-pinned-thread-during-launch-issue: - 3.4.0 - JVM logs pinned Virtual Threads - 3.3.6 - JVM does not log pinned Virtual Thraeds
Details
- Start process that continuously calls /actuator/health:
until curl --output /dev/null --silent --head --fail http://localhost:8080/actuator/health; do printf '.'; sleep 0.01; done
- Start Spring Boot app
./gradlew bootRun
Software Versions
- Spring Boot: 3.4.0
- Java: OpenJDK 64-Bit Server VM Corretto-21.0.5.11.1 (build 21.0.5+11-LTS, mixed mode, sharing)
- OS: Ubuntu 24.04.1
- Gradle 8.11.1
Source code
build.gradle.kts:
plugins {
java
id("org.springframework.boot") version "3.4.0"
id("io.spring.dependency-management") version "1.1.6"
}
group = "com.example"
version = "0.0.1-SNAPSHOT"
java {
toolchain {
languageVersion = JavaLanguageVersion.of(21)
}
}
repositories {
mavenCentral()
}
dependencies {
implementation("org.springframework.boot:spring-boot-starter-actuator")
implementation("org.springframework.boot:spring-boot-starter-web")
}
tasks.bootRun {
jvmArgs = listOf("-Djdk.tracePinnedThreads=full")
}
src/main/java/com/example/demo/DemoApplication.java:
package com.example.demo;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
@SpringBootApplication
public class DemoApplication {
public static void main(String[] args) {
SpringApplication.run(DemoApplication.class, args);
}
}
src/main/resources/application.yaml:
spring:
main:
lazy-initialization: true
threads:
virtual:
enabled: true
Expected Logs (Spring Boot 3.3.6)
No thread pinning detected.
./gradlew bootRun
> Task :bootRun
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v3.3.6)
2024-11-23T10:43:14.002Z INFO 193730 --- [ main] com.example.demo.DemoApplication : Starting DemoApplication using Java 21.0.5 with PID 193730 (/home/chris/dev/loom-webflux-errors/3.4.0-monitor/sample/demo/build/classes/java/main started by chris in /home/chris/dev/loom-webflux-errors/3.4.0-monitor/sample/demo)
2024-11-23T10:43:14.005Z INFO 193730 --- [ main] com.example.demo.DemoApplication : No active profile set, falling back to 1 default profile: "default"
2024-11-23T10:43:14.653Z INFO 193730 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port 8080 (http)
2024-11-23T10:43:14.663Z INFO 193730 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2024-11-23T10:43:14.663Z INFO 193730 --- [ main] o.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/10.1.33]
2024-11-23T10:43:14.692Z INFO 193730 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2024-11-23T10:43:14.693Z INFO 193730 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 659 ms
2024-11-23T10:43:14.871Z INFO 193730 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port 8080 (http) with context path '/'
2024-11-23T10:43:14.914Z INFO 193730 --- [omcat-handler-0] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2024-11-23T10:43:14.915Z INFO 193730 --- [omcat-handler-0] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2024-11-23T10:43:14.997Z INFO 193730 --- [ main] o.s.b.a.e.web.EndpointLinksResolver : Exposing 1 endpoint beneath base path '/actuator'
2024-11-23T10:43:15.008Z INFO 193730 --- [ main] com.example.demo.DemoApplication : Started DemoApplication in 1.293 seconds (process running for 1.493)
2024-11-23T10:43:15.062Z INFO 193730 --- [omcat-handler-0] o.s.web.servlet.DispatcherServlet : Completed initialization in 147 ms
Actual Logs (Spring Boot 3.4.0)
Thread pinning detected.
./gradlew bootRun
> Task :bootRun
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v3.4.0)
2024-11-23T10:44:40.524Z INFO 194398 --- [ main] com.example.demo.DemoApplication : Starting DemoApplication using Java 21.0.5 with PID 194398 (/home/chris/dev/loom-webflux-errors/3.4.0-monitor/sample/demo/build/classes/java/main started by chris in /home/chris/dev/loom-webflux-errors/3.4.0-monitor/sample/demo)
2024-11-23T10:44:40.526Z INFO 194398 --- [ main] com.example.demo.DemoApplication : No active profile set, falling back to 1 default profile: "default"
2024-11-23T10:44:41.194Z INFO 194398 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port 8080 (http)
2024-11-23T10:44:41.203Z INFO 194398 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2024-11-23T10:44:41.203Z INFO 194398 --- [ main] o.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/10.1.33]
2024-11-23T10:44:41.232Z INFO 194398 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2024-11-23T10:44:41.232Z INFO 194398 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 680 ms
2024-11-23T10:44:41.415Z INFO 194398 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port 8080 (http) with context path '/'
2024-11-23T10:44:41.450Z INFO 194398 --- [omcat-handler-0] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2024-11-23T10:44:41.450Z INFO 194398 --- [omcat-handler-0] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
VirtualThread[#37,tomcat-handler-0]/runnable@ForkJoinPool-1-worker-1 reason:MONITOR
java.base/java.lang.VirtualThread$VThreadContinuation.onPinned(VirtualThread.java:199)
java.base/jdk.internal.vm.Continuation.onPinned0(Continuation.java:393)
java.base/java.lang.VirtualThread.park(VirtualThread.java:596)
java.base/java.lang.System$2.parkVirtualThread(System.java:2643)
java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:54)
java.base/java.util.concurrent.locks.LockSupport.park(LockSupport.java:219)
java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:990)
java.base/java.util.concurrent.locks.ReentrantLock$Sync.lock(ReentrantLock.java:153)
java.base/java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:322)
org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:263)
org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:334)
org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:204)
org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1278)
org.springframework.web.servlet.DispatcherServlet.initMultipartResolver(DispatcherServlet.java:527)
org.springframework.web.servlet.DispatcherServlet.initStrategies(DispatcherServlet.java:509)
org.springframework.web.servlet.DispatcherServlet.onRefresh(DispatcherServlet.java:501)
org.springframework.web.servlet.FrameworkServlet.initWebApplicationContext(FrameworkServlet.java:603) <== monitors:1
org.springframework.web.servlet.FrameworkServlet.initServletBean(FrameworkServlet.java:537)
org.springframework.web.servlet.HttpServletBean.init(HttpServletBean.java:169)
jakarta.servlet.GenericServlet.init(GenericServlet.java:143)
jakarta.servlet.http.HttpServlet.init(HttpServlet.java:121)
org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:837) <== monitors:1
org.apache.catalina.core.StandardWrapper.allocate(StandardWrapper.java:588) <== monitors:1
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:115)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:483)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344)
org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:397)
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:905)
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1741)
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
java.base/java.lang.VirtualThread.run(VirtualThread.java:329)
2024-11-23T10:44:41.543Z INFO 194398 --- [ main] o.s.b.a.e.web.EndpointLinksResolver : Exposing 1 endpoint beneath base path '/actuator'
2024-11-23T10:44:41.557Z INFO 194398 --- [ main] com.example.demo.DemoApplication : Started DemoApplication in 1.314 seconds (process running for 1.538)
VirtualThread[#37,tomcat-handler-0]/runnable@ForkJoinPool-1-worker-1 reason:MONITOR
java.base/java.lang.VirtualThread$VThreadContinuation.onPinned(VirtualThread.java:199)
java.base/jdk.internal.vm.Continuation.onPinned0(Continuation.java:393)
java.base/java.lang.VirtualThread.park(VirtualThread.java:596)
java.base/java.lang.System$2.parkVirtualThread(System.java:2643)
java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:54)
java.base/java.util.concurrent.locks.LockSupport.park(LockSupport.java:219)
java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:990)
java.base/java.util.concurrent.locks.ReentrantLock$Sync.lock(ReentrantLock.java:153)
java.base/java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:322)
org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:263)
org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:334)
org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:204)
org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1278)
org.springframework.web.servlet.DispatcherServlet.initThemeResolver(DispatcherServlet.java:577)
org.springframework.web.servlet.DispatcherServlet.initStrategies(DispatcherServlet.java:511)
org.springframework.web.servlet.DispatcherServlet.onRefresh(DispatcherServlet.java:501)
org.springframework.web.servlet.FrameworkServlet.initWebApplicationContext(FrameworkServlet.java:603) <== monitors:1
org.springframework.web.servlet.FrameworkServlet.initServletBean(FrameworkServlet.java:537)
org.springframework.web.servlet.HttpServletBean.init(HttpServletBean.java:169)
jakarta.servlet.GenericServlet.init(GenericServlet.java:143)
jakarta.servlet.http.HttpServlet.init(HttpServlet.java:121)
org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:837) <== monitors:1
org.apache.catalina.core.StandardWrapper.allocate(StandardWrapper.java:588) <== monitors:1
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:115)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:483)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344)
org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:397)
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:905)
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1741)
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
java.base/java.lang.VirtualThread.run(VirtualThread.java:329)
2024-11-23T10:44:41.608Z INFO 194398 --- [omcat-handler-0] o.s.web.servlet.DispatcherServlet : Completed initialization in 158 ms
Monitors
This section shows the relevant code for each of the stack trace lines ending with <== monitors:1 in the stack trace above.
Monitor
Log:
org.springframework.web.servlet.FrameworkServlet.initWebApplicationContext(FrameworkServlet.java:603) <== monitors:1
Code:
protected WebApplicationContext initWebApplicationContext() {
WebApplicationContext rootContext = WebApplicationContextUtils.getWebApplicationContext(this.getServletContext());
WebApplicationContext wac = null;
if (this.webApplicationContext != null) {
wac = this.webApplicationContext;
if (wac instanceof ConfigurableWebApplicationContext) {
ConfigurableWebApplicationContext cwac = (ConfigurableWebApplicationContext)wac;
if (!cwac.isActive()) {
if (cwac.getParent() == null) {
cwac.setParent(rootContext);
}
this.configureAndRefreshWebApplicationContext(cwac);
}
}
}
if (wac == null) {
wac = this.findWebApplicationContext();
}
if (wac == null) {
wac = this.createWebApplicationContext(rootContext);
}
if (!this.refreshEventReceived) {
synchronized(this.onRefreshMonitor) {
this.onRefresh(wac);
}
}
Monitor
Log:
org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:837) <== monitors:1
Code:
private synchronized void initServlet(Servlet servlet) throws ServletException {
if (!this.instanceInitialized) {
try {
if (Globals.IS_SECURITY_ENABLED) {
boolean success = false;
Monitor
Log:
org.apache.catalina.core.StandardWrapper.allocate(StandardWrapper.java:588) <== monitors:1
Code:
public Servlet allocate() throws ServletException {
if (this.unloading) {
throw new ServletException(sm.getString("standardWrapper.unloading", new Object[]{this.getName()}));
} else {
boolean newInstance = false;
if (this.instance == null || !this.instanceInitialized) {
synchronized(this) {
Comment From: wilkinsona
Thanks for the sample.
Actuator doesn't appear to be relevant to the problem as it can be reproduced with a dependency on only spring-boot-starter-web and the following main class:
package com.example.gh_43276;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
@RestController
@SpringBootApplication
public class Gh43276Application {
@GetMapping
String ping() {
return "pong";
}
public static void main(String[] args) {
SpringApplication.run(Gh43276Application.class, args);
}
}
Repeatedly accessing http://localhost:8080 during startup will then trigger the problem. It appears that enabling lazy initialization is required as I've been unable to reproduce without it.
If you want to keep lazy initialization enabled, the problem can also be avoided by setting spring.mvc.servlet.load-on-startup=0. This will ensure that DispatcherServlet is initialized on the main thread rather than on a potentially virtual request-handling thread.
The synchronisation in Tomcat's StandardWrapper and Framework's FrameworkServlet hasn't changed. What has changed is the locking in DefaultSingletonBeanRegistry and I think it's this change in Framework 6.2 that's causing that synchronisation to now be flagged as a cause of pinning. We'll transfer this issue to the Framework team so that they can consider any changes that may be appropriate here.
Comment From: chrisgleissner
Thanks for the detailed analysis and the workaround @wilkinsona. Much appreciated.
I have tried the work-around in my sample project and as per https://github.com/chrisgleissner/spring-boot-3.4-pinned-thread-during-launch-issue/actions/runs/12016916807/job/33498136714#step:4:47, the thread pinning no longer occurs.
I will use this workaround until the root issue is fixed.
Comment From: sdeleuze
I confirm @wilkinsona analysis.
We try to prevent pinned threads when possible, that said here I am wondering what we could do as ReentrantLock is already used here (no synchronized block). I am also not sure there is a concrete impact as I am only able to reproduce 1 or 2 pinned threads at startup when the application is still initializing and not yet able to handle the traffic.
@jhoeller Any thoughts? You may be interested by such use case as a way to reproduce BeanCurrentlyInCreationException. The trick is the generate some workload before starting the application (I used oha -z 60s http://localhost:8080/) and then start a Spring Boot webapplication with spring.main.lazy-initialization=true and spring.threads.virtual.enabled=true configured.
Comment From: sdeleuze
I can reproduce the thread pinning logging with Spring Boot 3.3.6 as well when using oha -z 60s http://localhost:8080/, with the locking appearing in a different place.
I think this locking is by design when you enable both lazy init and virtual threads, and does not reflect a real impact that reduces the scalability or performance or web workloads as suggested in my previous message.
And as proposed by Andy you still have the opportunity to configure spring.mvc.servlet.load-on-startup=0 to change the DispatcherServlet initialization behavior for that use case set at Spring Boot level.
As a consequence, I will decline this issue.
Comment From: chrisgleissner
Thanks for your explanation. The suggested workaround is a viable solution for me.