一次druid数据库连接池连接泄露的排查分析

本文涉及的产品
Serverless 应用引擎免费试用套餐包,4320000 CU,有效期3个月
可观测可视化 Grafana 版,10个用户账号 1个月
容器镜像服务 ACR,镜像仓库100个 不限时长
简介: 一次druid数据库连接池连接泄露的排查分析

最近项目组某应用将数据库由Oracle切换到了TBase,遇到了数据库连接泄露导致无法创建新连接的问题,下面是问题的分析过程。

问题现象

应用侧异常日志

为了便于阅读,去掉了线程栈中不相关的栈帧。

com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 5000, active 0, maxActive 30, creating 0, createErrorCount 13047 
  at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1773) 
  at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1427) 
  at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5059) 
  at com.alibaba.druid.filter.logging.LogFilter.dataSource_getConnection(LogFilter.java:917) 
  at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5055) 
  at com.alibaba.druid.filter.stat.StatFilter.dataSource_getConnection(StatFilter.java:726) 
  at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5055) 
  at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1405) 
  at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1397) 
  at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:100) 
  at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:204) 
  at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) 
  at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:430) 
  at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:276) 
  at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) 
  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) 
  at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) 
  ... ...//省略的栈帧
  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.postgresql.util.PSQLException: FATAL: remaining connection slots are reserved for non-replication superuser connections 
  at org.postgresql.core.v3.ConnectionFactoryImpl.doAuthentication(ConnectionFactoryImpl.java:693) 
  at org.postgresql.core.v3.ConnectionFactoryImpl.tryConnect(ConnectionFactoryImpl.java:203) 
  at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:258) 
  at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:54) 
  at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:263) 
  at org.postgresql.Driver.makeConnection(Driver.java:443) 
  at org.postgresql.Driver.connect(Driver.java:297) 
  at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:156) 
  at com.alibaba.druid.filter.FilterAdapter.connection_connect(FilterAdapter.java:787) 
  at com.alibaba.druid.filter.FilterEventAdapter.connection_connect(FilterEventAdapter.java:38) 
  at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:150) 
  at com.alibaba.druid.filter.stat.StatFilter.connection_connect(StatFilter.java:251) 
  at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:150) 
  at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1659) 
  at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1723) 
  at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2838)

从上面线程栈可知,org.postgresql.util.PSQLException导致了com.alibaba.druid.pool.GetConnectionTimeoutException,所以org.postgresql.util.PSQLException是根因:FATAL: remaining connection slots are reserved for non-replication superuser connections,该异常表示TBase Server端该用户的连接数达到了阈值。接下来看一下TBase服务端连接数的情况。

TBase服务端连接数

从上图可知

  • 由于达到了TBase Server端连接数2000的阈值,所以导致了应用无法创建连接的异常;
  • 随着应用运行,连接数在慢慢增加,很明显存在连接泄露的问题。

基本信息

应用使用的druid连接池,版本是_druid-1.2.8;TBase JDBC Driver是postgresql-42.6.0;TBase Server版本是10.0 @ Tbase_v5.06.4.3 (commit: 6bd7f61dc)_。

JDK版本:

java version "1.8.0_65"
Java(TM) SE Runtime Environment (build 1.8.0_65-b17)
Java HotSpot(TM) 64-Bit Server VM (build 25.65-b01, mixed mode)

druid配置

druid配置包括两部分,分别是:Filter、DataSource。

Filter

<bean id="filter-log4j2" class="com.alibaba.druid.filter.logging.Log4j2Filter">
    <property name="connectionLogEnabled" value="true" />
    <property name="statementLogEnabled" value="true" />
    <property name="statementExecutableSqlLogEnable" value="true" />
    <property name="resultSetLogEnabled" value="false" />
</bean>

DataSource

