Bug #18719 Deadlock
Submitted: 2 Apr 2006 22:02 Modified: 31 Mar 2014 11:35
Reporter: Jeffrey Aguilera Email Updates:
Status: Closed Impact on me:
None 
Category:Connector / J Severity:S1 (Critical)
Version:3.1.12 OS:Windows (Windows XP Pro)
Assigned to: Alexander Soklakov CPU Architecture:Any

[2 Apr 2006 22:02] Jeffrey Aguilera
Description:
ServerPreparedStatement.realClose and Connection.getCharsetConverter both synchronize on a connection, as well as other objects, in different order, resulting in a deadlock under heavy load.

There are other deadlock possibilities (that I have seen), for instance realClose deadlocks against is Closed.  

Java stack information for the threads listed above:
===================================================
"com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1":
        at com.mysql.jdbc.ServerPreparedStatement.realClose(ServerPreparedStatement.java:879)
        - waiting to lock <0x03425ec0> (a java.lang.Object)
        - locked <0x037e78e8> (a com.mysql.jdbc.Connection)
        - locked <0x095fc0a0> (a com.mysql.jdbc.ServerPreparedStatement)
        at com.mysql.jdbc.ServerPreparedStatement.close(ServerPreparedStatement.java:458)
        at com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
        at com.mchange.v2.c3p0.stmt.GooGooStatementCache$1.run(GooGooStatementCache.java:357)
        at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:368)
"impact-10":
        at com.mysql.jdbc.Connection.getCharsetConverter(Connection.java:3177)
        - waiting to lock <0x037e78e8> (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:926)
        - locked <0x09243740> (a com.mysql.jdbc.ResultSet)
        at com.mysql.jdbc.ResultSet.getInt(ResultSet.java:2401)
        at com.mysql.jdbc.SQLError.convertShowWarningsToSQLWarnings(SQLError.java:705)
        at com.mysql.jdbc.MysqlIO.scanForAndThrowDataTruncation(MysqlIO.java:3410)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1804)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2988)
        - locked <0x03425ec0> (a java.lang.Object)
        at com.mysql.jdbc.Connection.rollbackNoChecks(Connection.java:4837)
        at com.mysql.jdbc.Connection.rollback(Connection.java:4734)
        at com.mchange.v2.c3p0.impl.C3P0ImplUtils.resetTxnState(C3P0ImplUtils.java:124)
        at com.mchange.v2.c3p0.impl.NewPooledConnection.reset(NewPooledConnection.java:316)
        at com.mchange.v2.c3p0.impl.NewPooledConnection.markClosedProxyConnection(NewPooledConnection.java:297)
        - locked <0x0360c6b0> (a com.mchange.v2.c3p0.impl.NewPooledConnection)
        at com.mchange.v2.c3p0.impl.NewProxyConnection.close(NewProxyConnection.java:1146)
        - locked <0x094329d0> (a com.mchange.v2.c3p0.impl.NewProxyConnection)
        at model.soc.tables.GoodMessages.getByMessageID(GoodMessages.java:173)
        at services.ImpactServiceProvider.notifyObjectReceived(ImpactServiceProvider.java:183)
        at services.ImpactServiceProvider.notifyObjectReceived(ImpactServiceProvider.java:34)
        at redcondor.services.AbstractWorkerThread.pumpObject(AbstractWorkerThread.java:230)
        at redcondor.services.AbstractWorkerThread.pumpObject(AbstractWorkerThread.java:214)
        at redcondor.services.AbstractWorkerPool.notifyWorking(AbstractWorkerPool.java:268)
        at redcondor.services.AbstractWorkerPool$Worker.run(AbstractWorkerPool.java:499)

How to repeat:
Hibernate + C3P0 + a lot of database activity.  After a while, the getMutex call in realClose causes C3P0 to create hundreds of threads, all in the blocked state.  

Suggested fix:
getCharsetConverted should not be a synchronized Connection method.  Instread, it should synchronize the resource that it is trying to modify, namely charsetConverterMap

The getMutex call in realClose effectively serializes access to the database. I do not see how this code could possible be scaleable under heavy load or pass any meaningful stress test.
[3 Apr 2006 2:26] Mark Matthews
> The getMutex call in realClose effectively serializes access to the database. I
> do not see how this code could possible be scaleable under heavy load or pass
> any meaningful stress test.

