【解决方案】c3p0 APPARENT DEADLOCK创建紧急线程

前言：最近碰见了一个非常稀奇古怪的问题，查遍google和baidu，只有2个人碰见的类似，但都还有差异，就此对c3p0产生

APPARENT DEADLOCK 的现象分析一遍

现象：8月10日晚18:20分左右，当日无发布的情况下，突然抛出一个这个异常，导致系统响应变慢，之后的3天内，均产生大量的异常，系统应用oracle数据库。

异常如下：

Java代码  

1.  // 片段1:  
2.     Caused by: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: An   attempt by a client to checkout a Connection has timed out.  
3.     at <span style="color: #0000ff;">org.springframework.orm.ibatis.SqlMapClientTemplate.execute</span>  
4.   
5.   
6. (SqlMapClientTemplate.java:204)  
7.  // 片段2:  
8.     Caused by: java.sql.SQLException: An attempt by a client to checkout a Connection has timed out.  
9.     at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106)  
10.     at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:65)  
11.     at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:527)  
12.     at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)  
13.     at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:113)  
14.     at org.springframework.orm.ibatis.SqlMapClientTemplate.execute(SqlMapClientTemplate.java:190)  
15.     ... 81 more  
16.     Caused by: com.mchange.v2.resourcepool.TimeoutException: A client timed out while waiting to acquire a resource from com.mchange.v2.resourcepool.BasicResourcePool@5db533b0 -- timeout at awaitAvailable()  
17.     <span style="color: #800080;">at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable</span>  
18.   
19.   
20. (BasicResourcePool.java:1317)  
21.     at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)  
22.     at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)  
23.     at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)  
24.     ... 84 more  
25.   //  片段3:  
26. 2012-08-16 09:11:41,346:WARN Timer-1 com.mchange.v2.async.ThreadPoolAsynchronousRunner - Task com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@430e820d (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().  
27. 2012-08-16 09:11:41,346:WARN Timer-1 com.mchange.v2.async.ThreadPoolAsynchronousRunner - Task com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@6d7c45df (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().  
28. 2012-08-16 09:11:41,346:WARN Timer-1 com.mchange.v2.async.ThreadPoolAsynchronousRunner - Task com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@79cf6ba0 (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().  
29. 2012-08-16 09:11:41,354:WARN Timer-1 com.mchange.v2.async.ThreadPoolAsynchronousRunner - com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@6f853a49 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!  
30. 2012-08-16 09:11:41,356:WARN Timer-1 com.mchange.v2.async.ThreadPoolAsynchronousRunner - com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@6f853a49 -- APPARENT DEADLOCK!!! Complete Status:  
31.     Managed Threads: 3  
32.     Active Threads: 3  
33.     Active Tasks:  
34.         com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@264e25ab (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2)  
35.         com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@548b1132 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0)  
36.         com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@761614fa (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1)  
37.     Pending Tasks:  
38.         com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@23bb65a7  
39.         com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@640ec944  
40.         com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@6bfc2ae  
41.         com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@178630f8  
42.         com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@6af8f5d8  
43. Pool thread stack traces:  
44.     Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2,5,main]  
45.         <span style="color: #ff0000;">oracle.jdbc.driver.OracleStatement.close</span>  
46.   
47.   
48. (OracleStatement.java:1340)  
49.         com.alibaba.china.jdbc.proxy.simple.StatementProxy.close(StatementProxy.java:61)  
50.         com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)  
51.         com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)  
52.         com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)  
53.     Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0,5,main]  
54.         <span style="color: #ff0000;">oracle.jdbc.driver.OracleStatement.close</span>  
55.   
56.   
57. (OracleStatement.java:1340)  
58.         com.alibaba.china.jdbc.proxy.simple.StatementProxy.close(StatementProxy.java:61)  
59.         com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)  
60.         com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)  
61.         com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)  
62.     Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1,5,main]  
63.         <span style="color: #ff0000;">oracle.jdbc.driver.OracleStatement.close</span>  
64.   
65.   
66. (OracleStatement.java:1340)  
67.         com.alibaba.china.jdbc.proxy.simple.StatementProxy.close(StatementProxy.java:61)  
68.         com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)  
69.         com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)  
70.         com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)  

 日志里已经很明确了，无法获取JDBC连接，向SA和DBA询问后，机器网络和数据库都良好。

 晕了。。。当日无发布的情况下，运行1年的系统突然抛这个错误，尼玛坑爹啊！

 继续分析，翻遍google和百度，发现出现c3p0的DEADLOCK的原因有很多种，很大一部分是网络问题。但我这个，请看“红色”的异常，均在oracle驱动close的时候抛错，如果是网络问题，应该能看见net或socket什么的，不是网络……

 

这里有3篇文章。

1.c3p0开发者描述（第5楼）：https://forum.hibernate.org/viewtopic.php?t=947246&highlight=apparent+deadlock+c3p0

2. c3p0防死锁配置（跟我异常一样）：https://forum.hibernate.org/viewtopic.php?p=2390809

其中介绍了maxAdministrativeTaskTime和 numHelperThreads，仔细看这两个配置，第一个会中断你的程序，可能不安全。

 

3. 这位仁兄分析，他帖子最后 ： http://www.iteye.com/topic/1117330

 

看一下当时出错的系统线程情况：

可以看到，block的线程数很多。

 

在放大数据库连接池无效，排除jms消息对数据库压力无效的情况下。

 

换c3p0为dbcp，得以解决（其实是一种绕过问题的方法，从一个坑跳到另一个，但暂时解决了问题）。

 

附上c3p0配置：

Xml代码  

1. <bean id="dataSource" class="org.apache.commons.dbcp.BasicDataSource">  
2.         <property name="validationQuery">  
3.             <value>select 1 from dual</value>  
4.         </property>  
5.         <property name="driverClassName">  
6.             <value>数据库驱动</value>  
7.         </property>  
8.         <property name="url">  
9.             <value>数据库url</value>  
10.         </property>  
11.         <property name="username">  
12.             <value>用户名</value>  
13.         </property>  
14.         <property name="password">  
15.             <value>密码</value>  
16.         </property>  
17.         <property name="initialSize">  
18.             <value>3</value>  
19.         </property>  
20.         <property name="maxActive">  
21.             <value>20</value>  
22.         </property>  
23.         <property name="maxIdle">  
24.             <value>20</value>  
25.         </property>  
26.         <property name="maxWait">  
27.             <value>1000</value>  
28.         </property>  
29.         <property name="minIdle">  
30.             <value>3</value>  
31.         </property>  
32.         <property name="testWhileIdle"><value>true</value></property>  
33.         <property name="testOnBorrow"><value>false</value></property>  
34.         <property name="timeBetweenEvictionRunsMillis"><value>10000</value></property>  
35.     </bean>  

 

 

我实验了一下，放大当数据库连接池耗尽时一次获取数据库连接的个数，无效。

而这个参数 c3p0.maxStatements=0 没有设置，因为在生产环境，机会不多。希望有实验成功正在处理解决方法的

人能回复一下解决方案，大家多多交流。

 

我对此问题的看法：估计是c3p0在很多跟数据库交互很频繁并短促的情况下，c3p0 cache住了准备语句，造成了close时

死锁，死锁的是c3p0内部线程池，并不是数据库，就如第三个帖子中的描述一样。后面分析一下c3p0的源码，再仔细分析。