search

spring-projects / spring-boot

Spring Boot helps you to create Spring-powered, production-grade applications and services with absolute minimum fuss.
https://spring.io/projects/spring-boot
Apache License 2.0
75.35k stars 40.72k forks source link

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

Open chrisgleissner opened 2 days ago

chrisgleissner commented 2 days ago

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:

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

  2. Start Spring Boot app

    ./gradlew bootRun

Software Versions

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) {