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

问题描述

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

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

解决方法：

我有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网址，设置您的日志记录类别并您准备好了！

在记录的输出中，对于准备好的语句，绑定参数为自动插入SQL输出。这大大改善了许多人的可读性和调试案例。

SQL时序信息可以生成，以帮助识别需要多长时间SQL语句可以运行，有助于识别正在运行的语句太慢了，可以发布这些数据用附带的工具处理产生分析报告数据快速识别您的慢速SQL应用]]。

SQL连接号信息将生成以帮助识别连接池或线程问题。

与任何具有JDK 1.4及更高版本的基础JDBC驱动程序一起使用，以及SLF4J 1.x。

开源软件，根据商业友好型Apache 2.0获得许可执照：http://www.apache.org/licenses/LICENSE-2.0

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

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

我确定大多数其他数据库都将提供类似的功能。

这是一个非常常见的问题，所以我决定将此答案转换为full-blown article。

休眠5.4

此慢查询日志功能自Hibernate ORM 5.4.5开始提供，并在给定JPQL，Criteria API或本机SQL查询的执行时间超过您先前配置的某个阈值时通知您。

配置

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

在我们的情况下，任何花费超过25毫秒的查询都会触发Hibernate慢速查询日志。

Spring Boot配置

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

hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS=25
Java EE配置
如果使用的是Java EE，则可以在persistence.xml配置文件中进行设置：
记录器配置
您还需要将org.hibernate.SQL_SLOW记录器设置为至少INFO级别。
如果使用的是Logback，则可以如下设置：
就是这样！
测试时间
假设我们在应用程序中定义了以下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 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 postQuery = builder
    .createQuery(Post.class);

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