Bug #1955 deadlock in LogicalConnection and MySqlPooledConnection
Submitted: 25 Nov 2003 16:12 Modified: 28 Mar 2014 13:36
Reporter: Quartz 12h Email Updates:
Status: Can't repeat Impact on me:
None 
Category:Connector / J Severity:S1 (Critical)
Version:3.0.9, 3.0.8, ...? OS:Any
Assigned to: Alexander Soklakov CPU Architecture:Any

[25 Nov 2003 16:12] Quartz 12h
Description:
After waiting foever, I dump a stack:

[...]

Found one Java-level deadlock:
=============================
"t-2000":
  waiting to lock monitor 0x0091ea4c (object 0x10bcf290, a com.mysql.jdbc.jdbc2.optional.MysqlPooledConnection),
  which is held by "t-3000"
"t-3000":
  waiting to lock monitor 0x0091eaac (object 0x11c82298, a com.mysql.jdbc.jdbc2.optional.LogicalHandle),
  which is held by "t-2000"

Java stack information for the threads listed above:
===================================================
"t-2000":
        at com.mysql.jdbc.jdbc2.optional.MysqlPooledConnection.callListener(MysqlPooledConnection.java:159)
        - waiting to lock <0x10bcf290> (a com.mysql.jdbc.jdbc2.optional.MysqlPooledConnection)
        at com.mysql.jdbc.jdbc2.optional.LogicalHandle.close(LogicalHandle.java:769)
        - locked <0x11c82298> (a com.mysql.jdbc.jdbc2.optional.LogicalHandle)
        at com.mysql.jdbc.jdbc2.optional.LogicalHandle.close(LogicalHandle.java:431)
        - locked <0x11c82298> (a com.mysql.jdbc.jdbc2.optional.LogicalHandle)
        at 
            (our destroy code)

"t-3000":
        at com.mysql.jdbc.jdbc2.optional.LogicalHandle.close(LogicalHandle.java:764)
        - waiting to lock <0x11c82298> (a com.mysql.jdbc.jdbc2.optional.LogicalHandle)
        at com.mysql.jdbc.jdbc2.optional.MysqlPooledConnection.getConnection(MysqlPooledConnection.java:123)
        - locked <0x10bcf290> (a com.mysql.jdbc.jdbc2.optional.MysqlPooledConnection)
        at 
           (our init code)

Found 1 deadlock.

How to repeat:
A piece of code gets a (logical) connection from the pooledConnection,
then work with it and finally close the (logical) connection.

At least 2 threads are running the same code.
We don't add any explicit listener, although the callListener seams invoked.

Sometimes, a logical connection gets closed by the wron thread, leaing to an

java.sql.SQLException: Logical handle no longer valid
	at com.mysql.jdbc.jdbc2.optional.LogicalHandle.createStatement(LogicalHandle.java:462)

But sometimes, the threads collide and deadlock as described above.

Suggested fix:
Tryied once with 3.0.8 and it didn't deadlock.
(we run about 30 thousands of iterations like these for each threads, 4 threads),
over about 5 minutes.
[26 Nov 2003 14:37] Quartz 12h
also experienced with 3.0.8
[26 Nov 2003 15:25] Mark Matthews
Are you using the same PooledConnectionDataSource from two different threads, and calling getConnection() from each thread?

I need a way to repeat the behavior, so either a testcase, or a complete explanation of what your code is doing would help, here.
[28 Nov 2003 7:27] Quartz 12h
(I though I did explain the code... anyway)

the single piece of code is very simple. Given a single PooledConnection shared between threads, the code calls getConnection() to grab a logical connection.
Then it work with it, some statement etc...  then call the logical connection .close().

Connection c = null
try {
    c = this.sharedpooledConn.getConnection();
    //work with c
} finally {
    c.close();
}

Put a sleep if you want to increase time separation between getConnection and close(). You got the 2 thread stack to proove how the deadlock happen. I cannot be more precise.
[2 Dec 2003 9:19] Mark Matthews
Please the latest nightly snapshot build of 3.0 from http://downloads.mysql.com/snapshots.php as the synchronization has been re-worked to (hopefully) avoid this problem.
[29 Jul 2009 13:01] Ingo Siebert
We encountered the same problem several times with MySQL driver 5.1.6. That's quite critical, I wonder why this bug is still open.
I'm quite sure it also exists in newer releases.

We fixed it now and I upload a test case which reproduces the problem within seconds and I upload the fix as diff file.
I hope you apply the patch to your trunk.

First fix part: the synchronized keywords for methods of MysqlPooledConnection are removed and replaces by a synchronized block with a new lock object.

Second fix part: The second fix part is that the ConnectionEventListeners are called outside the of the sychronization with the help of a snapshot copy of all listeners.

Stacktraces of our deadlock:
Name: Timer-3
State: BLOCKED on com.mysql.jdbc.jdbc2.optional.MysqlPooledConnection@51acd5cc owned by: pool-1-thread-1
Total blocked: 38  Total waited: 120.774

Stack trace: 
com.mysql.jdbc.jdbc2.optional.MysqlPooledConnection.getConnection(MysqlPooledConnection.java:153)
org.apache.commons.dbcp.datasources.KeyedCPDSConnectionFactory.validateObject(KeyedCPDSConnectionFactory.java:195)
org.apache.commons.pool.impl.GenericKeyedObjectPool.evict(GenericKeyedObjectPool.java:1489)
org.apache.commons.pool.impl.GenericKeyedObjectPool$Evictor.run(GenericKeyedObjectPool.java:1750)
java.util.TimerThread.mainLoop(Timer.java:512)
java.util.TimerThread.run(Timer.java:462)

name: pool-1-thread-1
State: BLOCKED on org.apache.commons.pool.impl.GenericKeyedObjectPool@46244cd7 owned by: Timer-3
Total blocked: 1.784.777  Total waited: 85.536

Stack trace: 
org.apache.commons.pool.impl.GenericKeyedObjectPool.addObjectToPool(GenericKeyedObjectPool.java:1237)
org.apache.commons.pool.impl.GenericKeyedObjectPool.returnObject(GenericKeyedObjectPool.java:1199)
org.apache.commons.dbcp.datasources.KeyedCPDSConnectionFactory.connectionClosed(KeyedCPDSConnectionFactory.java:268)
com.mysql.jdbc.jdbc2.optional.MysqlPooledConnection.callConnectionEventListeners(MysqlPooledConnection.java:243)
com.mysql.jdbc.jdbc2.optional.ConnectionWrapper.close(ConnectionWrapper.java:854)
com.mysql.jdbc.jdbc2.optional.ConnectionWrapper.close(ConnectionWrapper.java:477)
org.springframework.jdbc.datasource.DataSourceUtils.doReleaseConnection(DataSourceUtils.java:313)
org.springframework.jdbc.datasource.DataSourceUtils.releaseConnection(DataSourceUtils.java:274)
org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:411)
[29 Jul 2009 13:03] Ingo Siebert
Testcase to reproduce the bug

Attachment: PoolDeadlockTest.java (application/octet-stream, text), 2.85 KiB.

[29 Jul 2009 13:03] Ingo Siebert
Bug fix as diff file

Attachment: mysql_deadlock_patch.diff (application/octet-stream, text), 4.50 KiB.

[28 Mar 2014 13:36] Alexander Soklakov
I close this report as "Can't repeat" because there is no feedback for a long time and codebase is too old. Please, feel free to reopen it if the problem still exists in current driver.