In general, a JDBC connection for most vendors (including MySQL) must serialize access to the database for methods that interact with the backend since most RDBMS wire protocols only allow one command to be executing at a time.

For this reason, and because of the architecture of the JDBC API itself (transactions scoped to connection instances, side-effects of statements and result sets interacting, etc), it doesn't make a lot of sense to share a connection between multiple threads.
[3 Apr 2006 2:49] Mark Matthews
We'll take care of the deadlock-prone charset converter stuff, but you might look at upgrading c3p0 too if you're not running the latest, as there was a fix awhile back that supposedly stops this from happening (i.e. multiple threads trying to async close prepared statements out from underneath connections):

http://sourceforge.net/project/shownotes.php?release_id=387332&group_id=25357
[3 Apr 2006 5:29] Jeffrey Aguilera
Are you saying that this is a bug in C3P0?
[3 Apr 2006 5:30] Jeffrey Aguilera
This is with C3P0 0.9.1-pre6 ... cannot get later than this.  Thanks!
[4 Apr 2006 21:47] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/4463
[5 Apr 2006 1:01] Mark Matthews
Please test propsed fixes in this nightly build:

http://downloads.mysql.com/snapshots/mysql-connector-java-5.0/mysql-connector-java-5.0-nig...
[5 May 2006 23:01] 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".
[10 Apr 2009 20:19] Ken Johanson
I am willing to test if 5.x drivers fix this, but I cant deploy the driver in a high volume env due to bug#38387 (and similar e.g bug#34562 and bug#34564). Here is the dump from my currently used (stuck as) version 3.1.12:

"IP 64.146.39.30 / 1988" Id=31013 BLOCKED on com.mysql.jdbc.Connection@1584e1e owned by "IP 99.180.19.38 / 61923" Id=31012 "IP 99.180.19.38 / 61923" Id=31012 BLOCKED on java.lang.Object@709d7e owned by "IP 64.146.39.30 / 1988" Id=31013 132 threads. Fri Apr 10 09:39:47 PDT 2009:

thread is 31012:
com.mysql.jdbc.ServerPreparedStatement.realClose(ServerPreparedStatement.java:879)
com.mysql.jdbc.ServerPreparedStatement.close(ServerPreparedStatement.java:458)
com.libertylivewire.core.Databases.close(Unknown Source)

thread is 31013:
com.mysql.jdbc.Connection.getCharsetConverter(Connection.java:3177)
com.mysql.jdbc.Field.getStringFromBytes(Field.java:583)
com.mysql.jdbc.Field.getName(Field.java:487)
com.mysql.jdbc.ResultSet.buildIndexMapping(ResultSet.java:593)
com.mysql.jdbc.ResultSet.findColumn(ResultSet.java:926)
com.mysql.jdbc.ResultSet.getInt(ResultSet.java:2401)
com.mysql.jdbc.SQLError.convertShowWarningsToSQLWarnings(SQLError.java:705)
com.mysql.jdbc.MysqlIO.scanForAndThrowDataTruncation(MysqlIO.java:3410)
com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1804)
com.mysql.jdbc.Connection.execSQL(Connection.java:2988)
com.mysql.jdbc.Connection.execSQL(Connection.java:2917)
com.mysql.jdbc.Statement.executeQuery(Statement.java:824)
....

Rock and hard place.
[2 Oct 2009 8:29] konstantin k
Hi! We a found this trouble on MS Windows 2003 Standard Edition SP 2 and MySQL Connector/J 5.0.
[31 Mar 2014 10:09] Alexander Soklakov
Bug#15067 was marked as duplicate of this one.
[31 Mar 2014 10:33] Alexander Soklakov
Bug#15636 was marked as duplicate of this one.
[31 Mar 2014 10:46] Alexander Soklakov
Bug#16192 was marked as duplicate of this one.
[31 Mar 2014 11:24] Alexander Soklakov
Bug#18367 was marked as duplicate of this one.
[31 Mar 2014 11:35] Alexander Soklakov
Fixed in c/J 5.0