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

Question

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

我正在使用 Spring 和 Hibernate，通过applicationContext.xmlSpring 配置文件进行配置。

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至少将logger设置为该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，这是一个不错的组合（请参阅此博客文章）。但请注意：

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

我个人现在使用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