Hibernate slow query log

栏目: IT技术 · 发布时间: 4年前

内容简介:In this article, I’m going to show you how you can activate the slow query log when using JPA and Hibernate.This slow query log feature has been available sinceLet’s consider we have the following
Last modified:

Imagine having a tool that can automatically detect if you are using JPA and Hibernate properly. Hypersistence Optimizer is that tool!

Introduction

In this article, I’m going to show you how you can activate the slow query log when using JPA and Hibernate.

This slow query log feature has been available since Hibernate ORM 5.4.5 and notifies you when the execution time of a given JPQL, Criteria API or native SQL query exceeds a certain threshold value you have previously configured.

Domain Model

Let’s consider we have the following Post entity class in our application:

Hibernate slow query log

The Post entity is mapped as follows:

@Entity(name = "Post")
@Table(name = "post")
public class Post {

    @Id
    private Long id;

    private String title;

    @Column(name = "created_on")
    @CreationTimestamp
    private Date createdOn;

    @Column(name = "created_by")
    private String createdBy;

    //Getters and setters omitted for brevity
}

We are going to persist 5000 Post entities so that we have enough data to generate queries that take more than 25 milliseconds:

LongStream
.rangeClosed(1, 5000)
.forEach(i -> {
    entityManager.persist(
        new Post()
        .setId(i)
        .setTitle(
            String.format(
                "High-Performance Java Persistence book - page %d review",
                i
            )
        )
        .setCreatedBy("Vlad Mihalcea")
    );
    
    if(i % 50 == 0 && i > 0) {
        entityManager.flush();
    }
});

Hibernate slow query log

In order to activate the Hibernate slow query log, you need to set the hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS property to a value that’s greater than 0 , representing the query execution threshold.

In our case, any query that takes more than 25 milliseconds will trigger the Hibernate slow query log.

If you’re using Spring Boot, you can set this Hibernate setting in the application.properties configuration file:

hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS=25

If you’re using Java EE, you can set it via the persistence.xml configuration file:

<property 
    name="hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS" 
    value="25"
/>

And, Hibernate will log all SQL queries that took more than 25 milliseconds to be executed. In order to see the slow query log entry, you need to make sure you have the following logger name set to at least the info level:

<logger name="org.hibernate.SQL_SLOW" level="info"/>

How does the Hibernate slow query log work?

To see how the Hibernate slow query log works, we can check the Hibernate org.hibernate.engine.jdbc.internal.ResultSetReturnImpl class which is used for all SQL query executions:

@Override
public ResultSet extract(
        Statement statement, String sql) {
        
    sqlStatementLogger.logStatement(sql);
    
    long executeStart = 0;
    if (this.sqlStatementLogger.getLogSlowQuery() > 0) {
        executeStart = System.currentTimeMillis();
    }
    
    try {
        final ResultSet rs;
        try {
            jdbcExecuteStatementStart();
            rs = statement.executeQuery(sql);
        }
        finally {
            jdbcExecuteStatementEnd();
            sqlStatementLogger.logSlowQuery( 
                sql, 
                executeStart 
            );
        }
        postExtract(rs, statement);
        return rs;
    }
    catch (SQLException e) {
        throw sqlExceptionHelper.convert( 
            e, 
            "could not extract ResultSet" 
        );
    }
}

So, the Hibernate slow query log validates the underlying SQL query execution without taking into account how the ResultSet is transformed into entities, DTOs, Tuple instances, or the default Object[] array.

Testing time

Next, we are going to check how the SQl query logs work for both entity queries and native SQL statements.

JPQL queries

When executing the following JPQL query:

List<Post> posts = entityManager
.createQuery(
    "select p " +
    "from Post p " +
    "where lower(title) like :titlePattern " +
    "order by p.createdOn desc", Post.class)
.setParameter(
    "titlePattern", 
    "%Java%book%review%".toLowerCase()
)
.setFirstResult(1000)
.setMaxResults(100)
.getResultList();

Hibernate generates the following slow query log entry:

o.h.SQL_SLOW - 
    SlowQuery: 32 milliseconds. 
    SQL: 
    'PgPreparedStatement [
        select 
            p.id as id1_0_, 
            p.created_by as created_2_0_, 
            p.created_on as created_3_0_, 
            p.title as title4_0_ 
        from 
            post p 
        where lower(p.title) like '%java%book%review%' 
        order by p.created_on desc 
        limit 100 
        offset 1000
    ]'

