Bug #14972 Found one Java-level deadlock
Submitted: 16 Nov 2005 9:25 Modified: 15 Jun 2006 16:23
Reporter: Sergey Vladimirov Email Updates:
Status: Duplicate Impact on me:
None 
Category:Connector / J Severity:S1 (Critical)
Version:3.1-nightly-20051121 OS:Linux (Linux, Java build 1.5.0_05-b05)
Assigned to: Mark Matthews CPU Architecture:Any

[16 Nov 2005 9:25] Sergey Vladimirov
Description:
Found one Java-level deadlock:
=============================
"http-8080-Processor24":
  waiting to lock monitor 0x081763fc (object 0x768c41a0, a com.mysql.jdbc.Connection),
  which is held by "http-8080-Processor17"
"http-8080-Processor17":
  waiting to lock monitor 0x08176a3c (object 0x768c6640, a java.lang.Object),
  which is held by "http-8080-Processor24"

Java stack information for the threads listed above:
===================================================
"http-8080-Processor24":
        at com.mysql.jdbc.Connection.unregisterStatement(Connection.java:5269)
        - waiting to lock <0x768c41a0> (a com.mysql.jdbc.Connection)
        at com.mysql.jdbc.Statement.realClose(Statement.java:1613)
        at com.mysql.jdbc.PreparedStatement.realClose(PreparedStatement.java:1699)
        at com.mysql.jdbc.ServerPreparedStatement.realClose(ServerPreparedStatement.java:899)
        - locked <0x768c6640> (a java.lang.Object)
        - locked <0x780ce1e8> (a com.mysql.jdbc.ServerPreparedStatement)
        at com.mysql.jdbc.ServerPreparedStatement.close(ServerPreparedStatement.java:458)
        at org.enhydra.jdbc.standard.StandardXAPreparedStatement.close(StandardXAPreparedStatement.java:115)
        - locked <0x780a82a0> (a org.enhydra.jdbc.standard.StandardXAPreparedStatement)
        at org.hibernate.jdbc.AbstractBatcher.closePreparedStatement(AbstractBatcher.java:460)
...
        at java.lang.Thread.run(Thread.java:595)
"http-8080-Processor17":
        at com.mysql.jdbc.ServerPreparedStatement.serverPrepare(ServerPreparedStatement.java:1252)
        - waiting to lock <0x768c6640> (a java.lang.Object)
        at com.mysql.jdbc.ServerPreparedStatement.<init>(ServerPreparedStatement.java:307)
        at com.mysql.jdbc.Connection.prepareStatement(Connection.java:4270)
        - locked <0x768c41a0> (a com.mysql.jdbc.Connection)
        at com.mysql.jdbc.Connection.prepareStatement(Connection.java:4210)
        at org.enhydra.jdbc.standard.StandardConnectionHandle.createPreparedStatement(StandardConnectionHandle.java:294)
        at org.enhydra.jdbc.standard.StandardXAConnectionHandle.checkPreparedCache(StandardXAConnectionHandle.java:181)
        - locked <0x77fa0a08> (a org.enhydra.jdbc.standard.StandardXAConnectionHandle)
        at org.enhydra.jdbc.standard.StandardXAPreparedStatement.<init>(StandardXAPreparedStatement.java:62)
        at org.enhydra.jdbc.standard.StandardXAConnectionHandle.prepareStatement(StandardXAConnectionHandle.java:320)
        at org.enhydra.jdbc.standard.StandardXAConnectionHandle.prepareStatement(StandardXAConnectionHandle.java:254)
        at ru.arptek.arpsite.db.XADelegatedConnection.prepareStatement(XADelegatedConnection.java:106)
        at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:431)
...
        at java.lang.Thread.run(Thread.java:595)

Found 1 deadlock.

How to repeat:
:(

Suggested fix:
lock connection also in com.mysql.jdbc.ServerPreparedStatement.close ?
or use one lock to connection and all its ServerPreparedStatements ?
[17 Nov 2005 17:27] Jim Redman
Just to confirm that this bug does exist on:

Linux localhost.localdomain 2.6.11-1.1369_FC4 #1 Thu Jun 2 22:55:56 EDT 2005 i686 i686 i386 GNU/Linux

It's intermittent, but frequent enough that I had to revert to 3.1.10 where the problem does not seem to exist (that is, I didn't see it in the limited time I had to run the project).

I have details of the threads at the time of the lock, but as png's unfortunately.  If they're useful, please drop me a line.   As I think you know, the deadlock is between a lock on "Object" and "Connection".

Jim
[17 Nov 2005 19:22] Mark Matthews
Seems like a deadlock between a connection instance and the mutex that serializes access to the communications channel w/ the MySQL server.

