I have posted a small part of a log below from which I would really appreciate if someone can decode the following:
- List item
- Managed Threads
- Active Threads
- Active Tasks
- Pending Tasks
- Pool thread stack traces
I have the following C3PO configuration:
c3p0.minPoolSize=10 c3p0.maxPoolSize=40 c3p0.acquireIncrement=5 c3p0.maxIdleTime=1800 c3p0.maxStatements=50 c3p0.idleConnectionTestPeriod=180
This is the Log:
09-02@12:28:43 WARN ThreadPoolAsynchronousRunner [Timer-0] - com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@700ec336 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
09-02@12:28:43 WARN ThreadPoolAsynchronousRunner [Timer-0] - com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@700ec336 -- APPARENT DEADLOCK!!! Complete Status:
Managed Threads: 3
Active Threads: 3
Active Tasks:
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@34ac7f2c (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1)
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@28d13cb8 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0)
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@40e968f7 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2)
Pending Tasks:
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@1bea516c
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@348797c5
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@31fd2174
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@619f604f
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@266c149b
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@1bcdfd2
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@170a54e2
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@274acd3f
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@1fe8f740
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@77c09b1d
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@607ca57
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@697518d8
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@6b242ff
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@214c76c8
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@230a558c
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@7b766c4c
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@1bc030e7
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@66ca9bec
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@7fc2d7ac
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@50dd9ebb
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@5e03077
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@418dd7a4
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@4748719b
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@651a9bac
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@35e26d0f
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@24660f6c
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@287e8e1f
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@ca4a9fe
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@e94692e
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@3185527c
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@27ea644a
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@d5e4abf
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@297d4874
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@601fccf3
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@47c896d2
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@4225d9cf
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@42fec6f6
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@64b862d6
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@5610343
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@241d2677
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@75c86126
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@36624233
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@6ce83e29
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@3492d9b
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@39511ccc
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@7c39b279
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@2ff465a6
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@563d8de2
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@632e1ca9
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@685bce1d
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@63390771
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@3517be9b
Pool thread stack traces:
Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0,5,main]
com.mysql.jdbc.StatementImpl.close(StatementImpl.java:575)
com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2,5,main]
com.mysql.jdbc.StatementImpl.close(StatementImpl.java:575)
com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1,5,main]
com.mysql.jdbc.StatementImpl.close(StatementImpl.java:575)
com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
Some information on the apparent deadlock would be appreciated.
Advertisement
Answer
The thread pool contains 3 threads. (“Managed Threads”). All 3 of them are “active”, trying to complete a task. (“Active Threads”), there are no dormant threads ready to take on work. The tasks are listed. They are all cached-statement close tasks.
An APPARENT DEADLOCK is triggered when all tasks in thread pool have remained the same for a long period of time. c3p0 (the thread pool library beneath it really) eventually assumes, if no task has managed to complete in the pool, that the pool is deadlocked. The library interrupt()s and then discards those Threads, and replaces them with new ones so that other tasks (you have a long task backlog, “Pending Tasks”) can try to run.
In your case, the issue is a well-known one. Some JDBC drivers’ Statement.close() operation may deadlock if their parent Connection is in use. For these (formally out-of-spec) drivers, c3p0 implements a cautious Statement close strategy, in which Statement destruction is tasked asynchronously and only performed when the parent Connection is known not to be in use.
TL; DR: set statementCacheNumDeferredCloseThreads to one.
c3p0.statementCacheNumDeferredCloseThreads=1