MySQL Bugs: #57432: Mysql Connector/J fails with StackOverflowError when calling connection.close()

Bug #57432	Mysql Connector/J fails with StackOverflowError when calling connection.close()
Submitted:	13 Oct 2010 14:08	Modified:	17 Dec 2015 11:09
Reporter:	Dan Dumitriu	Email Updates:
Status:	Closed	Impact on me:	None
Category:	Connector / J	Severity:	S2 (Serious)
Version:	5.1.9	OS:	Linux (fedora 11)
Assigned to:	Alexander Soklakov	CPU Architecture:	Any
Tags:	JDBC StackOverflowError Connection.close()

Description:
when calling connection.close() I get a StackOverflowError

I am using streaming on the table and have large amounts of data (rowSet.next() gets called around 25,000,000 times). When I am finisshed with the rowSet I am enabling the keys (simple alter statement: alter table x enable keys). This enabling is done on a different connection.

I am calling in my original connection connection.close and I get a StackOverflowError. Output is truncated as there are only a few lines in the stack which get repeated over and over again (... ofcourse, because it fails with a stack overflow! )

2010-10-13 10:11:42,944 [pool-1-thread-2] INFO com.xxxxxxx.DisableKeysRowWriter - Keys enabled on XXXXXX in 239426 ms
java.lang.StackOverflowError
at sun.nio.cs.UTF_8$Decoder.decodeLoop(UTF_8.java:305)
at java.nio.charset.CharsetDecoder.decode(CharsetDecoder.java:544)
at java.lang.StringCoding$StringDecoder.decode(StringCoding.java:140)
at java.lang.StringCoding.decode(StringCoding.java:173)
at java.lang.String.<init>(String.java:443)
at java.lang.String.<init>(String.java:515)
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
at java.io.BufferedOutputStream.write(BufferedOutputStream.java:109)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3292)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1940)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2109)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2637)
at com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1544)
at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:198)
at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:7556)
at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:907)
at com.mysql.jdbc.StatementImpl.realClose(StatementImpl.java:2363)
at com.mysql.jdbc.PreparedStatement.realClose(PreparedStatement.java:3008)
at com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1534)
at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4397)
at com.mysql.jdbc.ConnectionImpl.cleanup(ConnectionImpl.java:1310)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2670)
at com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1544)
at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:198)
at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:7556)
at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:907)
at com.mysql.jdbc.StatementImpl.realClose(StatementImpl.java:2363)
at com.mysql.jdbc.PreparedStatement.realClose(PreparedStatement.java:3008)
at com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1534)
at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4397)
at com.mysql.jdbc.ConnectionImpl.cleanup(ConnectionImpl.java:1310)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2670)
at com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1544)
at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:198)
at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:7556)
at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:907)
at com.mysql.jdbc.StatementImpl.realClose(StatementImpl.java:2363)
at com.mysql.jdbc.PreparedStatement.realClose(PreparedStatement.java:3008)
at com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1534)
at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4397)
at com.mysql.jdbc.ConnectionImpl.cleanup(ConnectionImpl.java:1310)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2670)
at com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1544)
at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:198)
at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:7556)
at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:907)
at com.mysql.jdbc.StatementImpl.realClose(StatementImpl.java:2363)
at com.mysql.jdbc.PreparedStatement.realClose(PreparedStatement.java:3008)
at 

How to repeat:
This is my setup:
I use 2 connections. 
On the first one I do:
read in streaming mode all rows from table (table is empty), no rows are returned.
(however rowset.next gets invoked on all inserts because I try to determine if the data exists and if it needs updating).

On the second one I do:
In order to improve performance I disable the keys on the table.
Insert into the table 25 million rows (using load data into file 500 row at a time).
enable keys.

when insert is over just close the connections => the writer connection is ok, it will close, but the reader one is not, it will fail with the above mentioned error.

I have tried to create a small UT for this but it really needs to write the 25 million records otherwise it is not reproduceable.
it takes about 40 min using in memory load data into file to write it so I could not come up with a small and smart enough test for this.

Hi Dan and thanks for your report.

If you can not find a way to make a test case for this how do you think I'll invent one? If needs be, attach a mysqldump of test database or something...

Ok, it will write you one but it will take hours to run probably.

I'll be back.

Hi,
were you able to reproduce the problem using the supplied test case?

