Java8 parallerStream causes Spring project startup thread to block (deadlock)

Directory

  • 1. Problems encountered
  • 2. Root cause of the problem
  • 3. Problem recurrence
    • 3.1. New project
    • 3.2. Start the project
  • 4. Problem solving
  • 5. Pay attention

1. Problems encountered

When starting the SpringBoot project, the service startup process is directly stuck, with no exceptions and no prompts.

2. Root cause of the problem

When registering Bean, the DefaultSingletonBeanRegistry.getSingleton method will be called to obtain the lock. During initialization (such as @PostConstruct or afterPropertiesSet code>) process, the main thread still holds the lock.
If parallelStream is used during this initialization process, it will create a new thread to perform operations through ForkJoinPool by default.
If the new thread goes to the container to obtain Bean at this time, it will wait for the lock when it runs to the getSingleton method. At this time, the lock is being held by the main thread, and the main thread The thread is executing the collect method in the stream until the new thread is wait completed, forming a deadlock.

org.springframework.beans.factory.support.DefaultSingletonBeanRegistry

public class DefaultSingletonBeanRegistry extends SimpleAliasRegistry implements SingletonBeanRegistry {<!-- -->

/**
* Return the (raw) singleton object registered under the given name,
* creating and registering a new one if none registered yet.
* @param beanName the name of the bean
* @param singletonFactory the ObjectFactory to lazily create the singleton
* with, if necessary
* @return the registered singleton object
*/
public Object getSingleton(String beanName, ObjectFactory<?> singletonFactory) {<!-- -->
Assert.notNull(beanName, "Bean name must not be null");
// The Bean cannot be obtained until the lock is obtained, and synchronized is a reentrant lock.
synchronized (this.singletonObjects) {<!-- -->
Object singletonObject = this.singletonObjects.get(beanName);
if (singletonObject == null) {<!-- -->
if (this.singletonsCurrentlyInDestruction) {<!-- -->
throw new BeanCreationNotAllowedException(beanName,
"Singleton bean creation not allowed while singletons of this factory are in destruction " +
"(Do not request a bean from a BeanFactory in a destroy method implementation!)");
}
if (logger.isDebugEnabled()) {<!-- -->
logger.debug("Creating shared instance of singleton bean '" + beanName + "'");
}
beforeSingletonCreation(beanName);
boolean newSingleton = false;
boolean recordSuppressedExceptions = (this.suppressedExceptions == null);
if (recordSuppressedExceptions) {<!-- -->
this.suppressedExceptions = new LinkedHashSet<>();
}
try {<!-- -->
singletonObject = singletonFactory.getObject();
newSingleton = true;
}
catch (IllegalStateException ex) {<!-- -->
// Has the singleton object implicitly appeared in the meantime ->
// if yes, proceed with it since the exception indicates that state.
singletonObject = this.singletonObjects.get(beanName);
if (singletonObject == null) {<!-- -->
throw ex;
}
}
catch (BeanCreationException ex) {<!-- -->
if (recordSuppressedExceptions) {<!-- -->
for (Exception suppressedException : this.suppressedExceptions) {<!-- -->
ex.addRelatedCause(suppressedException);
}
}
throw ex;
}
finally {<!-- -->
if (recordSuppressedExceptions) {<!-- -->
this.suppressedExceptions = null;
}
afterSingletonCreation(beanName);
}
if (newSingleton) {<!-- -->
addSingleton(beanName, singletonObject);
}
}
return singletonObject;
}
}
}

java.util.concurrent.ForkJoinTask
Worker thread of parallelStream

public abstract class ForkJoinTask<V> implements Future<V>, Serializable {<!-- -->

