Scenario

If a dialog is too slow, there might happen a lot of unexpected queries. This can be caused by eager loading of relations or you might just reuse the queries of another dialog. Did you know for example that 1:1 and n:1 relations are loaded eagerly, if you use annotations whereas XML mappings are lazy by default.

Solution

The best approach is to analyse what is happening behind the scenes. Hibernate offers two configuration settings to print the generated SQL. The first one is a property in the hibernate.cfg.xml

<property name="show_sql">true</property>

If it is set to true, the SQL statements will be printed to the console. You will not see any timestamps, this is why I prefer the second approach, which uses the normal logging output.

# logs the SQL statements
log4j.logger.org.hibernate.SQL=debug

# Some more useful loggings
# Logs SQL statements for id generation
log4j.logger.org.hibernate.id=info
# Logs the JDBC-Parameter which are passed to a query (very verboose)
log4j.logger.org.hibernate.type=trace
# Logs cache related activities
log4j.logger.org.hibernate.cache=debug

There are more useful settings in the Hibernate configuration hibernate.cfg.xml

The property format_sql will nicely format the SQL instead of printing it on a single line.

<property name="format_sql">true</property>

The property use_sql_comments adds a comment to each SQL explaining why it was created. It let’s you identity if a HQL statement, lazy loading or a criteria query led to the statement.

<property name="use_sql_comments">true</property>

Another good source for information are the statistics of Hibernate.

You can enable the statistics in the Hibernate configuration or programmatically. The statistics class offers a number methods to analyse what has happened. Here a quick example:

Statistics statistics = sessionFactory.getStatistics();
statistics.setStatisticsEnabled(true);
statistics.logSummary();

Furthermore you can call getStatistics on a session as well to gather information about it.