Recurring apparent deadlocks with c3p0, Oracle and Hibernate

Question

We have recurring apparent deadlocks on our production system which we can't seem to get to the bottom of. We've been unable to trace any correlation to the number of users online and it doesn't seem like we are running out of available connections.

We have a Java EE application connecting to Oracle through Hibernate and c3p0. Our c3p0 configuration is:

minPoolSize=10
maxPoolSize=300
initialPoolSize=30
acquireIncrement=10
maxIdleTime=1800
maxStatementsPerConnection=0
numHelperThreads=5

The apparent deadlock log output always looks more or less like this:

[com.mchange.v2.async.ThreadPoolAsynchronousRunner] (Timer-1) com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@4c9f1b4d -- APPARENT DEADLOCK!!! Complete Status:
    Managed Threads: 5
    Active Threads: 5
    Active Tasks:
            com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@7fe1ab86 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1)
            com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@38c42c01 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2)
            com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@572512c4 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#4)
            com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@42f32e8e (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0)
            com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@6b758ef8 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#3)
    Pending Tasks:
            com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@72fd72e5
            com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@5d82535d
            com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@172f2ea1
            com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@1a9e57eb
            com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@20ee5a35

The actual pool thread stack traces differ, and I've added some examples below:

Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#4,5,jboss]
            java.lang.AbstractStringBuilder.<init>(AbstractStringBuilder.java:45)
            java.lang.StringBuilder.<init>(StringBuilder.java:80)
            oracle.net.ns.Packet.<init>(Packet.java:513)
            oracle.net.ns.ConnectPacket.<init>(ConnectPacket.java:64)
            oracle.net.ns.NSProtocol.connect(NSProtocol.java:278)
            oracle.jdbc.driver.T4CConnection.connect(T4CConnection.java:1042)
            oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:301)
            oracle.jdbc.driver.PhysicalConnection.<init>(PhysicalConnection.java:531)
            oracle.jdbc.driver.T4CConnection.<init>(T4CConnection.java:221)
            oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
            oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:503)
            com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:135)
            com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:182)
            com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:171)

Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2,5,jboss]
            oracle.jdbc.driver.T4CTTIoauthenticate.processRPA(T4CTTIoauthenticate.java:491)
            oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:295)
            oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:186)
            oracle.jdbc.driver.T4CTTIoauthenticate.doOSESSKEY(T4CTTIoauthenticate.java:390)
            oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:356)
            oracle.jdbc.driver.PhysicalConnection.<init>(PhysicalConnection.java:531)
            oracle.jdbc.driver.T4CConnection.<init>(T4CConnection.java:221)
            oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
            oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:503)
            com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:135)
            com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:182)
            com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:171)
            com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:1

Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1,5,jboss]
            oracle.net.ns.NSProtocol.connect(NSProtocol.java:346)
            oracle.jdbc.driver.T4CConnection.connect(T4CConnection.java:1042)
            oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:301)
            oracle.jdbc.driver.PhysicalConnection.<init>(PhysicalConnection.java:531)
            oracle.jdbc.driver.T4CConnection.<init>(T4CConnection.java:221)
            oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
            oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:503)
            com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:135)
            com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:182)
            com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:171)
            com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:137)
            com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1014)
            com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:32)
            com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1810)
            com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)

Any suggestions for where we should our investigation? Is this c3p0, our queries, our code, the database?

Answer 1

so, your helper Threads are clearly getting saturated by Connection acquisitions. that means that multiple attempts to acquire Connections are neither succeeding nor failing with an Exception for prolonged periods of time. that is ultimately the issue that you need to debug.

the first thing that i'd to is upgrade to c3p0-0.9.2.1, which uses a "scattered" acquire task that economizes use of pooled Threads when acquisitions fail. a second suggestion might be to increase the c3p0 config param called numHelperThreads to something perhaps much higher than its default of 3, or even the 5 you are using. it looks like your Threads are in fact occupied in various stages of Connection acquisition, so increasing the number of "lanes" through which Connections can be acquired may help. [but see postscript below!]

ultimately, though, the question will come down to why is Connection acquisition completing so slowly (for an APPARENT DEADLOCK to be declared, no acquisitions will have succeeded for something on the order of 10 secs). that may be a database or network issue.

but do try upgrading to 0.9.2 and increasing numHelperThreads. [the default value of numHelperThreads is perhaps obsolete; in the era of multicore machines, a Thread pool devoted to IO bound tasks should probably be s multiple of the number of cores] these tweaks might well resolve the problem, or lead to better information about where to look next.

good luck!

p.s. i'm guessing that the Thread stack traces you show are not actually stack traces from during the build-up to an APPARENT DEADLOCK. it would be hard to time those, as you don't know an APPARENT DEADLOCK is imminent until c3p0 announces it. i'd bet that, in deadlock, these stack traces are much more similar to one another, and are waiting on some kind of IO.