Technology: Hibernate is most used framework for database related activities, using this database interaction will easily and quickly develop the application.
But if we get an exception and error in data either reading/inserting/updating/deleting the data from database we need to add some debugger logs, or we can enable hibernate logging so that we can easily know hibernate generated statement and parameters, what framework is passing to a database.
Hibernate provides different logging levels to log the statement.
Logging SQL: It is the basic level of debugging, we can log the Hibernate generated SQL statement, without actual parameter values.
Hibernate uses the category org.hibernate.SQL to log this information, so we can set the logger level to DEBUG for this package, so that generated statement will be logged.
Configuration for log4J:
<logger name="org.hibernate.SQL">
<level value="debug"/>
</logger>
Add these configuration either log4j.xml of log4j configuration file.
If we are using log4j2 then add the below in logger configuration:
<logger name="org.hibernate.SQL"value="debug"/>
If we are using logback, then add below line to configuration:
<logger name="org.hibernate.SQL"value="DEBUG"/>
And the generated SQL log will look like below:
2019-12-07 23:04:23 | DEBUG | [main] o.h.SQL:127 - insert into Employee (employeeNumber, name, title, id) values (?,?,?,?)
2019-12-07 23:04:23 | DEBUG | [main] o.h.SQL:127 - select employee0_.id as id1_0_, employee0_.employeeNumber as employee2_0_, employee0_.name as name3_0_, employee0_.title as title4_0_ from Employee employee0_
Using this information we only know the generated SQL statements, but it will not contain any parameter information.
Logging SQL Parameter Values: using the above approach, we know the generated SQL statement, in most cases, it is enough the understand the problem, but in some cases, we also need the parameters to understand the problem.
Hibernate logs the input parameters and retrieved results using the org.hibernate.type.descriptor.sql category with a log level of TRACE.
Log4j Configuration:
<loggername="org.hibernate.type.descriptor.sql">
<level value="trace"/>
</logger
Log4j2 Configuration:
<logger name="org.hibernate.type.descriptor.sql"level="trace"/>
Logback Configuration:
<logger name="org.hibernate.type.descriptor.sql"level="TRACE"/>
After adding these logging levels below logging will add logger output:
2019-12-07 23:04:23 | DEBUG | [main] o.h.SQL:127 - insert into Employee (employeeNumber, name, title, id) values (?, ?, ?, ?)
2019-12-07 23:04:23 | TRACE | [main] o.h.t.d.s.BasicBinder:64 - binding parameter [1] as [VARCHAR] - [001]
2019-12-07 23:04:23 | TRACE | [main] o.h.t.d.s.BasicBinder:64 - binding parameter [2] as [VARCHAR] - [John Smith]
2019-12-07 23:04:23 | TRACE | [main] o.h.t.d.s.BasicBinder:52 - binding parameter [3] as [VARCHAR] - [null]
2019-12-07 23:04:23 | TRACE | [main] o.h.t.d.s.BasicBinder:64 - binding parameter [4] as [BIGINT] - [1]
2019-12-07 23:04:23 | DEBUG | [main] o.h.SQL:127 - select employee0_.id as id1_0_, employee0_.employeeNumber as employee2_0_, employee0_.name as name3_0_, employee0_.title as title4_0_ from Employee employee0_
2019-12-07 23:04:23 | TRACE | [main] o.h.t.d.s.BasicExtractor:60 - extracted value ([id1_0_] : [BIGINT]) - [1]
2019-12-07 23:04:23 | TRACE | [main] o.h.t.d.s.BasicExtractor:60 - extracted value ([employee2_0_] : [VARCHAR]) - [001]
2019-12-07 23:04:23 | TRACE | [main] o.h.t.d.s.BasicExtractor:60 - extracted value ([name3_0_] : [VARCHAR]) - [John Smith]
2019-12-07 23:04:23 | TRACE | [main] o.h.t.d.s.BasicExtractor:50 - extracted value ([title4_0_] : [VARCHAR]) - [null]
As we see it will not only the parameters but it also logs the binding parameters, so we can enable and disable the previous logging level independent of this logging level.
Logging All Activity: To understand the problem even deeper, we can enable the whole hibernate logging to debug, to all activities.
Log4j Configuration:
<logger name="org.hibernate.type.descriptor.sql">
<level value="trace"/>
</logger>
Log4j2 Configuration:
<logger name="org.hibernate.type.descriptor.sql" value="trace"/>
Logback Configuration:
<logger name="org.hibernate.type.descriptor.sql" value="TRACE"/>
Hibernate Statistics: Apart from SQL and JDBC parameter values, Hibernate also logs the statistics, which will be useful for understanding the performance issues.
Hibernate uses the category org.hibernate.stat to log this information. But, Hibernate does not always generate these statistics because it can have a bad influence on the performance.
Hibernate provides one configuration property to specify the statistics logging.
true
Using this property hibernate will log all statistics for each SQL query.
2019-12-07 23:25:18 | DEBUG | [main] o.h.s.i.StatisticsInitiator:101 - Statistics initialized
[enabled=true]
2019-12-07 23:25:19 | DEBUG | [main] o.h.s.i.StatisticsImpl:729 - HHH000117: HQL:
from com.baeldung.hibernate.logging.Employee, time: 22ms, rows: 1
2019-12-07 23:25:19 | INFO | [main] o.h.e.i.StatisticalLoggingSessionEventListener:258 -
Session Metrics {
55600 nanoseconds spent acquiring 1 JDBC connections;
178600 nanoseconds spent releasing 1 JDBC connections;
2167200 nanoseconds spent preparing 2 JDBC statements;
2426800 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;
47098900 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)
}
Using these statistics we can easily analyze which query is taking more to execute and we can provide the solution based on this.
Conclusion: In the current tutorial we learned the different logging levels for Hibernate, how can a Java developer debug the exception/errors in data which executing the SQL statements. And finally, we learned the Hibernate statistics which are useful in understanding the time duration for each individual SQL query.
Top comments (0)