#86 C3P0 deadlock causing application to hang

open
nobody
None
5
2014-12-04
2010-08-31
Santosh Rao
No

When application running under extreme loads we observed a deadlock in two application threads where in one is trying to check-in after use and other is trying to open a connection. The java stack was taken using the kill -QUIT command on Solaris environment shows a deadlock between BasicResourcePool and ThreadPoolAsynchronousRunner objects. Tried looking at the code and also stack does not show where the lock to the runner object is held.
We are using C3P0 version 0.9.1.2. and below are the c3p0 properties through hibernate

hibernate.connection.driver_class oracle.jdbc.OracleDriver
hibernate.c3p0.max_size 1000
hibernate.dialect net.sf.hibernate.dialect.Oracle9Dialect
hibernate.c3p0.min_size 10

Properies in c3p0
c3p0.maxIdleTimeExcessConnections=120
c3p0.acquireRetryDelay=10000
c3p0.autoCommitOnClose=true

Discussion

  • Santosh Rao
    Santosh Rao
    2010-08-31

    Stack Trace with deatails on deadlock

     
    Attachments
  • This issue is still open. Can any one please help in this regard. I'm also facing the same issue with C3P0 version 0.9.1.2.

    Thanks

     
  • ipauldev
    ipauldev
    2011-09-06

    Also requesting any updates. Having the same issue.

     
  • Jason Thorpe
    Jason Thorpe
    2011-09-06

    We too are having this issue - any updates?

     
  • Krishna
    Krishna
    2014-07-24

    We are having this issue and due to this the CPU get hung 100%. Any help on this issue.
    Appreciate well in advance.
    Thank you,

     
  • Steve Waldman
    Steve Waldman
    2014-10-05

    First, please upgrade from 0.9.1.x. It's very old.

    The deadlock that began this Thread is odd. There is no actual deadlock visible in the stack traces.

    One Thread has locked the BasicResourcePool and is waiting to lock the ThreadPoolAsynchronousRunner.

    The other Thread is waiting to lock the BasicResourcePool, but does not (visibly) hold the lock to the ThreadPoolAsynchronousRunner, so should not prevent the first Thread from completing.

    No Thread holds the lock of the ThreadPoolAsynchronousRunner, except two PoolThreads that have given up the lock by wait()ing on it.

    So this is a weird alleged deadlock.

     
  • Steve Waldman
    Steve Waldman
    2014-10-05

    If any of you have detailed stack traces to offer, especially with a more recent c3p0 (ideally the latest c3p0-0.9.5-preX), I'd appreciate that.

     
  • Krishna
    Krishna
    2014-10-07

    Hi Steve, As you per you thread, the deadlock is due to old c3p0 jar.
    We have tested our appliction with latest c3p0-0.9.5-pre8. Till now haven't reported any deadlocks. Will post you if we experience any problems.
    Really appreciated for your advise.
    Thank you,

     
  • Krishna
    Krishna
    2014-12-03

    Hi Steve,

    Good day. As you suggested we have replaced the old c3p0 jar with newer version, c3p0-0.9.5-pre8. We have performed some testing on our test environment with new version of c3p0 jars. We found that there are two blocked threads which seems to be in deadlock condition. The below is the c3p0 configuration in our hibernate.cfg.xml. Also attaching the thread dump as you requested in earlier post. Please help us on this to resolve this burning issue.
    Appreciate your reply well in advance.
    Thank you,
    Krishna.

    hibernate.cfg.xml:

    <property name="connection.provider_class">org.hibernate.connection.C3P0ConnectionProvider</property>
    <property name="hibernate.c3p0.acquire_increment">1</property>
    <property name="hibernate.c3p0.idle_test_period">120</property>
    <property name="hibernate.c3p0.max_size">2</property>
    <property name="hibernate.c3p0.max_statements">0</property>
    <property name="hibernate.c3p0.min_size">1</property>
    <property name="hibernate.c3p0.timeout">120</property>

    Logs Trace:

    "C3P0PooledConnectionPoolManager[identityToken->1bqw28c962nnt8t8x2ibs|7b99e9e9]-HelperThread-#2" - Thread t@26
    java.lang.Thread.State: BLOCKED
    at com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1391)
    - waiting to lock <7eb5e307> (a com.mysql.jdbc.JDBC4Connection) owned by "C3P0PooledConnectionPoolManager[identityToken->1bqw28c962nnt8t8x2ibs|7b99e9e9]-HelperThread-#1" t@25
    - locked <3a758401> (a com.mysql.jdbc.StatementImpl)
    at com.mysql.jdbc.DatabaseMetaData$9.forEach(DatabaseMetaData.java:4984)
    at com.mysql.jdbc.IterateBlock.doForAll(IterateBlock.java:51)
    at com.mysql.jdbc.DatabaseMetaData.getTables(DatabaseMetaData.java:4962)
    at com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnectionNoQuery(DefaultConnectionTester.java:185)
    at com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnection(DefaultConnectionTester.java:62)
    at com.mchange.v2.c3p0.AbstractConnectionTester.activeCheckConnection(AbstractConnectionTester.java:67)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.testPooledConnection(C3P0PooledConnectionPool.java:491)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.testPooledConnection(C3P0PooledConnectionPool.java:451)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.refurbishIdleResource(C3P0PooledConnectionPool.java:423)
    - locked <3cbe5cf0> (a java.lang.Object)
    at com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask.run(BasicResourcePool.java:2139)
    at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
    Locked ownable synchronizers:
    - None

    "C3P0PooledConnectionPoolManager[identityToken->1bqw28c962nnt8t8x2ibs|7b99e9e9]-HelperThread-#1" - Thread t@25
    java.lang.Thread.State: BLOCKED
    at com.mysql.jdbc.StatementImpl.realClose(StatementImpl.java:2403)
    - waiting to lock <3a758401> (a com.mysql.jdbc.StatementImpl) owned by "C3P0PooledConnectionPoolManager[identityToken->1bqw28c962nnt8t8x2ibs|7b99e9e9]-HelperThread-#2" t@26
    at com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1585)
    at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4361)
    at com.mysql.jdbc.ConnectionImpl.close(ConnectionImpl.java:1557)
    - locked <7eb5e307> (a com.mysql.jdbc.JDBC4Connection)
    at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:617)
    at com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(NewPooledConnection.java:247)
    - locked <377a003b> (a com.mchange.v2.c3p0.impl.NewPooledConnection)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:607)
    at com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1012)
    at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
    Locked ownable synchronizers:
    - None

     
  • Krishna
    Krishna
    2014-12-03

    Post awaiting moderation.
  • Steve Waldman
    Steve Waldman
    2014-12-04

    So the issue here is pretty clear. A Connection is being closed at the same time as it is being tested. The close() requires, within MySQL's JDBC driver, acquisition of the Connection's lock and then acquisition of any open Statement's lock. The test -- you are using c3p0's slow default Connection test -- has a Thread lock a Statement then its parent Connection. So, the MySQL driver is deadlock prone if someone tries to list database tables at the same time as a Connection is close()ed, as the two operations require lock acquisitions in different orders.

    I suspect that you can resolve this issue easily by avoiding the complexities of c3p0's default Connection test. You can do that by setting a preferredTestQuery:

    c3p0.hibernate.preferredTestQuery=SELECT 1

    Alternatively, updating your MySQL driver to a JDBC4 compliant driver that supports the Connection.isValid() method would probably be the very best approach. (If you do this, leave out the preferredTestQuery, and let the driver manage its own Connection test.) I'm not sure what version of the MySQL driver you are using, but apparently it is not one that supports Connection.isValid(), or c3p0 would have chosen that over its default Connection test with no preferredTestQuery set.

    I hate to always tell you to upgrade, but please do try to upgrade to a more recent MySQL driver (and while you're at it, you might as well upgrade to c3p0-0.9.5-pre10).

    Or, if you don't want to do any of that, just set preferredTestQuery. Either way should solve your problem.

    I'm blaming this issue on MySQL's driver; the inconsistent lock ordering is entirely within that code. I think the issue is easy to work around. Nevertheless, c3p0 could be modified to prevent the possibility of a Connection test coincident with a Connection expiration, which would prevent the possibility of this deadlock. But that won't happen so soon -- this is an issue very few users experience (because most users avoid the overhead of the default Connection test) -- and I don't want to muck around in the core pool management code this close to a final release. (I hope to release c3p0-0.9.5-final imminently.) I hope that the suggestions above are effective at working around your issue. I'll try to look into it during the 0.9.6 series, and decide whether dealing with this (I think increasingly rare) issue is worth the added code complexity.

    Do let me know, please, how things work out for you if you try one of the suggestions above. I'm hoping that an ordinary query wouldn't involve the nested lock acquisitions that the DatabaseMetaData query in the default test appears to trigger, but I could be mistaken about that.