| 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: | |
| 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 |
[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?
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 ?