Log When JDBC Connection Is Acquired And Released

We are fond of one db session per request pattern. For web applications with JPA & Hibernate, it is good strategy in common cases. But for some long-running requests (definition of long-running depends on your use case, maybe 500 ms or 2 s), we need to tweak when we are actually acquiring a db connection from JDBC database connection pool & releasing it back. Otherwise if we are holding the connection for entire duration of the long running request, that might choke our Java application. The number of connections in JDBC pool is limited after all.

Just wanted to add another point. Until you make a database query from your application, request thread won't actually acquire a connection from the database pool.

So ultimately you might need to track when the database connection is actually getting acquired & when it is released. Based on the findings you can manually acquire & release db connection inside you code block & optimize the connection holding time in specific cases. For an example, you made a JDBC query & then you are making a network call which might take tens or hundreds of milliseconds. It would be better to release the connection before you make the API call over the network. You can acquire it again later in the same request if needed.

To log actually when Hibernate is acquiring a database connection from JDBC connection pool & releasing it back, you would have to enable DEBUG level logging on org.hibernate.engine.jdbc.internal.LogicalConnectionImpl class. You can enable logging at a higher package level. But here I am trying to keep log uncluttered. Just by enabling DEBUG log level on the above class, you will be able to see log getting printed as below:



2021-04-21_14:40:42.512 DEBUG o.h.e.j.i.LogicalConnectionImpl - Obtaining JDBC connection
2021-04-21_14:40:42.512 DEBUG o.h.e.j.i.LogicalConnectionImpl - Obtained JDBC connection
2021-04-21_14:40:47.500 DEBUG o.h.e.j.i.LogicalConnectionImpl - Releasing JDBC connection
2021-04-21_14:40:47.500 DEBUG o.h.e.j.i.LogicalConnectionImpl - Released JDBC connection

If we are using log4j framework, enabling log level would be somewhat similar to below:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
    </Console>
  </Appenders>
  <Loggers>
    <Logger name="org.hibernate.engine.jdbc.internal.LogicalConnectionImpl" level="DEBUG">
      <AppenderRef ref="Console"/>
    </Logger>
    <Root level="error">
      <AppenderRef ref="Console"/>
    </Root>
  </Loggers>
</Configuration>

Comments