I'll push a proposed fix that will end up in tonight's nightly build (available at http://downloads.mysql.com/snapshots.php#connector-j), if you could test it that would be great, as I'm not able to repeat the deadlock here locally.

I'm curious as to what framework/pool you're using that's closing things in a multi-threaded manner, as that's the only way (that I can see) that this could happen.
[18 Nov 2005 15:58] Sergey Vladimirov
Error not showed anymore

Thanks!

BTW, it is hibernate with XAPool. I think, this bug was linked with hibernate bug "[HHH-1034] - The connection is closed  *outside* the JTA transaction in TransactionHelper", which was fixed yesterday.
[21 Nov 2005 15:50] Sergey Vladimirov
mysql-connector-java-3.1-nightly-20051121-bin.jar

deadlock found

Found one Java-level deadlock:
=============================
"http-8080-Processor25":
  waiting to lock monitor 0x081764cc (object 0x7643c438, a java.lang.Object),
  which is held by "Arp.Site Timer: ru.arptek.arpsite.db.ConnectionPool"
"Arp.Site Timer: ru.arptek.arpsite.db.ConnectionPool":
  waiting to lock monitor 0x08176c4c (object 0x7635e018, a com.mysql.jdbc.Connection),
  which is held by "http-8080-Processor25"

Java stack information for the threads listed above:
===================================================
"http-8080-Processor25":
        at com.mysql.jdbc.ServerPreparedStatement.serverPrepare(ServerPreparedStatement.java:1253)
        - waiting to lock <0x7643c438> (a java.lang.Object)
        at com.mysql.jdbc.ServerPreparedStatement.<init>(ServerPreparedStatement.java:307)
        at com.mysql.jdbc.Connection.prepareStatement(Connection.java:4270)
        - locked <0x7635e018> (a com.mysql.jdbc.Connection)
        at com.mysql.jdbc.Connection.prepareStatement(Connection.java:4210)
        at org.enhydra.jdbc.standard.StandardConnectionHandle.createPreparedStatement(StandardConnectionHandle.java:294)
        at org.enhydra.jdbc.standard.StandardXAConnectionHandle.checkPreparedCache(StandardXAConnectionHandle.java:181)
        - locked <0x765ee570> (a org.enhydra.jdbc.standard.StandardXAConnectionHandle)
        at org.enhydra.jdbc.standard.StandardXAPreparedStatement.<init>(StandardXAPreparedStatement.java:62)
        at org.enhydra.jdbc.standard.StandardXAConnectionHandle.prepareStatement(StandardXAConnectionHandle.java:320)
        at org.enhydra.jdbc.standard.StandardXAConnectionHandle.prepareStatement(StandardXAConnectionHandle.java:254)
        at ru.arptek.arpsite.db.XADelegatedConnection.prepareStatement(XADelegatedConnection.java:106)
        at org.apache.commons.dbcp.DelegatingConnection.prepareStatement(DelegatingConnection.java:185)
        at ru.arptek.arpsite.db.AbstractConnectionPool.prepareStatement(AbstractConnectionPool.java:231)
...
        at java.lang.Thread.run(Thread.java:595)
"Arp.Site Timer: ru.arptek.arpsite.db.ConnectionPool":
        at com.mysql.jdbc.Connection.getCharsetConverter(Connection.java:3161)
        - waiting to lock <0x7635e018> (a com.mysql.jdbc.Connection)
        at com.mysql.jdbc.Field.getStringFromBytes(Field.java:583)
        at com.mysql.jdbc.Field.getName(Field.java:487)
        at com.mysql.jdbc.ResultSet.buildIndexMapping(ResultSet.java:593)
        at com.mysql.jdbc.ResultSet.findColumn(ResultSet.java:915)
        - locked <0x766552f8> (a com.mysql.jdbc.ResultSet)
        at com.mysql.jdbc.ResultSet.getInt(ResultSet.java:2382)
        at com.mysql.jdbc.SQLError.convertShowWarningsToSQLWarnings(SQLError.java:705)
        at com.mysql.jdbc.MysqlIO.scanForAndThrowDataTruncation(MysqlIO.java:3408)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1802)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2972)
        - locked <0x7643c438> (a java.lang.Object)
        at com.mysql.jdbc.Connection.rollbackNoChecks(Connection.java:4819)
        at com.mysql.jdbc.Connection.rollback(Connection.java:4716)
        at org.enhydra.jdbc.standard.StandardXAConnectionHandle.close(StandardXAConnectionHandle.java:83)
        - locked <0x7665e7a0> (a org.enhydra.jdbc.standard.StandardXAConnectionHandle)
        at ru.arptek.arpsite.db.XADelegatedConnection.closeDelegate(XADelegatedConnection.java:26)
        at ru.arptek.arpsite.db.XAConnectionPool$ThreadConnectionCache.destroy(XAConnectionPool.java:111)
        - locked <0x763b9fa8> (a ru.arptek.arpsite.db.XAConnectionPool$ThreadConnectionCache)
        at ru.arptek.arpsite.db.XAConnectionPool$DestroyCacheTask.run(XAConnectionPool.java:45)
        at java.util.TimerThread.mainLoop(Timer.java:512)
        at java.util.TimerThread.run(Timer.java:462)

