Introduction

In this article, we are going to see how we can find the source of an SQL query generated by Hibernate.

Knowing where a given SQL query originates from is very useful when trying to investigate performance issues caused by either long-running queries or queries that are executed excessively (e.g., N+1 query issues).

Hypersistence Utils

This feature that we are going to describe in this article is provided by the Hypersistence Utils open-source project.

First, you will need the proper Hypersistence Utils dependency based on the Hibernate version used by your project.

For Hibernate 6.2, you need to add the hypersistence-utils-hibernate-62 dependency:

<dependency>
    <groupId>io.hypersistence</groupId>
    <artifactId>hypersistence-utils-hibernate-62</artifactId>
    <version>${hypersistence-utils.version}</version>
</dependency>

For Hibernate 6.1 and 6.0, you need to add the hypersistence-utils-hibernate-60 dependency:

<dependency>
    <groupId>io.hypersistence</groupId>
    <artifactId>hypersistence-utils-hibernate-60</artifactId>
    <version>${hypersistence-utils.version}</version>
</dependency>

For Hibernate 5.6 or 5.5, you need to add the hypersistence-utils-hibernate-55 dependency:

<dependency>
    <groupId>io.hypersistence</groupId>
    <artifactId>hypersistence-utils-hibernate-55</artifactId>
    <version>${hypersistence-utils.version}</version>
</dependency>

Check out the project Installation Guide for more details about other Hibernate versions.

Finding the source of an SQL query generated by Spring

Let’s assume we have a Spring Boot application that has performance issues due to long-running queries or SQL queries that are executed too many times.

The DBA provides us with a list of problematic queries, and now we have to figure out the source of those SQL queries.

To simplify our analysis, we will define the following HibernatePropertiesCustomizer Spring Boot configuration class:

@Component
public class HibernateConfig implements HibernatePropertiesCustomizer {

    @Override
    public void customize(Map<String, Object> hibernateProperties) {
        hibernateProperties.put(
            AvailableSettings.STATEMENT_INSPECTOR,
            new QueryStackTraceLogger(
                "org.springframework.samples.petclinic"
            )
        );
    }
}

The QueryStackTraceLogger utility is provided by the Hypersistence Utils project, and the package name provided via the Java constructor represents the last package where the stack trace printing will stop reporting.

After setting the HibernateConfig component in our Spring Petclinic application, we will need to add the following log configuration in the application.properties file:

logging.level.io.hypersistence.utils.hibernate.query=DEBUG

That’s it!

Now, when using our Spring Boot application, we will see the following log entries printed in the application log:

2023-09-20 13:49:31.343 DEBUG 16640 --- [nio-8080-exec-4] i.h.u.h.query.QueryStackTraceLogger      : This SQL query: [
    select o1_0.id,o1_0.address,o1_0.city,o1_0.first_name,o1_0.last_name,p1_0.owner_id,p1_0.id,p1_0.birth_date,p1_0.name,p1_0.type_id,o1_0.telephone from owners o1_0 left join pets p1_0 on o1_0.id=p1_0.owner_id where o1_0.id=? order by p1_0.name
]
was generated by Hibernate like this: [
    org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.<init>(StatementPreparerImpl.java:165)
    org.hibernate.engine.jdbc.internal.StatementPreparerImpl$QueryStatementPreparationTemplate.<init>(StatementPreparerImpl.java:208)
    org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.<init>(StatementPreparerImpl.java:146)
    org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:146)
    org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.lambda$list$0(JdbcSelectExecutorStandardImpl.java:102)
    org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.executeQuery(DeferredResultSetAccess.java:226)
    org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.getResultSet(DeferredResultSetAccess.java:163)
    org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.advanceNext(JdbcValuesResultSetImpl.java:254)
    org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.processNext(JdbcValuesResultSetImpl.java:134)
    org.hibernate.sql.results.jdbc.internal.AbstractJdbcValues.next(AbstractJdbcValues.java:19)
    org.hibernate.sql.results.internal.RowProcessingStateStandardImpl.next(RowProcessingStateStandardImpl.java:66)
    org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:178)
    org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33)
    org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:361)
    org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:168)
    org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.list(JdbcSelectExecutorStandardImpl.java:93)
    org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:31)
    org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.lambda$new$0(ConcreteSqmSelectQueryPlan.java:110)
    org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.withCacheableSqmInterpretation(ConcreteSqmSelectQueryPlan.java:303)
    org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.performList(ConcreteSqmSelectQueryPlan.java:244)
    org.hibernate.query.sqm.internal.QuerySqmImpl.doList(QuerySqmImpl.java:518)
    org.hibernate.query.spi.AbstractSelectionQuery.list(AbstractSelectionQuery.java:367)
    org.hibernate.query.spi.AbstractSelectionQuery.getSingleResult(AbstractSelectionQuery.java:473)
    org.springframework.data.jpa.repository.query.JpaQueryExecution$SingleEntityExecution.doExecute(JpaQueryExecution.java:223)
    org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:92)
    org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:148)
    org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:136)
    org.springframework.data.repository.core.support.RepositoryMethodInvoker.doInvoke(RepositoryMethodInvoker.java:136)
    org.springframework.data.repository.core.support.RepositoryMethodInvoker.invoke(RepositoryMethodInvoker.java:120)
    org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.doInvoke(QueryExecutorMethodInterceptor.java:164)
    org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.invoke(QueryExecutorMethodInterceptor.java:143)
    org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
    org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123)
    org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:391)
    org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
    org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
    org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137)
    org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
    org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:135)
    org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
    org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
    org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
    org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:244)
    jdk.proxy2/jdk.proxy2.$Proxy142.findById(Unknown Source)
    org.springframework.samples.petclinic.owner.OwnerController.showOwner(OwnerController.java:155)
]

