休眠日志：常见问题的提示和解决方案

如何通过适当的日志记录解决一些最常见的Hibernate问题？

Hibernate的日志记录配置是一个重要但很少讨论的主题。正确的配置可以帮助您在开发过程中发现潜在的问题，而错误的配置则可以在生产中导致严重的性能问题。这就是我在新书《 Hibernate提示》中解释不同配置选项的原因之一： 常见的Hibernate问题有70多种解决方案 。

在本文中，我们将分享本书中最有用的2个Hibernate日志记录技巧。让我们开始吧。

1.解决最常见的Hibernate性能问题

让我们看一下本书中包含的食谱之一。它可以帮助您在开发过程中找到n + 1个选择问题。当Hibernate必须初始化实体之间的延迟获取的关联时，经常会发生此性能问题。不幸的是，在源代码中很难找到此问题，因为您只需调用映射关联的属性的getter方法，例如author.getBooks（）即可 。如果在循环访问Author实体列表的循环中执行此操作，则Hibernate必须执行1个查询以加载n个Author实体，并执行n个其他查询来初始化关联。这就是n + 1选择问题，它是最常见的性能问题之一。

您可以通过激活Hibernate的Statistics组件找到它，该组件提供了一种简单的方法来对Hibernate Session中所有已执行的查询进行计数。让我们看看它是如何完成的。

如何计算会话中已执行的查询

问题

我的一些用例很慢，似乎执行了太多查询。

如何计算在Hibernate 会话中执行的所有查询？

解

计算所有已执行查询的最简单方法是激活Hibernate的统计信息组件。然后，Hibernate收集了大量内部统计数据，并将它们作为日志消息并通过Statistics API提供。

警告：请勿在生产中使用该产品！ 收集统计信息会产生开销，从而降低您的应用程序速度。

默认情况下，Hibernate的统计信息组件处于禁用状态。您可以通过将hibernate.generate_statistics参数设置为true来激活它。您可以通过提供具有相同名称的系统属性或通过在persistence.xml文件中设置参数来执行此操作。

<persistence><persistence-unit name="my-persistence-unit"><description>Hibernate Tips</description><provider>org.hibernate.jpa.HibernatePersistenceProvider</provider><properties><property name="hibernate.generate_statistics" value="true" />…</properties></persistence-unit>
</persistence>

您有两个选项可以访问统计信息。 Hibernate可以将每个会话的最重要信息的子集写入日志文件，或者您可以通过Statistics API访问它们。

让我们先来看一下日志消息。 Hibernate在每个会话结束时会写一条类似于以下内容的日志消息。它显示了SQL语句的数量，准备和执行它们所花费的时间以及与第二级缓存的交互。

16:24:55,318 INFO [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] – Session Metrics {25659 nanoseconds spent acquiring 1 JDBC connections;22394 nanoseconds spent releasing 1 JDBC connections;1091216 nanoseconds spent preparing 12 JDBC statements;11118842 nanoseconds spent executing 12 JDBC statements;0 nanoseconds spent executing 0 JDBC batches;0 nanoseconds spent performing 0 L2C puts;0 nanoseconds spent performing 0 L2C hits;0 nanoseconds spent performing 0 L2C misses;16999942 nanoseconds spent executing 1 flushes (flushing a total of 17 entities and 17 collections);63915 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)

您还可以通过Hibernate的Statistics界面访问Statistics API。您可以从SessionFactory获取它。它提供了几种获取方法，使您可以访问比日志输出更详细的信息。

Statistics stats = sessionFactory.getStatistics();
long queryCount = stats.getQueryExecutionCount();
long collectionFetchCount = stats.getCollectionFetchCount();

源代码

在本书中，您可以找到带有可执行测试用例的项目的下载链接，其中包含可执行的测试用例。

学到更多

如果您想了解有关Hibernate日志记录功能的更多信息，请查看以下章节：

如何记录SQL语句及其参数
如何使用查询注释来识别查询

=============

计算已执行的查询可以帮助发现效率低下和避免性能问题。但这还不够。您还需要知道Hibernate执行哪些查询以及它使用哪些参数值。使用正确的日志记录配置，Hibernate会将所有这些信息写入日志。

=============

2.如何记录SQL语句及其参数

问题

您如何配置Hibernate，使其将已执行的SQL语句和已使用的绑定参数写入日志文件？

