开发的系统使用了Spring JdbcTemplate + c3p0组合,在做性能测试的时候出现了严重的性能问题。40的并发访问,开始的时候系统正常,等过了几分钟后,应用程序不能访问了。停止40并发的压力 后,过1分钟左右又可以正常访问应用程序了,很迷茫。后台log文件有警告信息:
Java代码- 2011-11-01 13:48:39,378 [com.mchange.v2.async.ThreadPoolAsynchronousRunner:435]
- -[WARN] com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@4ec5571b
- -- APPARENT DEADLOCK!!!
- Complete Status: [num_managed_threads: 10, num_active: 10; activeTasks: com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@7dd9d603 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#6), com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@68719f81 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#9), com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@7b9f03b8 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#7),
把c3p0换为DBCP后,系统可以正常进行性能测试,访问正常,判定c3p0存在bug。
上网查找资料,发现很多人也遇到了"APPARENT DEADLOCK"的问题
Java代码- http://www.iteye.com/topic/71051
- http://www.iteye.com/topic/22160
- http://www.iteye.com/topic/87313
- http://www.iteye.com/topic/429677
- https://forum.hibernate.org/viewtopic.php?f=1&t=947246&sid=ad2b8cc3213c9dac834d81b55bbf6291
没有找到解决答案,但是基本了解了c3p0的运行原理。c3p0在从连接池中获取和返回连接的时候,采用了异步的处理方式,使用一个线程池来异步的 把返回关闭了(没有真正关闭)的连接放入连接池中。这样就意味着,我们在调用了从c3p0获得的连接的close方法时,不是立即放回池中的,而是放入一 个事件队列中等待c3p0内部的线程池顺序的处理。
c3p0中有2个参数和内部的连接池有关,分别是:maxAdministrativeTaskTime、 numHelperThreads
其含义的官方描述在:
Java代码- http://www.mchange.com/projects/c3p0/index.html
其中maxAdministrativeTaskTime含义中说了c3p0中的很多功能不是由 client threads完成的,是通过内部线程池完成的,如果某些内部功能“挂起”了线程池中的线程,那线程池中的线程将被耗尽,其最后结果就是c3p0停止响应了。
其中通过查看c3p0的源码,可以看出那些功能是需要内部线程池处理的:
Java代码
- expandPool -- 在扩大池中连接的时候,如管理的连接从20扩大到40个
- shrinkPool -- 在缩小连接池的时候,这个过程需要真正关闭一些连接
- doCheckinManaged -- 把连接返回给连接池
- checkIdleResources -- 定时检查池中的连接
遇到上面的“APPARENT DEADLOCK”警告就是由于c3p0内部线程池的所有线程都被挂起而造成的,因此官方文档说把numHelperThreads设置大一些可以有效避免这个警告。但是这种方法只能延缓问题的出现,并不能避免整个应用被挂起的问题。
仔细查看log日志,会发现都是那些任务占据了宝贵的线程:
Java代码
- [com.mchange.v2.async.ThreadPoolAsynchronousRunner:435]-[WARN] com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@4ec5571b
- -- APPARENT DEADLOCK!!! Complete Status: [num_managed_threads: 10, num_active: 10;
- activeTasks:
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@7dd9d603 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#6),
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@68719f81 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#9),
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@7b9f03b8 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#7),
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@4ad6470 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#4),
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@139cf776 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0),
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@263a6e09 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2),
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@460e247a (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#3),
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@4a7ce984 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1),
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@4ec6ff50 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#5),
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@6aa40597 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#8);
- pendingTasks:
- com.mchange.v2.resourcepool.BasicResourcePool$6@366b3333,
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@37ee752e,
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@84f3bb2,
- com.mchange.v2.resourcepool.BasicResourcePool$6@9d82761,
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@4e015653,
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@39ca8b27,
- com.mchange.v2.resourcepool.BasicResourcePool$6@2075cb15,
- com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@1567e059,
- com.mchange.v2.resourcepool.BasicResourcePool$6@56b9fe09,
可以看到AcquireTask占用了内部线程池的所有线程,没有线程可以来执行BasicResourcePool$6对应的任务,而这个任务的作用就是把池外使用完的连接放回池内的,c3p0被挂起了。
maxAdministrativeTaskTime用于定时检查任务列表,如果activeTasks列表在2次检查中一致,那么c3p0就会认为APPARENT DEADLOCK了,会interrept所有任务,重新排队,因此c3p0会自动恢复正常。
我的解决方法是用单独的线程来处理“归还”连接的任务,因为这个任务的优先级最高,而且耗费的时间很短。
上传我修改后的 c3p0 jar包,只改了一个文件:BasicResourcePool
c3p0的确存在问题,大家不要怀疑我写的程序有问题
我写了一个测试程序,模拟c3p0在压力很大的时候的运行状态,说明如下:
1 JDBC是自己写的一个mock,也就是一个自定义java.sql.Driver,前20个连接马上生成返回,后面的连接需要15秒才能生成(模拟数据库繁忙,生成连接慢)
2 测试线程从1开始,每1秒增加一个测试线程,最终会达到100个线程
3 每一秒种输出一句log,包含的信息有:测试线程数(totalThreads)、正在处理con的线程数(dealConThreads)、处理con的总次数(dealConCount)
c3p0配置如下:
Java代码- cpds.setDriverClass("com.thunisoft.test.jdbcmock.TestDriver");
- cpds.setJdbcUrl( "jdbc:test://192.168.0.1/test" );
- cpds.setUser("user");
- cpds.setPassword("123456");
- cpds.setAcquireIncrement(20);
- cpds.setInitialPoolSize(20);
- cpds.setMaxPoolSize(200);
- cpds.setMinPoolSize(20);
其中使用c3p0-0.9.1.2.jar在20个线程的时候,基本处于挂起状态了,随后就会报 DEADLOCK 的警告
使用c3p0-0.9.1.2_fix_APPARENT_DEADLOCK.jar也会报 DEADLOCK 的警告,但是不会被挂起,可以继续提供连接给测试线程,只是能提供的线程少于线程总数。
发生 DEADLOCK 的前提条件:
1 连接池会进行expandPool操作,因为这样才能产生AcquireTask对象,这个对象会阻塞内部连接池,因此,如果把minPoolSize和maxPoolSize设置为一样大可以避免这个问题
2 AcquireTask的执行持续很长时间,要大于10秒,在实际环境中是有可能放生的
3 acquireIncrement要大于numHelperThreads,这样才有可能把所有内部线程都占用
4 连接池的访问压力要很大,压力线程数要大于连接池现有的连接数