#52 Still getting APPARENT DEADLOCK with 0.9.1.2

open
nobody
None
5
2007-06-26
2007-06-26
icebrain2
No

I´m still getting APPARENT DEADLOCK with version 0.9.1.2.

Using hibernate 3.0
MySql 5.0

My config file:
<property
name="hibernate.connection.url">jdbc:mysql://localhost:3306/mktmanager</property>
<property
name="hibernate.connection.driver_class">com.mysql.jdbc.Driver</property>
<property
name="hibernate.connection.autoReconnect">true</property> <property
name="hibernate.connection.username">root</property>
<property name="hibernate.connection.password">macaco</property>
<property name="hibernate.c3p0.acquire_increment">1</property>
<property name="hibernate.c3p0.idle_test_period">100</property> <!--
seconds -->
<property name="hibernate.c3p0.max_size">100</property>
<property name="hibernate.c3p0.max_statements">0</property>
<property name="hibernate.c3p0.min_size">10</property>
<property name="hibernate.c3p0.timeout">100</property> <!-- seconds -->

The stack trace:
16149615 [Timer-0] WARN com.mchange.v2.async.ThreadPoolAsynchronousRunner
- com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@d96b45
-- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending
tasks!
16149631 [Timer-0] WARN com.mchange.v2.async.ThreadPoolAsynchronousRunner
- com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@d96b45
-- APPARENT DEADLOCK!!! Complete Status:
Managed Threads: 3
Active Threads: 3
Active Tasks:
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@1f523a3
(com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2)
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@f6ab8a
(com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0)
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@782d03
(com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1)
Pending Tasks:
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@1d3589e
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@5ef73d
Pool thread stack traces:
Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2,5,main]
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:129)
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1862)
com.mysql.jdbc.MysqlIO.readPacket(MysqlIO.java:493)
com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:936)
com.mysql.jdbc.Connection.createNewIO(Connection.java:2720)
com.mysql.jdbc.Connection.<init>(Connection.java:1509)
com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:266)
com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:134)
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)
Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1,5,main]
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:129)
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1862)
com.mysql.jdbc.MysqlIO.readPacket(MysqlIO.java:493)
com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:936)
com.mysql.jdbc.Connection.createNewIO(Connection.java:2720)
com.mysql.jdbc.Connection.<init>(Connection.java:1509)
com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:266)
com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:134)
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)
Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0,5,main]
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:129)
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1862)
com.mysql.jdbc.MysqlIO.readPacket(MysqlIO.java:493)
com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:936)
com.mysql.jdbc.Connection.createNewIO(Connection.java:2720)
com.mysql.jdbc.Connection.<init>(Connection.java:1509)
com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:266)
com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:134)
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)

Thanks in advance!

Discussion

  • Steve Waldman
    Steve Waldman
    2007-06-29

    Logged In: YES
    user_id=175530
    Originator: NO

    So this is an "APPARENT DEADLOCK" where all pools in the thread pool are hung on AcquireTasks.

    That means that for some reason, when c3p0 is trying to acquire Connections from the underlying database, its attempt are neither succeeding nor failing promptly with an Exception, but are instead "hanging" for long periods of time.

    Here are some things you can do to try to resolve the issue:

    1) Try to understand what's going on at your database. Why are Connection acquisition attempts freezing? Are too many Connections checked out? Is there some network issue?

    2) Try c3p0's experimental (but much better) new logic for Connection acquisition. Do this by setting...

    com.mchange.v2.resourcepool.experimental.useScatteredAcquireTask=true

    ...in c3p0.properties or as a System property. This will be the default behavior in future c3p0's, and is much better than the old Acquire task. It's not the default only because it was added late to the c3p0-0.9.1.x series.

    3) If you decide that nothing is broken, it's just that your load is very high and the database gets bogged down, increase c3p0.numHelperThreads from its default of 3 to diminish the likelihood of c3p0 declaring a deadlock. (c3p0 only declares a deadlock if all pooled threads are stuck on the same taks for a prolonged period of time.)

    4) If all else fails, try to force slow tasks to fail using c3p0.maxAdministrativeTaskTime. Between 5 and 9 seconds would probably be reasonable values for this.

     
  • Logged In: NO

    Swaldman, thanks for answering!

    Lets see your points:
    1) Try to understand what's going on at your database. Why are Connection
    acquisition attempts freezing? Are too many Connections checked out? Is
    there some network issue?

    I´ve tried but I couldn´t figure out. Even stressing the application with jMeter, I just cant reproduce the error.

    2) Try c3p0's experimental (but much better) new logic for Connection
    acquisition. Do this by setting...

    I will put that now... (didn´t put before because I believed it was the default for 0.9.2)

    3) If you decide that nothing is broken, it's just that your load is very
    high and the database gets bogged down, increase c3p0.numHelperThreads from
    its default of 3 to diminish the likelihood of c3p0 declaring a deadlock.
    (c3p0 only declares a deadlock if all pooled threads are stuck on the same
    taks for a prolonged period of time.)

    As I´ve mentioned before, it isn´t the load.

    4) If all else fails, try to force slow tasks to fail using
    c3p0.maxAdministrativeTaskTime. Between 5 and 9 seconds would probably be
    reasonable values for this.

    I will put this too (my client is already stressed and I can't take any chances).

    One thing I see about the problem, is in the logic of:
    try
    do something in the database
    catch (HangException)
    open another thread

    is that will almost ever cause a machine deadlock.

    Anyway, thanks for the c3p0 and for the support. It´s very handy!

     
  • Damien B
    Damien B
    2007-11-07

    Logged In: YES
    user_id=237265
    Originator: NO

    Another Apparent Deadlock, but maybe not related:
    c3p0 0.9.1.2
    MySQL 5.0.41
    Connector 3.1.8

    Debugging what was happening, I see lingering in the acquiring thread a SQLException with the message "unknown database 'db_support'"... which simply meant that my JDBC URL was wrong... oops. But it seems that c3p0 was not giving up on the exception, thus in a very long loop.

     
  • Damien B
    Damien B
    2007-11-07

    Logged In: YES
    user_id=237265
    Originator: NO

    Another comment: removing autoReconnect=true corrects in fact the "very long loop", now c3p0 fails a bit faster. I'm not sure that autoReconnect is a good idea when using MySQL with c3p0.

     
  • Steve Waldman
    Steve Waldman
    2007-11-12

    Logged In: YES
    user_id=175530
    Originator: NO

    nkame,

    Thanks for the good suggestion. That's worth keeping in mind. Using c3p0's Connection testing and MySql's autoReconnect is overkill, and as you've discovered, the autoReconnect could cause c3p0 to notice acquisition failures more slowly.

    I hope that things are working for you now.

    smiles,
    Steve

     
  • Damien B
    Damien B
    2007-11-12

    Logged In: YES
    user_id=237265
    Originator: NO

    With a correct JDBC URL and removing autoReconnect it's working perfectly now (my main goal was to test the JMX reporting of c3p0, the only "problem" I have is that in a Tomcat scenario, there is no correlation between the c3p0 MBean and the JNDI path, but I can live with that).