    /**
     * Blocks a non-worker-thread until completion.
     * @return status upon completion
     */
    private int externalAwaitDone() {<!-- -->
        int s = ((this instanceof CountedCompleter) ? // try helping
                 ForkJoinPool.common.externalHelpComplete(
                     (CountedCompleter<?>)this, 0) :
                 ForkJoinPool.common.tryExternalUnpush(this) ? doExec() : 0);
        if (s >= 0 & amp; & amp; (s = status) >= 0) {<!-- -->
            boolean interrupted = false;
            do {<!-- -->
                if (U.compareAndSwapInt(this, STATUS, s, s | SIGNAL)) {<!-- -->
                    synchronized (this) {<!-- -->
                        if (status >= 0) {<!-- -->
                            try {<!-- -->
                            // The working thread blocks the non-working thread (main thread), 0 means waiting forever
                                wait(0L);
                            } catch (InterruptedException ie) {<!-- -->
                                interrupted = true;
                            }
                        }
                        else
                        // Wake up the non-working thread (main thread) after the working thread completes execution
                            notifyAll();
                    }
                }
            } while ((s = status) >= 0);
            if (interrupted)
                Thread.currentThread().interrupt();
        }
        return s;
    }
}

3. Problem recurrence

3.1. New project

  • ParallelApplicaiton: Spring project startup class
  • BadService: Reproduce the problem
  • YourController: Test interface
-parallelstream
- src.main.java.com.luna
-controller
-YourController.java
-deadlock
-BadService.java
- ParallelApplication.java
-pom.xml

BadService

  • @Service: identified as Bean
  • ApplicationContextAware: Inject the Spring container into the class
  • @PostConstruct: Complete some initialization operations of the Bean, and the execution time is later than @Autowired

When registering the badService bean, after instantiation and initialization, use @PostConstruct to assign a value to the list attribute, which uses concurrent streams parallelStream to get the beans loaded in the container

package com.luna.deadlock;

import org.springframework.beans.BeansException;
import org.springframework.context.ApplicationContext;
import org.springframework.context.ApplicationContextAware;
import org.springframework.lang.NonNull;
import org.springframework.stereotype.Service;

import javax.annotation.PostConstruct;
import java.util.Arrays;
import java.util.List;
import java.util.stream.Collectors;

/**
 * @author qiongying.huai([email protected])
 * @version 1.0
 * @className BadService
 * @description description
 * @date 15:19 2023/10/24
 */
@Service
public class BadService implements ApplicationContextAware {<!-- -->

    private ApplicationContext applicationContext;

    private List<Object> list;

    @PostConstruct
    public void parallel() {<!-- -->
        list = Arrays.stream(applicationContext.getBeanDefinitionNames())
                .parallel()
                .filter(name -> !"badService".equals(name))
                .map(applicationContext::getBean)
                .collect(Collectors.toList());
        System.out.println(list.size());
    }

    @Override
    public void setApplicationContext(@NonNull ApplicationContext applicationContext) throws BeansException {<!-- -->
        this.applicationContext = applicationContext;
    }
}

YourController
Simple GET test interface

package com.luna.controller;

import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

/**
 * @author qiongying.huai([email protected])
 * @version 1.0
 * @className YourController
 * @description description
 * @date 18:57 2023/10/24
 */
@RestController
@RequestMapping("/api")
public class YourController {<!-- -->

    @GetMapping("/su")
    public String suMi() {<!-- -->
        return "ma se";
    }
}

ParallelApplication

package com.luna;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;

/**
 * @author qiongying.huai([email protected])
 * @version 1.0
 * @className ParallelApplication
 * @description description
 * @date 15:10 2023/10/24
 */
@SpringBootApplication
public class ParallelApplication {<!-- -->

    public static void main(String[] args) {<!-- -->
        SpringApplication.run(ParallelApplication.class, args);
    }
}

3.2. Start the project

Startup log

Connected to the target VM, address: '127.0.0.1:59360', transport: 'socket'

  . ____ _ __ _ _
 /\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \/ ___)| |_)| | | | | || (_| | ) ) ) )
  ' |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 ::Spring Boot:: (v2.6.5)

