HikariPool-1 - Interrupted during connection acquisition

最近在压测springboot服务的是时候，遇到 HikariPool-1 - Interrupted during connection acquisition，先记录一下临时解决办法，后面有时间在review这个问题。

问题描述

问题日志：

Caused by: org.apache.ibatis.exceptions.PersistenceException: 
### Error querying database.  Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLException: HikariPool-1 - Interrupted during connection acquisition
### The error may exist in URL [jar:file:/data/app.jar!/BOOT-INF/classes!/mapping/SessionDataMapper.xml]
### The error may involve com.geniuworks.bot.mapper.SessionDataMapper.selectById
### The error occurred while executing a query
### Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLException: HikariPool-1 - Interrupted during connection acquisition
	at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:149)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:140)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:76)
	at jdk.internal.reflect.GeneratedMethodAccessor121.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:567)
	at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:426)
	... 125 more
Caused by: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLException: HikariPool-1 - Interrupted during connection acquisition
	at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:82)
	at org.mybatis.spring.transaction.SpringManagedTransaction.openConnection(SpringManagedTransaction.java:80)
	at org.mybatis.spring.transaction.SpringManagedTransaction.getConnection(SpringManagedTransaction.java:67)
	at org.apache.ibatis.executor.BaseExecutor.getConnection(BaseExecutor.java:336)
	at com.baomidou.mybatisplus.core.executor.MybatisSimpleExecutor.prepareStatement(MybatisSimpleExecutor.java:93)
	at com.baomidou.mybatisplus.core.executor.MybatisSimpleExecutor.doQuery(MybatisSimpleExecutor.java:66)
	at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:324)
	at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
	at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:109)
	at com.github.pagehelper.PageInterceptor.intercept(PageInterceptor.java:143)
	at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
	at jdk.proxy3/jdk.proxy3.$Proxy354.query(Unknown Source)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:147)
	... 131 more
Caused by: java.sql.SQLException: HikariPool-1 - Interrupted during connection acquisition
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:201)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)
	at com.zaxxer.hikari.HikariDataSource.getConnection$original$ll24d7XA(HikariDataSource.java:128)
	at com.zaxxer.hikari.HikariDataSource.getConnection$original$ll24d7XA$accessor$Ht7KSzci(HikariDataSource.java)
	at com.zaxxer.hikari.HikariDataSource$auxiliary$lqHwejmZ.call(Unknown Source)
	at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java)
	at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:158)
	at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:116)
	at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:79)
	... 143 more
Caused by: java.lang.InterruptedException
	at java.base/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:940)
	at com.zaxxer.hikari.util.ConcurrentBag.borrow(ConcurrentBag.java:151)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:180)
	... 152 more

问题日志截图：

日志给出的原因:
HikariPool-1 - Interrupted during connection acquisition

jdbc的一个中间组件链接的时候被强制中断了。

导致压测百分之99.9的请求都失败了。

临时解决办法

去掉了下面的线程池配置，配置如下：

/**
 * @Author dingws
 * @PackageName geniubot_developer_service
 * @Package com.geniuworks.bot.config
 * @Date 2022/3/16 4:35 下午
 * @Version 1.0
 */
@Configuration
@Slf4j
public class ThreadPoolConfig implements AsyncConfigurer {

    private static final int cpuNum = Runtime.getRuntime().availableProcessors();

    @Override
    @Bean(name = "threadPoolTaskExecutor")
    public Executor getAsyncExecutor() {
        ThreadPoolTaskExecutor taskExecutor = new ThreadPoolTaskExecutor();
        // 最小线程数(核心线程数)
        taskExecutor.setCorePoolSize(cpuNum + 1);
        // 最大线程数
        taskExecutor.setMaxPoolSize(cpuNum * 2);
        // 等待队列(队列最大长度)
        taskExecutor.setQueueCapacity(1000);
        // 等待时间
        taskExecutor.setAwaitTerminationSeconds(300);
        // 线程池维护线程所允许的空闲时间 ，单位s
        taskExecutor.setKeepAliveSeconds(300);
        // 线程池名称前缀
        taskExecutor.setThreadNamePrefix("thread-pool-");
        // 线程池对拒绝任务(无线程可用)的处理策略
        taskExecutor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());

        taskExecutor.initialize();
        log.info("线程池初始化完成...");
        return taskExecutor;
    }


    /**
     * 异步异常处理
     *
     * @return
     */
    @Override
    public AsyncUncaughtExceptionHandler getAsyncUncaughtExceptionHandler() {
        return new SpringAsyncExceptionHandler();
    }

    class SpringAsyncExceptionHandler implements AsyncUncaughtExceptionHandler {
        @Override
        public void handleUncaughtException(Throwable throwable, Method method, Object... obj) {
            log.error("Exception occurs in async method", throwable.getMessage());
        }
    }
}

通过这个方法，可以使压测正常进行，且能预期的1000QPS。

根本原因

目前只能大概推测，大量并发请求过来后，导致线程并发数量增加，但是因为cpu是一定的，会存在少数线程得不到响应。在超过一定时长后，被HikariPool组件认为是僵死线程，强制清理退出导致请求失败。

但具体为什么会产生这种原因，个人还是有点困惑，还需要进一步研究，最近手头工作比较忙，先记录一下，等闲的时候再review这个问题。