Finding the source of an SQL query generated by JPA and Hibernate

The QueryStackTraceLogger utility can be used by any application that uses JPA and Hibernate. You don’t need to use Spring to configure it.

For instance, in my High-Performance Java Persistence GitHub repository, you can find the QueryStackTraceLoggerTest test case that configures the QueryStackTraceLogger utility like this:

protected void additionalProperties(Properties properties) {
    properties.put(
        AvailableSettings.STATEMENT_INSPECTOR,
        new QueryStackTraceLogger("com.vladmihalcea.hpjp")
    );
}

When running the following test case:

@Test
public void testBatch() {
    doInJPA(entityManager -> {
        for (long id = 1; id <= 5; id++) {
            entityManager.persist(
                new Post()
                    .setId(id)
                    .setTitle(
                        String.format(
                            "High-Performance Java Persistence, part %d",
                            id
                        )
                    )
            );
        }
    });
}

The QueryStackTraceLogger utility will print the following log entry:

2023-09-20 14:05:49,662 DEBUG [main]: i.h.u.h.q.QueryStackTraceLogger - This SQL query: [
    insert into post (title, version, id) values (?, ?, ?)
]
was generated by Hibernate like this: [
    org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.<init>(StatementPreparerImpl.java:164)
    org.hibernate.engine.jdbc.internal.StatementPreparerImpl$1.<init>(StatementPreparerImpl.java:85)
    org.hibernate.engine.jdbc.internal.StatementPreparerImpl.buildPreparedStatementPreparationTemplate(StatementPreparerImpl.java:85)
    org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareStatement(StatementPreparerImpl.java:81)
    org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.buildBatchStatement(AbstractBatchImpl.java:142)
    org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.getBatchStatement(AbstractBatchImpl.java:131)
    org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3419)
    org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:4073)
    org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:103)
    org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:612)
    org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:483)
    java.base/java.util.LinkedHashMap.forEach(LinkedHashMap.java:721)
    org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:480)
    org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:329)
    org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39)
    org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:107)
    org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1425)
    org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:477)
    org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:2234)
    org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:1930)
    org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:439)
    org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183)
    org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281)
    org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101)
    com.vladmihalcea.hpjp.util.AbstractTest.doInJPA(AbstractTest.java:532)
]

The stack trace part tells us that:

• the query was batched by the buildBatchStatement call
• the INSERT is done by the EntityInsertAction when the Hibernate Session is flushed
• the Session was flushed prior to committing the JPA transaction

Having such a detailed report not only allows us to locate the source of a given SQL statement, but we can even learn about the inner workings of Spring and Hibernate, which is very useful in the long run.

I'm running an online workshop on the 20-21 and 23-24 of November about High-Performance Java Persistence.

If you enjoyed this article, I bet you are going to love my Book and Video Courses as well.

Conclusion

With the QueryStackTraceLogger utility configured on the QA environment, you can collect the source of all commonly generated SQL queries and correlate their performance with the database query statistic report.

Another alternative you could employ to achieve the same goal is to use Visual VM JDBC Profiling.

Insert details about how the information is going to be processed

DOWNLOAD NOW