应用数据库操作报错问题排查

现象：

应用在高峰来临的时候报大量报下面的错误。

org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is
org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object
at org.springframework.orm.ibatis.SqlMapClientTemplate.execute(SqlMapClientTemplate.java:204)
at org.springframework.orm.ibatis.SqlMapClientTemplate.executeWithListResult(SqlMapClientTemplate.java:249)
at org.springframework.orm.ibatis.SqlMapClientTemplate.queryForList(SqlMapClientTemplate.java:296)

...................

Caused by: org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object
at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:114)
at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:113)
at org.springframework.orm.ibatis.SqlMapClientTemplate.execute(SqlMapClientTemplate.java:190)
... 33 more
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1134)
at org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:79)
at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
... 36 more

分析错误来源：

查看出错部分源码，发现出现这个问题出现的原因是数据库操作时超时了。

if(maxWait > 0 && ((System.currentTimeMillis() - starttime) >= maxWait)) {
synchronized(this) {
// Make sure allocate hasn't already assigned an object
// in a different thread or permitted a new object to be created
if (latch.getPair() == null && !latch.mayCreate()) {
// Remove latch from the allocation queue
_allocationQueue.remove(latch);
} else {
break;
}
}
throw new NoSuchElementException("Timeout waiting for idle object");
}

查看dbcp的数据源配置如下：

<property name="maxWait"><value>60000</value></property>
<property name="maxIdle"><value>14</value></property>

超时时间为60s，而调用量top的sql响应时间平均都在2～3ms左右，所以主要时间消耗应该是出现在获取数据库连接上面。

查看出现问题时的线程情况，发现线程有个大量的增长，多出了很多个数据库调用的线程，而数据库的连接池仅有14个，而等待队列用的是一个linkedList，及无限队列，如果调用量很大，队列过长，确实会出现大量60stimeout的情况。



然后查找线程池大量增长的原因。应用中有一个对外提供的接口，调用量比较大，而且接口中需要去好几个地方取数据，所以采用了多线程的方式来提高速度，线程池的配置如下。

executor = new ThreadPoolExecutor(10, 50, 3, TimeUnit.SECONDS,
new ArrayBlockingQueue<Runnable>(200));
executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());

corePoolSize=10
maxPoolSize=50
队列类型长度：ArrayBlockingQueue 200
reject策略：CallerRunsPolicy

首先前10个线程都通过threadFactory.newThread(w)获取新线程来跑，当池已经到达corePoolSize，则会把任务放入到队列中，已有线程通过获取队列中的任务来执行。当队列放满之后，再来新任务，则会继续通过threadFactory.newThread(w)获取新线程来执行，直到池到达50（maxPoolSize）。如果这个时候还有任务过来，则会按照设置的rejectedExecutionHandler的策略来执行（详细可查看ThreadPoolExecutor中的excute方法）。

rejectedExecutionHandler策略很简单，通过调用线程来执行。

当高并发的时候，线程池已经达到max并且队列已满，则确实会出现一个线程的大量增长。

public static class CallerRunsPolicy implements RejectedExecutionHandler {
public void rejectedExecution(Runnable r, ThreadPoolExecutor e) {
if (!e.isShutdown()) {
r.run();
}
}
}

推断：

高峰来的时候，首先的时候导致数据库调用的线程池增大，整体数据库调用的响应变慢，导致接口的多线程处理部分线程处理速度变慢，任务堆积，直到线程池和队列都满掉，直接通过工作线程来启动，导致更多线程来获取数据库连接线程，队列更长，知道最后，超过60s。

解决：

其实解决很好解决的，这个接口里面存在一个方法误用，本来这种大量调用的接口就不应该直接走数据库的，改成走缓存，问题解决。