排查Hibernate的慢查询日志–这是查找慢查询的最简单方法

分析运行缓慢的应用程序时，常见的问题之一是是否存在运行缓慢的数据库查询。当然，您可以监视数据库中的这些查询。但是随后，您仍然需要将它们与Java代码的一部分进行匹配。而且，由于没有简单的方法可以查看特定查询之前或之后立即发生的情况，因此这会比原先花费更多的精力。从Hibernate 5.4.5开始，您还可以从Hibernate的慢速查询日志中获取此信息。将其集成到您的应用程序日志中可以使您的分析容易得多。

正如我在日志记录指南中解释的那样，您应该使用2种不同的日志记录配置。一种用于生产的系统，可将开销保持在尽可能低的水平。一个用于开发的程序可以为您提供有关您的应用程序的尽可能多的信息。Hibernate的慢速查询日志应该是开发配置的一部分，并且您应该根据测试数据库的大小来调整其设置。该数据库越小，慢查询日志的阈值应越低。

开启Hibernate的慢查询日志

您可以通过2个步骤在配置中开启慢查询日志：

您需要配置阈值，高于该阈值，Hibernate会将查询视为慢速查询。
Hibernate的日志记录配置需要包括慢查询消息。

配置慢查询阈值

查询是否慢的决定取决于许多不同的因素，例如应用程序的性能要求，数据库的大小，部署方案以及可用资源。您需要为特定的应用程序和测试方案定义此阈值。

使用Hibernate的慢速查询日志，可以使用hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS属性定义此阈值。

如果您使用的是普通的Hibernate，则可以在persistence.xml配置中设置此属性。

<persistence>
    <persistence-unit name="my-persistence-unit">
        ...

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

            ...
        </properties>
    </persistence-unit>
</persistence>

对于Spring Boot应用程序，可以通过在属性名称中添加前缀spring.jpa.properties来在application.properties文件中进行设置。

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

注意： Hibernate将此阈值应用于查询的纯执行时间。这不包括任何Hibernate的准备或结果处理步骤，并且比Hibernate统计信息中所报告的时间要短！

激活记录

定义慢查询的阈值后，Hibernate将为每个查询写一条日志消息，该消息花费的时间超过指定的阈值。它将此消息以INFO级别写入类别org.hibernate.SQL_SLOW。因此，请确保相应地配置您的日志记录。

org.hibernate.SQL_SLOW=info

示例

Hibernate支持所有类型查询的慢查询日志。这包括JPQL语句，Criteria API，本机查询以及由EntityManager的方法触发的查询。

在下面的代码片段中，我使用前面讨论的配置，并执行一个本机SQL查询，该查询从数据库中选择所有Author实体。

EntityManager em = emf.createEntityManager();
em.getTransaction().begin();

Query q = em.createNativeQuery("SELECT * FROM Author a", Author.class);
q.getSingleResult();

em.getTransaction().commit();
em.close();

如果数据库花费的时间超过配置的阈值，则Hibernate将以下消息写入日志文件。

18:06:52,204 INFO  [org.hibernate.SQL_SLOW] - SlowQuery: 26 milliseconds. SQL: 'SELECT * FROM Author a'
18:06:52,221 DEBUG [org.hibernate.stat.internal.StatisticsImpl] - HHH000117: HQL: SELECT * FROM Author a, time: 47ms, rows: 100

第一行是慢查询日志的一部分。如您所见，数据库花了26毫秒来执行此查询。在第二行中，您可以看到来自Hibernate统计信息组件的消息。Hibernate报告执行时间为47ms，几乎是其两倍。这是因为慢速查询日志仅考虑查询的纯执行时间，而Hibernate统计信息所测量的时间也包括结果处理。

结论

如您所见，您可以轻松地在配置中激活Hibernate的慢查询日志。然后，Hibernate测量数据库处理每个查询所花的时间。对于每个比配置的阈值慢的查询，Hibernate都会向日志文件中写入一条消息。

此日志配置对于识别应用程序中缓慢的数据库查询非常有帮助。但是请记住，缓慢的查询日志仅会测量数据库的纯执行时间。Hibernate处理结果所花费的时间不包括在内，但会对查询的整体性能产生巨大影响。