生产程序报错
com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 5000, active 1
从报错信息来看，是数据库连接池获取连接池在规定时间内无法获取到有效连接，然后报错了。当前的druid版本为1.0.5
<dependency>
<groupId>com.alibaba</groupId>
<artifactId>druid</artifactId>
<version>1.0.5</version>
</dependency>
一般来说，一个程序根据并发度需要设置一个合理的连接池大小，如果连接池最大连接数比实际需要的连接数少，以上异常是很容易出现的。所以首先看下配置的最大连接池大小。而当前项目当中最大连接数设置为60，当前程序并发度并不是很高，60个最大连接也是合理的。
如果最大连接数没有问题，一般来说，连接泄漏也有可能造成连接池中没有连接可用。啥是连接泄漏呢？就是某处获取了连接池中的连接，但是没有释放。现在直接操作JDBC的Connection的机会可能比较少了，更多的是操作第三方的ORM框架。比如以下获取一个MyBatis的会话，然后进行各种操作，再关闭会话。如下所示
SqlSession sqlSession = sqlSessionFactory.openSession();
// .... 执行业务操作
sqlSession.close();
但是在这里可能会出现一些问题，如果执行业务操作时因为异常或者其他问题导致会话没有关闭，这样这个会话就会失去关闭的机会，而会话对应的是数据库的连接，这个连接就会一直存在（而不是正常回收），导致线程泄漏。所以对于这种资源回收必须仔细考虑，一般都是按照以下处理，将会话关闭的代码放到finally代码块当中。
SqlSession sqlSession = sqlSessionFactory.openSession();
try {
// .... 执行业务操作
} finally {
sqlSession.close();
}
通过版本工具查看了最近上线的代码，并没有发现有导致连接泄漏的代码。另外如果是线程泄漏导致的，报错信息里面的active 1应该是active 60。当然有些博客里面分析说，这里active的值不精确，
参考博客：记druid 连接池没满,但超时问题
但是，从现场报错来说，每次报错都是1，而且我们的程序并发度不高，因为并发问题导致active的计数出错不合理。
那么从这个点出发，我们认为目前正在使用（active）的连接数为1，并没有达到最大的线程数（maxActive），有点匪夷所思，所以研究一下源码。
@Override
public DruidPooledConnection getConnection() throws SQLException {
return getConnection(maxWait);
}
public DruidPooledConnection getConnection(long maxWaitMillis) throws SQLException {
init();
if (filters.size() > 0) {
FilterChainImpl filterChain = new FilterChainImpl(this);
return filterChain.dataSource_connect(this, maxWaitMillis);
} else {
return getConnectionDirect(maxWaitMillis);
}
}
这个获取连接的地方有一个init方法用于初始化（这个方法只会执行一次），getConnectionDirect用于获取连接。
在初始化方法中注意以下两个点：
- 根据配置参数initialSize创建连接存放到连接数组当中，比如我们程序当中设置为1，那么初始化就会往connections数组中放入一个连接，如果此时获取连接失败，会打印
init datasource error日志信息。
try {
// init connections
for (int i = 0, size = getInitialSize(); i < size; ++i) {
Connection conn = createPhysicalConnection();
DruidConnectionHolder holder = new DruidConnectionHolder(this, conn);
connections[poolingCount++] = holder;
}
if (poolingCount > 0) {
poolingPeak = poolingCount;
poolingPeakTime = System.currentTimeMillis();
}
} catch (SQLException ex) {
LOG.error("init datasource error", ex);
connectError = ex;
}
- 会创建三个线程分别用于打印日志、连接创建线程和连接销毁线程。如下所示
createAndLogThread();
createAndStartCreatorThread();
createAndStartDestroyThread();
这里只考虑创建线程的逻辑
protected void createAndStartCreatorThread() {
String threadName = "Druid-ConnectionPool-Create-" + System.identityHashCode(this);
createConnectionThread = new CreateConnectionThread(threadName);
createConnectionThread.start();
}
public void run() {
initedLatch.countDown();
int errorCount = 0;
for (;;) {
// addLast
try {
lock.lockInterruptibly();
} catch (InterruptedException e2) {
break;
}
try {
// 必须存在线程等待，才创建连接
if (poolingCount >= notEmptyWaitThreadCount) {
empty.await();
}
// 防止创建超过maxActive数量的连接
if (activeCount + poolingCount >= maxActive) {
empty.await();
continue;
}
} catch (InterruptedException e) {
lastCreateError = e;
lastErrorTimeMillis = System.currentTimeMillis();
break;
} finally {
lock.unlock();
}
Connection connection = null;
try {
connection = createPhysicalConnection();
} catch (SQLException e) {
LOG.error("create connection error", e);
errorCount++;
if (errorCount > connectionErrorRetryAttempts && timeBetweenConnectErrorMillis > 0) {
if (breakAfterAcquireFailure) {
break;
}
try {
Thread.sleep(timeBetweenConnectErrorMillis);
} catch (InterruptedException interruptEx) {
break;
}
}
} catch (RuntimeException e) {
LOG.error("create connection error", e);
continue;
} catch (Error e) {
LOG.error("create connection error", e);
break;
}
if (connection == null) {
continue;
}
DruidConnectionHolder holder = null;
try {
holder = new DruidConnectionHolder(DruidDataSource.this, connection);
} catch (SQLException ex) {
LOG.error("create connection holder error", ex);
break;
}
lock.lock();
try {
connections[poolingCount++] = holder;
if (poolingCount > poolingPeak) {
poolingPeak = poolingCount;
poolingPeakTime = System.currentTimeMillis();
}
errorCount = 0; // reset errorCount
notEmpty.signal();
notEmptySignalCount++;
} finally {
lock.unlock();
}
}
}
}
这里是一个无限循环去获取物理连接（createPhysicalConnection）的过程，开头与结尾的锁和等待逻辑这里不需要关注。主要看返回逻辑，有以下三种方式
- 正常逻辑，获取连接，然后包装为DruidConnectionHolder
- 获取连接失败，并不断尝试（connectionErrorRetryAttempts 默认为30次）而且timeBetweenConnectErrorMillis值大于0（默认成立），然后breakAfterAcquireFailure参数为true（默认为false），此处不成立。或者线程在等待着，被打断，此处也不成立。不过无论哪种获取连接失败的情况，会打印
create connection error的异常日志 - 创建包装类失败，此时会打印
create connection holder error异常日志。
以上两种异常都不会往connections数组中存放包装对象，也就是创建连接失败。
看过了连接创建的逻辑，再来看获取连接的逻辑，主要的逻辑在com.alibaba.druid.pool.DruidDataSource#getConnectionInternal方法当中。
获取连接的相关源码
if (maxWait > 0) {
holder = pollLast(nanos);
} else {
holder = takeLast();
}
一般来说，都会走到pollLast逻辑当中，
for (;;) {
if (poolingCount == 0) {
empty.signal(); // send signal to CreateThread create connection
if (estimate <= 0) {
waitNanosLocal.set(nanos - estimate);
return null;
}
notEmptyWaitThreadCount++;
if (notEmptyWaitThreadCount > notEmptyWaitThreadPeak) {
notEmptyWaitThreadPeak = notEmptyWaitThreadCount;
}
try {
long startEstimate = estimate;
estimate = notEmpty.awaitNanos(estimate); // signal by
// recycle or
// creator
notEmptyWaitCount++;
notEmptyWaitNanos += (startEstimate - estimate);
if (!enable) {
connectErrorCount.incrementAndGet();
throw new DataSourceDisableException();
}
} catch (InterruptedException ie) {
notEmpty.signal(); // propagate to non-interrupted thread
notEmptySignalCount++;
throw ie;
} finally {
notEmptyWaitThreadCount--;
}
if (poolingCount == 0) {
if (estimate > 0) {
continue;
}
waitNanosLocal.set(nanos - estimate);
return null;
}
}
poolingCount--;
DruidConnectionHolder last = connections[poolingCount];
connections[poolingCount] = null;
return last;
这里主要涉及两种情况，
- 池中存在连接（poolingCount不为0），会直接从池中拿走最后一个连接
- 池中不存在连接，会通知创建连接的线程（连接创建线程上面介绍过）创建连接。然后进入等待，等待又涉及两种情况，一种是创建连接很快就好了，现场创建线程就会通知获取连接的线程然后拿到连接退出，这也是正常的，但是还有另外一种情况，连接创建使用的时间超过了最大的等待时间（nanos），此时就不会再等待了，而是返回了一个null.对应逻辑
if (estimate <= 0) {
waitNanosLocal.set(nanos - estimate);
return null;
}
这个可以参考博客：记一次网络波动导致druid连接池无法创建新连接的BUG
一旦这边返回了null,那么最后都会因为连接为空而进入以下代码，抛出异常
if (holder == null) {
long waitNanos = waitNanosLocal.get();
StringBuilder buf = new StringBuilder();
buf.append("wait millis ")//
.append(waitNanos / (1000 * 1000))//
.append(", active " + activeCount)//
;
List<JdbcSqlStatValue> sqlList = this.getDataSourceStat().getRuningSqlList();
for (int i = 0; i < sqlList.size(); ++i) {
if (i != 0) {
buf.append('\n');
} else {
buf.append(", ");
}
JdbcSqlStatValue sql = sqlList.get(i);
buf.append("runningSqlCount ");
buf.append(sql.getRunningCount());
buf.append(" : ");
buf.append(sql.getSql());
}
String errorMessage = buf.toString();
if (this.createError != null) {
throw new GetConnectionTimeoutException(errorMessage, createError);
} else {
throw new GetConnectionTimeoutException(errorMessage);
}
}
综合报错信息和源码：不难得出一个结论，首先报错信息当中的active一直为1，恰好是初始化创建的连接个数，然后再次获取连接的时候，就进入了获取连接的过程，但是由于连接创建线程中创建线程出了超时问题（网络原因等），最后获取连接的线程等待超时，就抛出了异常。比如在创建物理连接的时候拔掉网线。
又或者在获取连接的时候在连接创建线程上打上断点卡住一段时间，获取连接的线程因为等待超时会抛出GetConnectionTimeoutException异常。
以上这两种情况都不是因为连接池满了或者连接泄漏导致的。
但是要验证以上的结论，就得有一些证明，此时能想到的就是日志。但是现场查找了日志，没有找到create connection error或者"create connection holder error"异常。经过分析发现，项目当中使用了logback日志框架，而这个版本的druid优先使用的是log4j.对应的源码参考com.alibaba.druid.support.logging.LogFactory。
static {
// TODO add slf4j logging
// 优先选择log4j,而非Apache Common Logging. 因为后者无法设置真实Log调用者的信息
tryImplementation("org.apache.log4j.Logger", "com.alibaba.druid.support.logging.Log4jImpl");
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);
}
}
}
这段代码完全COPY了MyBatis的逻辑，参考 MyBatis日志模块
如果项目当中没有涉及到Log4j，也不会有问题。但是老项目中，混杂了Log4J和Logback。最后再分析了一下依赖，没有将Log4J桥接到SLF4J的依赖包。添加依赖包
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>log4j-over-slf4j</artifactId>
<version>1.7.30</version>
</dependency>
此时就可以在日志中看到以下的日志了
2022-06-07 22:10:54,250 [Method=, URI=, IP=] [ERROR] [com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread:1651]-create connection error
java.sql.SQLRecoverableException: IO 错误: The Network Adapter could not establish the connection
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:489)
at oracle.jdbc.driver.PhysicalConnection.<init>(PhysicalConnection.java:553)
at oracle.jdbc.driver.T4CConnection.<init>(T4CConnection.java:254)
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:528)
at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:148)
at com.alibaba.druid.filter.FilterAdapter.connection_connect(FilterAdapter.java:786)
at com.alibaba.druid.filter.FilterEventAdapter.connection_connect(FilterEventAdapter.java:38)
at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:142)
at com.alibaba.druid.filter.stat.StatFilter.connection_connect(StatFilter.java:211)
at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:142)
at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1360)
at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1414)
at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:1649)
Caused by: oracle.net.ns.NetException: The Network Adapter could not establish the connection
7275
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
