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

Spring Boot 3.4.0 (WebMVC, Virtual Threads, Lazy Init) pins virtual threads if accessing /actuator/health during launch #33958

Open
chrisgleissner opened this issue Nov 23, 2024 · 2 comments
Labels
status: waiting-for-triage An issue we've not yet triaged or decided on

Comments

@chrisgleissner
Copy link

chrisgleissner commented Nov 23, 2024

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

  1. 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
  1. 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) {
@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged or decided on label Nov 23, 2024
@wilkinsona wilkinsona self-assigned this Nov 25, 2024
@wilkinsona
Copy link
Member

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.

@snicoll snicoll transferred this issue from spring-projects/spring-boot Nov 25, 2024
@chrisgleissner
Copy link
Author

chrisgleissner commented Nov 25, 2024

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
status: waiting-for-triage An issue we've not yet triaged or decided on
Projects
None yet
Development

No branches or pull requests

3 participants