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 classBadService
: Reproduce the problemYourController
: Test interface
-parallelstream - src.main.java.com.luna -controller -YourController.java -deadlock -BadService.java - ParallelApplication.java -pom.xml
BadService
@Service
: identified as BeanApplicationContextAware
: 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
- Start
arthas
- View blocked threads
- 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
tostream
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