Found 1 deadlock.
[21 Nov 2005 15:51] Sergey Vladimirov
May be I used wrong version? Which nightly build did you mean?
[21 Nov 2005 21:10] Mark Matthews
Different deadlock, according to your stack trace...We'll fix this one too, but still wondering what framework is using Connections in a multi-threaded way....JDBC is just not setup to do that (but is supposed to be multi-thread safe, so we have to fix the deadlocks).
[21 Nov 2005 21:31] Mark Matthews
The fixes to this require enough changes that they can't go into 3.1 since we have very few reports of deadlocks from our users, and can't destabilize the behavior of 3.1 at this time, since we can't change the synchronization model at runtime as we can do with other behavioral fixes we do (to allow backwards compatibility).

The potential fix (full synchronization of all factory methods for statements and command execution on the Connection class) is now in the Connector/J 5.0 source tree and will be available in the nightly build for November 22, or via the subversion repository _now_ (build it yourself) from http://svn.mysql.com/svnpublic/connector-j/branches/branch_5_0/

If you can come up with a standalone testcase, even if it uses the JBoss and XAPool components, we'd like to see it so we can test things for ourselves.
[22 Dec 2005 0:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".
[27 Apr 2006 13:06] Andy Seaborne
Connector/J 5.0.0.-beta (timestamp in the zip around Dec 2005)

I have had the following deadlock arise bewteen ServerPreparedStatement.serverPrepare and Connection.unregisterStatement
(annotated stacktrace below) which looks simalr to teh original bug report.

This isn't the onbly one I've found: below ------ I include another I turned up.

The trouble is a deadly embrace caused by the order locks are obtained.  The lock order is:
PatternStage-41:
   connection (outer)
     this.connection.getMutex()

Thread-23 lock
   connection.getMutex()
     connection 
   

Thread [PatternStage-41] (Suspended)
    ServerPreparedStatement.serverPrepare(String) line: 1311
**** synchronized (this.connection.getMutex()) {
    ServerPreparedStatement.<init>(Connection, String, String) line: 316
    Connection.prepareStatement(String, int, int) line: 4377
    Connection.prepareStatement(String) line: 4315
**** synchronized method
    SQLCache.doPrepareSQLStatement(String) line: 289
    SQLCache.getPreparedSQLStatement(String, String[]) line: 271
    SQLCache.getPreparedSQLStatement(String, String) line: 318
    PSet_ReifStore_RDB.findReifTripleMatch(TripleMatch, IDBID) line: 177
    SpecializedGraphReifier_RDB.find(TripleMatch, SpecializedGraph$CompletionFlag) line: 414
    GraphRDB.graphBaseFind(TripleMatch) line: 431
    GraphRDB(GraphBase).find(TripleMatch) line: 224
    GraphRDB(GraphBase).graphBaseFind(Node, Node, Node) line: 244
    GraphRDB(GraphBase).find(Node, Node, Node) line: 241
    QueryTriple$SimpleApplyer.find(Domain) line: 141
    QueryTriple$SimpleApplyer.applyToTriples(Domain, Matcher, StageElement) line: 145
    StageElement$FindTriples.run(Domain) line: 50
    PatternStage(PatternStageBase).run(Pipe, Pipe, StageElement) line: 43
    PatternStageBase$1.run() line: 53
Thread [Thread-23] (Suspended)
    Connection.unregisterStatement(Statement) line: 5380
**** synchronized
    ServerPreparedStatement(Statement).realClose(boolean, boolean) line: 1863
    ServerPreparedStatement(PreparedStatement).realClose(boolean, boolean) line: 1722
**** inside synchronized (this.connection.getMutex())

    ServerPreparedStatement.realClose(boolean, boolean) line: 906
    ServerPreparedStatement.close() line: 467
    DBQueryStage.run(Pipe, Pipe) line: 111
    DBQueryStage$1.run() line: 143

----------------------------
Abbreviated stack trace showing the two threads that seem to be deadlocked:

Jena-Misc DBtest [Java Application]
    dev.DBtest at localhost:3929
        Thread [main] (Suspended)
        Thread [Thread-1] (Suspended)
            Connection.getCatalog() line: 3194
*** synchronized            
            ServerPreparedStatement(PreparedStatement).execute() line: 709
*** inside synchronized (this.connection.getMutex())
            DBQueryStage.run(Pipe, Pipe) line: 76
            DBQueryStage$1.run() line: 136
        Thread [PatternStage-4] (Suspended)
        Thread [Thread-2] (Suspended)
            ServerPreparedStatement.serverPrepare(String) line: 1312
*** inside synchronized (this.connection.getMutex())
            ServerPreparedStatement.<init>(Connection, String, String) line: 316
            Connection.prepareStatement(String, int, int) line: 4377
*** synchronized
            Connection.prepareStatement(String) line: 4315
            DBQueryStage.run(Pipe, Pipe) line: 64
            DBQueryStage$1.run() line: 136
    C:\Program Files\Java\jdk1.5.0_06\bin\javaw.exe (26-Apr-2006 17:02:54)
[15 Jun 2006 16:23] Mark Matthews
There's been no feedback from the original poster, but this is most likely a duplicate of BUG#18719, BUG#18367, BUG#17709
      and BUG#15067 (which has been fixed in the source tree, checkout http://downloads.mysql.com/snapshots.php#connector-j for a 5.0 snapshot with the fixes)
[29 Feb 2008 3:15] Nadendla Venkata siva prasad
which is exact solution for this type dead lock?