The best way to log JDBC statements

Introduction

Whenever you are using a data access framework that auto generates statements on your behalf, it is mandatory to log all statements to ensure their effectiveness, as well as to assert the possible performance implications.

Hibernate logging

Hibernate defines the hibernate.show_sql configuration property to enable logging. Unfortunately, the logs go to console, which makes it very difficult to filter them appropriately. A much better approach is to enable SQL statement logging using a log adapter:

<logger name="org.hibernate.SQL" level="debug"/>

Because Hibernate uses PreparedStatement(s) exclusively, the bind parameter values are not available when the statement gets printed into the log:

INSERT INTO post (title, version, id) VALUES (?, ?, ?)

Although bind parameters might be logged separately (e.g. org.hibernate.type.descriptor.sql), the most straight-forward way of logging SQL statements along with their runtime bind parameter values is to use an external DataSource proxy. Because the proxy intercepts all statement executions, the bind parameter values can be introspected and printed as well.

Either the JDBC Driver or the DataSource must be proxied to intercept statement executions and log them along with the actual parameter values. Besides statement logging, a JDBC proxy can provide other cross-cutting features like long-running query detection or custom statement execution listeners.

DataSource-proxy

A lesser-known JDBC logging framework, datasource-proxy provides support for custom JDBC statement execution listeners. In Java EE, not all application servers allow configuring an external DataSource, as they rely on their own custom implementations that bind the user supplied JDBC Driver. Because it can only decorate a DataSource, datasource-proxy might not be suitable for all Java EE environments.

DataSourceProxyArchitecture

On the other hand, the programmatic configuration support fits the Java-based configuration approach taken by most modern Spring applications:

@Bean 
public DataSource dataSource() {
    SLF4JQueryLoggingListener loggingListener = new SLF4JQueryLoggingListener();
    loggingListener.setQueryLogEntryCreator(new InlineQueryLogEntryCreator());
    return ProxyDataSourceBuilder
        .create(actualDataSource())
        .name(DATA_SOURCE_PROXY_NAME)
        .listener(loggingListener)
        .build();
}

In the following example, datasource-proxy is used to log a batch insert of three PreparedStatement(s). Although normally a batch is printed in a single line of log, the output was split into multiple lines to fit the current page layout.

Name:DATA_SOURCE_PROXY, Time:6, Success:True, 
Type:Prepared, Batch:True, QuerySize:1, BatchSize:3, 
Query:["insert into post (title, version, id) values (?, ?, ?)"], 
Params:[(Post no. 0, 0, 0), (Post no. 1, 0, 1), (Post no. 2, 0, 2)]

Not only the bind parameter values are now present, but, because they are grouped all together, it is very easy to visualize the batching mechanism too.

With the custom statement listener support, datasource-proxy allows building a query count validator to assert the auto-generated statement count and, therefore, prevent N+1 query problems during the development phase.

P6spy

P6Spy was released in 2002, in an era when J2EE application servers were ruling the world of enterprise systems. Because Java EE application servers do not allow programmatic DataSource configuration, P6Spy supports a declarative configuration approach (through a spy.properties file).

P6Spy offers support for proxying both a JDBC Driver (which is suitable for Java EE applications) or a JDBC DataSource (supported by some Java EE containers and common practice for Spring enterprise applications).

P6SpyArchitecture

Running the previous example gives the following output (formatting was also applied):

p6spy - 1448122491807|0|batch|connection 7|
	insert into post (title, version, id) values (?, ?, ?)|
	insert into post (title, version, id) values ('Post no. 0', 0, 0)
p6spy - 1448122491807|0|batch|connection 7|
	insert into post (title, version, id) values (?, ?, ?)|
	insert into post (title, version, id) values ('Post no. 1', 0, 1)
p6spy - 1448122491807|0|batch|connection 7|
	insert into post (title, version, id) values (?, ?, ?)|
	insert into post (title, version, id) values ('Post no. 2', 0, 2)
p6spy - 1448122491812|5|statement|connection 7|
	insert into post (title, version, id) values (?, ?, ?)|
	insert into post (title, version, id) values ('Post no. 2', 0, 2)

In the order of their occurrence, the output is built out of the following columns:

Field Description
Timestamp The statement execution timestamp
Execution time The statement execution duration (in milliseconds)
Category The current statement category (e.g. statement, batch)
Connection The database connection identifier (as assigned by P6Spy)
Original statement The original statement that was intercepted by P6Spy
Formatted statement The statement with all parameter placeholders replaced with the actual bind values

The first three lines are associated with adding statements to the batch, while the fourth line is logging the actual batch execution (which also explains the execution time column value).

One very useful configuration is the outagedetection property, which can detect long-running statements.

If you enjoyed this article, I bet you are going to love my book as well.

Video

Because this is a very interesting topic, I decided to record a video as well. Enjoy watching it!

Conclusion

Logging statements is a very important aspect for a data access layer, and using a JDBC statement interceptor framework can leverage other cross-cutting functionalities, such as monitoring statement execution, or even automatically detecting N+1 query problems.

Enter your email address to follow this blog and receive notifications of new posts by email.

Advertisements

14 thoughts on “The best way to log JDBC statements

  1. Excellent article Vlad, logging the underlying SQL queries of the executed JDBC statements, particularly when these statements match given criteria, is a very useful feature that may help to uncover various database performance issues in the application.

    I just wanted to add to what you’ve written above that if Vibur DBCP is used as a DataSource for the application (a standalone DataSource or through a ConnectionProvider for Hibernate), it has a built-in SQL queries logging mechanism for queries which execution has taken longer than a configured timeout or queries that have retrieved longer than a configured ResultSet. The configuration can be set in such way that to log all queries, however being able to filter which exactly queries need logging is helpful as it reduces the volume of the generated logs.

    The configuration options for the queries logging can be seen at http://www.vibur.org/#slow-queries-and-get-connection-calls-logging and there are also links to sample generated logs.

  2. It’s worth mentioning tools which can show the executed SQL queries directly inside the browser window. After all nowadays most of the applications where Hibernate is used are web based. Some notable examples are XRebel and Sniffy.

  3. I dont have the import com.vladmihalcea.book.hpjp.util.logging.InlineQueryLogEntryCreator;
    What to use instead?

  4. Hello, and thanks for your interesting article.

    I’ve got a question : Why don’t you use the Statistic class of Hibernate ?

    I see full of method which permit to count UPDATE, DELETE, Fetch or whatever in it…. ?

      1. Ok I agree. But for fine grained count Hibernate Statistic class seems much better.
        Thx

      2. The Hibernate Statistics will not render proper results if you’re using Soft Delete because Hibernate counts entity state transitions not the actual SQL statements that are executed.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s