<bean id="dataSource6" class="com.alibaba.druid.pool.DruidDataSource" init-method="init" destroy-method="close">
    <property name="driverClassName" value="org.postgresql.Driver" />
    <property name="url" value="${db.tbase.url}" />
    <property name="username" value="${db.tbase.username}" />
    <property name="password" value="${db.tabse.secpwd}" />
    <property name="initialSize" value="2" />
    <property name="minIdle" value="5" />
    <property name="maxActive" value="30" />
    <property name="maxWait" value="5000" />
    <property name="timeBetweenEvictionRunsMillis" value="60000" />
    <property name="minEvictableIdleTimeMillis" value="300000" />
    <property name="testWhileIdle" value="true" />
    <property name="testOnBorrow" value="false" />
    <property name="testOnReturn" value="false" />
    <property name="phyTimeoutMillis" value="1800000" />
    <property name="poolPreparedStatements" value="false" />
    <property name="maxPoolPreparedStatementPerConnectionSize" value="20" />
    <!-- 对泄漏的连接 自动关闭 -->
    <!-- 打开removeAbandoned功能 -->
    <property name="removeAbandoned" value="true" />
    <!-- 60秒,也就是1分钟 -->
    <property name="removeAbandonedTimeout" value="60" />
    <!-- 关闭abanded连接时输出错误日志 -->
    <property name="logAbandoned" value="true" />
    <!-- 配置监控统计拦截的filters -->
    <property name="filters" value="mergeStat" />
    <property name="proxyFilters">
        <list>
            <ref bean="filter-log4j2" />
        </list>
    </property>
    <property name="connectionProperties" value="druid.stat.slowSqlMillis=5000" />
</bean>

问题分析

removeAbandoned

数据库连接泄露,首先想到的是应用程序从数据库连接池获取到连接,使用完之后是否没有释放?

从上面的异常信息看是不存在这种情况的,因为active是0(即当前正在使用的连接数是0),为了便于理解,下面分析下druid这块的逻辑。

从上面可知,druid removeAbandoned相关配置为:

<!-- 对泄漏的连接 自动关闭 -->
<!-- 打开removeAbandoned功能 -->
<property name="removeAbandoned" value="true" />
<!-- 60秒,也就是1分钟 -->
<property name="removeAbandonedTimeout" value="60" />
<!-- 关闭abanded连接时输出错误日志 -->
<property name="logAbandoned" value="true" />

申请连接

以下代码在DruidDataSource类的getConnectionDirect方法中。

DruidPooledConnection poolableConnection ;
... ...
if (removeAbandoned) {
    StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
    poolableConnection.connectStackTrace = stackTrace;
    poolableConnection.setConnectedTimeNano();
    poolableConnection.traceEnable = true;
    activeConnectionLock.lock();
    try {
        activeConnections.put(poolableConnection, PRESENT);
    } finally {
        activeConnectionLock.unlock();
    }
}

释放连接

以下代码在DruidDataSource类的recycle方法中,该方法是在应用程序将连接归还给连接池的时候调用。

DruidPooledConnection poolableConnection ;
... ...
if (pooledConnection.traceEnable) {
    Object oldInfo = null;
    activeConnectionLock.lock();
    try {
        if (pooledConnection.traceEnable) {
            oldInfo = activeConnections.remove(pooledConnection);
            pooledConnection.traceEnable = false;
        }
    } finally {
        activeConnectionLock.unlock();
    }
    if (oldInfo == null) {
        if (LOG.isWarnEnabled()) {
            LOG.warn("remove abandonded failed. activeConnections.size " + activeConnections.size());
        }
    }
}

如果应用程序没有释放连接,activeConnections会有未释放连接的引用

释放泄露的连接

DruidDataSource中有个Druid-ConnectionPool-Destroy-XX的线程负责释放连接:

protected void createAndStartDestroyThread() {
    destroyTask = new DestroyTask();
    if (destroyScheduler != null) {
        long period = timeBetweenEvictionRunsMillis;
        if (period <= 0) {
            period = 1000;
        }
        destroySchedulerFuture = destroyScheduler.scheduleAtFixedRate(destroyTask, period, period,
                                                                      TimeUnit.MILLISECONDS);
        initedLatch.countDown();
        return;
    }
    String threadName = "Druid-ConnectionPool-Destroy-" + System.identityHashCode(this);
    destroyConnectionThread = new DestroyConnectionThread(threadName);
    destroyConnectionThread.start();
}