解

Hibernate使用两种不同的日志类别和日志级别来记录已执行的SQL语句及其绑定参数：

SQL语句作为DEBUG消息写入类别org.hibernate.SQL 。
绑定参数值以日志级别TRACE记录到org.hibernate.type.descriptor.sql类别中。

您可以在日志配置中相互独立地激活和停用它们。

警告：记录所有SQL查询及其绑定参数绑定会减慢您的应用程序的速度并创建巨大的日志文件。

您不应该在生产中激活这些日志消息。

以下代码段显示了一个可同时激活两者的log4j配置示例。

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{HH:mm:ss,SSS} %-5p [%c] - %m%nlog4j.rootLogger=info, stdout
# basic log level for all messages
log4j.logger.org.hibernate=info# SQL statements and parameters
log4j.logger.org.hibernate.SQL=debug
log4j.logger.org.hibernate.type.descriptor.sql=trace

然后，Hibernate将类似于以下内容的日志消息写入您的日志文件。

17:34:50,353 DEBUG [org.hibernate.SQL] - select author0_.id as id1_0_, author0_.firstName as firstNam2_0_, author0_.lastName as lastName3_0_, author0_.version as version4_0_ from Author author0_ where author0_.id=1
17:34:50,362 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([id1_0_] : [BIGINT]) - [1]
17:34:50,373 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([firstNam2_0_] : [VARCHAR]) - [Thorben]
17:34:50,373 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([lastName3_0_] : [VARCHAR]) - [Janssen]
17:34:50,374 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([version4_0_] : [INTEGER]) - [0]

代码段中的SQL语句不容易阅读。当您告诉Hibernate格式化它时，情况会好得多。

您可以通过将配置参数hibernate.format_sql设置为true来实现。您可以将其提供为系统属性，也可以在persistence.xml文件中进行设置，例如以下代码片段，或在hibernate.cfg.xml文件中进行设置。

<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<persistence><persistence-unit name="my-persistence-unit"><description>Hibernate Tips</description><provider>org.hibernate.jpa.HibernatePersistenceProvider</provider><exclude-unlisted-classes>false</exclude-unlisted-classes><properties><property name="hibernate.format_sql" value="true" />...</properties></persistence-unit>
</persistence>

下面的代码片段显示了格式化的SQL语句，它比上一条消息更易于阅读。

16:42:56,873 DEBUG [org.hibernate.SQL] -selectauthor0_.id as id1_0_,author0_.firstName as firstNam2_0_,author0_.lastName as lastName3_0_,author0_.version as version4_0_fromAuthor author0_whereauthor0_.id=?
16:42:56,926 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [1] as [BIGINT] - [1]
16:42:56,950 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([id1_0_] : [BIGINT]) - [1]
16:42:56,965 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([firstNam2_0_] : [VARCHAR]) - [Thorben]
16:42:56,965 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([lastName3_0_] : [VARCHAR]) - [Janssen]
16:42:56,966 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([version4_0_] : [INTEGER]) - [0]

源代码

在本书中，您可以找到带有可执行测试用例的项目的下载链接，其中包含可执行的测试用例。

使您的日志更好

如前所述，激活TRACE和DEBUG级别的消息并将其发送到您的日志可能会导致文件很大，甚至可能减慢您的应用程序的速度。但是，它们可能包含对于调试过程至关重要的信息，并且可以帮助在关键错误投产之前确定关键错误。

OverOps向您显示在错误之前在生产中记录的最后250个DEBUG，TRACE和INFO级别的语句，即使它们已关闭并且从未到达日志文件。它还显示任何异常，记录的错误或警告背后的变量状态，而无需依赖实际记录的信息。您可以在错误的整个调用堆栈中看到完整的源代码和变量状态，甚至在微服务和计算机上也可以看到。

探索调试生产错误的新方法。观看OverOps的现场演示。

结论

有关更多类似的食谱，请查看我的新书《 Hibernate Tips：70多种常见Hibernate问题的解决方案》。它为您提供了70多个现成的食谱，用于基本和高级映射，日志记录，Java 8支持，缓存以及静态和动态定义的查询等主题。几天之内，您可以在hibernate-tips.com上以$ 2.99的价格获得电子书，以$ 12.99的价格获得平装本。