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

Question

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

我正在使用带有 Hibernate 的 Spring，通过 applicationContext.xml Spring 配置文件进行配置。

Answer 1

休眠 5.4

这个慢查询日志功能从 Hibernate ORM 5.4.5 开始可用，并在给定 JPQL、Criteria API 或本机 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
    ]'

检测慢速原生 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
    ]'

在我们的案例中，应用程序查询类型不会影响慢查询日志，因为 JPQL 和 Criteria API 生成的 SQL 查询类似于我们在上一个测试案例中使用的原生 SQL 查询。

Answer 2

我有 2 条建议：

• 您可以使用 Oracle 的 Statspack。
• 您可以使用某种 JDBC 代理驱动程序记录执行时间 P6Spy 或 log4jdbc。

我过去使用过来自 IronGrid 的 P6Spy 和 IronTrack SQL，这是一个不错的组合（请参阅 this blog post）。但请注意：

• P6Spy 并没有真正得到维护（5 年没有变化）。
• 测量值并不完全准确（在追逐贪婪的猪时这不是一个大问题）。
• IronTrack SQL 似乎不再可用（但您仍然可以找到它，例如here）。

我现在个人使用log4jdbc，它提供了类似的功能（没有花哨的 GUI，但谁在乎，可以使用 Excel 或他们提供的脚本来生成报告）。来自其网站：

特点

• 完全支持 JDBC 3 和 JDBC 4！
• 易于配置，在大多数情况下，您只需更改驱动程序即可 类名 net.sf.log4jdbc.DriverSpy 和前置 "jdbc:log4" 到您现有的 jdbc url， 设置您的日志记录类别和 你准备好了！
• 在记录的输出中，对于准备好的语句，绑定参数是 自动插入到 SQL 输出。这大大提高了 许多人的可读性和调试 案例。
• 可以生成 SQL 计时信息，以帮助确定多长时间 SQL 语句需要运行，有助于 识别正在运行的语句 太慢了，这个数据可以发布 使用附带的工具进行处理 生成分析报告数据 快速识别你的慢 SQL 应用程序。
• 生成SQL连接号信息，帮助识别连接 池或线程问题。
• 适用于任何底层 JDBC 驱动程序、JDK 1.4 及更高版本，以及 SLF4J 1.x.
• 开源软件，在商业友好的 Apache 2.0 下获得许可 执照： http://www.apache.org/licenses/LICENSE-2.0

Answer 3

您可以通过将 hibernate.show_sql 属性设置为 true 来启用 hibernate 中所有 SQL 的日志记录（请参阅http://www.javalobby.org/java/forums/t44119.html）。但是，无法过滤以仅查看慢查询。但是，如果您使用的是 mysql，您可以启用它的慢查询日志并在那里查看比设置阈值慢的查询。

见：http://adminlinux.blogspot.com/2009/07/mysql-slow-queries-log.html

我相信大多数其他数据库都会提供类似的功能。

Answer 4

这是added natively in Hibernate 5.4.5.Final。配置参数可在AvailableSettings.LOG_SLOW_QUERY获取。

描述是：

设置执行比指定慢的日志查询 毫秒。默认值为 0（禁用）。