因为destroyScheduler是null,所以使用的是DestroyConnectionThread,每隔timeBetweenEvictionRunsMillis执行一次释放任务。

public class DestroyConnectionThread extends Thread {
    public DestroyConnectionThread(String name){
        super(name);
        this.setDaemon(true);
    }
    public void run() {
        initedLatch.countDown();
        for (;;) {
            // 从前面开始删除
            try {
                if (closed || closing) {
                    break;
                }
                if (timeBetweenEvictionRunsMillis > 0) {
                    Thread.sleep(timeBetweenEvictionRunsMillis);
                } else {
                    Thread.sleep(1000); //
                }
                if (Thread.interrupted()) {
                    break;
                }
                destroyTask.run();
            } catch (InterruptedException e) {
                break;
            }
        }
    }
}
public class DestroyTask implements Runnable {
    public DestroyTask() {
    }
    @Override
    public void run() {
        shrink(true, keepAlive);
        if (isRemoveAbandoned()) {
            removeAbandoned();
        }
    }
}
public int removeAbandoned() {
    int removeCount = 0;
    long currrentNanos = System.nanoTime();
    List<DruidPooledConnection> abandonedList = new ArrayList<DruidPooledConnection>();
    activeConnectionLock.lock();
    try {
        Iterator<DruidPooledConnection> iter = activeConnections.keySet().iterator();
        for (; iter.hasNext();) {
            DruidPooledConnection pooledConnection = iter.next();
            if (pooledConnection.isRunning()) {
                continue;
            }
            long timeMillis = (currrentNanos - pooledConnection.getConnectedTimeNano()) / (1000 * 1000);
            if (timeMillis >= removeAbandonedTimeoutMillis) {
                iter.remove();
                pooledConnection.setTraceEnable(false);
                abandonedList.add(pooledConnection);
            }
        }
    } finally {
        activeConnectionLock.unlock();
    }
    if (abandonedList.size() > 0) {
        for (DruidPooledConnection pooledConnection : abandonedList) {
            final ReentrantLock lock = pooledConnection.lock;
            lock.lock();
            try {
                if (pooledConnection.isDisable()) {
                    continue;
                }
            } finally {
                lock.unlock();
            }
          //释放连接
            JdbcUtils.close(pooledConnection);
            pooledConnection.abandond();
            removeAbandonedCount++;
            removeCount++;
          //打印日志
            if (isLogAbandoned()) {
                StringBuilder buf = new StringBuilder();
                buf.append("abandon connection, owner thread: ");
                buf.append(pooledConnection.getOwnerThread().getName());
                buf.append(", connected at : ");
                buf.append(pooledConnection.getConnectedTimeMillis());
                buf.append(", open stackTrace\n");
                StackTraceElement[] trace = pooledConnection.getConnectStackTrace();
                for (int i = 0; i < trace.length; i++) {
                    buf.append("\tat ");
                    buf.append(trace[i].toString());
                    buf.append("\n");
                }
                buf.append("ownerThread current state is " + pooledConnection.getOwnerThread().getState()
                           + ", current stackTrace\n");
                trace = pooledConnection.getOwnerThread().getStackTrace();
                for (int i = 0; i < trace.length; i++) {
                    buf.append("\tat ");
                    buf.append(trace[i].toString());
                    buf.append("\n");
                }
                LOG.error(buf.toString());
            }
        }
    }
    return removeCount;
}

从以上分析可知,即使应用没有释放连接,Druid-ConnectionPool-Destroy线程也会释放掉activeConnections中的连接(除非业务线程一直阻塞,连接处于running==true的状态,通过分析线程栈不存在这种情况)。

泄露的连接不是通过连接池申请的?

另一个可能的原因是泄露的连接不是通过连接池申请的,而是应用自己创建出来,但是没有执行关闭连接的操作。所以思路是拿到所有创建连接的线程栈,然后通过分析线程栈找到有哪些地方创建的连接,这里我们使用arthas的watch来完成。

