Соединение HikariPool недоступно после длительной операции ввода-вывода для параллельного запроса

Недавно я начал получать сообщение об ошибке в своем проекте, который вызывает сторонний API, что обычно занимает 40 секунд. Похоже, что соединение с базой данных из hikaripool перехвачено родительским потоком и недоступно для других одновременных запросов.

Вот обзор реализации

Вставка в БД (бизнес-логика)
Реформа вызова (40 сек.)
Обновление БД (бизнес-логика)

Некоторые ошибки при высоком уровне параллелизма

java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30005ms.

Я попытался имитировать это локально и обнаружил, что эти ошибки такие же, как и в производстве.

Хикари Конфиги

hikari:
      maximumPoolSize: 2
      idleTimeout: 60000
      minimumIdle: 2
      maxLifetime: 120000
      leak-detection-threshold: 1000

Сервисный метод для имитации производственной логики


public void insertComment() throws InterruptedException {
        Load load =  new Load();
        load.setComment("new comment "+System.currentTimeMillis());
        repo.save(load);
        Thread.sleep(60000); // mocking restemplate long i/o
        load =  new Load();
        load.setComment("new comment "+System.currentTimeMillis());
        repo.save(load);
    }

Редактировать 1:

Теперь выполняется 3 одновременных запроса к API (2 соединения в hikari-cp + 1), вызывающих этот сервисный метод.

Трассировка стека -1

2021-01-01 22:50:01.309  WARN 6599 --- [l-1 housekeeper] com.zaxxer.hikari.pool.ProxyLeakTask     : Connection leak detection triggered for com.mysql.jdbc.JDBC4Connection@462abec3 on thread http-nio-8080-exec-1, stack trace follows

java.lang.Exception: Apparent connection leak detected
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.5.jar:na]
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:108) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:273) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:281) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:246) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:83) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:164) ~[spring-orm-5.3.2.jar:5.3.2]
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:421) ~[spring-orm-5.3.2.jar:5.3.2]
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:400) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:595) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:382) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:174) ~[spring-data-jpa-2.4.2.jar:2.4.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215) ~[spring-aop-5.3.2.jar:5.3.2]
    at com.sun.proxy.$Proxy77.save(Unknown Source) ~[na:na]
    at com.example.demo.Service.insertComment(Service.java:89) ~[classes/:na]

Трассировка стека — 2


java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30002ms.
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:695) ~[HikariCP-3.4.5.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197) ~[HikariCP-3.4.5.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162) ~[HikariCP-3.4.5.jar:na]
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.5.jar:na]
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:108) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:273) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:281) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:246) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:83) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:164) ~[spring-orm-5.3.2.jar:5.3.2]
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:421) ~[spring-orm-5.3.2.jar:5.3.2]
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:400) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:595) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:382) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:174) ~[spring-data-jpa-2.4.2.jar:2.4.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215) ~[spring-aop-5.3.2.jar:5.3.2]
    at com.sun.proxy.$Proxy77.save(Unknown Source) ~[na:na]
    at com.example.demo.Service.insertComment(Service.java:89) ~[classes/:na]

Трассировка стека -3


2021-01-01 22:50:51.411  INFO 6599 --- [nio-8080-exec-1] com.zaxxer.hikari.pool.ProxyLeakTask     : Previously reported leaked connection com.mysql.jdbc.JDBC4Connection@462abec3 on thread http-nio-8080-exec-1 was returned to the pool (unleaked)

Как справиться с этой проблемой?

ИЗМЕНИТЬ 2:

Нашел этот пост. Установка этой конфигурации spring.jpa.open-in-view=false, кажется, решает проблему. Любые сведения о том, что делает этот конфиг. Это безопасно?

pranav prashant 01.01.2021 источник

Ответы (2)

arrow_upward
1
arrow_downward

Вы сказали, что у вас есть:

Некоторые ошибки при высоком уровне параллелизма

И вы получаете:

java.sql.SQLTransientConnectionException: HikariPool-1 — соединение недоступно, время ожидания запроса истекло через 30005 мс.

Это означает, что пулу соединений БД (Hikari) не удалось обеспечить соединение максимум за 30 секунд.
Вы настроили максимальное количество соединений пула на 2 :

  maximumPoolSize: 2

Их мало, и более того, если ваши запросы обрабатываются довольно долго и ваше приложение имеет высокий параллелизм, этот параметр выглядит действительно заниженным.
Увеличьте его до большего числа, например, 10 или более, и наблюдайте за поведением. Вы также можете поиграть с параметром connectionTimeout, но в результате это замедлит работу вашего приложения, если клиентские запросы ожидают подключения.

Документация по размеру пула Hikari может дать вам некоторую информацию о том, как подправить конфигурацию.

В качестве альтернативы вы можете переосмыслить свой источник данных. Например, определите два источника данных: один для длинных соединений (для длинных запросов) и другой для сортировки соединений (для коротких запросов) и используйте источники данных, которые лучше подходят в зависимости от случая.

В качестве примечания Spring Boot предоставляет исполнительный механизм, ориентированный на подключения к источникам данных: DataSourceHealthIndicator который проверяет возможность получения подключения к источнику данных.
При подключении к системному инструменту мониторинга (Prometheus или любому другому) они могут быть полезны для диагностики того, что вид вопросов.

davidxxx 01.01.2021

comment

Привет, @davidxxx, это был просто макет .... в prod я установил его на 10, но для 10 одновременных запросов это нормально, но для 11-го запроса та же история. - pranav prashant; 01.01.2021

comment

Привет, Пранав, у меня были некоторые сомнения, когда я прочитал твой вопрос. Вы можете увеличить выше 10. 15 или 20 могут улучшить ситуацию. Я отредактировал свой ответ с дополнительной идеей. - davidxxx; 01.01.2021

comment

Конечно. Есть ли другой способ справиться с этим или это задумано. один поток одно соединение db. - pranav prashant; 01.01.2021

comment

То есть по дизайну. Соединение с базой данных является состоянием: оно содержит определенную информацию, связанную с отправкой вызывающей стороной и базой данных. Вы не можете поделиться им, не рискуя нарушить его состояние. - davidxxx; 01.01.2021

comment

Привет, Дэвид, при установке этого значения spring.jpa.open-in-view=false в .yml Соединения возвращаются обратно в пул hikari и доступны для одновременных запросов... Нагрузка протестировала тот же сценарий с 15 одновременными запросами и 2 подключениями к пулу hikari. Проблем не наблюдается. Можете ли вы поделиться здесь своими мыслями... Утечки соединения также не обнаружено... Спасибо. - pranav prashant; 05.01.2021

arrow_upward
0
arrow_downward

Вы можете увеличить время ожидания подключения, установив соответствующее свойство:

hikari:
  connectionTimeout: 60000        #30000 (or 30 sec) by default

Однако лучше не удерживать соединение при вызове стороннего API, а в этом случае выполнять вызовы БД с отдельными соединениями.

amseager 01.01.2021

Соединение HikariPool недоступно после длительной операции ввода-вывода для параллельного запроса

Ответы (2)

Похожие вопросы