About Alex Soto

Log JDBC operations with Log4jdbc

When we develop any application, after we finish it or when we end up any of its module, we start optimization process. Most applications contain database access, and if you are using an ORM, probably you will use hibernate. Optimizing hibernate persistence layer,requiresto be prepared to read, understand and evaluate sql.

If we take an overview on hibernate configuration, two properties, hibernate.format_sqland hibernate.use_sql_comments,should be enabled to printperformed sqlcode through console.

This is a good start but it seems that we need more information to make an accurate diagnosis of performance like connection events, returned data on queries, or parameters binding ( hibernate shows parameters values with question mark ?) . Hence, we need another way to inspect generated sql. Log4jdbcis a jdbc driver that can log sql/jdbc calls. In fact log4jdbcis an implementation of proxy pattern which will automatically load popular jdbc drivers ( Oracle, Derby, MySql, PostgreSql, H2, Hsqldb, …), intercept calls, log information, and then send data to ‘ spied‘ driver.

In log4jdbc, there are 5 loggers that can be used depending on data to monitor:

  • jdbc.sqlonly: logs executed sql with binding arguments replaced with bound data.
  • jdbc.sqltiming: logs how long a sql took to execute.
  • jdbc.audit: logs all jdbc calls except for ResultSets.
  • jdbc.resultset: same as jdbc.audit plus ResultsSets.
  • jdbc.connection: logs open and close connection events.

In this post we are going to see how to configure log4jdbc-remix, a fork of log4jdbc, which apart from inheriting log4jdbc capabilities, also let us:

  • jdbc.resultsettable: log results set in table format.
  • configure it as datasource.
  • available in maven repository (log4jdbc is not present on maven repositories).

For this example we are going to use the project created by JPA Spring Template which contains two entities Order and Item associated with one-to-many relationship, and one test that executes some database operations.
First thing to do is add log4jdb-remixand slf4j-log4j12 dependencies to project:

 <dependency>
  <groupId>org.slf4j<groupId>
  <artifactId>slf4j-log4j12<artifactId>
  <version>1.6.4<version>
 <dependency>
 
 <dependency>
  <groupId>org.lazyluke<groupId>
  <artifactId>log4jdbc-remix<artifactId>
  <version>0.2.7<version>
 <dependency>

Next thing to do is configure active loggers. Depending on the data we are interested to monitor, we activate the required loggers. As an example let’s configure log4j.xml so result set is printed in table format and also time taken to execute each query is shown.

 <?xml version='1.0' encoding='UTF-8' ?>
 <!DOCTYPE log4j:configuration SYSTEM 'log4j.dtd'>
 
 <log4j:configuration xmlns:log4j='http:jakarta.apache.orglog4j'>
  <appender name='console-log4jdbc' class='org.apache.log4j.ConsoleAppender'>
   <param name='Target' value='System.out' >
   <layout class='org.apache.log4j.PatternLayout'>
    <param name='ConversionPattern' value='%m%n' >
   <layout>
  <appender>
 
 
 <!--  <logger name='jdbc.sqlonly' additivity='false'> -->
 <!--   <level value='debug' > -->
 <!--   <appender-ref ref='console-log4jdbc' > -->
 <!--  <logger> -->
  <logger name='jdbc.sqltiming' additivity='false'>
   <level value='info' >
   <appender-ref ref='console-log4jdbc' >
  <logger>
 <!--  <logger name='jdbc.connection' additivity='false'> -->
 <!--   <level value='info' > -->
 <!--   <appender-ref ref='console-log4jdbc' > -->
 <!--  <logger> -->
 
  <!-- log4jdbc option log the jdbc results as a table -->
  <logger name='jdbc.resultsettable' additivity='false'>
   <level value='info' >
   <appender-ref ref='console-log4jdbc' >
  <logger>
 
 <log4j:configuration>