//抓取PgConnection本地端口号和线程栈
watch org.postgresql.core.v3.ConnectionFactoryImpl openConnectionImpl "{returnObj.pgStream.connection.impl.localport,@org.apache.commons.lang3.exception.ExceptionUtils@getStackTrace(new java.lang.Exception())}" -n 99999999 > /xxx/xxx/xxx/xxx.txt &

TBase的数据库连接对象是org.postgresql.jdbc.PgConnection,在PgConnection初始化的时候会调用org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl。

生成的文件中记录了每个数据库连接的【本地端口号】和【线程栈】,通过对线程栈进行分析,发现数据库连接都是通过连接池创建出来的。下面是创建数据库连接的线程栈:

at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:330)
at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:54)
at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:263)
at org.postgresql.Driver.makeConnection(Driver.java:443)
at org.postgresql.Driver.connect(Driver.java:297)
at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:156)
at com.alibaba.druid.filter.FilterAdapter.connection_connect(FilterAdapter.java:787)
at com.alibaba.druid.filter.FilterEventAdapter.connection_connect(FilterEventAdapter.java:38)
at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:150)
at com.alibaba.druid.filter.stat.StatFilter.connection_connect(StatFilter.java:251)
at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:150)
at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1659)
at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1723)
at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2838)

既然数据库连接都是通过连接池创建出来的,那么数据库连接应该都是受到连接池管理的。

数据库连接池连接与netstat看到的不一致

既然连接都是连接池管理的,那么分析下连接池中的连接信息:

连接池中连接信息

//查看连接池信息
vmtool --action getInstances --className com.alibaba.druid.pool.DruidDataSource --express 'instances.{? #this.dbTypeName=="postgresql"}.{#this}'
//查看连接池中连接本地端口号
vmtool --action getInstances --className com.alibaba.druid.pool.DruidDataSource --express 'instances.{? #this.dbTypeName=="postgresql"}.{#this.connections[0].conn.connection.getQueryExecutor().pgStream.connection.impl.localport}' -x 1

netstat连接信息

netstat共查出8个连接,其中只有33946和33324是在连接池中的,其他6个都不在连接池中。

分析到这里,可以确定存在连接泄露,即有连接没有被关闭的情况,那么哪些地方进行了连接关闭呢?

连接关闭的路径有哪些?

上面已经抓取到了每个PgConnection的创建路径,现在抓取每个PgConnection的关闭路径,如果一个PgConnection有创建但是没有关闭,那么这个PgConnection就是泄露的连接。

//抓取PgConnection本地端口号和线程栈
watch org.postgresql.jdbc.PgConnection close "{target.getQueryExecutor().pgStream.connection.impl.localport,@org.apache.commons.lang3.exception.ExceptionUtils@getStackTrace(new java.lang.Exception()),throwExp}" -b -n 99999999 > /xxx/xxx/xxx/xxx.txt &

通过分析以上抓取的数据,关闭连接主要有两条路径:

通过业务路径:

