APPARENT DEADLOCK!!! - C3P0连接池DeadLock机制分析
1 问题
近期,刚上线不久的生产系统的数据库连接池 C3P0 (版本为0.9.5.2)突然报出 APPARENT DEADLOCK!!! 错误。
1.1 错误日志
错误日志如下。
com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@7cf60134 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks! com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@7cf60134 -- APPARENT DEADLOCK!!! Complete Status: Managed Threads: 3 Active Threads: 3 Active Tasks: com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask@3ce7f8aa on thread: C3P0PooledConnectionPoolManager[identityToken->1hgepsj9u1w3a4je54sly0|70165722]-HelperThread-#1 com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask@17f3c7a1 on thread: C3P0PooledConnectionPoolManager[identityToken->1hgepsj9u1w3a4je54sly0|70165722]-HelperThread-#2 com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask@65dc473c on thread: C3P0PooledConnectionPoolManager[identityToken->1hgepsj9u1w3a4je54sly0|70165722]-HelperThread-#0 Pending Tasks: com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@744937e8 com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@77e8b363 com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@7eafacf0 com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@79cde1be com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@44067f18 com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@76c7bf50 Pool thread stack traces: Thread[C3P0PooledConnectionPoolManager[identityToken->1hgepsj9u1w3a4je54sly0|70165722]-HelperThread-#0,5,main] java.net.SocketInputStream.socketRead0(Native Method) java.net.SocketInputStream.socketRead(SocketInputStream.java:116) java.net.SocketInputStream.read(SocketInputStream.java:171) java.net.SocketInputStream.read(SocketInputStream.java:141) oracle.net.ns.Packet.receive(Unknown Source) oracle.net.ns.DataPacket.receive(Unknown Source) oracle.net.ns.NetInputStream.getNextPacket(Unknown Source) oracle.net.ns.NetInputStream.read(Unknown Source) oracle.net.ns.NetInputStream.read(Unknown Source) oracle.net.ns.NetInputStream.read(Unknown Source) oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1099) oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1070) oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:478) oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:213) oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:796) oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1031) oracle.jdbc.driver.T4CPreparedStatement.executeMaybeDescribe(T4CPreparedStatement.java:836) oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1124) oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3285) oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3329) oracle.jdbc.OracleDatabaseMetaData.getTables(OracleDatabaseMetaData.java:2471) com.mchange.v2.c3p0.impl.DefaultConnectionTester$1.activeCheckConnectionNoQuery(DefaultConnectionTester.java:84) com.mchange.v2.c3p0.impl.DefaultConnectionTester$3.activeCheckConnectionNoQuery(DefaultConnectionTester.java:182) com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnection(DefaultConnectionTester.java:275) com.mchange.v2.c3p0.AbstractConnectionTester.activeCheckConnection(AbstractConnectionTester.java:79) com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.testPooledConnection(C3P0PooledConnectionPool.java:504) com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.testPooledConnection(C3P0PooledConnectionPool.java:464) com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.refurbishIdleResource(C3P0PooledConnectionPool.java:436) com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask.run(BasicResourcePool.java:2211) com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696) Thread[C3P0PooledConnectionPoolManager[identityToken->1hgepsj9u1w3a4je54sly0|70165722]-HelperThread-#1,5,main] java.net.SocketInputStream.socketRead0(Native Method) java.net.SocketInputStream.socketRead(SocketInputStream.java:116) java.net.SocketInputStream.read(SocketInputStream.java:171) java.net.SocketInputStream.read(SocketInputStream.java:141) oracle.net.ns.Packet.receive(Unknown Source) oracle.net.ns.DataPacket.receive(Unknown Source) oracle.net.ns.NetInputStream.getNextPacket(Unknown Source) oracle.net.ns.NetInputStream.read(Unknown Source) oracle.net.ns.NetInputStream.read(Unknown Source) oracle.net.ns.NetInputStream.read(Unknown Source) oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1099) oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1070) oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:478) oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:213) oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:796) oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1031) oracle.jdbc.driver.T4CPreparedStatement.executeMaybeDescribe(T4CPreparedStatement.java:836) oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1124) oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3285) oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3329) oracle.jdbc.OracleDatabaseMetaData.getTables(OracleDatabaseMetaData.java:2471) com.mchange.v2.c3p0.impl.DefaultConnectionTester$1.activeCheckConnectionNoQuery(DefaultConnectionTester.java:84) com.mchange.v2.c3p0.impl.DefaultConnectionTester$3.activeCheckConnectionNoQuery(DefaultConnectionTester.java:182) com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnection(DefaultConnectionTester.java:275) com.mchange.v2.c3p0.AbstractConnectionTester.activeCheckConnection(AbstractConnectionTester.java:79) com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.testPooledConnection(C3P0PooledConnectionPool.java:504) com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.testPooledConnection(C3P0PooledConnectionPool.java:464) com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.refurbishIdleResource(C3P0PooledConnectionPool.java:436) com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask.run(BasicResourcePool.java:2211) com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696) Thread[C3P0PooledConnectionPoolManager[identityToken->1hgepsj9u1w3a4je54sly0|70165722]-HelperThread-#2,5,main] java.net.SocketInputStream.socketRead0(Native Method) java.net.SocketInputStream.socketRead(SocketInputStream.java:116) java.net.SocketInputStream.read(SocketInputStream.java:171) java.net.SocketInputStream.read(SocketInputStream.java:141) oracle.net.ns.Packet.receive(Unknown Source) oracle.net.ns.DataPacket.receive(Unknown Source) oracle.net.ns.NetInputStream.getNextPacket(Unknown Source) oracle.net.ns.NetInputStream.read(Unknown Source) oracle.net.ns.NetInputStream.read(Unknown Source) oracle.net.ns.NetInputStream.read(Unknown Source) oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1099) oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1070) oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:478) oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:213) oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:796) oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1031) oracle.jdbc.driver.T4CPreparedStatement.executeMaybeDescribe(T4CPreparedStatement.java:836) oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1124) oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3285) oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3329) oracle.jdbc.OracleDatabaseMetaData.getTables(OracleDatabaseMetaData.java:2471) com.mchange.v2.c3p0.impl.DefaultConnectionTester$1.activeCheckConnectionNoQuery(DefaultConnectionTester.java:84) com.mchange.v2.c3p0.impl.DefaultConnectionTester$3.activeCheckConnectionNoQuery(DefaultConnectionTester.java:182) com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnection(DefaultConnectionTester.java:275) com.mchange.v2.c3p0.AbstractConnectionTester.activeCheckConnection(AbstractConnectionTester.java:79) com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.testPooledConnection(C3P0PooledConnectionPool.java:504) com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.testPooledConnection(C3P0PooledConnectionPool.java:464) com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.refurbishIdleResource(C3P0PooledConnectionPool.java:436) com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask.run(BasicResourcePool.java:2211) com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696) Task com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask@65dc473c (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt(). Task com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask@3ce7f8aa (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt(). Task com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask@17f3c7a1 (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
上面的日志报出了 APPARENT DEADLOCK!!! 错误,然后输出了
ThreadPoolAsynchronousRunner 的状态,包括线程数,当前正在处理的任务,队列中等待处理的任务,以及 ThreadPoolAsynchronousRunner 任务线程的堆栈。
1.2 配置
生产上的配置如下。
<bean id="dataSource" class="com.mchange.v2.c3p0.ComboPooledDataSource" > <property name="driverClass" value="oracle.jdbc.driver.OracleDriver"></property> <property name="jdbcUrl" value="${datasource.jdbcUrl}"></property> <property name="user" value="${datasource.user}"></property> <property name="password" value="${datasource.pass}"></property> <property name="maxPoolSize" value="${datasource.maxPoolSize}"></property> <property name="maxIdleTime" value="180"></property> <property name="idleConnectionTestPeriod" value="60"></property> <property name="checkoutTimeout" value="30000"></property> </bean>
基本相当于使用默认配置。
1.3 初步判断
根据日志,C3P0判断其线程池(ThreadPoolAsynchronousRunner)中的任务出现死锁(DEADLOCK),此时线程处于检查空闲数据链接状态是否可用。单从日志字面暂时无法判断问题所在。
查阅了网上的资料,对此问题原因分析较少,绝大部分不甚了了。比较多的文章是尝试通过调整参数来避免问题的出现的帖子。
秉着 “知其所以然” 的态度,再加上一点点的好奇心,我翻阅了一下C3P0的代码,试图从中发现端倪。
2 C3P0的死锁(DeadLock)机制分析
2.1 C3P0类结构
为了后面展示代码的需要,先附上一个我整理的C3P0的类结构图,有助于我们分析问题时确定问题的位置。如果下面的图太小,可以点击这里浏览
我们重点关注右下角的几个类。
2.2 ThreadPoolAsynchronousRunner线程池
在 C3P0PooledConnectionPoolManager 类在初始化时中创建了一个taskRunner,其类型为 ThreadPoolAsynchronousRunner , 是一个 C3P0 自定实现的线程池。
public final class C3P0PooledConnectionPoolManager{ ... ThreadPoolAsynchronousRunner taskRunner; ... private synchronized void _poolsInit() { ... this.taskRunner = createTaskRunner( num_task_threads, matt, timer, idStr + "-HelperThread" ); ... } ... private ThreadPoolAsynchronousRunner createTaskRunner( int num_threads, int matt /* maxAdministrativeTaskTime */, Timer timer, String threadLabel ) { ... out = new ThreadPoolAsynchronousRunner( num_threads, true, timer, threadLabel ); return out; ... } ... }
ThreadPoolAsynchronousRunner 线程池被作为成员注入到多个对象之中,最终用于执行 BasicResourcePool 类中定义的 ScatteredAcquireTask, AcquireTask, RemoveTask, DestroyResourceTask, RefurbishCheckinResourceTask, AsyncTestIdleResourceTask 等任务。
我们来看一下 ThreadPoolAsynchronousRunner 的代码。
public final class ThreadPoolAsynchronousRunner implements AsynchronousRunner { ... TimerTask deadlockDetector = new DeadlockDetector(); ... public ThreadPoolAsynchronousRunner( int num_threads, boolean daemon, Timer sharedTimer, String threadLabel ) { this( num_threads, daemon, DFLT_MAX_INDIVIDUAL_TASK_TIME, DFLT_DEADLOCK_DETECTOR_INTERVAL, DFLT_INTERRUPT_DELAY_AFTER_APPARENT_DEADLOCK, sharedTimer, false, threadLabel ); } ... private ThreadPoolAsynchronousRunner( int num_threads, boolean daemon, int max_individual_task_time, int deadlock_detector_interval, int interrupt_delay_after_apparent_deadlock, Timer myTimer, boolean should_cancel_timer, String threadLabel ) { this.num_threads = num_threads; this.daemon = daemon; this.max_individual_task_time = max_individual_task_time; this.deadlock_detector_interval = deadlock_detector_interval; this.interrupt_delay_after_apparent_deadlock = interrupt_delay_after_apparent_deadlock; this.myTimer = myTimer; this.should_cancel_timer = should_cancel_timer; this.threadLabel = threadLabel; recreateThreadsAndTasks(); myTimer.schedule( deadlockDetector, deadlock_detector_interval, deadlock_detector_interval ); } ... }
可以看到, ThreadPoolAsynchronousRunner 线程池默认创建3个执行线程,并且创建了一个 死锁检测(DeadLockDetector) 的定时任务,默认情况下每10秒执行一次。
2.3 DeadLockDetector内部机制
public final class ThreadPoolAsynchronousRunner implements AsynchronousRunner { ... class DeadlockDetector extends TimerTask { LinkedList last = null; LinkedList current = null; public void run() { ... current = (LinkedList) pendingTasks.clone(); ... if ( current.equals( last ) ) { //System.err.println(this + " -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!"); ... recreateThreadsAndTasks(); run_stray_tasks = true; } ... if (run_stray_tasks) { AsynchronousRunner ar = new ThreadPerTaskAsynchronousRunner( DFLT_MAX_EMERGENCY_THREADS, max_individual_task_time ); for ( Iterator ii = current.iterator(); ii.hasNext(); ) ar.postRunnable( (Runnable) ii.next() ); ar.close( false ); //tell the emergency runner to close itself when its tasks are complete last = null; } else last = current; ...
可以看到,DeadLockDetector是
ThreadPoolAsynchronousRunner 的内部类,是一个默认每10秒执行一次的定时任务。其工作原理是定时检查任务队列(pendingTasks)中的任务,如果前后两次检查发现待执行的任务没有变化,就认为可能产生了死锁,并额外创建线程执行等待任务。
3 问题分析
3.1 线程等待
从代码中可以看出,APPARENT DEADLOCK!!!报错原因主要是ThreadPoolAsynchronousRunner线程池的中的等待任务队列在经过一定时长(默认10秒)前后没有变化。
结合问题日志。我们可以初步判断问题的原因,是由于某些任务(如日志中显示AsyncTestIdleResourceTask)执行过程中失去响应(超过60s没有收到响应),导致后续的任务长时间等待,进而报错。
3.2 具体分析
进而观察执行线程的堆栈,可以发现三个任务都在执行检测连接有效性时,向服务端发送请求数据后,Oracle数据库未返回响应,导致线程长时间等待。
由于此问题无法通过构造场景重现,只能猜测,产生这种原因可能是连接在服务端已经超时,由服务端主动关闭连接,但由于TCP协议断开连接需要完成4次握手,而服务端只完成了前两次握手,这样就导致了客户端可以发送消息但接收不到任何内容,长时间等待直到超时。
3.3 解决方案
根据以上分析,我认为问题是maxIdleTime(连接最大空闲时间)与idleConnectionTestPeriod(空闲检测周期)参数配置与数据库不匹配引起的。
根据DBA的建议,将maxIdleTime调整为30秒,将idleConnectionTestPeriod调整为10秒。
4 后续
调整完后系统稳定运行,至今未再报出同样的错误。
在查看资料的过程中,发现有与我类似的情况,请看这里。问题出在同一块代码,但现象与原因均与我不同。我并不认为这是C3P0的缺陷,而是具体环境上的配置没有相匹配。
我再说一点废话,C3P0中大量使用了synchronized关键字进行加锁,由于单例没有使用double-check,导致正常代码中大量加锁,在高并发下效率很低。因此,如果性能对系统较为重要,还是推荐大家使用HikariCP替换C3P0。
低调大师中文资讯倾力打造互联网数据资讯、行业资源、电子商务、移动互联网、网络营销平台。
持续更新报道IT业界、互联网、市场资讯、驱动更新,是最及时权威的产业资讯及硬件资讯报道平台。
转载内容版权归作者及来源网站所有,本站原创内容转载请注明来源。
- 上一篇
大数据技术的4个E
大数据的4个V说法在业界已经尽人皆知,这是指的大数据本身的特征。现在我们来考察一下用于处理大数据的技术应该具有的特性。为方便记忆,类似4个V,我们把这些特性总结成4个E,用户在选择大数据技术解决方案时可作为参考。 1. Easy 大数据技术要足够简单易用 这个E很容易理解。 要进行大数据处理的场景很多,涉及工作人员也是各种各样的。如果技术的难度太大,那会导致只有少数人能应用,而且实施复杂度较高,这样大数据的应用就会大打折扣了。 大数据领域这种例子并不少,Hadoop刚出来时只有MapReduce,相对于完全用Java硬写,MapReduce已经简单了很多,所以会积累出一批拥趸。但MapReduce的难度仍然不小,所以逐步被后来封装出来的HIVE SQL替代。Spark上的Scala也风靡过一阵,但难度仍然不少,目前也逐步归于平静,更多的人还是愿意使用更简单的Spark SQL。 2. Elastic 大数据技术要具有弹性扩展能力 这个E也容易理解。 很多情况下,大数据并不是一下子就很大,而是逐步变大的。即使已经较大的数据,也还会进一步变得更大。因此要求大数据处理技术有一定的弹性扩展能力...
- 下一篇
【Java入门提高篇】Day19 Java容器类详解(二)Map接口
上一篇里介绍了容器家族里的大族长——Collection接口,今天来看看容器家族里的二族长——Map接口。 Map也是容器家族的一个大分支,但里面的元素都是以键值对(key-value)的形式存放的,就像字典一样,用相应的key就可以拿到相应的value。 先来看看Map接口的内容,下面是阉割版的Map接口(去掉了defaultmethod),去掉的部分涉及Stream操作,属于Map的高级用法,所以暂时不做介绍。 import java.io.Serializable; import java.util.Collection; import java.util.Comparator; import java.util.Objects; import java.util.Set; public interface Map<K,V> { // 查询操作 /** * 返回键值对数量 */ int size(); /** * Map是否为空 */ boolean isEmpty(); /** * Map中是否包含指定的key */ boolean containsKey(Obje...
相关文章
文章评论
共有0条评论来说两句吧...
文章二维码
点击排行
推荐阅读
最新文章
- SpringBoot2整合Redis,开启缓存,提高访问速度
- CentOS关闭SELinux安全模块
- CentOS7编译安装Cmake3.16.3,解决mysql等软件编译问题
- Docker快速安装Oracle11G,搭建oracle11g学习环境
- Jdk安装(Linux,MacOS,Windows),包含三大操作系统的最全安装
- 设置Eclipse缩进为4个空格,增强代码规范
- MySQL8.0.19开启GTID主从同步CentOS8
- SpringBoot2整合MyBatis,连接MySql数据库做增删改查操作
- Docker安装Oracle12C,快速搭建Oracle学习环境
- CentOS7安装Docker,走上虚拟化容器引擎之路