druid活跃线程数量持续增长问题

1、问题现象

前一阵子，在一个老项目里面加了一个接口，分页查询数据库里面的记录，用于前端展示。

（嗯，先别急，我要说的不是分页查询的性能导致的问题。）

需求很easy，三两下就搞定了，结果上线后过不了多久就收到告警druid活跃线程数量超过90%。

以前活跃线程数平均下来几乎为0，这次就加了一个分页查询接口，竟然导致活跃线程数量飙升？奇怪，我也没改特别的呀。

分页查询嘛，需要查询总记录数 + 当前页的记录。一般习惯用PageHelper之类的分页插件，但需要额外引入PageHelper这个jar，我看原来项目里已经有mybatis-paginator。想着还是少引入一个jar吧，就基于mybatis-paginator干吧。

2、问题分析

突然收到这个报警，也是觉得挺莫名其妙的，毕竟改动很小，就加了一个分页查询。

仔细确认了一下分页的代码，嗯，没啥毛病！

那咋弄呢？好在druid有monitor页面，先把monitor监控页面整出来，借助它来分析一下。

2.1、配置druid-monitor

首先，需要在web.xml里加上一些配置

	<filter>
        <filter-name>DruidWebStatFilter</filter-name>
        <filter-class>com.alibaba.druid.support.http.WebStatFilter</filter-class>
        <init-param>
            <param-name>exclusions</param-name>
            <param-value>/static/*,*.js,*.gif,*.jpg,*.png,*.css,*.ico,/druid/*</param-value>
        </init-param>
        <init-param>
            <param-name>profileEnable</param-name>
            <param-value>true</param-value>
        </init-param>
    </filter>
    <filter-mapping>
        <filter-name>DruidWebStatFilter</filter-name>
        <url-pattern>/*</url-pattern>
    </filter-mapping>
    <servlet>
        <servlet-name>DruidStatView</servlet-name>
        <servlet-class>com.alibaba.druid.support.http.StatViewServlet</servlet-class>
        <init-param>
            <param-name>loginUsername</param-name>
            <param-value>druid</param-value>
        </init-param>
        <init-param>
            <param-name>loginPassword</param-name>
            <param-value>druid</param-value>
        </init-param>
    </servlet>
    <servlet-mapping>
        <servlet-name>DruidStatView</servlet-name>
        <url-pattern>/druid/*</url-pattern>
    </servlet-mapping>

然后，需要在DruidDataSource对象申明的地方，配置上

<property name="filters" value="config,stat,slf4j" />

配置好之后，就可以打开druid-monitor页面了。没什么意外的话，就可以看到数据源、连接数之类的信息了。

没意外的话，意外发生了---页面是出来了，数据源信息死活没出来。

这是什么情况？难道是配置哪里不对？查找了各种配置说明之后，才发现这可能是druid的bug。升级一下druid就解决了。

于是把druid从1.0.12升级到 1.0.29，数据源tab页就正常了。

2.2、观察数据指标

通过druid-monitor，重点关注【数据源】页的三个参数：

• 活跃连接数
• 逻辑连接打开次数
• 逻辑连接关闭次数

在测试环境试了一段时间，发现有些时候逻辑连接打开数 略大于 关闭数，这说明有些连接确实没关闭了。只不过测试环境请求量比较小，问题不容易暴漏。

那有啥办法定位是哪里没关闭连接吗？

2.3、连接泄露检测

百度谷歌了下，找到了温少的wiki-连接泄露检测

  <bean id="dataSource" class="com.alibaba.druid.pool.DruidDataSource" destroy-method="close">
  	... ...
  	<property name="removeAbandoned" value="true" /> <!-- 打开removeAbandoned功能 -->
  	<property name="removeAbandonedTimeout" value="1800" /> <!-- 1800秒，也就是30分钟 -->
  	<property name="logAbandoned" value="true" /> <!-- 关闭abanded连接时输出错误日志 -->
  	... ...
  </bean>

当removeAbandoned=true之后，可以在内置监控界面datasource.html中的查看ActiveConnection StackTrace属性的，可以看到未关闭连接的具体堆栈信息，从而方便查出哪些连接泄漏了。

比如下面这样：

这些堆栈信息貌似也没啥特殊的，没有一行是项目的代码

java.lang.Thread.getStackTrace(Thread.java:1552)
com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1140)
com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4544)
com.alibaba.druid.filter.logging.LogFilter.dataSource_getConnection(LogFilter.java:854)
com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4540)
com.alibaba.druid.filter.stat.StatFilter.dataSource_getConnection(StatFilter.java:670)
com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4540)
com.alibaba.druid.filter.FilterAdapter.dataSource_getConnection(FilterAdapter.java:2723)
com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4540)
com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1064)
com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1056)
com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:104)
org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77)
org.mybatis.spring.transaction.SpringManagedTransaction.openConnection(SpringManagedTransaction.java:81)
org.mybatis.spring.transaction.SpringManagedTransaction.getConnection(SpringManagedTransaction.java:67)
org.apache.ibatis.executor.BaseExecutor.getConnection(BaseExecutor.java:315)
org.apache.ibatis.executor.SimpleExecutor.prepareStatement(SimpleExecutor.java:75)
org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:61)
org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:303)
org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:154)
org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:102)
org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:82)
sun.reflect.GeneratedMethodAccessor300.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:497)
org.apache.ibatis.plugin.Invocation.proceed(Invocation.java:49)
com.github.miemiedev.mybatis.paginator.OffsetLimitInterceptor$1.call(OffsetLimitInterceptor.java:87)
com.github.miemiedev.mybatis.paginator.OffsetLimitInterceptor$1.call(OffsetLimitInterceptor.java:85)
java.util.concurrent.FutureTask.run(FutureTask.java:266)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
java.lang.Thread.run(Thread.java:745)

不过，多来几次之后，就发现一个类名出现的次数比较多----OffsetLimitInterceptor！难道是这玩意导致的？

OffsetLimitInterceptor是mybatis-paginator实现分页查询的类。

于是乎尝试不使用mybatis-paginator，而是换了最原始的分页查询。结果问题解决了~

是的，就这么解决了！ 这谁能想的到！

3、原因分析

前面猜测是mybatis-paginator的OffsetLimitInterceptor引起的，没想到蒙对了。改了之后问题就消失了。

那来看看OffsetLimitInterceptor到底做了什么

@Intercepts({@Signature(
		type= Executor.class,
		method = "query",
		args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class})})
public class OffsetLimitInterceptor implements Interceptor{
    private static Logger logger = LoggerFactory.getLogger(OffsetLimitInterceptor.class);
	static int MAPPED_STATEMENT_INDEX = 0;
	static int PARAMETER_INDEX = 1;
	static int ROWBOUNDS_INDEX = 2;
	static int RESULT_HANDLER_INDEX = 3;

    static ExecutorService Pool;
    String dialectClass;
    boolean asyncTotalCount = false;
	
	public Object intercept(final Invocation invocation) throws Throwable {
        final Executor executor = (Executor) invocation.getTarget();
        final Object[] queryArgs = invocation.getArgs();
        final MappedStatement ms = (MappedStatement)queryArgs[MAPPED_STATEMENT_INDEX];
        final Object parameter = queryArgs[PARAMETER_INDEX];
        final RowBounds rowBounds = (RowBounds)queryArgs[ROWBOUNDS_INDEX];
        final PageBounds pageBounds = new PageBounds(rowBounds);

        if(pageBounds.getOffset() == RowBounds.NO_ROW_OFFSET
                && pageBounds.getLimit() == RowBounds.NO_ROW_LIMIT
                && pageBounds.getOrders().isEmpty()){
            return invocation.proceed();
        }

        final Dialect dialect;
        try {
            Class clazz = Class.forName(dialectClass);
            Constructor constructor = clazz.getConstructor(MappedStatement.class, Object.class, PageBounds.class);
            dialect = (Dialect)constructor.newInstance(new Object[]{ms, parameter, pageBounds});
        } catch (Exception e) {
            throw new ClassNotFoundException("Cannot create dialect instance: "+dialectClass,e);
        }

        final BoundSql boundSql = ms.getBoundSql(parameter);

        queryArgs[MAPPED_STATEMENT_INDEX] = copyFromNewSql(ms,boundSql,dialect.getPageSQL(), dialect.getParameterMappings(), dialect.getParameterObject());
        queryArgs[PARAMETER_INDEX] = dialect.getParameterObject();
        queryArgs[ROWBOUNDS_INDEX] = new RowBounds(RowBounds.NO_ROW_OFFSET,RowBounds.NO_ROW_LIMIT);

        Boolean async = pageBounds.getAsyncTotalCount() == null ? asyncTotalCount : pageBounds.getAsyncTotalCount();
        // 查记录
        Future<List> listFuture = call(new Callable<List>() {
            public List call() throws Exception {
                return (List)invocation.proceed();
            }
        }, async);


        // 查总数
        if(pageBounds.isContainsTotalCount()){
            Callable<Paginator> countTask = new Callable() {
                public Object call() throws Exception {
                    Integer count;
                    Cache cache = ms.getCache();
                    if(cache != null && ms.isUseCache() && ms.getConfiguration().isCacheEnabled()){
                        CacheKey cacheKey = executor.createCacheKey(ms,parameter,new PageBounds(),copyFromBoundSql(ms,boundSql,dialect.getCountSQL(), boundSql.getParameterMappings(), boundSql.getParameterObject()));
                        count = (Integer)cache.getObject(cacheKey);
                        if(count == null){
                            count = SQLHelp.getCount(ms,executor.getTransaction(),parameter,boundSql,dialect);
                            cache.putObject(cacheKey, count);
                        }
                    }else{
                        count = SQLHelp.getCount(ms,executor.getTransaction(),parameter,boundSql,dialect);
                    }
                    return new Paginator(pageBounds.getPage(), pageBounds.getLimit(), count);
                }
            };
            Future<Paginator> countFutrue = call(countTask, async);
            return new PageList(listFuture.get(),countFutrue.get());
        }

        return listFuture.get();
	}

    // 这里可以同步 or 异步 去查
    private <T> Future<T> call(Callable callable, boolean async){
        if(async){
             return Pool.submit(callable);
        }else{
            FutureTask<T> future = new FutureTask(callable);
            future.run();
            return future;
        }
    }
    // ......
}

从源码看，这里支持同步或者异步去执行2个sql。然后通过Future.get()返回结果。

异步使用的pool线程池是

public void setPoolMaxSize(int poolMaxSize) {
    if(poolMaxSize > 0){
        logger.debug("poolMaxSize: {} ", poolMaxSize);
        Pool = Executors.newFixedThreadPool(poolMaxSize);
    }else{
        Pool = Executors.newCachedThreadPool();
    }
}

至此，问题应该比较清楚了。Pool连接池线程终止后，数据库连接未释放，导致活跃数持续增长。

（为啥使用这个Pool线程池就会出现数据库连接未回收问题呢？我跟着源码 也没找到答案，o(╥﹏╥)o）

看网上很多类似的问题，但最后都是配置removeAbandoned=true就完了。但

RemoveAbandanded功能不建议在生产环境中使用，仅用于连接泄露检测诊断

4、其他

1、为啥以前就没出问题呢？

项目里面的mybatis.xml中配置的是：

<plugins>
	<plugin interceptor="com.github.miemiedev.mybatis.paginator.OffsetLimitInterceptor">
		<property name="dialectClass" value="com.github.miemiedev.mybatis.paginator.dialect.MySQLDialect"/>
		<property name="asyncTotalCount" value="false"/>
	</plugin>
</plugins>

asyncTotalCount=false，那为啥实际情况是使用的Pool线程池去异步执行的呢？

原来是依赖的一个二方包里面，包含了一个mybatis的配置文件，里面配置的asyncTotalCount为true，而且它先被先一步加载！

2、druid为什么不打印日志？

druid不依赖任何的log组件，但支持多种log组件，会检测当前环境，选择一种合适的log实现。选择日志的优先级依次是：

log4j > log4j2 > slf4j > commons-logging > jdk-logging

具体检测方法是尝试加载对应的class，如果加载成功就认为当前环境支持此种log组件，就使用它来处理日志打印。

如果想要指定特定的log组件，你可以通过JVM启动参数来配置，比如：

-Ddruid.logType=slf4j
-Ddruid.logType=log4j
-Ddruid.logType=log4j2
-Ddruid.logType=commonsLog
-Ddruid.logType=jdkLog

源码见：

// com.alibaba.druid.support.logging.LogFactory
public class LogFactory {

    private static Constructor logConstructor;

    static {
        String logType= System.getProperty("druid.logType");
        if(logType != null){
            if(logType.equalsIgnoreCase("slf4j")){
                tryImplementation("org.slf4j.Logger", "com.alibaba.druid.support.logging.SLF4JImpl");
            }else if(logType.equalsIgnoreCase("log4j")){
                tryImplementation("org.apache.log4j.Logger", "com.alibaba.druid.support.logging.Log4jImpl");
            }else if(logType.equalsIgnoreCase("log4j2")){
                tryImplementation("org.apache.logging.log4j.Logger", "com.alibaba.druid.support.logging.Log4j2Impl");
            }else if(logType.equalsIgnoreCase("commonsLog")){
                tryImplementation("org.apache.commons.logging.LogFactory",
                        "com.alibaba.druid.support.logging.JakartaCommonsLoggingImpl");
            }else if(logType.equalsIgnoreCase("jdkLog")){
                tryImplementation("java.util.logging.Logger", "com.alibaba.druid.support.logging.Jdk14LoggingImpl");
            }
        }
        // 优先选择log4j,而非Apache Common Logging. 因为后者无法设置真实Log调用者的信息
        tryImplementation("org.apache.log4j.Logger", "com.alibaba.druid.support.logging.Log4jImpl");
        tryImplementation("org.apache.logging.log4j.Logger", "com.alibaba.druid.support.logging.Log4j2Impl");
        tryImplementation("org.slf4j.Logger", "com.alibaba.druid.support.logging.SLF4JImpl");
        tryImplementation("org.apache.commons.logging.LogFactory",
                          "com.alibaba.druid.support.logging.JakartaCommonsLoggingImpl");
        tryImplementation("java.util.logging.Logger", "com.alibaba.druid.support.logging.Jdk14LoggingImpl");

        if (logConstructor == null) {
            try {
                logConstructor = NoLoggingImpl.class.getConstructor(String.class);
            } catch (Exception e) {
                throw new IllegalStateException(e.getMessage(), e);
            }
        }
    }
    // ...
}

配置上启动参数后【-Ddruid.logType=slf4j】，有连接未正常关闭，就会打印如下日志：

2023-05-25 10:19:49.153 [TID:] [trace ] [userName ] [eid ] [Druid-ConnectionPool-Destroy-1392407412] ERROR com.alibaba.druid.pool.DruidDataSource - abandon connection, owner thread: pool-1-thread-2, connected at : 1684980819318, open stackTrace
	at java.lang.Thread.getStackTrace(Thread.java:1559)
	at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1140)
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4544)
	at com.alibaba.druid.filter.logging.LogFilter.dataSource_getConnection(LogFilter.java:854)
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4540)
	at com.alibaba.druid.filter.stat.StatFilter.dataSource_getConnection(StatFilter.java:670)
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4540)
	at com.alibaba.druid.filter.FilterAdapter.dataSource_getConnection(FilterAdapter.java:2723)
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4540)
	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1064)
	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1056)
	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:104)
	at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
	at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77)
	at org.mybatis.spring.transaction.SpringManagedTransaction.openConnection(SpringManagedTransaction.java:81)
	at org.mybatis.spring.transaction.SpringManagedTransaction.getConnection(SpringManagedTransaction.java:67)
	at com.github.miemiedev.mybatis.paginator.support.SQLHelp.getCount(SQLHelp.java:56)
	at com.github.miemiedev.mybatis.paginator.OffsetLimitInterceptor$2.call(OffsetLimitInterceptor.java:105)
	at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266)
	at java.util.concurrent.FutureTask.run(FutureTask.java)
	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:748)
ownerThread current state is TERMINATED, current stackTrace