= Spring Data JPA - Deferred bootstrap modes

The project shows what's necessary to use Spring Data JPA's bootstrap modes to optimize the startup type with different trade-offs. It consists of:

* 2000 JPA entities
* 2000 Spring Data JPA repositories
* 2000 Spring Beans referring to the repositories

== tl;dr

The example can be run in three different modes that will expose significant differences in bootstrap time:

[cols="1,1,1,4", options="header"]
|====
|Mode|Profile|Startup time|Comment
|_DEFAULT_|none|35s|Standard JPA infrastructure and repository bootstrap.
|_DEFERRED_|`deferred`|23s|Background JPA infrastructure initialization and repository initialization deferred until the `ApplicationContext` has completed its initialization.
|_LAZY_|`lazy`|13s|Background JPA infrastructure initialization. Repository initialization deferred until first access.
|====

== Details

=== Default mode

* Uses Spring Boot's default `LocalContainerEntityManagerFactoryBean` mode for synchronous JPA bootstrap.
* Uses Spring Data's default repository bootstrap mode.

The bootstrap log will look like follows:

[source, bash]
----
2018-08-16 14:38:49.540  INFO 44538 --- [           main] example.Application                      : Starting Application v2.0.0.BUILD-SNAPSHOT on …
2018-08-16 14:38:49.544  INFO 44538 --- [           main] example.Application                      : No active profile set, falling back to default profiles: default
2018-08-16 14:38:51.034  INFO 44538 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data repositories in DEFAULT mode.
2018-08-16 14:38:53.433  INFO 44538 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 2390ms. Found 2000 repository interfaces.
2018-08-16 14:38:54.444  INFO 44538 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2018-08-16 14:38:54.447  WARN 44538 --- [           main] com.zaxxer.hikari.util.DriverDataSource  : Registered driver with driverClassName=org.hsqldb.jdbcDriver was not found, trying direct instantiation.
2018-08-16 14:38:54.773  INFO 44538 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Driver does not support get/set network timeout for connections. (feature not supported)
2018-08-16 14:38:54.776  INFO 44538 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
2018-08-16 14:38:55.068  INFO 44538 --- [           main] o.hibernate.jpa.internal.util.LogHelper  : HHH000204: Processing PersistenceUnitInfo [name: default ...] <1>
2018-08-16 14:38:55.144  INFO 44538 --- [           main] org.hibernate.Version                    : HHH000412: Hibernate Core {5.3.5.Final}
2018-08-16 14:38:55.146  INFO 44538 --- [           main] org.hibernate.cfg.Environment            : HHH000206: hibernate.properties not found
2018-08-16 14:38:55.473  INFO 44538 --- [           main] o.hibernate.annotations.common.Version   : HCANN000001: Hibernate Commons Annotations {5.0.4.Final}
2018-08-16 14:38:55.875  INFO 44538 --- [           main] org.hibernate.dialect.Dialect            : HHH000400: Using dialect: org.hibernate.dialect.HSQLDialect
2018-08-16 14:39:00.977  INFO 44538 --- [           main] o.h.t.schema.internal.SchemaCreatorImpl  : HHH000476: Executing import script 'org.hibernate.tool.schema.internal.exec.ScriptSourceInputNonExistentImpl@60169e0f'
2018-08-16 14:39:00.985  INFO 44538 --- [           main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2018-08-16 14:39:23.378  INFO 44538 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService  'applicationTaskExecutor'
2018-08-16 14:39:23.504  INFO 44538 --- [           main] example.Application                      : Started Application in 34.423 seconds (JVM running for 34.899)
----
<1> JPA is bootstrapped synchronously and thus will block all initialization of repositories and downstream components until its completion.

== Deferred mode

[NOTE]
====
To run the example in deferred mode, start it with the `deferred` profile activated.

[source, bash]
----
$ java -jar -Dspring.profiles.active=deferred target/*.jar`
----
====

* Uses a custom `LocalContainerEntityManagerFactoryBean` configured with a `ThreadPoolTaskExecutor` (see `Application.LazyJpaConfiguration`) to enable JPA initialization in a background thread.
* Uses Spring Data's deferred repository initialization mechanism that creates lazy injection proxies for repositories so that downstream Spring beans can already be instantiated while JPA still bootstraps.
Repository initialization is eventually triggered on `ContextRefreshedEvent` to make sure all initialization and verification has been performed before the application starts taking requests.

[source, bash]
----
  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::  (v2.1.0.BUILD-SNAPSHOT)

2018-08-16 14:51:15.294  INFO 45068 --- [           main] example.Application                      : Starting Application v2.0.0.BUILD-SNAPSHOT on Serendipity-3.local with PID 45068 (/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar started by olivergierke in /Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred)
2018-08-16 14:51:15.294  INFO 45068 --- [           main] example.Application                      : The following profiles are active: deferred
2018-08-16 14:51:15.294 DEBUG 45068 --- [           main] o.s.boot.SpringApplication               : Loading source class example.Application
2018-08-16 14:51:15.329 DEBUG 45068 --- [           main] o.s.b.c.c.ConfigFileApplicationListener  : Activated activeProfiles deferred
2018-08-16 14:51:15.329 DEBUG 45068 --- [           main] o.s.b.c.c.ConfigFileApplicationListener  : Loaded config file 'jar:file:/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar!/BOOT-INF/classes!/application.properties' (classpath:/application.properties)
2018-08-16 14:51:15.330 DEBUG 45068 --- [           main] s.c.a.AnnotationConfigApplicationContext : Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@71f2a7d5
2018-08-16 14:51:15.342 DEBUG 45068 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'org.springframework.context.annotation.internalConfigurationAnnotationProcessor'
2018-08-16 14:51:15.354 DEBUG 45068 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.internalCachingMetadataReaderFactory'
2018-08-16 14:51:15.596 DEBUG 45068 --- [           main] o.s.c.a.ClassPathBeanDefinitionScanner   : Identified candidate component class: URL [jar:file:/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar!/BOOT-INF/classes!/example/Application$LazyJpaConfiguration.class]
2018-08-16 14:51:15.644 DEBUG 45068 --- [           main] o.s.c.a.ClassPathBeanDefinitionScanner   : Identified candidate component class: URL [jar:file:/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar!/BOOT-INF/classes!/example/service/Customer1803Service.class]
… <1>
2018-08-16 14:51:16.160 DEBUG 45068 --- [           main] o.s.c.a.ClassPathBeanDefinitionScanner   : Identified candidate component class: URL [jar:file:/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar!/BOOT-INF/classes!/example/service/Customer1830Service.class]
2018-08-16 14:51:16.614  INFO 45068 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data repositories in DEFERRED mode.
2018-08-16 14:51:16.636 DEBUG 45068 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Scanning for repositories in packages example.
2018-08-16 14:51:16.764 DEBUG 45068 --- [           main] o.s.d.r.c.RepositoryComponentProvider    : Identified candidate component class: URL [jar:file:/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar!/BOOT-INF/classes!/example/repo/Customer177Repository.class]
… <2>
2018-08-16 14:51:16.879 DEBUG 45068 --- [           main] o.s.d.r.c.RepositoryComponentProvider    : Identified candidate component class: URL [jar:file:/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar!/BOOT-INF/classes!/example/repo/Customer829Repository.class]
2018-08-16 14:51:19.087 DEBUG 45068 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Registering deferred repository initialization listener.
2018-08-16 14:51:19.088  INFO 45068 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 2451ms. Found 2000 repository interfaces.
… <3>
2018-08-16 14:51:20.712 DEBUG 45068 --- [lTaskExecutor-1] j.LocalContainerEntityManagerFactoryBean : Building JPA container EntityManagerFactory for persistence unit 'default'
2018-08-16 14:51:20.719 DEBUG 45068 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'application'
2018-08-16 14:51:20.720 DEBUG 45068 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'customer1803Service'
2018-08-16 14:51:20.721 DEBUG 45068 --- [           main] ate$LazyRepositoryInjectionPointResolver : Creating lazy injection proxy for example.repo.Customer1803Repository…
… <4>
2018-08-16 14:51:26.118 DEBUG 45068 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'customer1830Service'
2018-08-16 14:51:26.118 DEBUG 45068 --- [           main] ate$LazyRepositoryInjectionPointResolver : Creating lazy injection proxy for example.repo.Customer1830Repository…
… <5>
2018-08-16 14:51:27.489  INFO 45068 --- [lTaskExecutor-1] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
… <6>
2018-08-16 14:51:27.801  INFO 45068 --- [           main] DeferredRepositoryInitializationListener : Triggering deferred initialization of Spring Data repositories…
2018-08-16 14:51:27.806 DEBUG 45068 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'customer1747Repository'
2018-08-16 14:51:27.842 DEBUG 45068 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'jpaMappingContext'
2018-08-16 14:51:27.842 DEBUG 45068 --- [           main] .c.JpaMetamodelMappingContextFactoryBean : Initializing JpaMetamodelMappingContext…
2018-08-16 14:51:27.860 DEBUG 45068 --- [           main] .c.JpaMetamodelMappingContextFactoryBean : Finished initializing JpaMetamodelMappingContext!
2018-08-16 14:51:27.869 DEBUG 45068 --- [           main] tor$SharedEntityManagerInvocationHandler : Creating new EntityManager for shared EntityManager invocation
2018-08-16 14:51:27.936 DEBUG 45068 --- [           main] o.s.orm.jpa.EntityManagerFactoryUtils    : Closing JPA EntityManager
2018-08-16 14:51:27.938 DEBUG 45068 --- [           main] tor$SharedEntityManagerInvocationHandler : Creating new EntityManager for shared EntityManager invocation
2018-08-16 14:51:27.939 DEBUG 45068 --- [           main] o.s.orm.jpa.EntityManagerFactoryUtils    : Closing JPA EntityManager
2018-08-16 14:51:27.979 DEBUG 45068 --- [           main] o.s.d.r.c.s.RepositoryFactorySupport     : Initializing repository instance for example.repo.Customer1747Repository…
2018-08-16 14:51:27.995 DEBUG 45068 --- [           main] tor$SharedEntityManagerInvocationHandler : Creating new EntityManager for shared EntityManager invocation
2018-08-16 14:51:27.995 DEBUG 45068 --- [           main] o.s.orm.jpa.EntityManagerFactoryUtils    : Closing JPA EntityManager
2018-08-16 14:51:28.021 DEBUG 45068 --- [           main] tor$SharedEntityManagerInvocationHandler : Creating new EntityManager for shared EntityManager invocation
2018-08-16 14:51:28.021 DEBUG 45068 --- [           main] o.s.orm.jpa.EntityManagerFactoryUtils    : Closing JPA EntityManager
2018-08-16 14:51:28.038 DEBUG 45068 --- [           main] o.s.d.j.r.query.JpaQueryFactory          : Looking up query for method findByLastName
2018-08-16 14:51:28.041 DEBUG 45068 --- [           main] o.s.d.jpa.repository.query.NamedQuery    : Looking up named query Customer1747.findByLastName
2018-08-16 14:51:28.043 DEBUG 45068 --- [           main] o.s.d.jpa.repository.query.NamedQuery    : Did not find named query Customer1747.findByLastName
2018-08-16 14:51:28.045 DEBUG 45068 --- [           main] tor$SharedEntityManagerInvocationHandler : Creating new EntityManager for shared EntityManager invocation
2018-08-16 14:51:28.045 DEBUG 45068 --- [           main] o.s.orm.jpa.EntityManagerFactoryUtils    : Closing JPA EntityManager
2018-08-16 14:51:28.098 DEBUG 45068 --- [           main] o.s.d.r.c.s.RepositoryFactorySupport     : Finished creation of repository instance for example.repo.Customer1747Repository.
… <7>
2018-08-16 14:51:37.882  INFO 45068 --- [           main] DeferredRepositoryInitializationListener : Spring Data repositories initialized!
2018-08-16 14:51:37.894  INFO 45068 --- [           main] example.Application                      : Started Application in 22.961 seconds (JVM running for 23.438)
----
<1> Spring triggered application component scanning and finds all services.
<2> Spring Data repository scanning is started and finds all repository interfaces.
<3> JPA bootstrap is initialized in a background thread.
<4> In the meantime, Spring beans are instantiated using lazy injection proxies for repositories to prevent the service instantiation from blocking on the JPA initialization. You should see the logs for the component initialization interleave with JPA initialization log output from the background thread.
<5> Spring bean instantiation completed while JPA still bootstraps. The container now waits for the JPA bootstrap to complete
<6> ApplicationContext publishes a `ContextRefreshedEvent` and triggers the repository initialization to make sure they properly bootstrap before the application is used.
<7> Repository initialization finishes and the application is started.

Note, how we gained 10 seconds of startup time by shifting most of the downstream component initialization work into the JPA bootstrap phase that happens in the background.
The key aspect here is that we created lazy injection proxies for the repositories, so that we can already inject them into clients to not block their initialization.
Still we have initialized and verified (query methods etc.) the repositories completely when the application starts.

== Lazy mode

[NOTE]
====
To run the example in lazy mode, start it with the `lazy` profile activated.

[source, bash]
----
$ java -jar -Dspring.profiles.active=lazy target/*.jar`
----
====

* Uses a custom `LocalContainerEntityManagerFactoryBean` configured with a `ThreadPoolTaskExecutor` (see `Application.LazyJpaConfiguration`) to enable JPA initialization in a background thread.
* Uses Spring Data's lazy repository initialization mechanism that creates lazy injection proxies for repositories so that downstream Spring beans can already be instantiated while JPA still bootstraps.
Repository initialization is completely skipped for the application to start quicker but accepting that repository initialization and verification will only be triggered for components in use to answer a request when they actually start calling methods on the repository instance.

[source, bash]
----
  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::  (v2.1.0.BUILD-SNAPSHOT)

2018-08-16 15:02:50.642  INFO 45568 --- [           main] example.Application                      : Starting Application v2.0.0.BUILD-SNAPSHOT on Serendipity-3.local with PID 45568 (/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar started by olivergierke in /Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred)
2018-08-16 15:02:50.642  INFO 45568 --- [           main] example.Application                      : The following profiles are active: lazy
2018-08-16 15:02:50.642 DEBUG 45568 --- [           main] o.s.boot.SpringApplication               : Loading source class example.Application
2018-08-16 15:02:50.684 DEBUG 45568 --- [           main] o.s.b.c.c.ConfigFileApplicationListener  : Activated activeProfiles lazy
2018-08-16 15:02:50.684 DEBUG 45568 --- [           main] o.s.b.c.c.ConfigFileApplicationListener  : Loaded config file 'jar:file:/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar!/BOOT-INF/classes!/application.properties' (classpath:/application.properties)
2018-08-16 15:02:50.684 DEBUG 45568 --- [           main] s.c.a.AnnotationConfigApplicationContext : Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@224aed64
2018-08-16 15:02:50.700 DEBUG 45568 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'org.springframework.context.annotation.internalConfigurationAnnotationProcessor'
2018-08-16 15:02:50.713 DEBUG 45568 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.internalCachingMetadataReaderFactory'
2018-08-16 15:02:50.945 DEBUG 45568 --- [           main] o.s.c.a.ClassPathBeanDefinitionScanner   : Identified candidate component class: URL [jar:file:/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar!/BOOT-INF/classes!/example/Application$LazyJpaConfiguration.class]
2018-08-16 15:02:50.989 DEBUG 45568 --- [           main] o.s.c.a.ClassPathBeanDefinitionScanner   : Identified candidate component class: URL [jar:file:/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar!/BOOT-INF/classes!/example/service/Customer1803Service.class]
… <1>
2018-08-16 15:02:51.442 DEBUG 45568 --- [           main] o.s.c.a.ClassPathBeanDefinitionScanner   : Identified candidate component class: URL [jar:file:/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar!/BOOT-INF/classes!/example/service/Customer1830Service.class]
2018-08-16 15:02:51.907  INFO 45568 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data repositories in LAZY mode.
2018-08-16 15:02:51.917 DEBUG 45568 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Scanning for repositories in packages example.
2018-08-16 15:02:52.048 DEBUG 45568 --- [           main] o.s.d.r.c.RepositoryComponentProvider    : Identified candidate component class: URL [jar:file:/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar!/BOOT-INF/classes!/example/repo/Customer177Repository.class]
… <2>
2018-08-16 15:02:52.152 DEBUG 45568 --- [           main] o.s.d.r.c.RepositoryComponentProvider    : Identified candidate component class: URL [jar:file:/Users/olivergierke/Documents/workspace/spring-data-examples/jpa/deferred/target/spring-data-jpa-deferred-2.0.0.BUILD-SNAPSHOT.jar!/BOOT-INF/classes!/example/repo/Customer829Repository.class]
2018-08-16 15:02:54.267  INFO 45568 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 2350ms. Found 2000 repository interfaces.
… <3>
2018-08-16 15:02:55.942 DEBUG 45568 --- [lTaskExecutor-1] j.LocalContainerEntityManagerFactoryBean : Building JPA container EntityManagerFactory for persistence unit 'default'
2018-08-16 15:02:55.952 DEBUG 45568 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'application'
2018-08-16 15:02:55.954 DEBUG 45568 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'customer1803Service'
2018-08-16 15:02:55.954 DEBUG 45568 --- [           main] ate$LazyRepositoryInjectionPointResolver : Creating lazy injection proxy for example.repo.Customer1803Repository…
… <4>
2018-08-16 15:03:01.274 DEBUG 45568 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'customer1830Service'
2018-08-16 15:03:01.274 DEBUG 45568 --- [           main] ate$LazyRepositoryInjectionPointResolver : Creating lazy injection proxy for example.repo.Customer1830Repository…
… <5>
2018-08-16 15:03:03.394  INFO 45568 --- [lTaskExecutor-1] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
… <6>
2018-08-16 15:03:03.717  INFO 45568 --- [           main] example.Application                      : Started Application in 13.612 seconds (JVM running for 14.212)
----
<1> Spring triggered application component scanning and finds all services.
<2> Spring Data repository scanning is started and finds all repository interfaces.
<3> JPA bootstrap is initialized in a background thread.
<4> In the meantime, Spring beans are instantiated using lazy injection proxies for repositories to prevent the service instantiation from blocking on the JPA initialization. You should see the logs for the component initialization interleave with JPA initialization log output from the background thread.
<5> Spring bean instantiation completed while JPA still bootstraps. The container now waits for the JPA bootstrap to complete
<6> The application signals that it is completely bootstrapped. Repositories have not been initialized.

We gained extra 10 seconds in startup time at the expense of not having the repositories properly initialized yet.
They will eventually get initialized once other Spring beans start invoking methods on them.
This bears the risk of running into a repository initialization problem too late but it might be worth taking in local development or even testing of narrow parts of your application if you're sufficiently confident that the repositories have been integration tested by other tests.