at org.postgresql.jdbc.PgConnection.close(PgConnection.java:857)
at com.alibaba.druid.filter.FilterChainImpl.connection_close(FilterChainImpl.java:186)
at com.alibaba.druid.filter.FilterAdapter.connection_close(FilterAdapter.java:777)
at com.alibaba.druid.filter.logging.LogFilter.connection_close(LogFilter.java:481)
at com.alibaba.druid.filter.FilterChainImpl.connection_close(FilterChainImpl.java:181)
at com.alibaba.druid.filter.stat.StatFilter.connection_close(StatFilter.java:294)
at com.alibaba.druid.filter.FilterChainImpl.connection_close(FilterChainImpl.java:181)
at com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl.close(ConnectionProxyImpl.java:114)
at com.alibaba.druid.util.JdbcUtils.close(JdbcUtils.java:85)
at com.alibaba.druid.pool.DruidDataSource.discardConnection(DruidDataSource.java:1546)
at com.alibaba.druid.pool.DruidDataSource.recycle(DruidDataSource.java:2011)
at com.alibaba.druid.pool.DruidPooledConnection.recycle(DruidPooledConnection.java:351)
at com.alibaba.druid.filter.FilterChainImpl.dataSource_recycle(FilterChainImpl.java:5049)
at com.alibaba.druid.filter.logging.LogFilter.dataSource_releaseConnection(LogFilter.java:907)
at com.alibaba.druid.filter.FilterChainImpl.dataSource_recycle(FilterChainImpl.java:5045)
at com.alibaba.druid.filter.stat.StatFilter.dataSource_releaseConnection(StatFilter.java:711)
at com.alibaba.druid.filter.FilterChainImpl.dataSource_recycle(FilterChainImpl.java:5045)
at com.alibaba.druid.pool.DruidPooledConnection.syncClose(DruidPooledConnection.java:324)
at com.alibaba.druid.pool.DruidPooledConnection.close(DruidPooledConnection.java:270)
at org.springframework.jdbc.datasource.DataSourceUtils.doCloseConnection(DataSourceUtils.java:341)
at org.springframework.jdbc.datasource.DataSourceUtils.doReleaseConnection(DataSourceUtils.java:328)
at org.springframework.jdbc.datasource.DataSourceUtils.releaseConnection(DataSourceUtils.java:294)
at org.springframework.jdbc.datasource.DataSourceTransactionManager.doCleanupAfterCompletion(DataSourceTransactionManager.java:329)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.cleanupAfterCompletion(AbstractPlatformTransactionManager.java:1016)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:811)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:730)
at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:487)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:291)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
at com.sun.proxy.$Proxy303.xxxxxxx业务方法(Unknown Source)
at sun.reflect.GeneratedMethodAccessor149.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at com.taobao.hsf.remoting.provider.ReflectInvocationHandler.handleRequest0(ReflectInvocationHandler.java:83)

通过druid Destroy线程路径:

at org.postgresql.jdbc.PgConnection.close(PgConnection.java:857)
at com.alibaba.druid.filter.FilterChainImpl.connection_close(FilterChainImpl.java:186)
at com.alibaba.druid.filter.FilterAdapter.connection_close(FilterAdapter.java:777)
at com.alibaba.druid.filter.logging.LogFilter.connection_close(LogFilter.java:481)
at com.alibaba.druid.filter.FilterChainImpl.connection_close(FilterChainImpl.java:181)
at com.alibaba.druid.filter.stat.StatFilter.connection_close(StatFilter.java:294)
at com.alibaba.druid.filter.FilterChainImpl.connection_close(FilterChainImpl.java:181)
at com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl.close(ConnectionProxyImpl.java:114)
at com.alibaba.druid.util.JdbcUtils.close(JdbcUtils.java:85)
at com.alibaba.druid.pool.DruidDataSource.shrink(DruidDataSource.java:3194)
at com.alibaba.druid.pool.DruidDataSource$DestroyTask.run(DruidDataSource.java:2938)
at com.alibaba.druid.pool.DruidDataSource$DestroyConnectionThread.run(DruidDataSource.java:2922)

【抓取到的创建PgConnection的本地端口号】如果没有出现在【抓取的关闭PgConnection的本地端口号】中,那么这个本地端口号对应的连接就是没有被关闭的,通过与netstat查的端口号对比,是一致的,所以猜测没有调用到PgConnection.close或者调用PgConnection.close出现异常了?

连接池到底做没做释放连接的操作?

以下分别从宏观统计数据和单个未关闭连接的角度分析:数据库连接池到底做没做释放连接的操作。

宏观统计数据

druid记录了很多指标数据:

vmtool --action getInstances --className com.alibaba.druid.pool.DruidDataSource --express 'instances.{? #this.dbTypeName=="postgresql"}.{#this}'
vmtool --action getInstances --className com.alibaba.druid.pool.DruidDataSource --express 'instances.{? #this.dbTypeName=="postgresql"}.{#this.discardCount}'

图上几个关键字段说明如下:

序号 字段 说明
1 ActiveCount 当前正在被应用程序使用中的连接数量
2 PoolingCount 当前连接池中空闲的连接数量
3 CreateCount 连接池创建过的物理连接的数量
4 DestroyCount 连接池关闭过的物理连接的数量
5 ConnectCount 应用向连接池申请过的逻辑连接的数量
6 CloseCount 应用向连接池释放过的逻辑连接的数量
7 discardCount 关闭过的物理连接的数量,具体逻辑可以查看discardConnection和shrink方法中的逻辑

