Bug #30990 JDBC connections do not properly free up resources when returned a pool

• Submitted: 13 Sep 2007 4:30
• Modified: 16 Nov 2007 20:35
• Reporter: Nathan McEachen
• Status: Closed
• Category: Connector / J
• Severity: S3 (Non-critical)
• Version: connectorJ 5.0.4 & 5.0.7
• OS: Any
• CPU Architecture: Any
• Tags: ConnectionPool, connectorj, jdbc

[13 Sep 2007 4:30] Nathan McEachen

Description:
I may have discovered a bug/feature of ConnectorJ JDBC connections.  It does not look like the connection objects completely free up all resources when they are returned to the pool.

I have an application that runs on four databases: MySQL, PostGreSQL, Oracle, and SQLServer with a test suite of over 4,400 tests that run nightly.

Database deadlocks occur only when I am using MySQL and only when I use connection pooling.  I am using the Apache commons SharedPoolDataSource for both MySQL and SQLServer, yet do not experience any deadlocking issues with SQLServer.

Below is the results from running "show innodb status" while the deadlock occurred.

I am using 5.0.27-0.rhel4.x86_64 and mysql-connector-java-5.0.4.jar

LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 29976, OS thread id 1158990176
MySQL thread id 58798, query id 3627830 localhost root
show innodb status
---TRANSACTION 0 55445752, ACTIVE 0 sec, process no 29976, OS thread id 1160055136 starting index read
mysql tables in use 2, locked 2
LOCK WAIT 2 lock struct(s), heap size 368
MySQL thread id 58872, query id 3627829 localhost 127.0.0.1 framework copy to tmp table
ALTER TABLE test DROP INDEX axak38ks6vpvu8uqe45t5gcsq28dhm
------- TRX HAS BEEN WAITING 0 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 3809 n bits 72 index `PRIMARY` of table `fwdb/test` trx id 0 55445752 lock_modeX waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 35; compact format; info bits 0
 0: len 30; hex 32617a676e63326d726665686f733732673977666879396a767375767539; asc 2azgnc2mrfehos72g9wfhy9jvsuvu9;...(truncated); 1: len 6; hex 0000034e08d7; asc    N  ;; 2: len 7; hex 8000000348069b; asc     H  ;; 3: len 25; hex 74656d706f726172792e6a756e69742e746573742e54657374; asc temporary.junit.test.Test;; 4: len 30; hex 303030303030303030303030303030303030303030303030303030303030; asc 000000000000000000000000000000;...(truncated); 5: len8; hex 800012411f9613a5; asc    A    ;; 6: len 30; hex 303030303030303030303030303030303030303030303030303030303030; asc 000000000000000000000000000000;...(truncated); 7: len 8; hex 800012411f9613a5; asc    A    ;; 8: SQL NULL; 9: len 8; hex 8000000000000798; asc         ;; 10: len 30; hex 303030303030303030303030303030303030303030303030303030303030; asc 000000000000000000000000000000;...(truncated); 11: len 26; hex 7777772e6f7074696d75732e74657272616672616d652e636f6d; asc www.optimus.terraframe.com;; 12: len 30; hex 306d6b37786a68666f756e6a623278317739617975706136706731357263; asc 0mk7xjhfounjb2x1w9ayupa6pg15rc;...(truncated); 13: len 30; hex 30616d6f3565366f3735673475786c776f32387635703474733171793333; asc 0amo5e6o75g4uxlwo28v5p4ts1qy33;...(truncated); 14: len 30; hex 79307465676e386a7578757165793471633862636d72706b346a69763469; asc y0tegn8juxuqey4qc8bcmrpk4jiv4i;...(truncated); 15: SQL NULL; 16: len 7; hex 44696767792031; asc Diggy 1;; 17: len 0; hex ; asc ;; 18: len 11; hex 536f6d657468696e672031; asc Something 1;; 19: SQL NULL; 20: SQL NULL; 21: SQL NULL; 22: SQL NULL; 23: SQL NULL; 24: SQL NULL; 25: SQL NULL; 26: SQL NULL; 27: SQL NULL; 28: SQL NULL; 29: SQL NULL; 30: SQL NULL; 31: SQL NULL; 32: len 21; hex 596f752063616e2774206368616e67652074686973; asc You can't change this;; 33: len 9; hex 4368617256616c7565; ascCharValue;; 34: len 4; hex 80000064; asc    d;;