2023-10-24 19:15:09.964 INFO 13178 --- [main] com.luna.ParallelApplication : Starting ParallelApplication using Java 1.8.0_271 on 111deMacBook-Pro.local with PID 13178 (/Users/111/code/mavendemo/ parallelstream/target/classes started by 111 in /Users/111/code/mavendemo)
2023-10-24 19:15:09.970 INFO 13178 --- [main] com.luna.ParallelApplication: No active profile set, falling back to 1 default profile: "default"
2023-10-24 19:15:11.089 INFO 13178 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer: Tomcat initialized with port(s): 8080 (http)
2023-10-24 19:15:11.102 INFO 13178 --- [main] o.apache.catalina.core.StandardService: Starting service [Tomcat]
2023-10-24 19:15:11.102 INFO 13178 --- [main] org.apache.catalina.core.StandardEngine: Starting Servlet engine: [Apache Tomcat/9.0.60]
2023-10-24 19:15:11.244 INFO 13178 --- [main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2023-10-24 19:15:11.244 INFO 13178 --- [main] w.s.c.ServletWebServerApplicationContext: Root WebApplicationContext: initialization completed in 1154 ms

Request test interface
Request failed, service not started

parallerstream % curl --location --request GET 'http://localhost:8080/api/su'
curl: (7) Failed to connect to localhost port 8080 after 8 ms: Couldn't connect to server

Use arthas analysis
Official documentation: Introduction | arthas

  1. Startarthas
  2. View blocked threads
  3. Find out which thread is currently blocking other threads
"main" Id=1 WAITING on java.util.stream.ReduceOps$ReduceTask@a2ddf26
at java.lang.Object.wait(Native Method)
- waiting on java.util.stream.ReduceOps$ReduceTask@a2ddf26
at java.util.concurrent.ForkJoinTask.externalAwaitDone(ForkJoinTask.java:334)

The main thread is blocked by the ReduceTask@a2ddf26 object. The ReduceTask object is the worker thread object of parallelStream

at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
- locked java.util.concurrent.ConcurrentHashMap@5485df50 <---- but blocks 7 other threads!

The main thread blocks other 7 threads at the getSingleton method. Looking at the thread list in the blocked state, it is the worker thread of ForkJoinPool ForkJoinPool.commonPool-worker- 1, which is the default thread pool of parallelStream

parallerstream % java -jar ~/Downloads/software/arthas-packaging-3.6.2-bin/arthas-boot.jar
[INFO] arthas-boot version: 3.6.2
[INFO] Process 13412 already using port 3658
[INFO] Process 13412 already using port 8563
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
* [1]: 13412 com.luna.ParallelApplication
  [2]: 13411 org.jetbrains.jps.cmdline.Launcher
  [3]: 7411 org.jetbrains.idea.maven.server.RemoteMavenServer36
  [4]: 23220
  [5]: 10980 org.jetbrains.jps.cmdline.Launcher
1
[INFO] arthas home: /Users/111/Downloads/software/arthas-packaging-3.6.2-bin
[INFO] The target process already listens to port 3658, skip attach.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---. ,------. ,--------.,--. ,--. ,---. ,---.
 / O \ | .--. ''--. .--'| '--' | / O \ ' .-'
| .-. || '--'.' | | | .--. || .-. |`. `-.
| | | || |\ \ | | | | | || | | |.-' |
`--' `--'`--' '--' `--' `--' `--'`--' `--'`-----'

wiki https://arthas.aliyun.com/doc
tutorials https://arthas.aliyun.com/doc/arthas-tutorials.html
version 3.6.2
main_class com.luna.ParallelApplication
pid 13412
time 2023-10-24 19:20:55

[arthas@13412]$
[arthas@13412]$ thread --state BLOCKED
Threads Total: 24, NEW: 0, RUNNABLE: 7, BLOCKED: 7, WAITING: 6, TIMED_WAITING: 4, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTED DAEMON
20 ForkJoinPool.commonPool-worker-1 main 5 BLOCKED 0.0 0.000 0:0.006 false true
21 ForkJoinPool.commonPool-worker-2 main 5 BLOCKED 0.0 0.000 0:0.000 false true
22 ForkJoinPool.commonPool-worker-3 main 5 BLOCKED 0.0 0.000 0:0.000 false true
23 ForkJoinPool.commonPool-worker-4 main 5 BLOCKED 0.0 0.000 0:0.000 false true
24 ForkJoinPool.commonPool-worker-5 main 5 BLOCKED 0.0 0.000 0:0.000 false true
25 ForkJoinPool.commonPool-worker-6 main 5 BLOCKED 0.0 0.000 0:0.000 false true
[arthas@13412]$
[arthas@13412]$ thread -b
"main" Id=1 WAITING on java.util.stream.ReduceOps$ReduceTask@a2ddf26
    at java.lang.Object.wait(Native Method)
    - waiting on java.util.stream.ReduceOps$ReduceTask@a2ddf26
    at java.util.concurrent.ForkJoinTask.externalAwaitDone(ForkJoinTask.java:334)
    at java.util.concurrent.ForkJoinTask.doInvoke(ForkJoinTask.java:405)
    at java.util.concurrent.ForkJoinTask.invoke(ForkJoinTask.java:734)
    at java.util.stream.ReduceOps$ReduceOp.evaluateParallel(ReduceOps.java:714)
    at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:233)
    at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
    at com.luna.deadlock.BadService.parallel(BadService.java:32)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleElement.invoke(InitDestroyAnnotationBeanPostProcessor.java:389)
    at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleMetadata.invokeInitMethods(InitDestroyAnnotationBeanPostProcessor.java:333)
    at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor.postProcessBeforeInitialization(InitDestroyAnnotationBeanPostProcessor.java:157)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsBeforeInitialization(AbstractAutowireCapableBeanFactory.java:440)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1796)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:620)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542)
    at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335)
    at org.springframework.beans.factory.support.AbstractBeanFactory$$Lambda$179/872522004.getObject(Unknown Source)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
    - locked java.util.concurrent.ConcurrentHashMap@5485df50 <---- but blocks 7 other threads!
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333)
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208)
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:953)
    at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:918)
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:583)
    - locked java.lang.Object@41d9ae78
    at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:145)
    at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:740)
    at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:415)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:303)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1312)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1301)
    at com.luna.ParallelApplication.main(ParallelApplication.java:17)