I can second this bug description. We too read from a table with 20 millions of rows with a streaming statement. The query runs for 10-16 hours. While processing we update some columns of the table we are reading from via another connection which is still open when connection of read statement is closed. The table type is myisam, MySQL 5.1.30, driver: 5.1.16.
I don't know if it is the long time the statement is running which triggers the exception. Maybe one can deduce from the following stacktrace the cause of the call loop.

Stacktrace:
Exception in thread "DBReadThread" java.lang.StackOverflowError
        at java.net.SocketOutputStream.socketWrite0(Native Method)
        at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
        at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
        at java.io.BufferedOutputStream.write(BufferedOutputStream.java:109)
        at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3331)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1971)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2151)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2619)
        at com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1595)
        at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:198)
        at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:7617)
        at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:907)
        at com.mysql.jdbc.StatementImpl.realClose(StatementImpl.java:2419)
        at com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1585)
        at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4361)
        at com.mysql.jdbc.ConnectionImpl.cleanup(ConnectionImpl.java:1361)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2653)
        at com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1595)
        at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:198)
...
        at com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1585)
        at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4361)
        at com.mysql.jdbc.ConnectionImpl.cleanup(ConnectionImpl.java:1361)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2653)
        at com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1595)
        at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:198)
        at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:7617)
        at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:907)
        at com.mysql.jdbc.StatementImpl.realClose(StatementImpl.java:2419)
        at com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1585)
        at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4361)
        at com.mysql.jdbc.ConnectionImpl.cleanup(ConnectionImpl.java:1361)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2653)
        at com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1595)
        at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:198)
        at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:7617)
        at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:907)
        at com.mysql.jdbc.StatementImpl.realClose(StatementImpl.java:2419)
        at com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1585)
        at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4361)

I will add some more details to my previous comment.
OS: i86pc Solaris, Java: 1.6.0_13, 64bit

When I only process/read up to 50.000 rows the stack overflow does not happen; reading 100,000 rows the stack overflow happens reproducible.

Another update containing the table and queries used.
Table:
CREATE TABLE IF NOT EXISTS mytable (
  id     INT(11) UNSIGNED NOT NULL AUTO_INCREMENT,
  id2    INT,
  name   VARCHAR(254),
  wstate TINYINT(1) DEFAULT 0,
  rdate  DATE,
  name2  VARCHAR(254),
  name3  VARCHAR(254),
  pstate TINYINT(1) DEFAULT 0,
  bcol1  LONGBLOB,
  bcol2  LONGBLOB,
  log1   LONGTEXT,
  log2   LONGTEXT,
  utime  TIMESTAMP NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  UNIQUE KEY id2_idx (id2),
  KEY name_idx (name),
  KEY wstate_idx (wstate),
  KEY rdate_idx (rdate),
  KEY pstate_idx (pstate),
  PRIMARY KEY (id)
) ENGINE=MyISAM DEFAULT CHARACTER SET utf8 COLLATE utf8_unicode_ci

Read statement:
SELECT id, name, rdate, name2
FROM mytable
WHERE pstate=2
ORDER BY rdate

Write statement (2 extra threads with their own connection object running
one of following two inserts as prepared statements for each read row):
Insert1:
UPDATE mytable
SET    bcol1=?, pstate=?
WHERE  id2=?

Insert2:
UPDATE mytable
SET    bcol2=?, pstate=?
WHERE  id2=?

The BLOBs have a size of 20k-100k. All other data are short ids or names.
The table contains 500,000 rows.

Dan, I apologize for missing your test case...

Guys, did you play with your JVM settings? What are they? Did you tried allocating more RAM to JVM? Or, maybe even simple FLUSH TABLES might help.

JVM setting: -d64 -Xms256M -Xmx14000M
So there is enough RAM (14GB out of 128GB), even if all gets allocated GC is able to free needed RAM.
FLUSH TABLES will close tables for all users on server? This is not what I would like to do.

Independent how the situation on the server is (I can't see any problems here) the driver should not go into an infinite loop calling methods.

Could there be an overflow in the driver because of the RAM size > 2GB?

Can we get a fix for this issue?
there is no problem with the memory settings (it has 2G for not that much data).

As far as I know infinite loops are evil :)) so maybe it's good if this gets fixed.

Thank you for the feedback.

I can not repeat described behavior using test case provided. This also looks very like timeout issue: conn2 waits when conn1 finish inserting rows and dies silently.

What value of wait_timeout do you have? Please add 

aProperties.put("waitTimeout", "1200000");

try with it and if problem still exists send us output of SHOW PROCESSLIST taken about 10 minutes before test stops execution.

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".

