Search code examples
javaspring-bootjpatestcontainers

EntityManagerFactory is very slow to close


My Spring Boot v3.2.0 app uses JDK 21. When the test suite finishes, closing the EntityManagerFactory beans that were created takes over 30 seconds, which is about 33% of the test suite's total execution time. The logs indicate that 3 of these beans take 11 seconds to close, and it appears that most of this time is spent waiting for the associated Hikari connection pool to close.

When the application itself shuts down, no such delay occurs. Presumably this is because the application only creates 1 instance of this bean, but the test suite creates 14 instances (because of the different application contexts that are built by the test suite).

When the tests run, is there a way to either:

  • Reduce the number of EntityManagerFactory beans that are created
  • Reduce the time it takes to close a EntityManagerFactory bean

The following Hikari configuration is used by the tests

spring.datasource.hikari.maximumPoolSize=2

The relevant section of the test suite's logs are shown below

2023-12-07T15:53:41.555Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:53:41.556Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2023-12-07T15:53:41.557Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.
2023-12-07T15:53:52.831Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:53:52.832Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-2 - Shutdown initiated...
2023-12-07T15:53:52.834Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-2 - Shutdown completed.
2023-12-07T15:54:03.861Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:54:03.863Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-3 - Shutdown initiated...
2023-12-07T15:54:03.865Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-3 - Shutdown completed.
2023-12-07T15:54:03.886Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:54:03.887Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-4 - Shutdown initiated...
2023-12-07T15:54:03.888Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-4 - Shutdown completed.
2023-12-07T15:54:03.899Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:54:03.899Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-5 - Shutdown initiated...
2023-12-07T15:54:03.900Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-5 - Shutdown completed.
2023-12-07T15:54:14.916Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:54:14.917Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-6 - Shutdown initiated...
2023-12-07T15:54:14.919Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-6 - Shutdown completed.
2023-12-07T15:54:14.938Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:54:14.939Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-7 - Shutdown initiated...
2023-12-07T15:54:14.940Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-7 - Shutdown completed.
2023-12-07T15:54:14.953Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:54:14.954Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-8 - Shutdown initiated...
2023-12-07T15:54:14.954Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-8 - Shutdown completed.
2023-12-07T15:54:14.955Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:54:14.955Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-9 - Shutdown initiated...
2023-12-07T15:54:14.956Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-9 - Shutdown completed.
2023-12-07T15:54:14.960Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:54:14.960Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-10 - Shutdown initiated...
2023-12-07T15:54:14.960Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-10 - Shutdown completed.
2023-12-07T15:54:14.964Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:54:14.964Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-11 - Shutdown initiated...
2023-12-07T15:54:14.965Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-11 - Shutdown completed.
2023-12-07T15:54:14.968Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:54:14.968Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-12 - Shutdown initiated...
2023-12-07T15:54:14.969Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-12 - Shutdown completed.
2023-12-07T15:54:14.972Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:54:14.972Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-13 - Shutdown initiated...
2023-12-07T15:54:14.972Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-13 - Shutdown completed.
2023-12-07T15:54:14.975Z --- j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2023-12-07T15:54:14.976Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-14 - Shutdown initiated...
2023-12-07T15:54:14.992Z --- com.zaxxer.hikari.HikariDataSource       : HikariPool-14 - Shutdown completed.

> Task :test

SUCCESS: Executed 706 tests in 1m 37s (2 skipped)

Solution

  • This problem just magically fixed itself by upgrading Spring Boot. I'm currently using v3.3.0 and I still have 14 EntityManagerFactory to close, but now it only takes about 7 seconds, whereas in Spring v3.2.0 it took more than 30 seconds.

    I didn't change anything else that might be relevant apart from the Spring Boot version.