Với Hibernate chúng ta có thể giao tiếp với cơ sở dữ liệu một cách nhanh chóng. Nhưng, vấn đề có thể làm cho việc debug các lỗi liên quan đến cơ sở dữ liệu trở nên khó khăn. Do đó, chúng ta cần công cụ có thể hữu ích để xem sự tương tác của Hibernate với cơ sở dữ liệu. Ví dụ: SQL được tạo bởi Hibernate để đọc dữ liệu từ một bảng. Để giải quyết vấn đề này, chúng ta cần logging lại SQL đã được tạo và thực thi. Hãy cùng tìm hiểu về Hibernate logging trong bài viết này nhé.
Cài đặt Log4j2
Có nhiều thư viện hỗ trợ ghi log, trong bài này chúng ta sẽ sử dụng Log4j2, một trong những library fastest về performance và có nhiều advance feature.
Mở file pom.xml và thêm các denpendency sau:
<!-- Log4j2 -->
<!-- https://mvnrepository.com/artifact/org.apache.logging.log4j/log4j-api -->
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-api</artifactId>
<version>2.13.1</version>
</dependency>
<!-- https://mvnrepository.com/artifact/org.apache.logging.log4j/log4j-core -->
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-core</artifactId>
<version>2.13.1</version>
</dependency>
<!-- https://mvnrepository.com/artifact/org.hibernate/hibernate-core -->
<dependency>
<groupId>org.hibernate</groupId>
<artifactId>hibernate-core</artifactId>
<version>5.4.7.Final</version>
</dependency>
<!-- https://mvnrepository.com/artifact/org.projectlombok/lombok -->
<dependency>
<groupId>org.projectlombok</groupId>
<artifactId>lombok</artifactId>
<version>1.18.10</version>
</dependency>
Cấu hình Log4j2
Cả 2 Framework Log4j và Logback đều hỗ trợ cấu hình logging sử dụng log4j2.xml file hoặc log4j2.properties. Trong bài này tôi sẽ hướng dẫn các bạn sử dụng log4j2.xml.
Tạo file log4j2.xml trong thư mục resource với nội dung như sau:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
<Properties>
<Property name="logFolder">logs</Property>
</Properties>
<Appenders>
<!-- Console Appender -->
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%d{yyyy-MMM-dd HH:mm:ss a} [%t] %-5level %logger{36} - %msg%n" />
</Console>
<!-- Hibernate File Appender -->
<File name="HibernateFile" fileName="${logFolder}/hibernate.log">
<PatternLayout pattern="%d{yyyy-MMM-dd HH:mm:ss a} [%t] %-5level %logger{36} - %msg%n" />
</File>
<!-- GPCoder File Appender -->
<File name="GPCoderAppFile" fileName="${logFolder}/gpcoderApp.log">
<PatternLayout pattern="%d{yyyy-MMM-dd HH:mm:ss a} [%t] %-5level %logger{36} - %msg%n" />
</File>
</Appenders>
<Loggers>
<!-- Log everything in hibernate -->
<Logger name="org.hibernate" level="info" additivity="false">
<AppenderRef ref="Console" />
<AppenderRef ref="HibernateFile" />
</Logger>
<!-- Log SQL statements -->
<Logger name="org.hibernate.SQL" level="debug" additivity="false">
<AppenderRef ref="Console" />
<AppenderRef ref="HibernateFile" />
</Logger>
<!-- Parameters which are bound to SQL statements (ie. WHERE clause) -->
<Logger name="org.hibernate.type.descriptor.sql" level="trace" additivity="false">
<AppenderRef ref="Console"/>
<AppenderRef ref="HibernateFile" />
</Logger>
<!-- Log GP Coder App statements -->
<Logger name="com.gpcoder" level="debug" additivity="false">
<AppenderRef ref="Console" />
<AppenderRef ref="GPCoderAppFile" />
</Logger>
<Root level="error">
<AppenderRef ref="Console" />
<AppenderRef ref="File" />
</Root>
</Loggers>
</Configuration>
Ý nghĩa các tham số cấu hình log4j, các bạn xem lại bài viết “Giới thiệu Java logging“.
Trong cấu hình trên, tôi tạo 2 logger:
- Tất cả các log từ org.hibernate (bao gồm SQL, descriptor SQL paramter) sẽ lưu trong file logs/hibernate.log và show ở console.
- Tất cả các log từ com.gpcoder sẽ lưu trong file logs/gpcoderApp.log và show ở console.
Các category của Hibernate Logger chúng ta có thể cấu hình:
- org.hibernate : bao gồm tất cả các log message của Hibernate. Hãy cẩn thận log này trong môi trường production, bởi vì một số lượng message sẽ được log.
- org.hibernate.SQL : câu lệnh SQL được Hibernate generate và gởi đến JDBC, chẳng hạn INSERT INTO
- org.hibernate.type.descriptor.sql : Các parameter của câu lệnh SQL, chẳng hạn WHERE id = ? . Thường kết hợp với org.hibernate.SQL để có được thông tin SQL đầy đủ.
- org.hibernate.stat : Lưu các thống kê (statistic) hoạt động của Hibernate Session.
- org.hibernate.tool.hbm2ddl : Lưu câu lệnh DDL, chẳng hạn CREATE TABLE.
- org.hibernate.cache : Thông tin về các hoạt động Hibernate second-level cache.
- org.hibernate.pretty : ghi lại trạng thái tại thời điểm flush tối đa 20 Entity cho loại log này.
- org.hibernate.hql.internal.ast.AST : Nhóm các HQL và SQL AST trong quá trình phân tích cú pháp truy vấn.
Mở file hibernate.cfg.xml:
- hibernate.show_sql=false : do đã cấu hình logger cho Hibernate SQL.
- hibernate.generate_statistics=true : hiển thị thống kê hoạt động của Hibernate Session.
<hibernate-configuration>
<session-factory>
<!-- Database setting -->
<!-- Hide SQL -->
<property name="show_sql">false</property>
<!-- Show Session Metrics -->
<property name="generate_statistics">true</property>
</session-factory>
</hibernate-configuration>
Ví dụ sử dụng Log4j2
package com.gpcoder;
import com.gpcoder.entities.Category;
import com.gpcoder.utils.HibernateUtils;
import lombok.extern.log4j.Log4j2;
import org.hibernate.Session;
import org.hibernate.SessionFactory;
@Log4j2
public class HibernateExample {
public static void main(String[] args) {
try (SessionFactory sessionFactory = HibernateUtils.getSessionFactory();
Session session = sessionFactory.openSession();) {
session.beginTransaction();
Category cat = new Category();
cat.setName("Hibernate Logging");
log.debug("Insert new category: " + cat);
session.save(cat);
session.getTransaction().commit();
}
}
}
Console output:
2020-Apr-01 21:49:39 PM [main] DEBUG com.gpcoder.HibernateExample - Insert new category: Category(id=null, name=Hibernate Logging, posts=null)
2020-Apr-01 21:49:39 PM [main] DEBUG org.hibernate.SQL - insert into Category (name) values (?)
2020-Apr-01 21:49:39 PM [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [VARCHAR] - [Hibernate Logging]
2020-Apr-01 21:49:39 PM [main] INFO org.hibernate.engine.internal.StatisticalLoggingSessionEventListener - Session Metrics {
513515 nanoseconds spent acquiring 1 JDBC connections;
306945 nanoseconds spent releasing 1 JDBC connections;
12625794 nanoseconds spent preparing 1 JDBC statements;
705225 nanoseconds spent executing 1 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
5060781 nanoseconds spent performing 2 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
5350453 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)
}
Log file:
hibernate.log
2020-Apr-01 21:49:39 PM [main] DEBUG org.hibernate.SQL - insert into Category (name) values (?)
2020-Apr-01 21:49:39 PM [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [VARCHAR] - [Hibernate Logging]
2020-Apr-01 21:49:39 PM [main] INFO org.hibernate.engine.internal.StatisticalLoggingSessionEventListener - Session Metrics {
513515 nanoseconds spent acquiring 1 JDBC connections;
306945 nanoseconds spent releasing 1 JDBC connections;
12625794 nanoseconds spent preparing 1 JDBC statements;
705225 nanoseconds spent executing 1 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
5060781 nanoseconds spent performing 2 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
5350453 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)
}
gpcoderApp.log
2020-Apr-01 21:49:39 PM [main] DEBUG com.gpcoder.HibernateExample - Insert new category: Category(id=null, name=Hibernate Logging, posts=null)
Như bạn thấy, log của chúng ta được lưu rất đầy đủ và tách biệt riêng ở 2 file: hibernate.log và gpcoderApp.log.
Better SQL logger with P6Spy
Bằng cách sử dụng P6Spy với Hibernate, chúng ta có thể ghi lại thời gian thực hiện hiện tại, tổng thời gian đã thực hiện, câu lệnh sql với biến liên kết, câu lệnh sql được thực thi, v.v.
Đầu tiên cần thêm thư viện p6spy vào file pom.xml:
<!-- https://mvnrepository.com/artifact/p6spy/p6spy -->
<dependency>
<groupId>p6spy</groupId>
<artifactId>p6spy</artifactId>
<version>3.8.7</version>
</dependency>
Tiếp theo, chúng ta cần sửa lại 2 thông số kết nối database sau:
hibernate.cfg.xml
<hibernate-configuration>
<session-factory>
<!-- Database setting -->
<!-- <property name="connection.driver_class">com.mysql.jdbc.Driver</property>-->
<!-- <property name="connection.url">jdbc:mysql://192.168.64.2:3306/gp_system?serverTimezone=UTC&useUnicode=true&characterEncoding=utf8</property>-->
<property name="connection.driver_class">com.p6spy.engine.spy.P6SpyDriver</property>
<property name="connection.url">jdbc:p6spy:mysql://192.168.64.2:3306/gp_system?serverTimezone=UTC&useUnicode=true&characterEncoding=utf8</property>
</session-factory>
</hibernate-configuration>
Cuối cùng, tạo 1 file có tên spy.properties nằm trong thư mục src/main/resources:
driverlist=com.mysql.cj.jdbc.Driver dateformat=yyyy-MMM-dd HH:mm:ss a #appender=com.p6spy.engine.spy.appender.Slf4JLogger appender=com.p6spy.engine.spy.appender.StdoutLogger #appender=com.p6spy.engine.spy.appender.FileLogger #logfile=C:/spy.log logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat customLogMessageFormat=%(currentTime) | %(executionTime) | %(category) | connection %(connectionId) | %(sqlSingleLine)
Ở đây, do mình muốn test ngay trên console, nên đã sử dụng appender là com.p6spy.engine.spy.appender.StdoutLogger. Nếu các bạn muốn ghi log ra file, có thể dùng appender com.p6spy.engine.spy.appender.FileLogger và chỉ ra đường dẫn của file log trong thuộc tính logfile.
Chi tiết các cấu hình spy.properties các bạn có thể tham khảo thêm ở P6Spy Configuration document.
Chạy lại chương trình trên, chúng ta có output như sau:
2020-Apr-01 21:52:21 PM [main] DEBUG org.hibernate.SQL - insert into Category (name) values (?)
2020-Apr-01 21:52:21 PM [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [VARCHAR] - [Hibernate Logging]
2020-Apr-01 21:52:21 PM | 0 | statement | connection 0 | insert into Category (name) values ('Hibernate Logging')
2020-Apr-01 21:52:21 PM | 0 | commit | connection 0 |
2020-Apr-01 21:52:21 PM [main] INFO org.hibernate.engine.internal.StatisticalLoggingSessionEventListener - Session Metrics {
493749 nanoseconds spent acquiring 1 JDBC connections;
266651 nanoseconds spent releasing 1 JDBC connections;
13746392 nanoseconds spent preparing 1 JDBC statements;
1334640 nanoseconds spent executing 1 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
4606268 nanoseconds spent performing 2 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
4929280 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)
}
Như bạn thấy, P6Spy giúp chúng ta log ra câu SQL đầy đủ với các tham số, thời gian thực thi, … Thư viện này đặc biệt hữu ích khi cần kiểm tra dữ liệu đã lấy chính xác hay chưa với các tham số truyền vào đầy đủ, chúng ta dễ dàng copy và thực thi SQL trực tiếp trong hệ quản trị để kiểm tra tính đúng đắn của SQL. Nhờ vậy dễ dàng debug và phát hiện lỗi dữ liệu hơn.
Bài viết đến đây là hết, hy vọng giúp ích cho các bạn!!!
Tài liệu tham khảo:
- https://gpcoder.com/5500-gioi-thieu-java-logging/
- https://logging.apache.org/log4j/2.x/manual/configuration.html
- https://thoughts-on-java.org/hibernate-logging-guide/
- https://p6spy.readthedocs.io/en/latest/install.html
- https://stackify.com/log4j2-java/