During our optimization efforts in JPA bootstrapping we stumbled above DataSourceInitializedPublisher.publishEventIfRequired(…) calling EntityManagerFactory.getProperties().
In case of an asynchronously bootstrapped EntityManagerFactory this will cause the initialization to block and prevent the container from continuing to initialize other components. I wonder it there was a way to rather consume the DataSource by inspecting EntityManagerFactoryInfo.getDataSource() as method calls to this interface do not trigger the blocking.
Comment From: wilkinsona
The DataSource is used as part of determining whether or not a DataSourceSchemaCreatedEvent should be published. Such an event should be published when Hibernate is responsible for creating the database's schema and has done so. As such, the fact that the current implementation blocks until the EntityManagerFactory has complete its initialisation is helpful. If we switched to the non-blocking EntityManagerFactoryInfo.getDataSource() instead, the event would be published too soon.
It looks like we need a way of being notified that the EntityManagerFactory has been initialized and at that point when can publish the event. This may require a change in Framework.
Comment From: wilkinsona
In my testing, the current call blocks for ~800ms when running our Data JPA sample. That's quite a large window in which some other processing could be done in parallel with the entity manager factory's initialisation. If we can figure out how to do it, the proposed change looks like it'll be beneficial.
Comment From: wilkinsona
I tried moving the event publication into the postProcessEntityManagerFactory method of a JpaVendorAdapter decorator. This method is called at the end of buildNativeEntityManagerFactory() at which point any schema creation will have been performed. Unfortunately, it results in deadlock:
"executor-1" #16 prio=5 os_prio=31 tid=0x00007fc11f088000 nid=0x5d03 waiting for monitor entry [0x00007000035ed000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.springframework.context.event.AbstractApplicationEventMulticaster.getApplicationListeners(AbstractApplicationEventMulticaster.java:190)
- waiting to lock <0x00000006c01faa28> (a java.util.concurrent.ConcurrentHashMap)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:133)
at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:398)
at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:355)
at org.springframework.boot.autoconfigure.orm.jpa.DataSourceInitializedPublisher.publishEventIfRequired(DataSourceInitializedPublisher.java:92)
at org.springframework.boot.autoconfigure.orm.jpa.DataSourceInitializedPublisher.access$0(DataSourceInitializedPublisher.java:88)
at org.springframework.boot.autoconfigure.orm.jpa.DataSourceInitializedPublisher$DataSourceSchemeCreatedPublisher.postProcessEntityManagerFactory(DataSourceInitializedPublisher.java:194)
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.buildNativeEntityManagerFactory(AbstractEntityManagerFactoryBean.java:411)
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean$$Lambda$411/116184677.call(Unknown Source)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
…
"main" #1 prio=5 os_prio=31 tid=0x00007fc11a003800 nid=0x1c03 waiting on condition [0x0000700001fa6000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000007763f2468> (a java.util.concurrent.FutureTask)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
at java.util.concurrent.FutureTask.get(FutureTask.java:191)
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.getNativeEntityManagerFactory(AbstractEntityManagerFactoryBean.java:539)
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.invokeProxyMethod(AbstractEntityManagerFactoryBean.java:496)
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean$ManagedEntityManagerFactoryInvocationHandler.invoke(AbstractEntityManagerFactoryBean.java:679)
at com.sun.proxy.$Proxy66.getMetamodel(Unknown Source)
at org.springframework.data.jpa.repository.config.JpaMetamodelMappingContextFactoryBean$$Lambda$441/2104842259.apply(Unknown Source)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.Iterator.forEachRemaining(Iterator.java:116)
at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
at org.springframework.data.jpa.repository.config.JpaMetamodelMappingContextFactoryBean.getMetamodels(JpaMetamodelMappingContextFactoryBean.java:106)
at org.springframework.data.jpa.repository.config.JpaMetamodelMappingContextFactoryBean.createInstance(JpaMetamodelMappingContextFactoryBean.java:80)
at org.springframework.data.jpa.repository.config.JpaMetamodelMappingContextFactoryBean.createInstance(JpaMetamodelMappingContextFactoryBean.java:44)
at org.springframework.beans.factory.config.AbstractFactoryBean.afterPropertiesSet(AbstractFactoryBean.java:142)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1802)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1739)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:576)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:498)
at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:320)
at org.springframework.beans.factory.support.AbstractBeanFactory$$Lambda$115/454325163.getObject(Unknown Source)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
- locked <0x00000006c01faa28> (a java.util.concurrent.ConcurrentHashMap)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:318)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:199)
at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveReference(BeanDefinitionValueResolver.java:367)
at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:110)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyPropertyValues(AbstractAutowireCapableBeanFactory.java:1646)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:1398)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:575)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:498)
at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:320)
at org.springframework.beans.factory.support.AbstractBeanFactory$$Lambda$115/454325163.getObject(Unknown Source)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
- locked <0x00000006c01faa28> (a java.util.concurrent.ConcurrentHashMap)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:318)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:204)
at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1091)
at org.springframework.data.repository.support.Repositories.cacheRepositoryFactory(Repositories.java:97)
- locked <0x00000007766b1760> (a org.springframework.data.repository.support.Repositories)
at org.springframework.data.repository.support.Repositories.populateRepositoryFactoryInformation(Repositories.java:90)
at org.springframework.data.repository.support.Repositories.<init>(Repositories.java:83)
at org.springframework.data.repository.support.DomainClassConverter.setApplicationContext(DomainClassConverter.java:109)
at org.springframework.data.web.config.SpringDataWebConfiguration.addFormatters(SpringDataWebConfiguration.java:131)
at org.springframework.web.servlet.config.annotation.WebMvcConfigurerComposite.addFormatters(WebMvcConfigurerComposite.java:81)
at org.springframework.web.servlet.config.annotation.DelegatingWebMvcConfiguration.addFormatters(DelegatingWebMvcConfiguration.java:78)
at org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration.mvcConversionService(WebMvcAutoConfiguration.java:505)
at org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration$$EnhancerBySpringCGLIB$$4e8f0b77.CGLIB$mvcConversionService$9(<generated>)
at org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration$$EnhancerBySpringCGLIB$$4e8f0b77$$FastClassBySpringCGLIB$$70a5418f.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:244)
at org.springframework.context.annotation.ConfigurationClassEnhancer$BeanMethodInterceptor.intercept(ConfigurationClassEnhancer.java:363)
at org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration$$EnhancerBySpringCGLIB$$4e8f0b77.mvcConversionService(<generated>)
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.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:154)
at org.springframework.beans.factory.support.ConstructorResolver.instantiate(ConstructorResolver.java:619)
at org.springframework.beans.factory.support.ConstructorResolver.instantiateUsingFactoryMethod(ConstructorResolver.java:604)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateUsingFactoryMethod(AbstractAutowireCapableBeanFactory.java:1282)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1126)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:538)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:498)
at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:320)
at org.springframework.beans.factory.support.AbstractBeanFactory$$Lambda$115/454325163.getObject(Unknown Source)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
- locked <0x00000006c01faa28> (a java.util.concurrent.ConcurrentHashMap)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:318)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:199)
at org.springframework.context.annotation.ConfigurationClassEnhancer$BeanMethodInterceptor.resolveBeanReference(ConfigurationClassEnhancer.java:394)
at org.springframework.context.annotation.ConfigurationClassEnhancer$BeanMethodInterceptor.intercept(ConfigurationClassEnhancer.java:366)
at org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration$$EnhancerBySpringCGLIB$$4e8f0b77.mvcConversionService(<generated>)
at org.springframework.web.servlet.config.annotation.WebMvcConfigurationSupport.getConfigurableWebBindingInitializer(WebMvcConfigurationSupport.java:602)
at org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration.getConfigurableWebBindingInitializer(WebMvcAutoConfiguration.java:534)
at org.springframework.web.servlet.config.annotation.WebMvcConfigurationSupport.requestMappingHandlerAdapter(WebMvcConfigurationSupport.java:564)
at org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration.requestMappingHandlerAdapter(WebMvcAutoConfiguration.java:477)
at org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration$$EnhancerBySpringCGLIB$$4e8f0b77.CGLIB$requestMappingHandlerAdapter$3(<generated>)
at org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration$$EnhancerBySpringCGLIB$$4e8f0b77$$FastClassBySpringCGLIB$$70a5418f.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:244)
at org.springframework.context.annotation.ConfigurationClassEnhancer$BeanMethodInterceptor.intercept(ConfigurationClassEnhancer.java:363)
at org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration$$EnhancerBySpringCGLIB$$4e8f0b77.requestMappingHandlerAdapter(<generated>)
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.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:154)
at org.springframework.beans.factory.support.ConstructorResolver.instantiate(ConstructorResolver.java:619)
at org.springframework.beans.factory.support.ConstructorResolver.instantiateUsingFactoryMethod(ConstructorResolver.java:604)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateUsingFactoryMethod(AbstractAutowireCapableBeanFactory.java:1282)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1126)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:538)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:498)
at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:320)
at org.springframework.beans.factory.support.AbstractBeanFactory$$Lambda$115/454325163.getObject(Unknown Source)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
- locked <0x00000006c01faa28> (a java.util.concurrent.ConcurrentHashMap)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:318)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:199)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:829)
at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:865)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:548)
- locked <0x00000006c0015258> (a java.lang.Object)
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:140)
at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:785)
at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:418)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:337)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1269)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1257)
at sample.data.jpa.SampleDataJpaApplication.main(SampleDataJpaApplication.java:26)
The deadlock can be avoided by using the factory's bootstrap executor (if it has one) to execute the event publication. @jhoeller does that seem like a reasonable approach to you, or is there a better way that we could be doing this?
Comment From: wilkinsona
The code for these changes and for #13833 are available in this branch of my fork.
Here are some numbers for starting the Data JPA sample on my laptop in Eclipse. Each entry is the average JVM running time of starting the app 10 times:
| Default | Lazy | Deferred |
|---|---|---|
| 4.606 | 3.992 | 4.479 |
Comment From: odrotbohm
Looks good to me. We have seen the improvements to take even more effect rising with the number of entities in the system, i.e. the longer the EMF needs to build as that might allow even all application components to bootstrap just while the EMF finishes initialization.
Dave's (admittedly esotheric) sample app containing a couple of thousand entities and repositories could be brought down from > 70 seconds to just slightly over 10.
Comment From: sforner405
By migrating to 2.3.5 we now having issues with MOCK tests. webEnvironment = SpringBootTest.WebEnvironment.MOCK leads to hanging DataSourceInitializedPublisher
Comment From: wilkinsona
@sforner405 We've had a few problems in this area unfortunately but we hoped we'd straightened things out in 2.3.5. If that's not the case for you, can you please open a new issue and provide a small sample that reproduces the hang in your tests with a mock web environment?