这里我们分析两个数据,分别是:

物理连接创建和关闭

通过对druid逻辑分析,得出公式:

CreateCount = ActiveCount + PoolingCount + DestroyCount + discardCount,

将数据代入以上公式,即:243 = 0 + 2 + 107 + 134。

逻辑连接申请和释放

通过对druid逻辑分析,得出公式:

ConnectCount = ActiveCount + CloseCount + discardCount,

将数据代入以上公式,即:212586 = 0 + 212452 + 134。

通过以上分析,从连接池的角度是已经释放连接了。

单个未关闭连接的角度

首先需要弄清楚连接池中几个关键对象的关系,当应用向连接池申请连接的时候,连接池返回给应用的是DruidPooledConnection;当应用归还连接到连接池的时候,调用的是DruidPooledConnection.close();某些条件下连接会被关闭。

应用向连接池申请连接

应用向连接池归还连接

归还连接的时候,代码不会走到com.alibaba.druid.util.JdbcUtils.close的逻辑。

关闭连接

如果一个PgConnection被关闭,那么与该PgConnection之前有关联的对象的状态会有变化,下面我们分析下与本地端口号是34802的PgConnection有关系的对象的状态。

DruidPooledConnection
vmtool --action getInstances --className com.alibaba.druid.pool.DruidPooledConnection --express 'instances.{? #this.conn!=null && #this.conn.dataSource.dbTypeName=="postgresql" && #this.conn.connection.getQueryExecutor().pgStream.connection.impl.localport==34802}.{#this.disable}' --limit 200000 -x 2

没有找到对应的对象,说明已经调用了DruidPooledConnection.close(),因为调用close后,会设置该对象的conn为null。

DruidConnectionHolder
vmtool --action getInstances --className com.alibaba.druid.pool.DruidConnectionHolder --express 'instances.{? #this.dataSource.dbTypeName=="postgresql" && #this.conn.connection.getQueryExecutor().pgStream.connection.impl.localport==34802}.{#this.discard}' --limit 20000

DruidConnectionHolder.discard=false,因为连接的关闭有两条路径:

  • 通过DestroyTask.run路径关闭,不会设置DruidConnectionHolder.discard为true,分析发现泄露连接的discard字段值都为false,所以泄露的连接是通过该路径执行的关闭
  • 通过DruidPooledConnection.close()路径关闭,会设置DruidConnectionHolder.discard为true
ConnectionProxyImpl
@Override
public void close() throws SQLException {
    FilterChainImpl chain = createChain();
    chain.connection_close(this);
    closeCount++;
    recycleFilterChain(chain);
}
vmtool --action getInstances --className com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl --express 'instances.{? #this.dataSource.dbTypeName=="postgresql" && #this.connection.getQueryExecutor().pgStream.connection.impl.localport==34802}.{#this.closeCount}' --limit 20000

ConnectionProxyImpl.closeCount=0,如果连接池正确关闭的话应该等于1。

PgConnection
@Override
public void close() throws SQLException {
    if (queryExecutor == null) {
      return;
    }
    if (queryExecutor.isClosed()) {
      return;
    }
    releaseTimer();
    queryExecutor.close();
    openStackTrace = null;
}
// queryExecutor.close()
@Override
public void close() {
    if (closed) {
      return;
    }
    try {
      LOGGER.log(Level.FINEST, " FE=> Terminate");
      sendCloseMessage();
      pgStream.flush();
      pgStream.close();
    } catch (IOException ioe) {
      LOGGER.log(Level.FINEST, "Discarding IOException on close:", ioe);
    }
    closed = true;
}
// pgStream.close()
@Override
public void close() throws IOException {
    if (encodingWriter != null) {
      encodingWriter.close();
    }
    pgOutput.close();
    pgInput.close();
    connection.close();
}

PgConnection.isClosed()=false,如果连接正确关闭的话应该等于true。