[arthas@13412]$
[arthas@13412]$ stop
Resetting all enhanced classes ...
Affect(class count: 0, method count: 0) cost in 2 ms, listenerId: 0
Arthas Server is going to shutdown...
[arthas@13412]$ session (7d8cdf29-04f0-464e-b1c9-334dc2fd00a9) is closed because server is going to shutdown.

4. Problem solving

When registering a bean, change parallelStream to stream during the initialization process, and do not use concurrent streams

BadService

package com.luna.deadlock;

import org.springframework.beans.BeansException;
import org.springframework.context.ApplicationContext;
import org.springframework.context.ApplicationContextAware;
import org.springframework.lang.NonNull;
import org.springframework.stereotype.Service;

import javax.annotation.PostConstruct;
import java.util.Arrays;
import java.util.List;
import java.util.stream.Collectors;

/**
 * @author qiongying.huai([email protected])
 * @version 1.0
 * @className BadService
 * @description description
 * @date 15:19 2023/10/24
 */
@Service
public class BadService implements ApplicationContextAware {<!-- -->

    private ApplicationContext applicationContext;

    private List<Object> list;

    @PostConstruct
    public void parallel() {<!-- -->
        list = Arrays.stream(applicationContext.getBeanDefinitionNames())
// .parallel()
                .filter(name -> !"badService".equals(name))
                .peek(applicationContext::getBean)
                .collect(Collectors.toList());
        System.out.println(list.size());
    }

    @Override
    public void setApplicationContext(@NonNull ApplicationContext applicationContext) throws BeansException {<!-- -->
        this.applicationContext = applicationContext;
    }
}

Startup log

