Hibernate Logging
Bài viết được sự cho phép của tác giả Giang Phan
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/
Bài viết gốc được đăng tải tại gpcoder.com
Có thể bạn quan tâm:
- Hibernate Batch processing
- Hibernate Interceptor & StatementInspector
- Sử dụng EclipseLink thay thế Hibernate trong Spring Data JPA Starter
Xem thêm Việc làm Developer hấp dẫn trên TopDev
- B BenQ RD Series – Dòng Màn Hình Lập Trình 4k+ Đầu Tiên Trên Thế Giới
- i iOS 18 có gì mới? Có nên cập nhật iOS 18 cho iPhone của bạn?
- G Gamma AI là gì? Cách tạo slide chuyên nghiệp chỉ trong vài phút
- P Power BI là gì? Vì sao doanh nghiệp nên sử dụng PBI?
- K KICC HCMC x TOPDEV – Bước đệm nâng tầm sự nghiệp cho nhân tài IT Việt Nam
- T Trello là gì? Cách sử dụng Trello để quản lý công việc
- T TOP 10 SỰ KIỆN CÔNG NGHỆ THƯỜNG NIÊN KHÔNG NÊN BỎ LỠ
- T Tìm hiểu Laptop AI – So sánh Laptop AI với Laptop thường
- M MySQL vs MS SQL Server: Phân biệt hai RDBMS phổ biến nhất
- S SearchGPT là gì? Công cụ tìm kiếm mới có thể đánh bại Google?