继续分析

从以上分析可知,泄露连接DruidConnectionHolder.discard都为false,所以发现问题的代码大概率出现在DestroyTask.run()方法中:该方法主要包括shrink方法和removeAbandoned方法,其中removeAbandoned方法已经在前面分析过,下面主要分析下shrink逻辑,shrink逻辑主要包括(我们的配置不涉及keepAlive处理逻辑):

【筛选出evictConnections和keepAliveConnections】、【从connections中去掉evictConnections和keepAliveConnections的连接】、【处理evictConnections和keepAliveConnections】。

连接池删除了连接,但是连接没close掉?

最开始怀疑问题出在【处理evictConnections和keepAliveConnections】,即在关闭连接的时候出现了异常,虽然连接池中删除了该连接,但是close该连接的时候并没有关闭干净,所以通过arthas watch抓取close阶段是否出现异常:

watch com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl close "{target.connection.getQueryExecutor().pgStream.connection.impl.localport,@org.apache.commons.lang3.exception.ExceptionUtils@getStackTrace(new java.lang.Exception())}" 'target.dataSource.dbTypeName=="postgresql"' -e > /xxx/xxx/xxx/error.txt &

结果没有抓到。

另外从PgConnection角度分析,如果PgConnection调用了close方法,那么PgConnection相关联的org.postgresql.core.QueryExecutorCloseAction类的PG_STREAM_UPDATER会变为null,而PG_STREAM_UPDATER并没有变为null。下面是QueryExecutorCloseAction中的方法:

@Override
public void close() throws IOException {
    ... ...
    PGStream pgStream = this.pgStream;
    if (pgStream == null || !PG_STREAM_UPDATER.compareAndSet(this, pgStream, null)) {
      // The connection has already been closed
      return;
    }
    sendCloseMessage(pgStream);
    if (pgStream.isClosed()) {
      return;
    }
    pgStream.flush();
    pgStream.close();
}

总上分析,泄露的连接压根就没有调用其close方法。

难道在【从connections中去掉evictConnections和keepAliveConnections的连接】阶段把连接弄丢了?

通过分析代码及翻找druid issues,出问题的代码主要在:

int removeCount = evictCount + keepAliveCount;
if (removeCount > 0) {
    System.arraycopy(connections, removeCount, connections, 0, poolingCount - removeCount);
    Arrays.fill(connections, poolingCount - removeCount, poolingCount, null);
    poolingCount -= removeCount;
}

问题大概是这样子的:

1.假设connections中有四个连接,分别是1001、1002、1003、1004,其中1001、1003被确认是evictConnection

2.去除connections中的evictConnection

从上面图中可以看出,最终把1002连接给弄丢了,所以该连接也不会再调用到close方法,导致了连接泄露。

解决办法

从druid 1.2.18开始对shrink逻辑进行了优化,可以尝试切换到新版本

