This article provides some guidance on how to spot Database queries which are taking most of your time during the execution of a Spring Boot application.
Most application bottlenecks derive from the execution of Database / Enterprise Systems due to different factors, such as network, memory, CPU usage or suboptimal database statements.
Database Administration can monitor the execution of Database sessions using different types of views which are available in any Relational Database. On the other hand, you can also approach this problem in an agnostic way, using just a couple of Hibernate properties.
Using Hibernate SQL_SLOW to find slow queries
For Spring Boot applications, the following configuration properties allow you to trace all queries which take more than a threshold. In our example, the threshold is 500 ms:
logging.level.org.hibernate.SQL_SLOW.level=INFO spring.jpa.properties.hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS=500
When the above configuration is in place, you will see a similar INFO message from org.hibernate.SQL_SLOW packages with a clear indication of the offending SQL Statements. The log also includes the Query execution time:
2022-09-10 18:08:27.438 INFO 80886 --- [ main] org.hibernate.SQL_SLOW : SlowQuery: 700 milliseconds. SQL: 'Pooled statement wrapping physical statement select taskimpl0_.id as col_0_0_, deadlineim1_.id as col_1_0_, deadlineim1_.deadline_date as col_2_0_ from Task taskimpl0_ cross join Deadline deadlineim1_ where taskimpl0_.archived=0 and (deadlineim1_.id in (select startdeadl2_.id from Deadline startdeadl2_ where taskimpl0_.id=startdeadl2_.Deadlines_StartDeadLine_Id)) and deadlineim1_.escalated=0 order by deadlineim1_.deadline_date' SlowQuery: 2 milliseconds. SQL: 'Pooled statement wrapping physical statement select taskimpl0_.id as col_0_0_, deadlineim1_.id as col_1_0_, deadlineim1_.deadline_date as col_2_0_ from Task taskimpl0_ cross join Deadline deadlineim1_ where taskimpl0_.archived=0 and (deadlineim1_.id in (select startdeadl2_.id from Deadline startdeadl2_ where taskimpl0_.id=startdeadl2_.Deadlines_StartDeadLine_Id)) and deadlineim1_.escalated=0 order by deadlineim1_.deadline_date'
Using Session metrics to capture overall Query metrics
There is also another option: you can generate statistics for all JDBC phases, therefore including acquiring, releasing, preparing and execution of JDBC statements. Here is the property you can add to your Spring Boot configuration:
spring.jpa.properties.hibernate.generate_statistics=true
You can also enable statistics directly in the persistence.xml file as follows:
<property name="hibernate.generate_statistics" value="true" />
When the above configuration is in place, you will see in your log messages like this:
12:11:30,215 INFO StatisticalLoggingSessionEventListener:156 - Session Metrics {
57986 nanoseconds spent acquiring 1 JDBC connections;
86326 nanoseconds spent releasing 1 JDBC connections;
114459 nanoseconds spent preparing 1 JDBC statements;
1234619 nanoseconds spent executing 1 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
0 nanoseconds spent performing 0 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
24313767 nanoseconds spent executing 1 flushes (flushing a total of 1 entities and 1 collections);
32179 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Finally, you should also set the log level of the org.hibernate.stat category to DEBUG so that Hibernate logs a message with the SQL statement and each query’s execution time to the log file:
14:38:05,231 DEBUG ConcurrentStatisticsImpl:387 - HHH000117: HQL: SELECT o FROM Customer o WHERE id = 1, time: 148ms, rows: 1Found the article helpful? if so please follow us on Socials