So, it works!

The slow query threshold was set to 25 milliseconds, and, since the above SQL query took more than that, Hibernate added a slow query log entry.

 Notice that the log entry was formatted on multiple lines to increase readability for this article. However, by default, there will be a single line of text containing the slow query log entry. 

Criteria API queries

When executing this Criteria API query:

CriteriaBuilder builder = entityManager
    .getCriteriaBuilder();

CriteriaQuery<Post> postQuery = builder
    .createQuery(Post.class);
    
Root<Post> post = postQuery.from(Post.class);

postQuery
    .where(
        builder.like(
            builder.lower(post.get("title")), 
            "%Java%book%review%".toLowerCase()
        )
    )
    .orderBy(
        builder.desc(post.get("createdOn"))
    );

List<Post> posts = entityManager.createQuery(
    postQuery
)
.setFirstResult(1000)
.setMaxResults(100)
.getResultList();

Hibernate generates a slow query log entry, like this one:

o.h.SQL_SLOW - 
    SlowQuery: 27 milliseconds. 
    SQL: 'PgPreparedStatement [
        select 
            p.id as id1_0_, 
            p.created_by as created_2_0_, 
            p.created_on as created_3_0_, 
            p.title as title4_0_ 
        from 
            post p 
        where 
            lower(p.title) like '%java%book%review%' 
        order by p.created_on desc 
        limit 100 
        offset 1000
    ]'

Writing Criteria API queries is not very straightforward. That’s why it’s a good idea to use the Codota IDE plugin to help you with this task. Check outthis article for more details about this topic.

Native SQL queries

When executing the native SQL query equivalent to the previous JPQL and Criteria API queries:

List<Post> posts = entityManager
.createNativeQuery(
    "SELECT p.* " +
    "FROM post p " +
    "WHERE LOWER(p.title) LIKE :titlePattern " +
    "ORDER BY p.created_on DESC", Post.class)
.setParameter(
    "titlePattern", 
    "%Java%book%review%".toLowerCase()
)
.setFirstResult(1000)
.setMaxResults(100)
.getResultList();

We get a slow query log message written by Hibernate:

o.h.SQL_SLOW - 
    SlowQuery: 27 milliseconds. 
    SQL: 'PgPreparedStatement [
        SELECT 
            p.* 
        FROM post 
            p 
        WHERE 
            LOWER(p.title) LIKE '%java%book%review%' 
        ORDER BY p.created_on DESC 
        LIMIT 100 
        OFFSET 1000
    ]'

In our case, the application query type doesn’t influence the slow query log since both JPQL and Criteria API generate SQL queries that are similar to the native SQL one we used in the last test case.

If you enjoyed this article, I bet you are going to love my Book and Video Courses as well.

Hibernate slow query log Hibernate slow query log

Conclusion

The Hibernate 5.4 slow query log is a very nice feature since it allows you to correlate slow queries with the application-specific business methods that were executing at that particular time.

Hypersistence Optimizer is also going to add support for slow queries , and it will consider the entity query parsing as well as the ResultSet transformation, so stay tuned for an awesome alternative that’s going to be available to all Hibernate versions since 3.3.


以上所述就是小编给大家介绍的《Hibernate slow query log》,希望对大家有所帮助,如果大家有任何疑问请给我留言,小编会及时回复大家的。在此也非常感谢大家对 码农网 的支持!

查看所有标签

猜你喜欢:

本站部分资源来源于网络,本站转载出于传递更多信息之目的,版权归原作者或者来源机构所有,如转载稿涉及版权问题,请联系我们

Thirty-three Miniatures

Thirty-three Miniatures

Jiří Matoušek / American Mathematical Socity / 2010-6-18 / USD 24.60

This volume contains a collection of clever mathematical applications of linear algebra, mainly in combinatorics, geometry, and algorithms. Each chapter covers a single main result with motivation and......一起来看看 《Thirty-three Miniatures》 这本书的介绍吧!

JSON 在线解析
JSON 在线解析

在线 JSON 格式化工具

UNIX 时间戳转换
UNIX 时间戳转换

UNIX 时间戳转换

RGB CMYK 转换工具
RGB CMYK 转换工具

RGB CMYK 互转工具