我们如何意外地将Hibernate的JDBC流量增加了一倍

这篇文章描述了我最近使用Hibernate ORM的经验。多年以来，该框架并没有让我感到惊讶，您可能会在使用它时遇到性能问题。我以为我已经看完了，但是这次我又措手不及了。

该问题的基础是在对一个完全不相关的库进行故障排除时建立的，该库导致我们的生产服务器之一出现问题。为了收集有关手头原始问题的更多见解，我们增加了logback配置中的详细信息。

因此，产生以下描述的效果所需要的只是org。*软件包从ERROR到WARN的日志冗长更改。进行必要的测试后，我们从日志中收集了信息，却忘记了改回日志级别。

在日志配置传播到生产后不久，问题就在第二天开始暴露出来。突然之间，我们的监视开始报告左右生产中的问题。当我们吃自己的狗食并使用Plumbr Performance Monitoring解决方案监视我们自己的服务时，我们收到的信息是，发布给最终用户的某些服务面临着与延迟相关的问题。

检查公开的信息后，很明显一切似乎都受到了影响。这次不是整个性能较差的代码位于单个服务/模块中的更典型的情况，而是整个JVM似乎行为异常。此外，似乎对于99％的事务，延迟几乎没有受到影响，但是几乎所有服务的最坏情况下的延迟都已经消失了。

对我们来说幸运的是，问题的根源正盯着我们。 Plumbr检测到的根本原因列表已将罪魁祸首暴露给源代码中的一行。我们面临的是成千上万的调用，它们正在JDBC上执行SHOW WARNINGS语句。

此外，Plumbr根本原因检测还向我们暴露了进行调用的调用堆栈：

com.mysql.jdbc.StatementImpl.executeQuery():1500
com.mysql.jdbc.SQLError.convertShowWarningsToSQLWarnings():714
com.mysql.jdbc.SQLError.convertShowWarningsToSQLWarnings():666
com.mysql.jdbc.StatementImpl.getWarnings():2299
com.zaxxer.hikari.pool.HikariProxyPreparedStatement.getWarnings():N/A
org.hibernate.engine.jdbc.spi.SqlExceptionHelper.handleAndClearWarnings():320
org.hibernate.engine.jdbc.spi.SqlExceptionHelper.logAndClearWarnings():273
org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.close():529
... cut for brevity ...
org.hibernate.jpa.spi.AbstractEntityManagerImpl.merge():1196
sun.reflect.GeneratedMethodAccessor.invoke():N/A
sun.reflect.DelegatingMethodAccessorImpl.invoke():43
java.lang.reflect.Method.invoke():606
org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke():293
com.sun.proxy.$Proxy.merge():N/A
eu.plumbr.portal.service.ServiceDao.save():21

有了调用堆栈，我们直接进入了休眠状态。显然，Hibernate在SqlExceptionHelper.handeAndClearWarnings（）方法中包含以下代码：

public void handleAndClearWarnings(Statement statement, WarningHandler handler) {// See HHH-9174.  Statement#getWarnings can be an expensive call for many JDBC libs.  Don't do it unless// the log level would actually allow a warning to be logged.if (LOG.isEnabled(Level.WARN)) {try {walkWarnings( statement.getWarnings(), handler );}catch (SQLException sqlException) {// cut for brevity}//cut for brevity
}

在这里，我们有罪魁祸首，正视着我们。对日志配置的更改已启用了Hibernate模块的WARN级别日志记录。反过来，这导致对数据库的每次访问都执行重复的SQL查询“ SHOW WARNINGS ”，实际上使对数据库的JDBC调用次数增加了一倍。

根据Google的说法，这个问题相当普遍。这是Hibernate作者的合理设计吗？一方面，该功能确实有用：如果您的JDBC访问已生成任何警告，则可能希望公开此信息。乍一看，当前的实现绝对是合乎逻辑的：配置是否要查看一些警告，然后配置日志记录框架。

似乎毫无意义的是系统绝对不相关的方面（日志记录和数据库性能）之间的高度凝聚力。配置日志记录会导致数据库调用数量增加一倍？完全出乎意料的蝴蝶效果。如果没有正确的工具，则可以对增加的数据库负载进行故障排除，很幸运。这次，我们在20分钟内修补了该问题，然后继续进行工作，但是我只能想象，如果没有适当的监控工具来进行故障排除，需要花费多长时间。