JUnit test case

Attachment: TestBug57432.java (text/x-java), 2.72 KiB.

I was able to reproduce this exception with current driver sources and 5.6.11 server, see test case above. It was running for about 11 hrs and inserted 1M rows, finally I got the stack trace:

java.lang.StackOverflowError
	at java.nio.charset.Charset.atBugLevel(Charset.java:257)
	at java.nio.charset.CharsetEncoder.<init>(CharsetEncoder.java:177)
	at java.nio.charset.CharsetEncoder.<init>(CharsetEncoder.java:209)
	at sun.nio.cs.UTF_8$Encoder.<init>(UTF_8.java:375)
	at sun.nio.cs.UTF_8$Encoder.<init>(UTF_8.java:372)
	at sun.nio.cs.UTF_8.newEncoder(UTF_8.java:108)
	at java.lang.StringCoding$CharsetSE.<init>(StringCoding.java:321)
	at java.lang.StringCoding$CharsetSE.<init>(StringCoding.java:312)
	at java.lang.StringCoding.encode(StringCoding.java:369)
	at java.lang.String.getBytes(String.java:812)
	at java.io.UnixFileSystem.getBooleanAttributes0(Native Method)
	at java.io.UnixFileSystem.getBooleanAttributes(UnixFileSystem.java:228)
	at java.io.File.exists(File.java:702)
	at sun.misc.URLClassPath$FileLoader.getResource(URLClassPath.java:905)
	at sun.misc.URLClassPath.getResource(URLClassPath.java:161)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:192)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.net.URLClassLoader.findClass(URLClassLoader.java:188)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:307)
	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:268)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:252)
	at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:320)
	at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4721)
	at com.mysql.jdbc.ConnectionImpl.cleanup(ConnectionImpl.java:1464)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2843)
	at com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1703)
	at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:202)
	at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:7474)
	at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:923)
	at com.mysql.jdbc.StatementImpl.realClose(StatementImpl.java:2585)
	at com.mysql.jdbc.PreparedStatement.realClose(PreparedStatement.java:3158)
	at com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1658)
	at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4690)
	at com.mysql.jdbc.ConnectionImpl.cleanup(ConnectionImpl.java:1464)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2843)
	at com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1703)
	at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:202)
	at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:7474)
	at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:923)
	at com.mysql.jdbc.StatementImpl.realClose(StatementImpl.java:2585)
	at com.mysql.jdbc.PreparedStatement.realClose(PreparedStatement.java:3158)
	at com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1658)
	at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4690)
	at com.mysql.jdbc.ConnectionImpl.cleanup(ConnectionImpl.java:1464)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2843)
	at com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1703)
	at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:202)
	at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:7474)
	at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:923)
	at com.mysql.jdbc.StatementImpl.realClose(StatementImpl.java:2585)
	at com.mysql.jdbc.PreparedStatement.realClose(PreparedStatement.java:3158)
...
	at com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1658)
	at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4690)
	at com.mysql.jdbc.ConnectionImpl.cleanup(ConnectionImpl.java:1464)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2843)
	at com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1703)
	at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:202)
	at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:7474)
	at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:923)
	at com.mysql.jdbc.StatementImpl.realClose(StatementImpl.java:2585)
	at com.mysql.jdbc.PreparedStatement.realClose(PreparedStatement.java:3158)
	at com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1658)
	at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4690)
	at com.mysql.jdbc.ConnectionImpl.cleanup(ConnectionImpl.java:1464)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2843)
	at com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1703)
	at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:202)
	at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:7474)
	at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:923)
	at com.mysql.jdbc.StatementImpl.realClose(StatementImpl.java:2585)
	at com.mysql.jdbc.PreparedStatement.realClose(PreparedStatement.java:3158)
	at com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1658)
	at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4690)
	at com.mysql.jdbc.ConnectionImpl.cleanup(ConnectionImpl.java:1464)

The cause of this recursion is that RowDataDynamic.close() tries to call "SET net_write_timeout" with connection which was unused for a long time, this causes SQLError.SQL_STATE_COMMUNICATION_LINK_FAILURE and call of ConnectionImpl.cleanup() which again tries to close the connection.

The workaround is to ensure that connection is alive.

And we should fix connector to avoid recursion in such situation.

Bug#70893 marked as duplicate of this one. Please look there for the simplified description of the problem and junit test case.

Posted by developer:
 
Fixed in Connector/J 5.1.28 after patch for Bug#68916 fix.