Bug #27188 Memory leak in ResultSet and/or Statement (com.mysql.jdbc.Field)
Submitted: 15 Mar 2007 18:25 Modified: 20 Mar 2007 18:44
Reporter: Rene Lares Email Updates:
Status: Can't repeat Impact on me:
None 
Category:Connector / J Severity:S2 (Serious)
Version:5.0.4 - 5.0.5 OS:Linux (Linux / Ubuntu 6.0.6)
Assigned to: CPU Architecture:Any
Tags: field, memory leak

[15 Mar 2007 18:25] Rene Lares
Description:
I'm running a thread that it's looking up for new tables and in each table search for new rows to be process. This routine it's executed every 10 seconds.
After a while running the JVM throws an OutOfMemoryException, so I use JProfiler to try to find th problem and founded that after 7 minutes and 30 seconds I have 22981 instance of com.mysql.jdbc.Field class (using 3231kb of the heap) and also it's creating a similar amount of instances of byte[].
I wait to see the behavior and I found that the instances were growing to the point that they used all the heap memory available. 
I search for similar BUGS and founded that this happens before (BUGS #5022, #9812, #26632), and try to make all the changes suggested in those BUGS but nothing seems to eliminate the problem.

I'm running the program with:
Java Runtime Environment, Standard Edition (build 1.5.0_08-b03)
MySQL Community Edition 5.0.27-standard-log
MySQL Connector/J 5.0.5
C3P0 - JDBC3 Connection and Statement Pooling version 0.9.1.1

How to repeat:
This is the exact routine I'm using, execute this every 10 seconds:

public static final String QUERY_SHOW_LUSERS_TABLES = "SHOW TABLES LIKE 'LUSERS_%'";
public static final String QUERY_GET_NEW_LUSERS  ="SELECT * FROM LUSERS_<idsite>_<idTp> l, TPMESSAGES_<idsite> tpm WHERE l.idTPMESSAGE = tpm.idTPMESSAGE AND IDSENDER = <idsender> AND USERSTATUS = 'NEW' AND tpm.STATE != 'FAILED' LIMIT 0,50";
private static final int POSITION_RESULTSET_LUSER_TABLENAME = 1;
private static final int POSITION_IDSITE = 1;
private static final int POSITION_IDTP = 2;
private static final int COLUMNS_IN_A_LUSER_ROW = 24;

private void connectToDB() {
		try	{
			if (dbConnection != null){
				if (!dbConnection.isOpen()) {
					dbConnection = dbFactory.retrieveConnection();
				}
			}
		} catch (Exception e) {
			logger.error("Could not contact DB.", e);
		}
	}

private void lookupForNewLusersToBuild() {
		Statement statement = null;
		ResultSet rs = null;
		Statement innerStatement = null;
		ResultSet innerRs = null;
		String query;
		Vector<String[]> lusersTables = new Vector<String[]>();
		try {
			connectToDB();
			query = QUERY_SHOW_LUSERS_TABLES;
			statement = dbConnection.createStatement();
			rs = statement.executeQuery(query);
			while (rs.next()) {
				lusersTables.add( rs.getString(POSITION_RESULTSET_LUSER_TABLENAME).split("_"));
			}
			if (rs != null) { rs.close(); }
			if (statement != null) { statement.close(); }
			rs = null;
			statement = null;
			for (String[] luserTable : lusersTables) {
				String idSite = luserTable[POSITION_IDSITE];
				String idTp = luserTable[POSITION_IDTP];
				logger.info("Looking for LUsers to build on idSIte=" + idSite + " idTP=" + idTp);
				query = QUERY_GET_NEW_LUSERS;
				query = query.replaceAll("<idsite>", idSite);
				query = query.replaceAll("<idTp>", idTp);
				query = query.replaceAll("<idsender>", String.valueOf(BuilderConfig.getInstance().getServerNumber()));
				connectToDB();
				innerStatement = dbConnection.createStatement();
				logger.debug("Executing query: \"" + query + "\"");
				innerRs = innerStatement.executeQuery(query);
				while (innerRs.next()) {
					String columnName = CONSTANTS.EMPTY_STRING;
					HashMap<String, String> luser = new HashMap<String, String>((int) Math.floor(COLUMNS_IN_A_LUSER_ROW * 1.35));
					ResultSetMetaData metaData = innerRs.getMetaData();
					for (int i = 1; i <= metaData.getColumnCount(); i++) {
						columnName = metaData.getColumnName(i);
						luser.put(columnName, innerRs.getString(columnName));
					}
					metaData = null;
					
					luser.put("idSITE", idSite);
					luser.put("idTP", idTp);
					lusersToBuild.add((HashMap<String, String>) luser.clone());
					luser.clear();
					luser = null;
					if (innerRs != null) { innerRs.close(); }
					if (innerStatement != null) { innerStatement.close(); }
					innerRs = null;
					innerStatement = null;
				}
				logger.info(lusersToBuild.size() + " current LUsers to build");
				idSite = null;
				idTp = null;
			}
			lusersTables.clear();
		} catch (Exception e) {
			logger.error("Error while trying to get new LUSERS to build.", e);
		} finally {
			try {
				if (rs != null) { rs.close(); }
				if (statement != null) { statement.close(); }
				if (innerRs != null) { innerRs.close(); }
				if (innerStatement != null) { innerStatement.close(); }
				statement = null;
				rs = null;
				innerRs = null;
				innerStatement = null;
				lusersTables = null;
				query = null;
			} catch (Exception e) {
				logger.warn("Error while trying to close the statement, resultset and/or connection.", e);
			}
		}
	}

The dbConnection object it's a java.sql.Connection object and It's use in a hole class and this connection is never closed unless the program has to exit.
The dbFactory object it's a C3P0ConnectionFactory object that I use as a connection pool.
[15 Mar 2007 20:03] Mark Matthews
What happens if we remove a variable, say c3p0? 

It appears that something's holding on to the physical statements and result sets, even though you're closing them.

If you remove c3p0 and use our JDBC driver directly, does the memory leak go away?
[15 Mar 2007 22:42] Rene Lares
I try to use the JDBC driver directly, and the problem remains. But I reviewed the code with some coworkers and one of them suggest to move the creation of the statement outside the "For" (statement = dbConnection.createStatement()), and this solved the problem. 
Here is the code with the changes:

public static final String QUERY_SHOW_LUSERS_TABLES = "SHOW TABLES LIKE
'LUSERS_%'";
public static final String QUERY_GET_NEW_LUSERS  ="SELECT * FROM
LUSERS_<idsite>_<idTp> l, TPMESSAGES_<idsite> tpm WHERE l.idTPMESSAGE =
tpm.idTPMESSAGE AND IDSENDER = <idsender> AND USERSTATUS = 'NEW' AND tpm.STATE
!= 'FAILED' LIMIT 0,50";
private static final int POSITION_RESULTSET_LUSER_TABLENAME = 1;
private static final int POSITION_IDSITE = 1;
private static final int POSITION_IDTP = 2;
private static final int COLUMNS_IN_A_LUSER_ROW = 24;

private void connectToDB() {
		try	{
			if (dbConnection != null){
				if (!dbConnection.isOpen()) {
					dbConnection = dbFactory.retrieveConnection();
				}
			}
		} catch (Exception e) {
			logger.error("Could not contact DB.", e);
		}
	}

private void lookupForNewLusersToBuild() {
		Statement statement = null;
		ResultSet rs = null;
		String query;
		Vector<String[]> lusersTables = new Vector<String[]>();
		try {
			connectToDB();
			query = QUERY_SHOW_LUSERS_TABLES;
			statement = dbConnection.createStatement();
			rs = statement.executeQuery(query);
			while (rs.next()) {
				lusersTables.add(
rs.getString(POSITION_RESULTSET_LUSER_TABLENAME).split("_"));
			}
			if (rs != null) { rs.close(); }
			if (statement != null) { statement.close(); }
			rs = null;
			statement = null;
                        statement = dbConnection.createStatement();
			for (String[] luserTable : lusersTables) {
				String idSite = luserTable[POSITION_IDSITE];
				String idTp = luserTable[POSITION_IDTP];
				logger.info("Looking for LUsers to build on idSIte=" + idSite + " idTP=" +
idTp);
				query = QUERY_GET_NEW_LUSERS;
				query = query.replaceAll("<idsite>", idSite);
				query = query.replaceAll("<idTp>", idTp);
				query = query.replaceAll("<idsender>",
String.valueOf(BuilderConfig.getInstance().getServerNumber()));
				connectToDB();
				logger.debug("Executing query: \"" + query + "\"");
				innerRs = innerStatement.executeQuery(query);
				while (innerRs.next()) {
					String columnName = CONSTANTS.EMPTY_STRING;
					HashMap<String, String> luser = new HashMap<String, String>((int)
Math.floor(COLUMNS_IN_A_LUSER_ROW * 1.35));
					ResultSetMetaData metaData = innerRs.getMetaData();
					for (int i = 1; i <= metaData.getColumnCount(); i++) {
						columnName = metaData.getColumnName(i);
						luser.put(columnName, innerRs.getString(columnName));
					}
					metaData = null;
					luser.put("idSITE", idSite);
					luser.put("idTP", idTp);
					lusersToBuild.add((HashMap<String, String>) luser.clone());
					luser.clear();
					luser = null;
				}
				logger.info(lusersToBuild.size() + " current LUsers to build");
				idSite = null;
				idTp = null;
			}
			lusersTables.clear();
		} catch (Exception e) {
			logger.error("Error while trying to get new LUSERS to build.", e);
		} finally {
			try {
				if (rs != null) { rs.close(); }
				if (statement != null) { statement.close(); }
				statement = null;
				rs = null;
				lusersTables = null;
				query = null;
			} catch (Exception e) {
				logger.warn("Error while trying to close the statement, resultset and/or
connection.", e);
			}
		}
	}

With the mentioned changes the thread works properly and the instance of the Field class didn't exceed the 1500 instances and the GC was able to deallocate all the memory used by the instances, this behavior also changed for the byte[] object. 

I think (at least in theory) that the close() and the "null" assignation should be enough to deallocate all the field objects, but seems that if the createStatement() function it's called inside a loop the object doesn't release it's previous references to some objects.

Hope this help.
[20 Mar 2007 17:30] Mark Matthews
I'm closing as "can't repeat". 

If you can come back with a standalone, repeatable testcase that demonstrates the behavior, feel free to reopen the bug, and we'll take a look ourselves in a profiler. 

We have similar tests in our testsuite, and don't notice this behavior ourselves, so it's something very particular to the logic you're using.

On the surface, this appears to be an interaction between your VM's GC strategy and the fact that you're allocating Statements so often through the loop, and the VM decides to postpone the GC until after the loop (and eventually fails because you haven't left the loop before you run out of young generation heap), or some interaction with your connection pool and the GC strategy is happening. (which appears to be the case, since you modified your code and the issue went away).
[20 Mar 2007 18:44] Rene Lares
Ok, 
I will try to create a simple routine in order to duplicate the behavior I'm getting.

Thanks, 
Lares