After configuring loggers, run test and inspect the output

 create table Item (id bigint generated by default as identity, price double not null, product 
 varchar(255), quantity integer not null, order_id bigint, primary key (id))  {executed in 10 msec}
 create table T_ORDER (id bigint generated by default as identity, customer varchar(255), primary 
 key (id))  {executed in 1 msec}
 alter table Item add constraint FK22EF339F325255 foreign key (order_id) references T_ORDER 
 {executed in 11 msec}
 insert into T_ORDER (id, customer) values (null, NULL)  {executed in 1 msec}
 insert into Item (id, order_id, price, product, quantity) values (null, NULL, 0.0, NULL, 0) 
 {executed in 0 msec}
 batching 1 statements: 0: update Item set ORDER_ID=1 where id=1  {executed in 2 msec}
 insert into T_ORDER (id, customer) values (null, NULL)  {executed in 0 msec}
 insert into Item (id, order_id, price, product, quantity) values (null, NULL, 0.0, NULL, 0) 
 {executed in 0 msec}
 batching 1 statements: 0: update Item set ORDER_ID=2 where id=2  {executed in 0 msec}
 select order0_.id as id1_0_, order0_.customer as customer1_0_ from T_ORDER order0_ where order0_.id=2 
 {executed in 0 msec}
 |---------|---------|
 |ID       |CUSTOMER |
 |---------|---------|
 |[unread] |null     |
 |---------|---------|
 select items0_.ORDER_ID as ORDER5_1_2_, items0_.id as id2_, items0_.id as id0_1_, items0_.order_id 
 as order5_0_1_, items0_.price as price0_1_, items0_.product as product0_1_, items0_.quantity 
 as quantity0_1_, order1_.id as id1_0_, order1_.customer as customer1_0_ from Item items0_ left 
 outer join T_ORDER order1_ on items0_.order_id=order1_.id where items0_.ORDER_ID=2  {executed in 0 msec}
 |---------|---|---|---------|------|--------|---------|---|---------|
 |ORDER_ID |ID |ID |ORDER_ID |PRICE |PRODUCT |QUANTITY |ID |CUSTOMER |
 |---------|---|---|---------|------|--------|---------|---|---------|
 |2        |2  |2  |2        |0.0   |null    |0        |2  |[unread] |
 |---------|---|---|---------|------|--------|---------|---|---------|
 insert into T_ORDER (id, customer) values (null, NULL)  {executed in 0 msec}
 insert into Item (id, order_id, price, product, quantity) values (null, NULL, 0.0, 'foo', 0) 
 {executed in 0 msec}
 batching 1 statements: 0: update Item set ORDER_ID=3 where id=3  {executed in 0 msec}
 select order0_.id as id1_, order0_.customer as customer1_ from T_ORDER order0_ inner join Item 
 items1_ on order0_.id=items1_.ORDER_ID where items1_.product='foo' limit 2  {executed in 6 msec}
 |---|---------|
 |ID |CUSTOMER |
 |---|---------|
 |3  |null     |
 |---|---------|
 select items0_.ORDER_ID as ORDER5_1_2_, items0_.id as id2_, items0_.id as id0_1_, items0_.order_id 
 as order5_0_1_, items0_.price as price0_1_, items0_.product as product0_1_, items0_.quantity 
 as quantity0_1_, order1_.id as id1_0_, order1_.customer as customer1_0_ from Item items0_ left 
 outer join T_ORDER order1_ on items0_.order_id=order1_.id where items0_.ORDER_ID=3  {executed in 0 msec}
 |---------|---|---|---------|------|--------|---------|---|---------|
 |ORDER_ID |ID |ID |ORDER_ID |PRICE |PRODUCT |QUANTITY |ID |CUSTOMER |
 |---------|---|---|---------|------|--------|---------|---|---------|
 |3        |3  |3  |3        |0.0   |foo     |0        |3  |[unread] |
 |---------|---|---|---------|------|--------|---------|---|---------|

