這篇文章描述了我最近使用Hibernate ORM的經(jīng)驗(yàn)。 多年以來(lái)，該框架并沒(méi)有讓我感到驚訝，您可能會(huì)在使用它時(shí)遇到性能問(wèn)題。 我以為我已經(jīng)看完了，但是這次我又措手不及了。

該問(wèn)題的基礎(chǔ)是在對(duì)一個(gè)完全不相關(guān)的庫(kù)進(jìn)行故障排除時(shí)建立的，該庫(kù)導(dǎo)致我們的生產(chǎn)服務(wù)器之一出現(xiàn)問(wèn)題。 為了收集有關(guān)手頭原始問(wèn)題的更多見(jiàn)解，我們?cè)黾恿薼ogback配置中的詳細(xì)信息。

因此，產(chǎn)生以下描述的效果所需要的只是org。*軟件包從ERROR到WARN的日志冗長(zhǎng)更改。 進(jìn)行必要的測(cè)試后，我們從日志中收集了信息，卻忘記了改回日志級(jí)別。

在日志配置傳播到生產(chǎn)后不久，問(wèn)題就在第二天開(kāi)始暴露出來(lái)。 突然之間，我們的監(jiān)視開(kāi)始報(bào)告左右生產(chǎn)中的問(wèn)題。 當(dāng)我們吃自己的狗食并使用Plumbr Performance Monitoring解決方案監(jiān)視我們自己的服務(wù)時(shí)，我們收到的信息是，發(fā)布給最終用戶的某些服務(wù)面臨著與延遲相關(guān)的問(wèn)題。

檢查公開(kāi)的信息后，很明顯一切似乎都受到了影響。 這次不是整個(gè)性能較差的代碼位于單個(gè)服務(wù)/模塊中的更典型的情況，而是整個(gè)JVM似乎行為異常。 此外，似乎對(duì)于99％的事務(wù)，延遲幾乎沒(méi)有受到影響，但是幾乎所有服務(wù)的最壞情況下的延遲都已經(jīng)消失了。

對(duì)我們來(lái)說(shuō)幸運(yùn)的是，問(wèn)題的根源正盯著我們。 Plumbr檢測(cè)到的根本原因列表已將罪魁禍?zhǔn)妆┞督o源代碼中的一行。 我們面臨的是成千上萬(wàn)的調(diào)用，它們正在JDBC上執(zhí)行SHOW WARNINGS語(yǔ)句。

此外，Plumbr根本原因檢測(cè)還向我們暴露了進(jìn)行調(diào)用的調(diào)用堆棧：

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

有了調(diào)用堆棧，我們直接進(jìn)入了休眠狀態(tài)。 顯然，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 }

在這里，我們有罪魁禍?zhǔn)?#xff0c;正視著我們。 對(duì)日志配置的更改已啟用了Hibernate模塊的WARN級(jí)別日志記錄。 反過(guò)來(lái)，這導(dǎo)致對(duì)數(shù)據(jù)庫(kù)的每次訪問(wèn)都執(zhí)行重復(fù)的SQL查詢“ SHOW WARNINGS ”，實(shí)際上使對(duì)數(shù)據(jù)庫(kù)的JDBC調(diào)用次數(shù)增加了一倍。

根據(jù)Google的說(shuō)法， 這個(gè)問(wèn)題相當(dāng)普遍。 這是Hibernate作者的合理設(shè)計(jì)嗎？ 一方面，該功能確實(shí)有用：如果您的JDBC訪問(wèn)已生成任何警告，則可能希望公開(kāi)此信息。 乍一看，當(dāng)前的實(shí)現(xiàn)絕對(duì)是合乎邏輯的：配置是否要查看一些警告，然后配置日志記錄框架。

似乎毫無(wú)意義的是系統(tǒng)絕對(duì)不相關(guān)的方面（日志記錄和數(shù)據(jù)庫(kù)性能）之間的高度凝聚力。 配置日志記錄會(huì)導(dǎo)致數(shù)據(jù)庫(kù)調(diào)用數(shù)量增加一倍？ 完全出乎意料的蝴蝶效果。 如果沒(méi)有正確的工具，則可以對(duì)增加的數(shù)據(jù)庫(kù)負(fù)載進(jìn)行故障排除，很幸運(yùn)。 這次，我們?cè)?0分鐘內(nèi)修補(bǔ)了該問(wèn)題，然后繼續(xù)進(jìn)行工作，但是我只能想象，如果沒(méi)有適當(dāng)?shù)谋O(jiān)控工具來(lái)進(jìn)行故障排除，需要花費(fèi)多長(zhǎng)時(shí)間。

翻譯自: https://www.javacodegeeks.com/2016/01/how-we-accidentally-doubled-our-jdbc-traffic-with-hibernate.html

總結(jié)

以上是生活随笔為你收集整理的我们如何意外地将Hibernate的JDBC流量增加了一倍的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問(wèn)題。

如果覺(jué)得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。