如何监视由 JPA 和 Hibernate 执行的慢 SQL 查询

休眠 5.4

此慢查询日志功能自 Hibernate ORM 5.4.5 起可用，当给定的 JPQL、Criteria API 或本机 SQL 查询的执行时间超过您之前配置的某个阈值时，它会通知您。

配置

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

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

弹簧靴配置

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

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_SLOWINFO

如果您使用的是 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 个实体，以便我们有足够的数据来生成 querie st，这需要超过 25 毫秒：Post

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

休眠会生成以下慢速查询日志条目：

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

检测慢速条件 API 查询

执行此条件 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();

休眠会生成一个缓慢的查询日志条目，如下所示：

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查询。

我有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 url之前附加“jdbc：log4”，设置日志记录类别，然后就可以开始了！
• 在记录的输出中，对于预准备语句，绑定参数会自动插入到 SQL 输出中。这大大提高了许多情况下的可读性和调试。
• 可以生成 SQL 计时信息以帮助确定 SQL 语句的运行时间，从而帮助识别运行速度太慢的语句，并且可以使用随附的工具对此数据进行后处理，以生成分析报告数据，以便快速识别应用程序中运行缓慢的 SQL。
• 生成 SQL 连接号信息以帮助识别连接池或线程问题。
• 适用于任何底层 JDBC 驱动程序、JDK 1.4 及更高版本和 SLF4J 1.x。
• 开源软件，在商业友好的Apache 2.0许可证下授权：http://www.apache.org/licenses/LICENSE-2.0