Output is printed in a fashion format, queries contains bind parameters (not a question mark (?)), and process time is also informed.

Notice that logging more or less information is simply a matter of configuring a log. Moreover depending on log level, more or less information will be provided in each case. If logger is configured in DEBUG class name and line number (if available) at which the sql was executed will be included. In INFO will include only sql, and finally ERROR which show stacktraces if any SQLException occurs.

Optimizing hibernate applications can imply touching many parts of an application ( JVM configuration, database engine, network, …) but one very important aspect to take care is the number of queries that are sent to RDBMS (for example N+1 problem), and the amount of data that is retrieved from database (Projection problem), and log4jdbc-remix perfectly fits to help in this purpose.

As final note, log4jdbc(- remix) is a jdbc logger, so it is not necessary to use only in hibernate applications, can be used with any framework that uses a datasource.

I wish this library would help you.

Keep Learning,

Download Code

Reference: Log JDBC operations with Log4jdbc from our JCG partner Alex Soto at the One Jar To Rule Them All blog.

Do you want to know how to develop your skillset to become a Java Rockstar?

Subscribe to our newsletter to start Rocking right now!

To get you started we give you two of our best selling eBooks for FREE!

JPA Mini Book

Learn how to leverage the power of JPA in order to create robust and flexible Java applications. With this Mini Book, you will get introduced to JPA and smoothly transition to more advanced concepts.

JVM Troubleshooting Guide

The Java virtual machine is really the foundation of any Java EE platform. Learn how to master it with this advanced guide!

Given email address is already subscribed, thank you!
Oops. Something went wrong. Please try again later.
Please provide a valid email address.
Thank you, your sign-up request was successful! Please check your e-mail inbox.
Please complete the CAPTCHA.
Please fill in the required fields.

4 Responses to "Log JDBC operations with Log4jdbc"

  1. can we use this and print this logs to a mongo db or mysql db for quick analizing ? 
    if we can, it would be a good blog post to show how ? 

  2. also you should improve your site’s 
    You might also like:  part. it shows irrelevant posts.

  3. Basil Abbas says:

    This article is missing important stuff:
    Please make sure to read this first:http://code.google.com/p/log4jdbc/

    Make sure to perform the following:
    1. In your hibernate.cfg.xml replace the line:
    com.mysql.jdbc.Driver

    with:
    net.sf.log4jdbc.DriverSpy

    2. In your hibernate.cfg.xml replace the line:
    jdbc:mysql://localhost:3306/oncall

    with:
    jdbc:log4jdbc:mysql://localhost:3306/oncall

    3. If you are using a log4j.properties file, use the following instead:
    log4j.logger.jdbc.sqlonly=debug
    log4j.logger.jdbc.sqltiming=debug
    log4j.logger.jdbc.audit=debug
    log4j.logger.jdbc.resultset=debug
    log4j.logger.jdbc.connection=debug
    log4j.logger.jdbc.resultsettable=debug

    Thats it.

  4. Isotherm says:

    Maybe you’d like to know that there is now a log4jdbc fork based on Log4j 2, using one single logger (so easier configuration than described here): http://code.google.com/p/log4jdbc-log4j2/

Leave a Reply


5 × = twenty five



Java Code Geeks and all content copyright © 2010-2014, Exelixis Media Ltd | Terms of Use | Privacy Policy | Contact
All trademarks and registered trademarks appearing on Java Code Geeks are the property of their respective owners.
Java is a trademark or registered trademark of Oracle Corporation in the United States and other countries.
Java Code Geeks is not connected to Oracle Corporation and is not sponsored by Oracle Corporation.
Do you want to know how to develop your skillset and become a ...
Java Rockstar?

Subscribe to our newsletter to start Rocking right now!

To get you started we give you two of our best selling eBooks for FREE!

Get ready to Rock!
You can download the complementary eBooks using the links below:
Close