------------------
---TRANSACTION 0 55445719, ACTIVE 0 sec, process no 29976, OS thread id 1158191456
9 lock struct(s), heap size 1216, undo log entries 22
MySQL thread id 58870, query id 3627823 localhost 127.0.0.1 framework
---TRANSACTION 0 55445051, ACTIVE 12 sec, process no 29976, OS thread id 1159256416
2 lock struct(s), heap size 368, undo log entries 133
MySQL thread id 58871, query id 3627799 localhost 127.0.0.1 framework

How to repeat:
The deadlock occurs when a DDL command is executed on a table that a different connection object has performed a DML command on and is then returned to a connection pool.  The connection object that executes the DML command properly cleans up after itself by closing the transaction and closing the statement object.  This only happens when I am using connection pooling and only with MySQL. 

Suggested fix:
Here is my theory:

When a non-pooled connection is explicitly closed (via .close()), any and all resources it uses are freed.  I remember reading in a post somewhere that some resources are bound to the thread that executes the connection. However, in MySQL, connection objects returned to the pool retain these resources, as the threads that own them do not terminate.  Perhaps this could be a read handle on a file that stores the contents of a table.  This handle prevents another thread from modifying the file via a DDL command.

I was wondering if anyone else has experienced behavior that confirms my theory that connection objects returned to the pool do not free up all resources.

If I am right, then any and all resources need to be freed when the connection object closes a transaction via .commit() or .rollback()

[13 Sep 2007 13:15] Mark Matthews

If you're using a connection pool that _doesn't_ use the ConnectionPoolDataSource API to create connections that have lifecycle callbacks, then it is the _pool's_ responsibility to cleanup "logical" pooled connections when they're returned to the pool. Otherwise there is no way for a JDBC driver to tell that a connection is being pooled "above" it, and thus no event/method call where one can hook in to determine that you've been "logically" closed and returned to the pool.

You don't state which version of DBCP you're using, but more recent ones automatically call rollback() on connections that are returned to the pool.

You can see whether this is happening or not by looking at MySQL's "general" query log on the mysql server side of things, or by adding "profileSQL=true" to your JDBC URL configuration properties.

(I know that DBCP 1.2.1, a somewhat older release does take care of sending rollback() on connections returned to a pool, we use it internally in our monitoring application, so I've been through the code quite q bit).

Would it be possible to get this information from you? If you can show us that for your case, Connector/J is flowing a commit() or rollback() to the database for _both_ the DML and DDL connections, then this is more than likely a MySQL server bug, since the only "lock release" mechanisms a client has at a transactional level is sending "commit" or "rollback" to the server.

[21 Sep 2007 15:59] Nathan McEachen

profileSql=true

Attachment: log.txt (text/plain), 12.04 KiB.

[21 Sep 2007 16:00] Nathan McEachen

Mark,

Thanks for the very fast response. I will just post here instead of the bug forum until it is confirmed this is a bug or not. I am sorry for not providing you with more specifics on the DBCP I am using. I am using the Apache SharedPoolDataSoure:

MysqlDataSource mysqlDataSource = new MysqlConnectionPoolDataSource();

String url = "jdbc:mysql://" + vendorProps.getString(this.serverName) + ":" + portNumber + "/"+ vendorProps.getString(this.databaseName) + "?useServerPrepStmts=false";
mysqlDataSource.setURL(url);
mysqlDataSource.setUser(vendorProps.getString(this.user));
mysqlDataSource.setPassword(vendorProps.getString(this.password));

SharedPoolDataSource sharedPoolDataSource = new SharedPoolDataSource();
sharedPoolDataSource
.setConnectionPoolDataSource((MysqlConnectionPoolDataSource) mysqlDataSource);
sharedPoolDataSource.setMaxActive(this.maxDbConnections);

I explicitly perform a commit or a rollback on the connection object before I return it to the pool. I would think regardless as to whether the DBCP called commit or rollback, I should be OK.

Thanks for your time looking into this!

I attached a file containing the output by setting  profileSql to true.

[16 Nov 2007 17:13] Nathan McEachen

PING!

Hey, thanks for looking into this issue.  Any ideas?  I am willing to also discuss this off line, even over the phone.

[16 Nov 2007 20:35] Nathan McEachen

Hey,

I discovered that the problem is on my end.  I have aspects loaded at runtime that were interfering with the internals of com.mysql.jdbc.Connection.  The reason it was working with the other databases is because I was explicitly excluding their packages from load time weaving.  Once I explicitly excluded the "com.mysql" package, everything worked fine.

More specifically, it looks like my Aspect was bypassing an internal call to rollback on Connection.  

Sorry for suggesting this might be a bug.  Thanks for your time.

-Nathan