Re: [c3p0-users] How to investigate an APPARENT DEADLOCK on helper threads

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

hi,

so this is an interesting one. usually a thread pool saturated with BasicResourcePool$ScatteredAcquireTask signifies a problem or bottleneck at the database, Connection acquisitions are neither succeeding nor failing with an Exception for a prolonged period of time.

however, in your case, all of the pool threads are blocked at https://github.com/swaldman/c3p0/blob/c3p0-0.9.2.1-final/src/java/com/mchange/v2/resourcepool/BasicResourcePool.java#L1095 , the first operation which requires the lock for your DataSource's com.mchange.v2.resourcepool.BasicResourcePool. this implies some other Thread, some thread not belonging to the Thread pool, is holding the resource pool's lock, and failing to release it for a long period of time.

unfortunately, it may not be easy to debug. if you can reliably reproduce this deadlock and the application visibly freezes prior to emitting the APPARENT DEADLOCK message, the best thing to do would be to use "jstack -l" during the pre-deadlock freeze. you'd then search for a Thread holding a com.mchange.v2.resourcepool.BasicResourcePool lock.

since timing a jstack snapshot to APPARENT DEADLOCKS may be difficult, perhaps a better solution would be for me to add an option to log stacktraces of all JVM Threads. i've added that to the latest snapshot version (of the mchange-commons-java library), which would be picked up as a transitive dependency of the latest snapshot c3p0-0.9.5-pre3. if that's convenient to use, you might give that a try. be sure logging [for com.mchange.v2.async.ThreadPoolAsynchronousRunner] is at the FINEST DEBUG/TRACE level that your logging library supports. you won't be able to see lock ownership, but look for a stack trace hung after crossing a com.mchange.v2.resourcepool.BasicResourcePool element.

good luck!

   smiles,
       steve

p.s. as long as Statement caching is off [ c3p0.maxStatementsPerConnection=0 and c3p0.maxStatements=0 ], c3p0.statementCacheNumDeferredCloseThreads does no good, and uselessly starts up a Thread. 

On May 8, 2013, at 1:00 AM, Jaco Prinsloo wrote:

> We have an issue where our production system grinds to a halt about once a day or so. Whenever this happens, c3p0 writes out an APPARENT DEADLOCK to our log files. We've investigated all we could think of, but we have not been able to determine the root cause.
> 
> What is the best way to investigate an APPARENT DEADLOCK error?
> Is there any additional logging we can configured, or perhaps scenarios that we can test?
> 
> We are using Hibernate 3.6 along with c3p0 0.9.2.1 on Oracle 10g 10.2.0.4.0.
> Our c3p0 configuration is as follow:
> 
> c3p0.minPoolSize=10
> c3p0.maxPoolSize=300
> c3p0.initialPoolSize=30
> c3p0.acquireIncrement=10
> c3p0.maxIdleTime=1800
> c3p0.maxStatementsPerConnection=0
> c3p0.statementCacheNumDeferredCloseThreads=1
> c3p0.numHelperThreads=8
> 
> Our logs contain:
> 
> 2013-05-07 14:50:36,914 WARN  [com.mchange.v2.async.ThreadPoolAsynchronousRunner] (C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-AdminTaskTimer) com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@1e279a93 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
> 2013-05-07 14:50:36,993 WARN  [com.mchange.v2.async.ThreadPoolAsynchronousRunner] (C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-AdminTaskTimer) com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@1e279a93 -- APPARENT DEADLOCK!!! Complete Status: 
> 	Managed Threads: 8
> 	Active Threads: 8
> 	Active Tasks: 
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@203e7717
> 			on thread: C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#0
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@64fc978a
> 			on thread: C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#7
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@34118d2
> 			on thread: C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#1
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@26c484a9
> 			on thread: C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#3
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@2fe18721
> 			on thread: C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#2
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@7f6ea015
> 			on thread: C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#4
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@37d0040f
> 			on thread: C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#5
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@39ba9169
> 			on thread: C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#6
> 	Pending Tasks: 
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@7a0a21b
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@42f29e86
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@468591c0
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@6b23f86b
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@68a6fc1
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@6aaeeb41
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@1d72f1f
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@56569d2a
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@50685cae
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@739cccbf
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@3b464ae5
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@3df1eca
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@2d5e61c2
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@f641ed3
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@7623b689
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@22a518f7
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@50a11e6
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@581d159f
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@5d76a6ea
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@18c87c96
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@126b6890
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@499dcf62
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@179a50b0
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@14275eeb
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@24c8a0a3
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@6faa4032
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@125ccbe4
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@a4def27
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@28feeba
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@3781f6a6
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@356828c2
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@494bf3f2
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@197cba76
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@4bb5a60c
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@2a884a9
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@59d749c
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@2452b0a5
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@30cb3344
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@6c92ce62
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@1a2bbb9e
> 		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@2d2a8f7e
> Pool thread stack traces:
> 	Thread[C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#0,5,jboss]
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1095)
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1073)
> 		com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:44)
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1810)
> 		com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:648)
> 	Thread[C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#7,5,jboss]
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1095)
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1073)
> 		com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:44)
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1810)
> 		com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:648)
> 	Thread[C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#3,5,jboss]
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1095)
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1073)
> 		com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:44)
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1810)
> 		com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:648)
> 	Thread[C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#1,5,jboss]
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1095)
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1073)
> 		com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:44)
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1810)
> 		com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:648)
> 	Thread[C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#2,5,jboss]
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1095)
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1073)
> 		com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:44)
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1810)
> 		com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:648)
> 	Thread[C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#5,5,jboss]
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1095)
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1073)
> 		com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:44)
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1810)
> 		com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:648)
> 	Thread[C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#4,5,jboss]
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1095)
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1073)
> 		com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:44)
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1810)
> 		com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:648)
> 	Thread[C3P0PooledConnectionPoolManager[identityToken->1j80f518uz8nrkyjg7xop|5baa8b76]-HelperThread-#6,5,jboss]
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1095)
> 		com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1073)
> 		com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:44)
> 		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1810)
> 		com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:648)
> 
> Any help or advice will be appreciated.
> 
> Thank you,
> Jaco
> ------------------------------------------------------------------------------
> Learn Graph Databases - Download FREE O'Reilly Book
> "Graph Databases" is the definitive new guide to graph databases and 
> their applications. This 200-page book is written by three acclaimed 
> leaders in the field. The early access version is available now. 
> Download your free book today! http://p.sf.net/sfu/neotech_d2d_may_______________________________________________
> c3p0-users mailing list
> c3p...@li...
> https://lists.sourceforge.net/lists/listinfo/c3p0-users