This is the second part of Hibernate: logging SQL.
Using log4jdbc instead of Hibernate SQL logging
Hibernate logs a lot of information we can exploit to get the SQL is it generating in the end. That said, I miss some things:
• Get the SQL prepared statements with the parameter values right there, instead of getting each parameter in a different log line.
• Know how much time it took to execute every SQL statement (sigh!).
• Know what line in my code caused the SQL statement to be executed (not the line in Hibernate’s code)
Now, what if we could get this log,
DEBUG: jdbc.sqltiming - " com.softwarementors.hibernate.util.DataAccess.persistAll( DataAccess.java:40)
1. /* insert com.softwarementors.demo1.Article */
insert into Article (id, version, currentPrice, name) values (null, 0, 27.2, 'Article_1') {executed in 15 msec}"
instead of this one?
DEBUG: org.hibernate.SQL - "/* insert com.softwarementors.demo1.Article */ insert into Article (id, version, currentPrice, name) values (null, ?, ?, ?)" TRACE: org.hibernate.type.IntegerType - "binding '0' to parameter: 1" TRACE: org.hibernate.type.BigDecimalType - "binding '27.2' to parameter: 2" TRACE: org.hibernate.type.StringType - "binding 'Article_1' to parameter: 3"
This last version is what Hibernate will log for us for a given SQL statement, while the first version is what log4jdbc will log for that same statement. Log4jdbc is an open source library that logs all JDBC calls for a given application. What does the log4jdbc log provide that the Hibernate log does not?
• Log4Jdbc logs all SQL statements, whereas Hibernate only logs the SQL statements it generates. If we call SQL directly in some place, we might miss some SQL being executed if we rely on Hibernate logs to tell us the whole truth.
• Log4jdbc logs the time spent by every statement, 15 milliseconds in our example. That is great!
• Log4jdbc logs the SQL and writes the parameter values right there for prepared statements, whereas Hibernate logs them in separated lines, and is much more verbose.
• Log4jdbc can log the function in our code that caused the statement to be executed, in our case the persistAll method.
This deserves to be repeated: log4jdbc can log the line in our code, instead of the one deep down in Hibernate. It provides the name of the function, the file and the line number!
Of course, you need to compile your code enabling line number and file name information generation for your classes.
• Log4jdbc generates a logical connection number that identifies the connection that was used to execute a statement (or JDBC API call). That can be great to debug threading or pooling problems, because it helps us to know what statements belong together and what connection is really being used to execute a given statement.
That is the “1” that appears in the first log, just before “/* insert…”.
And, even if it does show not in our example, log4jdbc allows us to log slow statements as warning or errors: we can set how many milliseconds make us consider a statement slow (and generate a warning log) or very slow (and generate an error log).
However, Hibernate logging has a definite advantage: it logs human readable SQL. For complex queries, which tend to be the interesting ones, this is a definite plus.
Please, note that because Hibernate generates comments at the SQL level, log4jdbc can see and log them as well. Therefore, do not forget to set the hibernate.use_sql_comments Hibernate property to true.
Basic log4jdbc configuration
Now, how do we get all those benefits? Here are the steps I undertook to add logt4jdbc 1.1 to my existing project:
1. Add the required jars:
1.1. The log4jdbc jar itself. It is log4jdbc3-1.1.jar for version 1.1 and JDBC 3, because I’m using a JDBC3 capable driver.
1.2. The jars for libraries used by log4jdbc, in this version the Simple Logging Façade for Java, SLFJ4, version 1.5: this means slf4j-api-1.5.0.jar and sl4j-log4j12-1.5.0.jar, because we use log4j for logging, and this is the bridge between SLFJ4 and log4j 1.2. If you use a different logging tool, you’ll need to use a different jar.
2. Modify the Hibernate configuration so that it uses log4jdbc interceptor. I did that by modifying hibernate.properties as follows:
2.1. Set hibernate.connection.driver_class to net.sf.log4jdbc.DriverSpy.
2.2. Modify hibernate.connection.url, prepending jdbc:log4 to the existing connection url.
In my case, my old url was jdbc:hsqldb:hsql://localhost:9200/demo1_db. Therefore, the new url was jdbc:log4jdbc:hsqldb:hsql://localhost:9200/demo1_db.
3. Modify log4j.properties so that we get the desired logging information from log4jdbc:
3.1. Deactivate Hibernate SQL logging: comment the log4j.logger.org.hibernate.SQL=ALL and log4j.logger.org.hibernate.type=ALL entries.
But leave the hibernate.use_sql_comments Hibernate property set to true please: log4jdbc will log those comments too, and that will be nice.
3.2. Configure log4jdbc logging: just set the log4j.logger.jdbc.sqltiming category to ALL.
There are other logging categories, but that’s what I used to get the prior log, and most likely all you will need.
4. Help log4jdbc in determining the line in our source code that caused the SQL statement to be executed.
To do this, log4jdbc traverses the call stack when an statement is executed, looking for the first function that belong to one of our classes. It will know that because we will tell it what is the root package for our classes. In my case, this is com.softwarementors. I just set the system property to com.softwarementors passing it as a parameter to the JVM when executing my program, as follows:
-Dlog4jdbc.debug.stack.prefix=com.softwarementors.
That’s it: we are done!
Other goodies in the jdbc.sqltiming logger
We mentioned that log4jdbc allows us to mark a SQL statement as slow or very slow, logging it at the warn or error level, respectively. How do we do that? Well, if we consider a statements that takes 1000 milliseconds or more to deserve being logged as an error, and another one that takes 200 or more to deserve being logged as a warning, we will have to set two system properties, log4jdbc.sqltiming.warn.threshold=200 and log4jdbc.sqltiming.error.threshold=1000 The easiest way to do this is passing the following command line to the Java Virtual Machine, using the –D option, as follows:
-Dlog4jdbc.sqltiming.warn.threshold=200 -Dlog4jdbc.sqltiming.error.threshold=1000
I think you should almost always use this capability!
Understanding what “the line that caused the statement to be executed” means
Getting the line in my code that caused the SQL statement to be executed is really cool. However, some discussion is needed to understand what “the line that caused the SQL statement to be executed” means! As you probably know, Hibernate can delay the execution of SQL in order to get better performance. That means that the logical line that caused an SQL DELETE to be executed can be this one
entityManager.remove( myObject);
whereas the physical line that caused the DELETE statement to be executed might be this,
entitManager.getTransaction().commit();
That happens because Hibernate might have delayed the statement execution until commit time. What log4jdbc logs is the physical line.
Configuring Hibernate and getting human readable SQL
As I said before, Hibernate has the edge when it comes to statement readability. Therefore, you might want to activate Hibernate logging just to get a nicely formatted SQL, while at the same time logging the information provided by log4jdbc. To do that, set the hibernate.format_sql Hibernate property to true in the hibernate.properties file (or wherever you happen to specify those Hibernate properties). Then set enable the hibernate.SQL logger level to ALL. Of course, you will get duplicated logs for every SQL statement, but that will be easy to handle, because they will be consecutive and therefore easy to spot. And, if you use a tool like Chainsaw for viewing the logs, you can filter out the Hibernate logs and look at them only when you want to dig into the SQL itself!
More log4jdbc logging
As always, your logs are good only if you know and understand the existing logging categories provided by the library you want to monitor. There are four logging categories in log4jdbc. But just let me tell you that using jdbc.sqltiming will be enough if all you want to know is about the SQL statements that are executed. These are the logging categories provided by log4jdbc:
• jdbc.sqlonly: logs every SQL statement the program executes, but just the SQL itself. It shows the parameter values when using prepared statements.
• jdbc.sqltiming: as far as I know, it is exactly like jdbc.sqlonly, but adding the time the statement took to execute. I usually use this, instead of jdbc.sqlonly, and you should never use both at the same time unless you love to get almost duplicated logs.
• jdbc.audit: logs all JDBC API calls, except those for the ResultSet interface. This can generate a lot of information, use it with care.
• jdbc.resultset: this logs the ResultSet API calls only, so it does not overlap with jdbc.audit. This can generate massive amounts of information (lots of calls per returned row!), and I think you will rarely use this. Just to illustrate what kind of logging you can get out of jdbc.sqltiming, jdbc.audit and jdbc.resultset when combined, let’s see the log generated when the following line of code is executed:
InvoiceLine line = entityManager.find( InvoiceLine.class, lineId );
Well, here is the generated log:
DEBUG: jdbc.audit - "1. Connection.prepareStatement(/* load com.softwarementors.demo1.InvoiceLine */ select invoicelin0_.id as id3_0_, invoicelin0_.version as version3_0_, invoicelin0_.article_id as article5_3_0_, invoicelin0_.pricePerUnit as pricePer3_3_0_, invoicelin0_.quantity as quantity3_0_ from InvoiceLine invoicelin0_ where invoicelin0_.id=?) returned net.sf.log4jdbc.PreparedStatementSpy@1b18235 com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.audit - "1. PreparedStatement.setLong(1, 3) returned com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.sqltiming - " com.softwarementors.demo1.Main.main(Main.java:159)
1. /* load com.softwarementors.demo1.InvoiceLine */ select invoicelin0_.id
as id3_0_, invoicelin0_.version as version3_0_, invoicelin0_.article_id as article5_3_0_, invoicelin0_.pricePerUnit
as pricePer3_3_0_, invoicelin0_.quantity as quantity3_0_ from InvoiceLine invoicelin0_ where
invoicelin0_.id=3 {executed in 0 msec}"
DEBUG: jdbc.audit - "1. PreparedStatement.executeQuery() returned net.sf.log4jdbc.ResultSetSpy@46a09b com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.next() returned true com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.getInt(version3_0_) returned 0 com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.wasNull() returned false com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.getLong(article5_3_0_) returned 1 com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.wasNull() returned false com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.getBigDecimal(pricePer3_3_0_) returned 27.2 com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.wasNull() returned false com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.getInt(quantity3_0_) returned 4 com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.wasNull() returned false com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.next() returned false com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.close() returned com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.audit - "1. PreparedStatement.getMaxRows() returned 0 com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.audit - "1. PreparedStatement.getQueryTimeout() returned 0 com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.audit - "1. PreparedStatement.close() returned com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.audit - "1. Connection.isClosed() returned false com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.audit - "1. Connection.getAutoCommit() returned false com.softwarementors.demo1.Main.main(Main.java:159)"
As you can see, jdbc.audit adds tons of data, and jdbc.resultset adds even more. Just imagine the log had we executed a query returning 100 objects! It is very likely that you will want to enable this kind of logging for very little sections of code, programmatically, to avoid drowning in data. All these loggers provide different information depending on the level to which they are set:
• DEBUG: logs the method, file and line number at which the JDBC API method was called (if possible). Of course, log the SQL or other applicable information, such as “Connection.isClosed() returned false”.
• INFO: like DEBUG, omitting the method file and line number.
• ERROR: log data about SQL exceptions only. If you want no log for a given logger, set its level to FATAL. As an example, if a logger logs this when its level is set to DEBUG,
DEBUG: jdbc.audit - "1. Connection.getAutoCommit() returned false com.softwarementors.demo1.Main.main(Main.java:159)"
it will log this when it is set to INFO:
DEBUG: jdbc.audit - "1. Connection.getAutoCommit() returned false"
This can be much more manageable sometimes. By all means, if you are stepping through code with the debugger, set your logging level to INFO. You already know in which line you are (!), and you just want to focus in what JDBC methods are called at that moment: you don’t want to get that information in the middle of a lot of useless text. Finally, to log information about log4jdbc itself, you can use the log4jdbc.debug logging category. I always set it to ALL, because I find the information provided to be rather small and manageable (I’m talking about version 1.1 of log4jdbc all the time, so your mileage might vary). This is all logging I get in my sample application:
DEBUG: log4jdbc.debug - "... log4jdbc initializing ..." DEBUG: log4jdbc.debug - " log4jdbc.debug.stack.prefix = com.softwarementors" DEBUG: log4jdbc.debug - " log4jdbc.sqltiming.warn.threshold = 100" DEBUG: log4jdbc.debug - " log4jdbc.sqltiming.error.threshold = 500" DEBUG: log4jdbc.debug - "x log4jdbc.drivers is not defined" DEBUG: log4jdbc.debug - " FOUND DRIVER org.hsqldb.jdbcDriver" DEBUG: log4jdbc.debug - "... log4jdbc initialized! ..."
But it does not work with my JDBC driver!
Log4jdbc automatically recognizes and loads the more popular JDBC drivers, such as those for Oracle, HSQL, MySQL, the JTDS drivers for SQLServer and Sybase, etc. However, if your database driver is not directly recognized by log4jdbc, you still can integrate it with log4jdbc setting the following system property,
log4jdbc.drivers=<driver>[,<driver>,...]
Again, the easiest way might be to pass it to the JVM using the –D option, as follows:
-Dlog4jdbc.drivers=<driver>[,<driver>,...]
We want more!
Now, to the “wouldn’t it be nice?” department… I think it might be nice to be able to control logging per JDBC interface/class, i.e., Connection or PreparedStatement. An additional level of finer grained loggers might be nice too: I can imagine wanting to get logs for transaction related operations, but not the other Connection function calls. As always, the sky is the limit, but log4jdbc is a great library that you can put to good use with a minimal effort. As always, you should check newer log4jdbc versions for additional functionality.
Acknowledgements
I would like to thank José María Martínez for his criticism of this article.
Software Development "Built to Last" 