MySQL Bugs: #22566: DBConnection object being garbage-collected too early by Java 1.5

Bug #22566	DBConnection object being garbage-collected too early by Java 1.5
Submitted:	21 Sep 2006 21:07	Modified:	8 Nov 2006 22:25
Reporter:	dan f	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	Connector / J	Severity:	S2 (Serious)
Version:	Connector/J 5.0.3	OS:	Linux (Linux)
Assigned to:	Mark Matthews	CPU Architecture:	Any
Tags:	Connection, garbage collection, Java 1.5

Description:
I am connecting to a MySQL DB using a JDBC driver. I am
performing a long-running, read-only query ("read all the ratings from
the database"), and our connection wrapper is being garbage-collected
while the query is running. This may be pilot error, but I can't spot
it. Ideas?

Versions:

- Debian Linux, 2.6 kernel

- Java 1.5.0 (even up to 1.5.0_08). NOTE: Java 1.4.2 works! I believe
this is because the garbage collector in 1.4.2 is serial, and in 1.5
has shifted to parallel (see java.sun.com/j2se/1.5.0/docs/guide/vm/gc-ergonomics.html)

- MySQL 4.1.10a-Debian_2

- JDBC driver mysql-connector-java-3.1.13-bin.jar (crashes) or
mysql-connector-java-5.0.3-bin.jar (hangs)

...

The "Finalizing DBConnection, closing Connection .." message happens
*long* before the query is over, which is bad. Looking at the code
below, DBConnection has a Connection, Connection spits out a
Statement, which spits out a ResultSet. I don't see why any of them
should be garbage collected until the end.

Note it also occurs if I break the query up into lots of queries
(e.g., one query per user).

I was considering filing this as a bug, but it is right in that grey
area-- pilot error, overly aggressive garbage collection by Java, or
something in Connector/J's code that causes the collection?

Dan

P.S. I'll work around it by removing the close from finalize() and
closing explicitly, but I'd like to know why this bug happens!

P.P.S.  I posted on the forums (http://forums.mysql.com/read.php?39,116959,116959#msg-116959) and got no response.

How to repeat:
How to reproduce:

- Drop the two files below into a directory

- Drop a MySQL JDBC connector jar into the same directory

- Compile with "javac *.java"

- Create a table user_rating_pairs:

CREATE TABLE `user_rating_pairs` (
`userId` int(11) NOT NULL auto_increment,
`movieId` int(11) NOT NULL default '0',
`rating` float NOT NULL default '0',
`tstamp` timestamp NOT NULL default CURRENT_TIMESTAMP on update CURRENT_TIMESTAMP,
UNIQUE KEY `user_item_pair` (`userId`,`movieId`),
KEY `movie_idx` (`movieId`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1

- Stuff a few million ratings in it, so the query runs for awhile

- Run, e.g. with: java -Xmx800M -cp 'mysql-connector-java-5.0.3-bin.jar:.' DBRatingsSource

- Output should be blank, will likely be a hang for 5.0.3, or the following for 3.1.13:

% java -Xmx800M -cp 'mysql-connector-java-3.1.13-bin.jar:.' DBRatingsSource
/* conn id 0 */ SET NAMES latin1;
/* conn id 0 */ SET character_set_results = NULL;
/* conn id 0 */ SHOW VARIABLES;
/* conn id 0 */ SHOW COLLATION;
/* conn id 0 */ SET autocommit=1;
/* conn id 0 */ SELECT userId, movieId, rating FROM user_rating_pairs;
Finalizing DBConnection, closing Connection ..
Exception in thread "main" java.sql.SQLException: Operation not allowed after ResultSet closed
at com.mysql.jdbc.ResultSet.checkClosed(ResultSet.java:639)
at com.mysql.jdbc.ResultSet.next(ResultSet.java:5869)
at DBRatingsSource.<init>(DBRatingsSource.java:23)
at DBRatingsSource.main(DBRatingsSource.java:34)

=================================

// DBConnection.java

import java.sql.*;
import java.io.*;

public class DBConnection {
private Connection conn;

public DBConnection() {
try {
Class.forName("org.gjt.mm.mysql.Driver");
conn = DriverManager.getConnection( "jdbc:mysql://host/DB?autoGenerateTestcaseScript=true",
"user","password");
} catch (Exception e) {
System.err.println("Exception: " + e);
}
}

public void finalize() {
System.err.println("Finalizing DBConnection, closing Connection ..");
dbClose();
}

public void dbClose() {
try {
if (conn != null) {
conn.close();
conn = null;
}
} catch (SQLException e) {
System.err.println("SQLException: " + e.getMessage());
System.err.println("SQLState: " + e.getSQLState());
System.err.println("VendorError: " + e.getErrorCode());
}
}

public Connection getConn() {
return conn;
}
}

===============================================

// DBRatingsSource.java

import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;

public class DBRatingsSource {
public DBRatingsSource() throws SQLException {
DBConnection myConn = new DBConnection();

myConn.getConn().setReadOnly(true); // Optimization hint
// Tell MySQL to return results one row at a time
Statement stmt = myConn.getConn().createStatement(
java.sql.ResultSet.TYPE_FORWARD_ONLY,
java.sql.ResultSet.CONCUR_READ_ONLY);
stmt.setFetchSize(Integer.MIN_VALUE);

ResultSet rs = stmt.executeQuery("SELECT userId, movieId, rating FROM rating");

// ** BUG: myConn is garbage collected, and the DB connection is closed
// during this long loop:
//int i = 0;
while (rs.next()) {
//System.out.println(i++);
}

rs.close();
// Uncommenting this makes the bug go away, because myConn is
// not garbage collected
//System.out.println(myConn);
}

public static void main(String args[]) throws java.sql.SQLException {
DBRatingsSource source = new DBRatingsSource();
}
}

DBConnection.java

Attachment: DBConnection.java (java/*, text), 1.10 KiB.

DBRatingsSource.java

Attachment: DBRatingsSource.java (java/*, text), 1.21 KiB.

Thank you for a problem report. Please, try to repeat with a newer version, 5.0.4, and inform about the results.

Tried with 5.0.4.  Same problem:

dfrankow@gibson (~/windows/work/mysql-read3) % java -Xmx800M -cp 'mysql-connector-java-5.0.4-bin.jar:.' DBRatingsSource
/* conn id 0 */ SET NAMES latin1;
/* conn id 0 */ SET character_set_results = NULL;
/* conn id 0 */ SHOW VARIABLES;
/* conn id 0 */ SHOW COLLATION;
/* conn id 0 */ SET autocommit=1;
/* conn id 8897 */ SELECT userId, movieId, rating FROM user_rating_pairs;
Finalizing DBConnection, closing Connection ..
...

The "Finalizing" message came out almost right away (within a second or so), LONG before it could have finished reading ratings.  It continued to run for awhile before I control-c-ed it.

Used latest Java as well:

dfrankow@gibson (~/windows/work/mysql-read3) % java -version
java version "1.5.0_09"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_09-b01)
Java HotSpot(TM) Server VM (build 1.5.0_09-b01, mixed mode)

Hi. I consulted about this with my colleagues and here's what we came up with.
Looking briefly at your code I've decided to clasify this report as "not a bug" and here's why: 
  This is incorrect usage; to get a connection, get a result set, forget about the connection, never plan to close the connection. If you're rolling you're rolling your own database code (rather than using spring/hibernate or something) things should look something like this:    
Connection conn = null; try { .... } finally { if (conn != null) { conn.close(); } }
As for "no gc" in 1.4.x my guess is that java 5 has better (or at least different) garbage collection and recognizes that the connection is no longer referenced earlier in the process and it is correct to garbage collect an object which is no longer referenced, even indirectly, by an active thread.

As for your last remarks, the speed of gc could be connected to "softly reachable objects". See more in http://java.sun.com/docs/hotspot/gc1.4.2/faq.html. But the main problem is in, I believe, what I wrote above.

The key is your statement "it is correct to garbage
collect an object which is no longer referenced, even indirectly, by an
active thread."

My expectation was that ResultSet referenced Statement, and Statement referenced  Connection.  If that is true, then Connection is reachable and shouldn't be garbage collected.  Thus, under my expectation it took a long time to find out what was going on.

It would be best if MySQL JDBC code met that expectation, all other things equal.  Does it?  "Softly reachable" is only if objects have soft references.  Does it need to have soft references?

Sure, it's dodgy to not close the connection.  I wouldn't argue it's the best code.  It wasn't mine, I was just debugging it.  However, MySQL JDBC driver's unexpected behavior wasted a lot of time for me.

The driver doesn't use soft references to any instances of the classes you speak of (Connection, Statement, ResultSet), so the issue seems to be the fact that you're relying on a finalizer to clean up your DBConnection instance, which is perhaps no longer _itself_ referenced by anything (but isn't done with it's work?).

This might be timing-dependent, which is why a new VM with different GC implementations might trigger it, but it's not a bug in the driver.

In general, relying on finalizers to handle "lifecycle" of an object is discouraged in Java, this behavior being one of the reasons.

Mark-- sorry to communicate through this bug interface, I don't have anyone's email address.

Sure, I realize using a finalizer to close a DB connection is bad.  It wasn't my code, I was simply debugging it.

However, is it true or not that ResultSet refers to Statement, which refers to Connection?  If true, the Connection should not be garbage collected.  If not true, shouldn't it be true so this confusing thing doesn't happen to someone else?

As long as your application retains a reference to something that contains a reference to Connection, then it is definitely reachable. If it's being GC'd before your application releases the reference to the "holder", that's a bug with the VM. Are you sure you're not doing something (multithreaded?) that's causing behavior you're not expecting?

I forgot: the DBConnection (not referred to by anything) is garbage collected and its finalizer closes the Connection.

Yep, bad code.  Bug closed.