java - 如何监控 JPA 和 Hibernate 执行的慢 SQL 查询

Question

我可以设置任何 Hibernate 属性来查看所有慢速查询吗？我'，对返回结果集花费太多时间的查询感兴趣。

我将 Spring 与 Hibernate 结合使用，通过 applicationContext.xml Spring 配置文件进行配置。

Answer 1

hibernate 5.4

此慢速查询日志功能自 Hibernate ORM 5.4.5 起可用，并会在给定 JPQL、Criteria API 或 native SQL 查询的执行时间超过您之前配置的特定阈值时通知您。

配置

为了激活 Hibernate 慢查询日志，您需要将 hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS 属性设置为大于 0 的值，表示查询执行阈值。

在我们的例子中，任何超过 25 毫秒的查询都将触发 Hibernate 慢速查询日志。

Spring Boot 配置

如果您使用的是 Spring Boot，则可以在 application.properties 配置文件中设置此 Hibernate 设置:

spring.jpa.properties.hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS=25

Java EE 配置

如果您使用的是 Java EE，则可以在 persistence.xml 配置文件中进行设置:

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

记录器配置

您还需要至少将 org.hibernate.SQL_SLOW 记录器设置为 INFO 级别。

如果你正在使用 Logback，你可以按如下方式设置它:

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

就是这样!

测试时间

假设我们在应用程序中定义了以下 Post 实体类:

Post 实体映射如下:

@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
}

我们将保留 5000 个 Post 实体，以便我们有足够的数据来生成需要超过 25 毫秒的查询:

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();
    }
});

检测慢速 JPQL 查询

执行以下 JPQL 查询时:

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 生成以下慢查询日志条目:

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
    ]'

检测缓慢的 Criteria API 查询

执行此 Criteria API 查询时:

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 生成一个慢查询日志条目，如下所示:

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
    ]'

检测慢速 native SQL 查询

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();

我们得到一条由 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.