Этот пост описывает мой недавний опыт работы с Hibernate ORM . За прошедшие годы фреймворк не переставал удивлять меня проблемами производительности, которые могут возникнуть при его использовании. Я думал, что видел все это, но на этот раз меня снова застали врасплох.
Основа для этой проблемы была создана при устранении неполадок в совершенно не связанной библиотеке, вызывающей проблемы на одном из наших производственных серверов. Чтобы получить больше информации об исходной проблеме, мы расширили детализацию конфигурации logback .
Таким образом, все, что потребовалось для создания описанного ниже эффекта — это простое изменение многословия журнала для пакета org. * С ОШИБКИ на ПРЕДУПРЕЖДЕНИЕ . После проведения необходимых тестов мы собрали информацию из журналов и забыли изменить уровень журнала обратно.
Проблема начала проявляться на следующий день, вскоре после того, как конфигурация журнала была передана в производство. Внезапно наш мониторинг начал сообщать о проблемах производства слева и справа. Когда мы едим собственную собачью еду и контролируем свои собственные услуги с помощью решения Plumbr Performance Monitoring , нас встречает информация о том, что некоторые службы, опубликованные для конечных пользователей, сталкиваются с проблемами, связанными с задержкой.
Проверяя раскрытую информацию, стало ясно, что все, казалось, было затронуто. Вместо более типичной ситуации, когда неэффективный код локализован в одном сервисе / модуле, на этот раз казалось, что вся JVM ведет себя неправильно. Кроме того, казалось, что для 99% транзакций задержка была практически не затронута, но задержка наихудшего случая почти для каждой услуги прошла через крышу.
К счастью для нас, первопричина проблемы смотрела прямо на нас. Список первопричин, обнаруженных Plumbr, выявил виновника в одной строке исходного кода. Мы столкнулись с десятками тысяч обращений к инструкции SHOW WARNINGS , выполняемой через JDBC.
Кроме того, обнаружение первопричины Plumbr также показало нам стеки вызовов, через которые были сделаны вызовы:
|
01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
|
com.mysql.jdbc.StatementImpl.executeQuery():1500com.mysql.jdbc.SQLError.convertShowWarningsToSQLWarnings():714com.mysql.jdbc.SQLError.convertShowWarningsToSQLWarnings():666com.mysql.jdbc.StatementImpl.getWarnings():2299com.zaxxer.hikari.pool.HikariProxyPreparedStatement.getWarnings():N/Aorg.hibernate.engine.jdbc.spi.SqlExceptionHelper.handleAndClearWarnings():320org.hibernate.engine.jdbc.spi.SqlExceptionHelper.logAndClearWarnings():273org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.close():529... cut for brevity ...org.hibernate.jpa.spi.AbstractEntityManagerImpl.merge():1196sun.reflect.GeneratedMethodAccessor.invoke():N/Asun.reflect.DelegatingMethodAccessorImpl.invoke():43java.lang.reflect.Method.invoke():606org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke():293com.sun.proxy.$Proxy.merge():N/Aeu.plumbr.portal.service.ServiceDao.save():21 |
Наличие стека вызовов привело нас прямо к Hibernate. По-видимому, Hibernate содержит следующий код в методе SqlExceptionHelper.handeAndClearWarnings () :
|
01
02
03
04
05
06
07
08
09
10
11
12
|
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} |
И здесь у нас был виновник, уставившийся прямо нам в лицо. Изменение конфигурации журнала включило ведение журнала уровня WARN для модулей Hibernate. Это, в свою очередь, приводило к тому, что каждый доступ к базе данных выполнял дублирующий SQL-запрос « SHOW WARNINGS », что фактически удваивало количество вызовов JDBC к базе данных.
По словам Google, проблема довольно широко распространена. Это разумный дизайн от авторов Hibernate? С одной стороны, функциональность действительно полезна: если ваш доступ JDBC сгенерировал какие-либо предупреждения, вы можете захотеть раскрыть эту информацию. И на первый взгляд текущая реализация абсолютно логична: чтобы настроить, хотите ли вы видеть некоторые предупреждения или нет, вы настраиваете каркас ведения журналов.
Похоже, что не имеет смысла, так это высокая степень взаимосвязи между абсолютно не связанными аспектами вашей системы: ведение журнала и производительность базы данных. Конфигурирование регистрации приводит к удвоению количества вызовов БД? Совершенно неожиданный эффект бабочки во всей красе. Удачи в устранении проблем с увеличением нагрузки на БД без использования правильных инструментов. На этот раз мы исправили проблему через 20 минут и приступили к работе, но я могу только представить, сколько времени заняло бы устранение неполадок, если бы для нас не было должного контроля.
| Ссылка: | Как мы случайно удвоили наш трафик JDBC с помощью Hibernate от нашего партнера по JCG Никиты Сальникова Тарновского в блоге Plumbr Blog . |