HikariCP
HikariCP copied to clipboard
Published
20 hours ago •
brettwooldridge
brettwooldridge
Leak detection with simple operation and quartz
Environment
HikariCP version: 2.7.8
JDK version : 1.8.0_111
Database : MySQL version: 5.6.35
Hi,
I have recently updated spring boot 1 to spring boot 2.01, so im using Hikari now instead tomcat.
Here my hikari configuration :
com.zaxxer.hikari.HikariConfig : HikariPool-1 - configuration:
com.zaxxer.hikari.HikariConfig : allowPoolSuspension.............false
com.zaxxer.hikari.HikariConfig : autoCommit......................true
com.zaxxer.hikari.HikariConfig : catalog.........................none
com.zaxxer.hikari.HikariConfig : connectionInitSql...............none
com.zaxxer.hikari.HikariConfig : connectionTestQuery.............none
com.zaxxer.hikari.HikariConfig : connectionTimeout...............30000
com.zaxxer.hikari.HikariConfig : dataSource......................none
com.zaxxer.hikari.HikariConfig : dataSourceClassName.............none
com.zaxxer.hikari.HikariConfig : dataSourceJNDI..................none
com.zaxxer.hikari.HikariConfig : driverClassName................."com.mysql.jdbc.Driver"
com.zaxxer.hikari.HikariConfig : healthCheckProperties...........{}
com.zaxxer.hikari.HikariConfig : healthCheckRegistry.............none
com.zaxxer.hikari.HikariConfig : idleTimeout.....................600000
com.zaxxer.hikari.HikariConfig : initializationFailFast..........true
com.zaxxer.hikari.HikariConfig : initializationFailTimeout.......1
com.zaxxer.hikari.HikariConfig : isolateInternalQueries..........false
com.zaxxer.hikari.HikariConfig : jdbc4ConnectionTest.............false
com.zaxxer.hikari.HikariConfig : leakDetectionThreshold..........120000
com.zaxxer.hikari.HikariConfig : maxLifetime.....................1800000
com.zaxxer.hikari.HikariConfig : maximumPoolSize.................25
com.zaxxer.hikari.HikariConfig : metricRegistry..................none
com.zaxxer.hikari.HikariConfig : metricsTrackerFactory...........com.zaxxer.hikari.metrics.micrometer.MicrometerMetricsTrackerFactory@2b7e8044
com.zaxxer.hikari.HikariConfig : minimumIdle.....................5
com.zaxxer.hikari.HikariConfig : password........................<masked>
com.zaxxer.hikari.HikariConfig : poolName........................"HikariPool-1"
com.zaxxer.hikari.HikariConfig : readOnly........................false
com.zaxxer.hikari.HikariConfig : registerMbeans..................false
com.zaxxer.hikari.HikariConfig : scheduledExecutor...............none
com.zaxxer.hikari.HikariConfig : scheduledExecutorService........internal
com.zaxxer.hikari.HikariConfig : schema..........................none
com.zaxxer.hikari.HikariConfig : threadFactory...................internal
com.zaxxer.hikari.HikariConfig : transactionIsolation............default
com.zaxxer.hikari.HikariConfig : validationTimeout...............5000
I also use quartz 2.2.2 and have at least 8 scheduler (we have to migration the 8 scheduler to 1 in the future). Quartz conf : org.quartz.jobStore.isClustered=true org.quartz.jobStore.clusterCheckinInterval=15000
And jdbc informations : jdbc: batch_size: 1000 order_inserts: true order_updates: true
I use Zuul and netflix eureka to register servers.
I have often the timeout connection :
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:667)
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:183)
I added leakDetectionThreshold to find if some connections was lost and not available from pool, i have :
12:59:16.085 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=11, active=0, idle=11, waiting=0)
12:59:16.085 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=11, active=0, idle=11, waiting=0)
12:59:20.732 DEBUG 35763 --- [HikariPool-1 connection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection com.mysql.jdbc.JDBC4Connection@1b59d885: (connection has passed maxLifetime)
12:59:46.085 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
12:59:46.085 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=10, active=0, idle=10, waiting=0)
13:00:16.086 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
13:00:16.086 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=10, active=0, idle=10, waiting=0)
13:00:46.086 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
13:00:46.086 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=10, active=0, idle=10, waiting=0)
13:01:16.086 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=10, active=1, idle=9, waiting=0)
13:01:16.087 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=10, active=1, idle=9, waiting=0)
13:01:46.087 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=10, active=1, idle=9, waiting=0)
13:01:46.087 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=10, active=1, idle=9, waiting=0)
13:02:16.087 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=10, active=1, idle=9, waiting=0)
13:02:16.087 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=10, active=1, idle=9, waiting=0)
13:02:46.087 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=10, active=1, idle=9, waiting=0)
13:02:46.088 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=10, active=1, idle=9, waiting=0)
13:03:15.699 WARN 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.ProxyLeakTask : Connection leak detection triggered for com.mysql.jdbc.JDBC4Connection@62015a81 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)
at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:35)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:106)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:136)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:254)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:262)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:214)
at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:56)
at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:164)
at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:400)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:378)
at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:474)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:289)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
at app.services.FormManager$$EnhancerBySpringCGLIB$$428e4b00.getValue(<generated>)
at app.from.FormController.getValue(FormController.java:112)
at sun.reflect.GeneratedMethodAccessor379.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:209)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:136)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:102)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:877)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:783)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:991)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:925)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:974)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:866)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:851)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.security.oauth2.client.filter.OAuth2ClientContextFilter.doFilter(OAuth2ClientContextFilter.java:60)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:158)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:126)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:111)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:84)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:320)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:127)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:91)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:119)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111)
....
13:03:16.088 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=10, active=1, idle=9, waiting=0)
13:03:16.088 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=10, active=1, idle=9, waiting=0)
13:03:16.411 INFO 35763 --- [http-nio-8080-exec-1] com.zaxxer.hikari.pool.ProxyLeakTask : Previously reported leaked connection com.mysql.jdbc.JDBC4Connection@62015a81 on thread http-nio-8080-exec-1 was returned to the pool (unleaked)
13:03:29.005 DEBUG 35763 --- [HikariPool-1 connection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection com.mysql.jdbc.JDBC4Connection@62015a81: (connection was evicted)
13:03:46.088 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=9, active=0, idle=9, waiting=0)
13:03:46.088 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=9, active=0, idle=9, waiting=0)
13:04:16.088 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=9, active=0, idle=9, waiting=0)
13:04:16.089 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=9, active=0, idle=9, waiting=0)
13:04:32.873 DEBUG 35763 --- [HikariPool-1 connection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection com.mysql.jdbc.JDBC4Connection@1e6040ff: (connection was evicted)
And later i have :
13:37:46.114 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=15, active=11, idle=4, waiting=0)
13:37:46.114 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=15, active=11, idle=4, waiting=0)
13:37:46.137 DEBUG 35763 --- [HikariPool-1 connection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection com.mysql.jdbc.JDBC4Connection@67470385
13:37:46.137 DEBUG 35763 --- [HikariPool-1 connection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=16, active=11, idle=5, waiting=0)
13:38:16.115 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=16, active=11, idle=5, waiting=0)
13:38:16.115 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=16, active=11, idle=5, waiting=0)
13:38:46.115 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=16, active=11, idle=5, waiting=0)
13:38:46.115 DEBUG 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=16, active=11, idle=5, waiting=0)
13:39:06.248 WARN 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.ProxyLeakTask : Connection leak detection triggered for com.mysql.jdbc.JDBC4Connection@2ee3b71 on thread QuartzScheduler_graph-quartz-scheduler-NON_CLUSTERED_ClusterManager, stack trace follows
java.lang.Exception: Apparent connection leak detected
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
at org.springframework.scheduling.quartz.LocalDataSourceJobStore$2.getConnection(LocalDataSourceJobStore.java:134)
at org.quartz.utils.DBConnectionManager.getConnection(DBConnectionManager.java:108)
at org.quartz.impl.jdbcjobstore.JobStoreCMT.getNonManagedTXConnection(JobStoreCMT.java:165)
at org.quartz.impl.jdbcjobstore.JobStoreSupport.doCheckin(JobStoreSupport.java:3257)
at org.quartz.impl.jdbcjobstore.JobStoreSupport$ClusterManager.manage(JobStoreSupport.java:3870)
at org.quartz.impl.jdbcjobstore.JobStoreSupport$ClusterManager.run(JobStoreSupport.java:3907)
13:39:06.248 WARN 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.ProxyLeakTask : Connection leak detection triggered for com.mysql.jdbc.JDBC4Connection@7061197a on thread QuartzScheduler_tool-worklog-quartz-scheduler-NON_CLUSTERED_ClusterManager, stack trace follows
java.lang.Exception: Apparent connection leak detected
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
at org.springframework.scheduling.quartz.LocalDataSourceJobStore$2.getConnection(LocalDataSourceJobStore.java:134)
at org.quartz.utils.DBConnectionManager.getConnection(DBConnectionManager.java:108)
at org.quartz.impl.jdbcjobstore.JobStoreCMT.getNonManagedTXConnection(JobStoreCMT.java:165)
at org.quartz.impl.jdbcjobstore.JobStoreSupport.doCheckin(JobStoreSupport.java:3257)
at org.quartz.impl.jdbcjobstore.JobStoreSupport$ClusterManager.manage(JobStoreSupport.java:3870)
at org.quartz.impl.jdbcjobstore.JobStoreSupport$ClusterManager.run(JobStoreSupport.java:3907)
13:39:06.249 WARN 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.ProxyLeakTask : Connection leak detection triggered for com.mysql.jdbc.JDBC4Connection@5e093468 on thread QuartzScheduler_tz-quartz-scheduler-NON_CLUSTERED_ClusterManager, stack trace follows
java.lang.Exception: Apparent connection leak detected
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
at org.springframework.scheduling.quartz.LocalDataSourceJobStore$2.getConnection(LocalDataSourceJobStore.java:134)
at org.quartz.utils.DBConnectionManager.getConnection(DBConnectionManager.java:108)
at org.quartz.impl.jdbcjobstore.JobStoreCMT.getNonManagedTXConnection(JobStoreCMT.java:165)
at org.quartz.impl.jdbcjobstore.JobStoreSupport.doCheckin(JobStoreSupport.java:3257)
at org.quartz.impl.jdbcjobstore.JobStoreSupport$ClusterManager.manage(JobStoreSupport.java:3870)
at org.quartz.impl.jdbcjobstore.JobStoreSupport$ClusterManager.run(JobStoreSupport.java:3907)
13:39:06.254 WARN 35763 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.ProxyLeakTask : Connection leak detection triggered for com.mysql.jdbc.JDBC4Connection@3abc9b5f on thread QuartzScheduler_rm-quartz-scheduler-NON_CLUSTERED_ClusterManager, stack trace follows
java.lang.Exception: Apparent connection leak detected
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
at org.springframework.scheduling.quartz.LocalDataSourceJobStore$2.getConnection(LocalDataSourceJobStore.java:134)
at org.quartz.utils.DBConnectionManager.getConnection(DBConnectionManager.java:108)
at org.quartz.impl.jdbcjobstore.JobStoreCMT.getNonManagedTXConnection(JobStoreCMT.java:165)
at org.quartz.impl.jdbcjobstore.JobStoreSupport.doCheckin(JobStoreSupport.java:3257)
at org.quartz.impl.jdbcjobstore.JobStoreSupport$ClusterManager.manage(JobStoreSupport.java:3870)
at org.quartz.impl.jdbcjobstore.JobStoreSupport$ClusterManager.run(JobStoreSupport.java:3907)
I don't understand the error at app.from.FormController.getValue(FormController.java:112) because the operation is not a big query and the connection is managed by Spring, we do not make a connection manualy.
Also i don't understand all the quartz connection leak because quartz does not keep connection if it doesn't need. Is there a issue about Clustering mode and Hikari ?
