In my companies project, we are using Hikari for connection pool management. [Hibernate 4.3.5 + Spring 4 + Java 1.8] Below is the configuration
hibernate.connection.provider_class=com.zaxxer.hikari.hibernate.HikariConnectionProvider
hibernate.hikari.minimumIdle=5
hibernate.hikari.maximumPoolSize=10
hibernate.hikari.idleTimeout=60
hibernate.hikari.dataSourceClassName=com.mysql.jdbc.jdbc2.optional.MysqlDataSource
We are facing below problem two problem
For some reason, Hikari is creating 2 connection pool HikariPool-1 and HikariPool-2.
Only HikariPool-2 is being used and even that is giving error
Connection is not available, request timed out after 30000msafter some time
Below are the logs of Hikari initiation and the error of request timed out.
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.hibernate.HikariConnectionProvider -- Configuring HikariCP
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- HikariPool-1 - configuration:
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- allowPoolSuspension.............false
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- autoCommit......................true
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- catalog.........................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- connectionInitSql...............null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- connectionTestQuery............."SELECT 1"
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- connectionTimeout...............30000
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSource......................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSourceClassName............."com.mysql.jdbc.jdbc2.optional.MysqlDataSource"
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSourceJNDI..................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSourceProperties............{user=walletadmin, url=jdbc:mysql://111.111.11.11:3306/database,
password=<masked>}
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- driverClassName.................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- healthCheckProperties...........{}
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- healthCheckRegistry.............null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- idleTimeout.....................10800
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- initializationFailFast..........true
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- isolateInternalQueries..........false
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- jdbc4ConnectionTest.............false
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- jdbcUrl.........................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- leakDetectionThreshold..........0
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- maxLifetime.....................1800000
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- maximumPoolSize.................50
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- metricRegistry..................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- metricsTrackerFactory...........null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- minimumIdle.....................5
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- password........................<masked>
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- poolName........................"HikariPool-1"
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- readOnly........................false
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- registerMbeans..................false
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- scheduledExecutorService........null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- threadFactory...................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- transactionIsolation............null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- username........................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- validationTimeout...............5000
[2018-11-05 15:18:02] - [] - INFO com.zaxxer.hikari.HikariDataSource -- HikariPool-1 - Started.
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.hibernate.HikariConnectionProvider -- HikariCP Configured
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.hibernate.HikariConnectionProvider -- Configuring HikariCP
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- HikariPool-2 - configuration:
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- allowPoolSuspension.............false
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- autoCommit......................true
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- catalog.........................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- connectionInitSql...............null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- connectionTestQuery............."SELECT 1"
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- connectionTimeout...............30000
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSource......................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSourceClassName............."com.mysql.jdbc.jdbc2.optional.MysqlDataSource"
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSourceJNDI..................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSourceProperties............{user=walletadmin, url=jdbc:mysql://111.111.11.11:3306/database,
password=<masked>}
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- driverClassName.................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- healthCheckProperties...........{}
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- healthCheckRegistry.............null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- idleTimeout.....................10800
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- initializationFailFast..........true
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- isolateInternalQueries..........false
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- jdbc4ConnectionTest.............false
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- jdbcUrl.........................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- leakDetectionThreshold..........0
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- maxLifetime.....................1800000
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- maximumPoolSize.................50
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- metricRegistry..................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- metricsTrackerFactory...........null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- minimumIdle.....................5
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- password........................<masked>
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- poolName........................"HikariPool-2"
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- readOnly........................false
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- registerMbeans..................false
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- scheduledExecutorService........null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- threadFactory...................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- transactionIsolation............null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- username........................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- validationTimeout...............5000
[2018-11-05 15:18:03] - [] - INFO com.zaxxer.hikari.HikariDataSource -- HikariPool-2 - Started.
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.hibernate.HikariConnectionProvider -- HikariCP Configured
[2018-11-04 11:00:30] - [] - ERROR com.agwallet.serviceImpl.InstantGiftCardAcceptServiceImpl -- Exception getting from ================= instantGiftVirtualCardAccept() =============Could not open connection; nested exception is org.hibernate.exception.JDBCConnectionException: Could not open connection
org.springframework.dao.DataAccessResourceFailureException: Could not open connection; nested exception is org.hibernate.exception.JDBCConnectionException: Could not open connection
at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:234)
at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:221)
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(AbstractEntityManagerFactoryBean.java:417)
at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:59)
at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:213)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:147)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:119)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
at com.sun.proxy.$Proxy86.findAllPendingGiftVirtualCard(Unknown Source)
at com.agwallet.serviceImpl.InstantGiftCardAcceptServiceImpl.instantGiftVirtualCardAccept(InstantGiftCardAcceptServiceImpl.java:57)
at com.agwallet.jobs.InstantActivationForGiftCardJob.instantGiftVirtualCardRequest(InstantActivationForGiftCardJob.java:29)
at sun.reflect.GeneratedMethodAccessor66.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:81)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: org.hibernate.exception.JDBCConnectionException: Could not open connection
at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:65)
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112)
at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:235)
at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:63)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:162)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:186)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:160)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1884)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1861)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838)
at org.hibernate.loader.Loader.doQuery(Loader.java:909)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354)
at org.hibernate.loader.Loader.doList(Loader.java:2553)
at org.hibernate.loader.Loader.doList(Loader.java:2539)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2369)
at org.hibernate.loader.Loader.list(Loader.java:2364)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:496)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:387)
at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:231)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1264)
at org.hibernate.internal.QueryImpl.list(QueryImpl.java:103)
at org.hibernate.jpa.internal.QueryImpl.list(QueryImpl.java:573)
at org.hibernate.jpa.internal.QueryImpl.getResultList(QueryImpl.java:449)
at sun.reflect.GeneratedMethodAccessor65.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.orm.jpa.SharedEntityManagerCreator$DeferredQueryInvocationHandler.invoke(SharedEntityManagerCreator.java:364)
at com.sun.proxy.$Proxy96.getResultList(Unknown Source)
at org.springframework.data.jpa.repository.query.JpaQueryExecution$CollectionExecution.doExecute(JpaQueryExecution.java:114)
at org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:78)
at org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:100)
at org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:91)
at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:454)
at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:432)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:61)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
... 22 common frames omitted
Caused by: java.sql.SQLTransientConnectionException: HikariPool-2 - Connection is not available, request timed out after 30000ms.
at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:548)
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:186)
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:145)
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:83)
at com.zaxxer.hikari.hibernate.HikariConnectionProvider.getConnection(HikariConnectionProvider.java:106)
at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380)
at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228)
... 62 common frames omitted
