EntityManagerFactory is very slow to close

Question

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)

Monohydric

It's not all the pools that take a long time to close, but only the number 1, 2 and 3 that are taking 11 seconds each. Are the tests upon them doing something special? – Mendive

Can you provide your sample code at github? – Joan

Are you creating multiple EMF in each test or using a same EMF across multiple tests? – Stambaugh

Why would you create that many EMFs? Are you using Spring's @DirtiesContext? That's usually a huge performance killer. – Oldie

@StanislavBashkyrtsev I'm not using @DirtiesContext – Meier

@Joan no, it's a closed source application – Meier

@Dónal, then in different tests you probably use different Spring properties or import different contexts. You need to find the reason why you have so many datasources. – Oldie

Answer 1

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.

Monohydric

Answer 2

Your question provides quite a few prerequisites, however let's try to figure out what can we do about this.

First of all

Reduce the number of EntityManagerFactory beans that are created

EntityManagerFactory is singleton, so only one bean per application context is created. If you have multiple EntityManagerFactories this points out to the fact you have the same amount of application contexts.

So first of all let's try to reduce the number of them by caching. I'd extract an abstract class and put common annotations over it, e.g.:

@SpringBootTest
public abstract class BaseTest {
}

Now each test class involving Spring Boot should be a subclass of TestBase, this would allow to cache application context and reuse it:

class MyRepositoryTest extends BaseTest {
//...
}

class AnotherRepositoryTest extends BaseTest {
//...
}

class OneMoreRepositoryTest extends BaseTest {
//...
}

If needed you can create multiple abstract test classes in order to group tests with same application context, e.g.:

@DataJpaTest
@SpringBootTest
public abstract class BaseJpaRepoTest {
}


@SpringBootTest
@AutoConfigureMockMvc
public abstract class BaseControllerTest {
}

With this approach you'll have one cached application context for each group of tests (for repos, endpoints, etc.).

Then, as of this propery:

spring.datasource.hikari.maximumPoolSize=2

I don't think that you should configure pool size for tests, so let's try to remove this property and use default values. From another point of view this property is again context-specific, so if you have n application contexts the overall number of connections is 2*n. Providing that we have reduced the number of contexts to 1 and all the tests reuse it I think 2 might be not enough for the tests.

One more thing that comes to my mind is that all the connections are starting to closed simultaneously, so it looks like you are running your tests in parallel mode. This might cause issues either in case e.g. all of them deal with one and the same table and are transactional or do some heavy operations/clean-ups in @AfterEach.

So the steps for you are:

1. cache application context
2. rid custom pool configuration
3. pay attention to transactionality/tear-down methods

P.S. If this doesn't help try to put some breakpoints in SessionFactoryImpl.close():

// AbstractEntityManagerFactoryBean
@Override
public void destroy() {
    if (this.entityManagerFactory != null) {
        if (logger.isInfoEnabled()) {
            logger.info("Closing JPA EntityManagerFactory for persistence unit '" + getPersistenceUnitName() + "'");
        }
        this.entityManagerFactory.close();
    }
}
//SessionFactoryImpl
public void close() throws HibernateException {
    synchronized (this) {
        if ( status != Status.OPEN ) {
            if ( getSessionFactoryOptions().getJpaCompliance().isJpaClosedComplianceEnabled() ) {
                throw new IllegalStateException( "EntityManagerFactory is already closed" );
            }

            LOG.trace( "Already closed" );
            return;
        }

        status = Status.CLOSING;
    }

    try {
        LOG.closing();
        observer.sessionFactoryClosing( this );

    // NOTE : the null checks below handle cases where close is called from
    //      a failed attempt to create the SessionFactory

        if ( cacheAccess != null ) {
            cacheAccess.close();
        }

        if ( runtimeMetamodels != null && runtimeMetamodels.getMappingMetamodel() != null ) {
            final JdbcConnectionAccess jdbcConnectionAccess = jdbcServices.getBootstrapJdbcConnectionAccess();
            runtimeMetamodels.getMappingMetamodel().forEachEntityDescriptor(
                    entityPersister -> {
                        if ( entityPersister.getSqmMultiTableMutationStrategy() != null ) {
                            entityPersister.getSqmMultiTableMutationStrategy().release(
                                    this,
                                    jdbcConnectionAccess
                            );
                        }
                        if ( entityPersister.getSqmMultiTableInsertStrategy() != null ) {
                            entityPersister.getSqmMultiTableInsertStrategy().release(
                                    this,
                                    jdbcConnectionAccess
                            );
                        }
                    }
            );
            ( (MappingMetamodelImpl) runtimeMetamodels.getMappingMetamodel() ).close();
        }

        if ( queryEngine != null ) {
            queryEngine.close();
        }
        if ( eventEngine != null ) {
            eventEngine.stop();
        }
    }
    finally {
        status = Status.CLOSED;
    }

    observer.sessionFactoryClosed( this );
    serviceRegistry.destroy();
}

There are multiple loops there and one in AbstractServiceRegistryImpl:

@Override
public synchronized void destroy() {
    if ( active.compareAndSet( true, false ) ) {
        try {
            //First thing, make sure that the fast path read is disabled so that
            //threads not owning the synchronization lock can't get an invalid Service:
            initializedServiceByRole.clear();
            synchronized (serviceBindingList) {
                ListIterator<ServiceBinding<?>> serviceBindingsIterator = serviceBindingList.listIterator(
                        serviceBindingList.size()
                );
                while ( serviceBindingsIterator.hasPrevious() ) {
                    final ServiceBinding<?> serviceBinding = serviceBindingsIterator.previous();
                    serviceBinding.getLifecycleOwner().stopService( serviceBinding );
                }
                serviceBindingList.clear();
            }
            serviceBindingMap.clear();
        }
        finally {
            if ( parent != null ) {
                parent.deRegisterChild( this );
            }
        }
    }
}

Elongation

The reason there are multiple application contexts is because some tests use a complete application context, but others only use a subset of the context – Meier

Try caching at least some of them, I guess at least partially your problem will be cured – Elongation

The Spring test framework automatically caches and re-uses application contexts (unless a test is marked with @DirtiesContext) – Meier

It depends. If you have multiple classes annotated with @SpringBootTest or @DataJpaTest there'll be multiple contexts – Elongation

AFAIK that's only the case if they use different beans/application contexts e.g. if they @Import different configurations or have different values for the classes attribute of @SpringBootTest. For example, if you have 2 test classes annotated with just @SpringBootTest the same application context will be used for both – Meier

Do you have @MockBeans in some of the tests or otherwise modified configuration? – Elongation

Answer 3

Upgrade hibernate jar, and start using BOM Import for boot.

We need more information to see how your Hikari Pool working. You can always call out number of pools and their sizes you are creating. If automatic EMF's pools are heavy and slow, configure your own, by creating with big pool size. make sure they are not idle in between pools.

hikari:
      connection-timeout: 
      minimum-idle: 
      maximum-pool-size: to define pool size
      idle-timeout: 
      max-lifetime: 
      auto-commit: true
      driver-class-name: com.microsoft.sqlserver.jdbc.SQLServerDriver
      leak-detection-threshold:

Strake

I'm already using the Hibernate JAR that's included with the latest Spring Boot (v3.2.0) – Meier

How would anyone know that with you telling? You just replied to a portion of my answer and ignored the Hikari Pools. Did you try this at all? – Strake

I mentioned in my question that I'm using Spring 3.2.0 – Meier