Connected to the target VM, address: '127.0.0.1:60408', transport: 'socket'

  . ____ _ __ _ _
 /\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \/ ___)| |_)| | | | | || (_| | ) ) ) )
  ' |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 ::Spring Boot:: (v2.6.5)

2023-10-24 19:19:08.274 INFO 13357 --- [main] com.luna.ParallelApplication : Starting ParallelApplication using Java 1.8.0_271 on 111deMacBook-Pro.local with PID 13357 (/Users/111/code/mavendemo/ parallelstream/target/classes started by 111 in /Users/111/code/mavendemo)
2023-10-24 19:19:08.279 INFO 13357 --- [main] com.luna.ParallelApplication: No active profile set, falling back to 1 default profile: "default"
2023-10-24 19:19:09.233 INFO 13357 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer: Tomcat initialized with port(s): 8080 (http)
2023-10-24 19:19:09.243 INFO 13357 --- [main] o.apache.catalina.core.StandardService: Starting service [Tomcat]
2023-10-24 19:19:09.243 INFO 13357 --- [main] org.apache.catalina.core.StandardEngine: Starting Servlet engine: [Apache Tomcat/9.0.60]
2023-10-24 19:19:09.368 INFO 13357 --- [main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2023-10-24 19:19:09.368 INFO 13357 --- [main] w.s.c.ServletWebServerApplicationContext: Root WebApplicationContext: initialization completed in 1017 ms
131
2023-10-24 19:19:09.746 INFO 13357 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer: Tomcat started on port(s): 8080 (http) with context path ''
2023-10-24 19:19:09.755 INFO 13357 --- [main] com.luna.ParallelApplication : Started ParallelApplication in 1.979 seconds (JVM running for 2.496)

Request test interface
Request successful

parallerstream % curl --location --request GET 'http://localhost:8080/api/su'
ma se%

Use arthas analysis
Thread without BLOCKED status

vuedemo % java -jar ~/Downloads/software/arthas-packaging-3.6.2-bin/arthas-boot.jar
[INFO] arthas-boot version: 3.6.2
[INFO] Process 13687 already using port 3658
[INFO] Process 13687 already using port 8563
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
* [1]: 13687 com.luna.ParallelApplication
  [2]: 7411 org.jetbrains.idea.maven.server.RemoteMavenServer36
  [3]: 23220
  [4]: 10980 org.jetbrains.jps.cmdline.Launcher
  [5]: 13685 org.jetbrains.jps.cmdline.Launcher
1
[INFO] arthas home: /Users/111/Downloads/software/arthas-packaging-3.6.2-bin
[INFO] The target process already listens to port 3658, skip attach.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---. ,------. ,--------.,--. ,--. ,---. ,---.
 / O \ | .--. ''--. .--'| '--' | / O \ ' .-'
| .-. || '--'.' | | | .--. || .-. |`. `-.
| | | || |\ \ | | | | | || | | |.-' |
`--' `--'`--' '--' `--' `--' `--'`--' `--'`-----'

wiki https://arthas.aliyun.com/doc
tutorials https://arthas.aliyun.com/doc/arthas-tutorials.html
version 3.6.2
main_class com.luna.ParallelApplication
pid 13687
time 2023-10-24 19:25:45

[arthas@13687]$
[arthas@13412]$ thread --state BLOCKED
Threads Total: 29, NEW: 0, RUNNABLE: 10, BLOCKED: 0, WAITING: 15, TIMED_WAITING: 4, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTED DAEMON
                                                                                                                                          
[arthas@13687]$
[arthas@13412]$ thread -b
No most blocking thread found!
[arthas@13687]$
[arthas@13412]$ stop
Resetting all enhanced classes ...
Affect(class count: 0, method count: 0) cost in 1 ms, listenerId: 0
Arthas Server is going to shutdown...
[arthas@13687]$ session (25354803-d39c-4d22-9c9f-2723c1bfc81e) is closed because server is going to shutdown.

5. Attention

During the Spring service startup process, try to avoid multi-threaded concurrent operations