Problem
How do you determine what SQL query is being executed by Hibernate? How can you see the Hibernate’ internal workings? How do you enable logging to troubleshoot complex issues related to Hibernate?
Solution
You have to enable Hibernate logging in the Hibernate configuration. Hibernate uses Simple Logging Facade for Java (SLF4J) to log various system events. SLF4J, which is distributed as a free software license, abstracts the actual logging framework that an application uses. SLF4J can direct your logging output to several logging frameworks:
- NOP: Null logger implementation
- Simple: A logging antiframework that is very simple to use and attempts to solve every logging problem in one package
- Log4j version 1.2: A widely used open–source logging framework
- JDK 1.4 logging: A logging API provided by Java
- JCL: An open-source Commons logging framework that provides an interface with thin wrapper implementations for other logging tools
- Logback: A serializable logger that logs after its deserialization, depending on the chosen binding
To set up logging, you need the slf4j-api.jar file in your classpath, together with the JAR file for your preferred binding: slf4j-log4j12.jar in the case of log4j. You can also enable a property called showsql to see the exact query being executed. You can configure a logging layer such as Apache log4j to enable Hibernate class- or package-level logging. And you can use the Statistics interface provided by Hibernate to obtain detailed information.
How It Works
You have to configure the Hibernate show_sql property to enable logging.
Inspecting the SQL Statements Issued by Hibernate
Hibernate generates SQL statements that enable you to access the database behind the scene. You can set the show_sql property to true in the hibernate.cfg.xml XML configuration file to print the SQL statements to stdout:
<property name="show_sql">true</property>
Enabling Live Statistics
You can enable live statistics by setting the hibernate.generate_statistics property in the configuration file:
<property name="hibernate.generate_statistics">true</property>
You can also access statistics programmatically by using the Statistics interfaces. Hibernate provides SessionStatistics and Statistics interfaces in the org.hibernate.stat package. The following code shows the use of some utility methods:
1 SessionFactory sessionFactory = SessionManager.getSessionFactory();
2 session = sessionFactory.openSession();
3 SessionStatistics sessionStats = session.getStatistics();
4 Statistics stats = sessionFactory.getStatistics();
5 tx = session.beginTransaction();
6 Publisher publisher = new Publisher();
7 publisher.setCode("apress");
8 publisher.setName("Apress");
9 publisher.setAddress("233 Spring Street, New York, NY 10013");
10 session.persist(publisher);
11 tx.commit();
12 logger.info("getEntityCount- " + sessionStats.getEntityCount());
13 logger.info("openCount- " + stats.getSessionOpenCount());
14 logger.info("getEntityInsertCount- " + stats.getEntityInsertCount());
15 stats.logSummary();
16 session.close();
The output of this code sample is shown here (the complete log is given for clarity):
HCANN000001: Hibernate Commons Annotations {4.0.4.Final}
HHH000412: Hibernate Core {4.3.5.Final}
HHH000206: hibernate.properties not found HHH000021: Bytecode provider name : javassist
HHH000043: Configuring from resource: /hibernate.cfg.xml
HHH000040: Configuration resource: /hibernate.cfg.xml
HHH000221: Reading mappings from resource: com/apress/hibernaterecipes/chapter1/model/Book.hbm.xml
HHH000221: Reading mappings from resource: com/apress/hibernaterecipes/chapter1/model/Publisher.hbm.xml
HHH000041: Configured SessionFactory: null
HHH000402: Using Hibernate built-in connection pool (not for production use!)
HHH000401: using driver [org.hsqldb.jdbcDriver] at URL [jdbc:hsqldb:file:./chapter1;write_delay=false]
HHH000046: Connection properties: {}
HHH000006: Autocommit mode: false
HHH000115: Hibernate connection pool size: 20 (min=1)
HHH000400: Using dialect: org.hibernate.dialect.HSQLDialect
HHH000399: Using default transaction strategy (direct JDBC transactions)
HHH000397: Using ASTQueryTranslatorFactory
HHH000227: Running hbm2ddl schema export
HHH000230: Schema export complete Session Metrics {
14000 nanoseconds spent acquiring 1 JDBC connections; 0 nanoseconds spent releasing 0 JDBC connections; 2445000 nanoseconds spent preparing 2 JDBC statements; 1636000 nanoseconds spent executing 2 JDBC statements; 0 nanoseconds spent executing 0 JDBC batches; 0 nanoseconds spent performing 0 L2C puts; 0 nanoseconds spent performing 0 L2C hits; 0 nanoseconds spent performing 0 L2C misses; 0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections); 59000 nanoseconds spent executing 2 partial-flushes (flushing a total of 0 entities and 0 collections) } getEntityCount- 1 openCount- 2 getEntityInsertCount- 1 HHH000161: Logging statistics....
HHH000251: Start time: 1408349026472 HHH000242: Sessions opened: 2
HHH000241: Sessions closed: 1 HHH000266: Transactions: 2
HHH000258: Successful transactions: 2
HHH000187: Optimistic lock failures: 0
HHH000105: Flushes: 1
HHH000048: Connections obtained: 2
HHH000253: Statements prepared: 3
HHH000252: Statements closed: 0
HHH000239: Second level cache puts: 0
HHH000237: Second level cache hits: 0
HHH000238: Second level cache misses: 0
HHH000079: Entities loaded: 0
HHH000080: Entities updated: 0
HHH000078: Entities inserted: 1
HHH000076: Entities deleted: 0
HHH000077: Entities fetched (minimize this): 0
HHH000033: Collections loaded: 0
HHH000036: Collections updated: 0
HHH000035: Collections removed: 0
HHH000034: Collections recreated: 0
HHH000032: Collections fetched (minimize this): 0
HHH000438: NaturalId cache puts: 0
HHH000439: NaturalId cache hits: 0 HHH000440: NaturalId cache misses: 0
HHH000441: Max NaturalId query time: 0ms
HHH000442: NaturalId queries executed to database: 0
HHH000210: Queries executed to database: 0
HHH000215: Query cache puts: 0 HHH000433: update timestamps cache puts: 0
HHH000434: update timestamps cache hits: 0
HHH000435: update timestamps cache misses: 0
HHH000213: Query cache hits: 0
HHH000214: Query cache misses: 0
HHH000173: Max query time: 0ms Session Metrics { 5000 nanoseconds spent acquiring 1 JDBC connections; 0 nanoseconds spent releasing 0 JDBC connections; 262000 nanoseconds spent preparing 1 JDBC statements; 828000 nanoseconds spent executing 1 JDBC statements; 0 nanoseconds spent executing 0 JDBC batches; 0 nanoseconds spent performing 0 L2C puts; 0 nanoseconds spent performing 0 L2C hits; 0 nanoseconds spent performing 0 L2C misses; 8131000 nanoseconds spent executing 1 flushes (flushing a total of 1 entities and 0 collections); 0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections) }