Skip to content

Avoid blocking access to EntityManagerFactory in DataSourceInitializedPublisher #14061

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

Closed
odrotbohm opened this issue Aug 14, 2018 · 7 comments
Closed
Labels
type: enhancement A general enhancement
Milestone

Comments

@odrotbohm
Copy link
Member

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.

@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Aug 14, 2018
@wilkinsona
Copy link
Member

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.

@wilkinsona
Copy link
Member

wilkinsona commented Aug 15, 2018

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.

@wilkinsona
Copy link
Member

wilkinsona commented Aug 15, 2018

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?

@wilkinsona wilkinsona added type: enhancement A general enhancement and removed status: waiting-for-triage An issue we've not yet triaged labels Aug 15, 2018
@wilkinsona
Copy link
Member

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

@odrotbohm
Copy link
Member Author

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.

@wilkinsona wilkinsona changed the title Try to avoid blocking access to EntityManagerFactory in DataSourceInitializedPublisher Avoid blocking access to EntityManagerFactory in DataSourceInitializedPublisher Aug 15, 2018
@wilkinsona wilkinsona added this to the Backlog milestone Aug 16, 2018
wilkinsona added a commit to wilkinsona/spring-boot that referenced this issue Aug 16, 2018
Previously, we would retrieve the EntityManagerFactory’s DataSource as
soon as it was being post-processed. When the native
EntityManagerFactory is being bootstrapped asynchronously, this
retrieval would block until bootstrapping had completed. This negated
some of the benefits of asynchronous bootstrapping.

This commit updates DataSourceInitializedPublisher so that it only
accesses the EntityManagerFactory’s DataSource once its bootstrapping
has completed. This is achieved using a decorated JpaVendorAdapter
that is called one the boostrapping has completed.

Closes spring-projectsgh-14061
@wilkinsona wilkinsona modified the milestones: Backlog, 2.1.0.M2 Aug 16, 2018
@sforner405
Copy link

By migrating to 2.3.5 we now having issues with MOCK tests.
webEnvironment = SpringBootTest.WebEnvironment.MOCK
leads to hanging DataSourceInitializedPublisher

@wilkinsona
Copy link
Member

@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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type: enhancement A general enhancement
Projects
None yet
Development

No branches or pull requests

4 participants