Archivo de la categoría: Hibernate/JPA

Making sure Hibernate does not leak sessions/entity managers

Resource cleanup is a must for all applications, especially long-running ones.

The most precious Hibernate resource requiring cleanup is the Session. If you are using JPA, as I frequently do, a session is wrapped by an EntityManager, but is still there.

In order for your apps to behave, you will need to make sure you are not forgetting to release sessions, or you’ll end up having trouble sooner than later.

To ensure that, you’ll need a way to check whether, after finishing some self contained operation, you have released all sessions you allocated -but not more.

To do that, I created a utility class, called SessionAllocationChecker. How do you use it? The typical usage is as follows:

SessionAllocatorChecker checker = new SessionAllocatorChecker( 
   myHibernateSessionFactory );
try {
  // ... code that opens and closes hibernate sessions/entity managers
}
finally {
  checker.dispose();
}

Here, if there are 5 sessions open when checker is created, and 8 sessions open when dispose is called, you will get an AssertionError, telling you you’ve got 3 extra sessions open you probably forgot to close.

How does it do that?

Now, how does it work? When an instance of SessionAllocationChecker is allocated, it checks the statistics maintained by Hibernate and notes the number of open sessions vs. the number of closed sessions at the moment: the difference will be the number of effectively open sessions at creation time.

If Hibernate statistics are not enabled, it will enable them -and quietly disable them when you call dispose.

Next, when you call getOutstandingSessions or hasOutstandingSessions, it performs the same operation, to check the number of currently open sessions. getOutstandingSessions will return the number of sessions currently open minus the number of session open at creation time, that is, the number of additional sessions you have open and not closed yet.

When you call the dispose method, it ensures Hibernate statistics enabled state is restored to its old status. Besides, it will check whether you have session leakage, by calling getOutstandingSessions , but only if you are executing you app with the JVM -enableassertions option. If that’s the case, an AssertionError exception will be thrown.

If the -enableassertions flag is not set, you will have to check the number of outstanding sessions by calling getOutstandingSessions on you own.

While rough, I found this trick extremely useful: in fact, I use this class to check that I never forget to release sessions/entity managers in my own tests.

Another place where you can put this to good use is in web app filters, to ensure that your requests do not leak sessions.

Here is the full source code:

package com.softwarementors.bzngine.engines.hibernate;

import javax.persistence.EntityManagerFactory;

import org.hibernate.SessionFactory;
import org.hibernate.ejb.HibernateEntityManagerFactory;
import org.hibernate.stat.Statistics;

public class SessionAllocationChecker {

  private boolean statisticsEnabledOnEntry;

  private long outstandingSessionsOnEntry;

  private SessionFactory factory;

  private boolean disposed;

  public SessionAllocationChecker( SessionFactory factory ) {
    assert factory != null;
    
    this.factory = factory;
    Statistics statistics = factory.getStatistics();
    this.statisticsEnabledOnEntry = statistics.isStatisticsEnabled();
    statistics.setStatisticsEnabled(true);
    this.outstandingSessionsOnEntry = 
       statistics.getSessionOpenCount() 
       - statistics.getSessionCloseCount();
  }
  
  public SessionAllocationChecker(EntityManagerFactory factory) {
    this( ((HibernateEntityManagerFactory) factory).getSessionFactory() );
  }
  
/*  
  public SessionAllocationChecker( EntityManager entityManager ) {
    this( entityManager.getEntityManagerFactory());
  }
  
  public SessionAllocationChecker( Session session ) {
    this(session.getSessionFactory());
  }
*/  

  public boolean isDisposed() {
    return this.disposed;
  }
  
  public long getOutstandingSessions() {
    assert !isDisposed();

    Statistics statistics = this.factory.getStatistics();
    assert statistics.isStatisticsEnabled() : 
       "Somebody else disabled the statistics: avoid that";
    long outstandingSessions = statistics.getSessionOpenCount() 
       - statistics.getSessionCloseCount();
    long sessionsNotReleasedAfterCreation = outstandingSessions 
       - this.outstandingSessionsOnEntry;

    assert sessionsNotReleasedAfterCreation >= 0 : 
       "Somebody else played with the statistics " + 
       "(maybe cleared/disabled them?): avoid that";
    return sessionsNotReleasedAfterCreation;
  }

  public boolean hasOutstandingSessions() {
    assert !isDisposed();
    
    return getOutstandingSessions() > 0;
  }

  public void dispose() {
    if (!isDisposed()) {     
      assert !hasOutstandingSessions() : "There are " 
         + getOutstandingSessions() + 
         " additional sessions open and not closed";

      this.disposed = true;
      
      // Reset statistics to the state they were before we started to
      // be interested in open/closed session count
      Statistics statistics = this.factory.getStatistics();
      statistics.setStatisticsEnabled(this.statisticsEnabledOnEntry);
    }
  }
}

If you take a look at the code, you will find I have added lots of sanity checks via assertions: using the Hibernate statistics as I do is not completely foolproof, if you clear them or disable them between the moment you created the checker and you disposed it, you will get incoherent readings that will fool SessionAllocationChecker.

While I have provided lots of checks, they are not completely safe -not could they be, given the way statistics are implemented by Hibernate. Keep an open eye, and all will be well.

You’ll have noticed that I use assertions all around: you can read this article if you are interested in knowing why I’m such a fan of assertions.

By the way, if you don’t have at hand a SessionFactory or a EntityManagerFactory to pass it to the SessionAllocationChecker constructor, all is not lost: you can get them from a Session or an EntityManager. How to do it is part of the code: just look at the commented code.

Believe it or not, the code is commented because I just have no tests for it in the library where SessionAllocationChecker belongs.

No test, no public exposure -at least, as part of a high quality library.

Hibernate SQL Logging: log4jdbc / Haciendo log de SQL con Hibernate: log4jdbc

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.

Hibernate SQL Logging / Haciendo log de SQL con Hibernate

Here is the link to a (rather short ) article about SQL logging in Hibernate, Hibernate: logging SQL.