相关实践学习
使用PolarDB和ECS搭建门户网站
本场景主要介绍基于PolarDB和ECS实现搭建门户网站。
阿里云数据库产品家族及特性
阿里云智能数据库产品团队一直致力于不断健全产品体系,提升产品性能,打磨产品功能,从而帮助客户实现更加极致的弹性能力、具备更强的扩展能力、并利用云设施进一步降低企业成本。以云原生+分布式为核心技术抓手,打造以自研的在线事务型(OLTP)数据库Polar DB和在线分析型(OLAP)数据库Analytic DB为代表的新一代企业级云原生数据库产品体系, 结合NoSQL数据库、数据库生态工具、云原生智能化数据库管控平台,为阿里巴巴经济体以及各个行业的企业客户和开发者提供从公共云到混合云再到私有云的完整解决方案,提供基于云基础设施进行数据从处理、到存储、再到计算与分析的一体化解决方案。本节课带你了解阿里云数据库产品家族及特性。
目录
相关文章
|
1月前
|
SQL 开发框架 .NET
ASP.NET连接SQL数据库:详细步骤与最佳实践指南ali01n.xinmi1009fan.com
随着Web开发技术的不断进步,ASP.NET已成为一种非常流行的Web应用程序开发框架。在ASP.NET项目中,我们经常需要与数据库进行交互,特别是SQL数据库。本文将详细介绍如何在ASP.NET项目中连接SQL数据库,并提供最佳实践指南以确保开发过程的稳定性和效率。一、准备工作在开始之前,请确保您
157 3
|
21天前
|
关系型数据库 MySQL 数据库连接
python脚本:连接数据库,检查直播流是否可用
【10月更文挑战第13天】本脚本使用 `mysql-connector-python` 连接MySQL数据库,检查 `live_streams` 表中每个直播流URL的可用性。通过 `requests` 库发送HTTP请求,输出每个URL的检查结果。需安装 `mysql-connector-python` 和 `requests` 库,并配置数据库连接参数。
120 68
|
17天前
|
SQL Java 数据库连接
在Java应用中,数据库访问常成为性能瓶颈。连接池技术通过预建立并复用数据库连接,有效减少连接开销,提升访问效率
在Java应用中,数据库访问常成为性能瓶颈。连接池技术通过预建立并复用数据库连接,有效减少连接开销,提升访问效率。本文介绍了连接池的工作原理、优势及实现方法,并提供了HikariCP的示例代码。
31 3
|
24天前
|
关系型数据库 MySQL 数据库连接
DBeaver如何连接一个数据库
【10月更文挑战第27天】DBeaver 是一款功能强大的通用数据库管理工具,支持多种主流数据库。本文介绍了使用 DBeaver 连接数据库的基本步骤,包括下载安装、创建新连接、选择数据库类型、配置连接参数、测试连接以及最终连接到数据库。详细的操作指南帮助用户轻松管理和操作数据库。
124 9
|
17天前
|
Java 数据库连接 数据库
深入探讨Java连接池技术如何通过复用数据库连接、减少连接建立和断开的开销,从而显著提升系统性能
在Java应用开发中,数据库操作常成为性能瓶颈。本文通过问题解答形式,深入探讨Java连接池技术如何通过复用数据库连接、减少连接建立和断开的开销,从而显著提升系统性能。文章介绍了连接池的优势、选择和使用方法,以及优化配置的技巧。
16 1
|
17天前
|
Java 数据库连接 数据库
Java连接池在数据库性能优化中的重要作用。连接池通过预先创建和管理数据库连接,避免了频繁创建和关闭连接的开销
本文深入探讨了Java连接池在数据库性能优化中的重要作用。连接池通过预先创建和管理数据库连接,避免了频繁创建和关闭连接的开销,显著提升了系统的响应速度和吞吐量。文章介绍了连接池的工作原理,并以HikariCP为例,展示了如何在Java应用中使用连接池。通过合理配置和优化,连接池技术能够有效提升应用性能。
32 1
|
26天前
|
SQL JavaScript 关系型数据库
node博客小项目:接口开发、连接mysql数据库
【10月更文挑战第14天】node博客小项目:接口开发、连接mysql数据库
|
1月前
|
Java 关系型数据库 MySQL
springboot学习五:springboot整合Mybatis 连接 mysql数据库
这篇文章是关于如何使用Spring Boot整合MyBatis来连接MySQL数据库,并进行基本的增删改查操作的教程。
69 0
springboot学习五:springboot整合Mybatis 连接 mysql数据库
|
20天前
|
SQL 关系型数据库 数据库连接
"Nacos 2.1.0版本数据库配置写入难题破解攻略:一步步教你排查连接、权限和配置问题,重启服务轻松解决!"
【10月更文挑战第23天】在使用Nacos 2.1.0版本时,可能会遇到无法将配置信息写入数据库的问题。本文将引导你逐步解决这一问题,包括检查数据库连接、用户权限、Nacos配置文件,并提供示例代码和详细步骤。通过这些方法,你可以有效解决配置写入失败的问题。
44 0
|
1月前
|
SQL 存储 监控
串口调试助手连接SQL数据库的技巧与方法
串口调试助手是电子工程师和软件开发人员常用的工具,它能够帮助用户进行串口通信的调试和数据分析