Nasha nasha krovatka delala shik - shik, Ya tvo pianino , a ty moi nastroishchik, My tak letali chto ne zametili tvoyu matʹ, Ahaa..I ona skazala chto ya prosto blaz (Mama Lyuba - Serebro))

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, requires to be prepared to read, understand and evaluate sql.

If we take an overview on hibernate configuration, two properties, hibernate.format_sql and hibernate.use_sql_comments, should be enabled to print performed sql code 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. Log4jdbc is a jdbc driver that can log sql/jdbc calls. In fact log4jdbc is 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-remix and slf4j-log4j12 dependencies to project:

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.

After configuring loggers, run test and inspect the output.


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,
Alex

Download Code
Music: http://www.youtube.com/watch?v=h9HRHOXfRBI