javac3p0

Understanding "APPARENT DEADLOCK!!! Complete Status" details


I have posted a small part of a log below from which I would really appreciate if someone can decode the following:

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.


Solution

  • 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