I notice a strong degradation of startup time when updating my application from Spring Boot 2.5.2 to 2.5.3. The issue is still present in Spring Boot 2.5.4.
The processes seems to be within Hibernate. It hangs just after the "HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL10Dialect" message (~15s). I use two data sources. For the second data source, the delay is more than 1mn. The total time is 1:40.
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.5.3)
2021-09-01 10:40:16.361 DEBUG 12844 --- [ main] o.s.boot.SpringApplication : Loading source class com.ginkoia.restocking.service.RestockingApplication
2021-09-01 10:40:16.428 DEBUG 12844 --- [ main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@1ca25c47
2021-09-01 10:40:17.347 INFO 12844 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2021-09-01 10:40:17.464 INFO 12844 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 106 ms. Found 5 JPA repository interfaces.
2021-09-01 10:40:17.465 INFO 12844 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2021-09-01 10:40:17.483 INFO 12844 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 16 ms. Found 2 JPA repository interfaces.
2021-09-01 10:40:18.191 INFO 12844 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler@1115433e' of type [org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-09-01 10:40:18.197 INFO 12844 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'methodSecurityMetadataSource' of type [org.springframework.security.access.method.DelegatingMethodSecurityMetadataSource] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-09-01 10:40:18.516 DEBUG 12844 --- [ main] .s.b.w.e.t.TomcatServletWebServerFactory : Code archive: ****\.m2\repository\org\springframework\boot\spring-boot\2.5.3\spring-boot-2.5.3.jar
2021-09-01 10:40:18.517 DEBUG 12844 --- [ main] .s.b.w.e.t.TomcatServletWebServerFactory : Code archive: ****\.m2\repository\org\springframework\boot\spring-boot\2.5.3\spring-boot-2.5.3.jar
2021-09-01 10:40:18.517 DEBUG 12844 --- [ main] .s.b.w.e.t.TomcatServletWebServerFactory : Document root: ****\Workspaces\SpringToolSuite\****\src\main\webapp
2021-09-01 10:40:18.554 INFO 12844 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2021-09-01 10:40:18.567 INFO 12844 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2021-09-01 10:40:18.568 INFO 12844 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.50]
2021-09-01 10:40:19.150 INFO 12844 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2021-09-01 10:40:19.150 DEBUG 12844 --- [ main] w.s.c.ServletWebServerApplicationContext : Published root WebApplicationContext as ServletContext attribute with name [org.springframework.web.context.WebApplicationContext.ROOT]
2021-09-01 10:40:19.150 INFO 12844 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 2723 ms
2021-09-01 10:40:19.449 INFO 12844 --- [ main] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default]
2021-09-01 10:40:19.536 INFO 12844 --- [ main] org.hibernate.Version : HHH000412: Hibernate ORM core version 5.4.32.Final
2021-09-01 10:40:19.689 INFO 12844 --- [ main] o.hibernate.annotations.common.Version : HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
2021-09-01 10:40:19.949 INFO 12844 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
2021-09-01 10:40:21.414 INFO 12844 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
→ 2021-09-01 10:40:21.444 INFO 12844 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL10Dialect
→ 2021-09-01 10:40:36.080 INFO 12844 --- [ main] org.hibernate.orm.beans : HHH10005002: No explicit CDI BeanManager reference was passed to Hibernate, but CDI is available on the Hibernate ClassLoader.
2021-09-01 10:40:36.639 INFO 12844 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2021-09-01 10:40:36.653 INFO 12844 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2021-09-01 10:40:36.745 INFO 12844 --- [ main] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default]
2021-09-01 10:40:36.831 INFO 12844 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-2 - Starting...
2021-09-01 10:40:37.806 INFO 12844 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-2 - Start completed.
→ 2021-09-01 10:40:37.806 INFO 12844 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL10Dialect
→ 2021-09-01 10:41:54.197 INFO 12844 --- [ main] org.hibernate.orm.beans : HHH10005002: No explicit CDI BeanManager reference was passed to Hibernate, but CDI is available on the Hibernate ClassLoader.
2021-09-01 10:41:54.372 INFO 12844 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2021-09-01 10:41:54.372 INFO 12844 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2021-09-01 10:41:54.759 WARN 12844 --- [ main] JpaBaseConfiguration$JpaWebConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
2021-09-01 10:41:54.897 DEBUG 12844 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : 18 mappings in 'requestMappingHandlerMapping'
2021-09-01 10:41:55.126 DEBUG 12844 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Patterns [/webjars/**, /**] in 'resourceHandlerMapping'
2021-09-01 10:41:55.167 DEBUG 12844 --- [ main] o.s.b.w.s.ServletContextInitializerBeans : Mapping filters: springSecurityFilterChain urls=[/*] order=-100, characterEncodingFilter urls=[/*] order=-2147483648, formContentFilter urls=[/*] order=-9900, requestContextFilter urls=[/*] order=-105, jwtRequestFilter urls=[/*] order=2147483647
2021-09-01 10:41:55.167 DEBUG 12844 --- [ main] o.s.b.w.s.ServletContextInitializerBeans : Mapping servlets: dispatcherServlet urls=[/]
2021-09-01 10:41:55.199 DEBUG 12844 --- [ main] o.s.b.w.s.f.OrderedRequestContextFilter : Filter 'requestContextFilter' configured for use
2021-09-01 10:41:55.200 DEBUG 12844 --- [ main] s.b.w.s.f.OrderedCharacterEncodingFilter : Filter 'characterEncodingFilter' configured for use
2021-09-01 10:41:55.200 DEBUG 12844 --- [ main] .DelegatingFilterProxyRegistrationBean$1 : Filter 'springSecurityFilterChain' configured for use
2021-09-01 10:41:55.200 DEBUG 12844 --- [ main] o.s.b.w.s.f.OrderedFormContentFilter : Filter 'formContentFilter' configured for use
2021-09-01 10:41:55.794 INFO 12844 --- [ main] o.s.s.web.DefaultSecurityFilterChain : Will secure any request with [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@25639668, org.springframework.security.web.context.SecurityContextPersistenceFilter@1e6cd1c, org.springframework.security.web.header.HeaderWriterFilter@1dc9e4d2, org.springframework.security.web.authentication.logout.LogoutFilter@59f5a376, com.ginkoia.restocking.service.security.JwtRequestFilter@6e5a77ef, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@6cd1ee, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@a1c4f69, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@2c1b10f2, org.springframework.security.web.session.SessionManagementFilter@489989eb, org.springframework.security.web.access.ExceptionTranslationFilter@3da12ba4, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@d91e8c7]
2021-09-01 10:41:55.892 DEBUG 12844 --- [ main] s.w.s.m.m.a.RequestMappingHandlerAdapter : ControllerAdvice beans: 0 @ModelAttribute, 0 @InitBinder, 1 RequestBodyAdvice, 1 ResponseBodyAdvice
2021-09-01 10:41:55.942 DEBUG 12844 --- [ main] .m.m.a.ExceptionHandlerExceptionResolver : ControllerAdvice beans: 0 @ExceptionHandler, 1 ResponseBodyAdvice
2021-09-01 10:41:55.992 DEBUG 12844 --- [ main] inMXBeanRegistrar$SpringApplicationAdmin : Application Admin MBean registered with name 'org.springframework.boot:type=Admin,name=SpringApplication'
2021-09-01 10:41:56.217 INFO 12844 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
In comparison, with Spring boot 2.5.2, I have more reasonable times: around 1s after the "HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL10Dialect" messages and 11s for full startup.
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.5.2)
2021-09-01 11:09:23.583 DEBUG 24336 --- [ main] o.s.boot.SpringApplication : Loading source class com.ginkoia.restocking.service.RestockingApplication
2021-09-01 11:09:23.644 DEBUG 24336 --- [ main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@60fa3495
2021-09-01 11:09:24.525 INFO 24336 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2021-09-01 11:09:24.647 INFO 24336 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 110 ms. Found 5 JPA repository interfaces.
2021-09-01 11:09:24.648 INFO 24336 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2021-09-01 11:09:24.665 INFO 24336 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 16 ms. Found 2 JPA repository interfaces.
2021-09-01 11:09:25.445 INFO 24336 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler@3df1a1ac' of type [org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-09-01 11:09:25.450 INFO 24336 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'methodSecurityMetadataSource' of type [org.springframework.security.access.method.DelegatingMethodSecurityMetadataSource] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-09-01 11:09:25.813 DEBUG 24336 --- [ main] .s.b.w.e.t.TomcatServletWebServerFactory : Code archive: ****\.m2\repository\org\springframework\boot\spring-boot\2.5.2\spring-boot-2.5.2.jar
2021-09-01 11:09:25.813 DEBUG 24336 --- [ main] .s.b.w.e.t.TomcatServletWebServerFactory : Code archive: ****\.m2\repository\org\springframework\boot\spring-boot\2.5.2\spring-boot-2.5.2.jar
2021-09-01 11:09:25.814 DEBUG 24336 --- [ main] .s.b.w.e.t.TomcatServletWebServerFactory : Document root: ****\Workspaces\SpringToolSuite\****\src\main\webapp
2021-09-01 11:09:25.858 INFO 24336 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2021-09-01 11:09:25.875 INFO 24336 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2021-09-01 11:09:25.876 INFO 24336 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.48]
2021-09-01 11:09:26.500 INFO 24336 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2021-09-01 11:09:26.500 DEBUG 24336 --- [ main] w.s.c.ServletWebServerApplicationContext : Published root WebApplicationContext as ServletContext attribute with name [org.springframework.web.context.WebApplicationContext.ROOT]
2021-09-01 11:09:26.500 INFO 24336 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 2856 ms
2021-09-01 11:09:26.694 INFO 24336 --- [ main] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default]
2021-09-01 11:09:26.765 INFO 24336 --- [ main] org.hibernate.Version : HHH000412: Hibernate ORM core version 5.4.32.Final
2021-09-01 11:09:26.921 INFO 24336 --- [ main] o.hibernate.annotations.common.Version : HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
2021-09-01 11:09:27.174 INFO 24336 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
2021-09-01 11:09:28.560 INFO 24336 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
→ 2021-09-01 11:09:28.588 INFO 24336 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL10Dialect
→ 2021-09-01 11:09:29.769 INFO 24336 --- [ main] org.hibernate.orm.beans : HHH10005002: No explicit CDI BeanManager reference was passed to Hibernate, but CDI is available on the Hibernate ClassLoader.
2021-09-01 11:09:30.306 INFO 24336 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2021-09-01 11:09:30.320 INFO 24336 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2021-09-01 11:09:30.411 INFO 24336 --- [ main] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default]
2021-09-01 11:09:30.494 INFO 24336 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-2 - Starting...
2021-09-01 11:09:31.464 INFO 24336 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-2 - Start completed.
→ 2021-09-01 11:09:31.465 INFO 24336 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL10Dialect
→ 2021-09-01 11:09:32.656 INFO 24336 --- [ main] org.hibernate.orm.beans : HHH10005002: No explicit CDI BeanManager reference was passed to Hibernate, but CDI is available on the Hibernate ClassLoader.
2021-09-01 11:09:32.797 INFO 24336 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2021-09-01 11:09:32.798 INFO 24336 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2021-09-01 11:09:33.185 WARN 24336 --- [ main] JpaBaseConfiguration$JpaWebConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
2021-09-01 11:09:33.324 DEBUG 24336 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : 18 mappings in 'requestMappingHandlerMapping'
2021-09-01 11:09:33.546 DEBUG 24336 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Patterns [/webjars/**, /**] in 'resourceHandlerMapping'
2021-09-01 11:09:33.583 DEBUG 24336 --- [ main] o.s.b.w.s.ServletContextInitializerBeans : Mapping filters: springSecurityFilterChain urls=[/*] order=-100, characterEncodingFilter urls=[/*] order=-2147483648, formContentFilter urls=[/*] order=-9900, requestContextFilter urls=[/*] order=-105, jwtRequestFilter urls=[/*] order=2147483647
2021-09-01 11:09:33.583 DEBUG 24336 --- [ main] o.s.b.w.s.ServletContextInitializerBeans : Mapping servlets: dispatcherServlet urls=[/]
2021-09-01 11:09:33.615 DEBUG 24336 --- [ main] o.s.b.w.s.f.OrderedRequestContextFilter : Filter 'requestContextFilter' configured for use
2021-09-01 11:09:33.616 DEBUG 24336 --- [ main] s.b.w.s.f.OrderedCharacterEncodingFilter : Filter 'characterEncodingFilter' configured for use
2021-09-01 11:09:33.616 DEBUG 24336 --- [ main] .DelegatingFilterProxyRegistrationBean$1 : Filter 'springSecurityFilterChain' configured for use
2021-09-01 11:09:33.617 DEBUG 24336 --- [ main] o.s.b.w.s.f.OrderedFormContentFilter : Filter 'formContentFilter' configured for use
2021-09-01 11:09:34.197 INFO 24336 --- [ main] o.s.s.web.DefaultSecurityFilterChain : Will secure any request with [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@7f922523, org.springframework.security.web.context.SecurityContextPersistenceFilter@760ac834, org.springframework.security.web.header.HeaderWriterFilter@294c36b9, org.springframework.security.web.authentication.logout.LogoutFilter@52dc71b2, com.ginkoia.restocking.service.security.JwtRequestFilter@5418a659, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@5a1a5521, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@22cca101, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@1509bd56, org.springframework.security.web.session.SessionManagementFilter@5f662dd, org.springframework.security.web.access.ExceptionTranslationFilter@3d84f113, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@368e7d3a]
2021-09-01 11:09:34.304 DEBUG 24336 --- [ main] s.w.s.m.m.a.RequestMappingHandlerAdapter : ControllerAdvice beans: 0 @ModelAttribute, 0 @InitBinder, 1 RequestBodyAdvice, 1 ResponseBodyAdvice
2021-09-01 11:09:34.360 DEBUG 24336 --- [ main] .m.m.a.ExceptionHandlerExceptionResolver : ControllerAdvice beans: 0 @ExceptionHandler, 1 ResponseBodyAdvice
2021-09-01 11:09:34.418 DEBUG 24336 --- [ main] inMXBeanRegistrar$SpringApplicationAdmin : Application Admin MBean registered with name 'org.springframework.boot:type=Admin,name=SpringApplication'
2021-09-01 11:09:34.664 INFO 24336 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
In both cases, I'm using the same two distant PostGreSQL databases. I reproduced the case several times to conclude that the issue is really linked to Spring boot version, and not the connection state between the app and the database.
Comment From: bclozel
This problem has been reported on StackOverflow in the past and people seem to offer various solutions to that problem.
But this behavior change should not happen in a bugfix release of Spring Boot. We didn't change anything in that area, so I suspect that this is linked to #27202.
Could you try and use Spring Boot 2.5.3 (or 2.5.4) and manually downgrade the postgresql driver to "42.2.22" (using the postgresql.version property) and report back? See the Maven and Gradle instructions on how to do that.
Comment From: EricC-59
The downgrade to PG 42.2.22 seems to solve the issue. For Spring Boot 2.5.3:
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.5.3)
(...)
2021-09-02 11:49:56.048 INFO 17908 --- [ main] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default]
2021-09-02 11:49:56.129 INFO 17908 --- [ main] org.hibernate.Version : HHH000412: Hibernate ORM core version 5.4.32.Final
2021-09-02 11:49:56.299 INFO 17908 --- [ main] o.hibernate.annotations.common.Version : HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
2021-09-02 11:49:56.582 INFO 17908 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
2021-09-02 11:49:57.999 INFO 17908 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
→ 2021-09-02 11:49:58.029 INFO 17908 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL10Dialect
→ 2021-09-02 11:49:59.255 INFO 17908 --- [ main] org.hibernate.orm.beans : HHH10005002: No explicit CDI BeanManager reference was passed to Hibernate, but CDI is available on the Hibernate ClassLoader.
2021-09-02 11:49:59.844 INFO 17908 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2021-09-02 11:49:59.858 INFO 17908 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2021-09-02 11:49:59.960 INFO 17908 --- [ main] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default]
2021-09-02 11:50:00.076 INFO 17908 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-2 - Starting...
2021-09-02 11:50:01.056 INFO 17908 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-2 - Start completed.
→ 2021-09-02 11:50:01.057 INFO 17908 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL10Dialect
→ 2021-09-02 11:50:02.229 INFO 17908 --- [ main] org.hibernate.orm.beans : HHH10005002: No explicit CDI BeanManager reference was passed to Hibernate, but CDI is available on the Hibernate ClassLoader.
2021-09-02 11:50:02.428 INFO 17908 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2021-09-02 11:50:02.428 INFO 17908 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
For Spring Boot 2.5.4:
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.5.4)
(...)
2021-09-02 11:56:33.388 INFO 18312 --- [ main] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default]
2021-09-02 11:56:33.468 INFO 18312 --- [ main] org.hibernate.Version : HHH000412: Hibernate ORM core version 5.4.32.Final
2021-09-02 11:56:33.636 INFO 18312 --- [ main] o.hibernate.annotations.common.Version : HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
2021-09-02 11:56:33.920 INFO 18312 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
2021-09-02 11:56:35.284 INFO 18312 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
→ 2021-09-02 11:56:35.315 INFO 18312 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL10Dialect
→ 2021-09-02 11:56:36.515 INFO 18312 --- [ main] org.hibernate.orm.beans : HHH10005002: No explicit CDI BeanManager reference was passed to Hibernate, but CDI is available on the Hibernate ClassLoader.
2021-09-02 11:56:37.096 INFO 18312 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2021-09-02 11:56:37.109 INFO 18312 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2021-09-02 11:56:37.213 INFO 18312 --- [ main] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default]
2021-09-02 11:56:37.328 INFO 18312 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-2 - Starting...
2021-09-02 11:56:38.266 INFO 18312 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-2 - Start completed.
→ 2021-09-02 11:56:38.266 INFO 18312 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL10Dialect
→ 2021-09-02 11:56:39.400 INFO 18312 --- [ main] org.hibernate.orm.beans : HHH10005002: No explicit CDI BeanManager reference was passed to Hibernate, but CDI is available on the Hibernate ClassLoader.
2021-09-02 11:56:39.603 INFO 18312 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2021-09-02 11:56:39.603 INFO 18312 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
Comment From: bclozel
Could you raise this issue on the postgresql drive issue tracker? At this point, we don't know if this is a regression on their side or a particular problem with your setup - you'll need to provide more information to pinpoint where time is being spent.
I'm closing this issue, to be superseded by the upcoming postgresql issue - could you ping back here once you've created it so that we can follow up?
Comment From: EricC-59
https://github.com/pgjdbc/pgjdbc/issues/2236#issuecomment-926256651
This should be fixed in 42.2.24.