| Bug #63947 | Rollback hangs if OutOfMemoryException was thrown when reading the query results | ||
|---|---|---|---|
| Submitted: | 6 Jan 2012 10:01 | Modified: | 19 Mar 2014 14:10 |
| Reporter: | Topi Nieminen | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | Connector / J | Severity: | S3 (Non-critical) |
| Version: | 5.1.18 | OS: | Any |
| Assigned to: | Filipe Silva | CPU Architecture: | Any |
| Tags: | Contribution, jdbc | ||
[26 Jan 2012 19:21]
Sveta Smirnova
Thank you for the report. Problem is repeatable for me with 1 exception: connection still exists: [2012-01-26 21:15:01,084] INFO 681[main] - bug63947.run(bug63947.java:62) - connection closed ? false [2012-01-26 21:15:01,085] INFO 682[main] - bug63947.run(bug63947.java:64) - rolling back... ... *************************** 13. row *************************** event_time: 2012-01-26 21:15:00 user_host: root[root] @ localhost [127.0.0.1] thread_id: 3 server_id: 1 command_type: Query argument: select * from test r1, test r2, test r3, test r4, test r5, test r6, test r7, test r8, test r9, test r10, test r11, test r12, test r13, test r14, test r15 *************************** 14. row *************************** event_time: 2012-01-26 21:15:01 user_host: root[root] @ localhost [127.0.0.1] thread_id: 3 server_id: 1 command_type: Query argument: rollback So it is surely not closed and c/J confirms it. Please turn on general query log and check if this is your case too.
[26 Jan 2012 20:36]
Topi Nieminen
I'm curious to know how the connection goes through cleanup() and stays open in your case. Which location does OutOfMemoryError originate from in your test case? According my test program output connection is closed: 2012-01-26 22:19:59,896 [main] INFO test.TestOOM - -- select * from test r1, test r2, test r3, test r4, test r5, test r6, test r7, test r8, test r9, test r10, test r11, test r12, test r13, test r14, test r15 2012-01-26 22:19:59,896 [main] INFO test.TestOOM - executing query... com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Connection closed forcibly due to memory allocation failure. Transaction resolution unknown. at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source) at java.lang.reflect.Constructor.newInstance(Unknown Source) at com.mysql.jdbc.Util.handleNewInstance(Util.java:411) at com.mysql.jdbc.Util.getInstance(Util.java:386) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1013) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:987) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:982) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:927) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2674) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568) at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:842) at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:681) at test.TestOOM.execute(TestOOM.java:94) at test.TestOOM.run(TestOOM.java:69) at test.TestOOM.main(TestOOM.java:20) Caused by: java.lang.OutOfMemoryError: Java heap space at com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:1657) at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1434) at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2936) at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:477) at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2631) at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1800) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2221) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2618) ... 6 more 2012-01-26 22:20:00,460 [main] INFO test.TestOOM - connection closed ? true 2012-01-26 22:20:00,460 [main] INFO test.TestOOM - rolling back... com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed. at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source) at java.lang.reflect.Constructor.newInstance(Unknown Source) at com.mysql.jdbc.Util.handleNewInstance(Util.java:411) at com.mysql.jdbc.Util.getInstance(Util.java:386) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1013) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:987) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:982) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:927) at com.mysql.jdbc.ConnectionImpl.throwConnectionClosedException(ConnectionImpl.java:1205) at com.mysql.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:1197) at com.mysql.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:4705) at test.TestOOM.run(TestOOM.java:74) at test.TestOOM.main(TestOOM.java:20) Caused by: java.lang.OutOfMemoryError: Java heap space at com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:1657) at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1434) at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2936) at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:477) at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2631) at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1800) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2221) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2618) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568) at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:842) at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:681) at test.TestOOM.execute(TestOOM.java:94) at test.TestOOM.run(TestOOM.java:69) ... 1 more
[28 Jan 2012 0:40]
Sveta Smirnova
Thank you for the feedback. Verified as described. Error in my environment: There was 1 error: 1) testBug63947(bug63947)com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure The last packet successfully received from the server was 120 milliseconds ago. The last packet sent successfully to the server was 120 milliseconds ago. at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source) at java.lang.reflect.Constructor.newInstance(Unknown Source) at com.mysql.jdbc.Util.handleNewInstance(Util.java:411) at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1116) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3102) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532) at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2618) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568) at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:842) at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:681) at bug63947.testBug63947(bug63947.java:17) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at bug63947.main(bug63947.java:12) Caused by: java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(Unknown Source) at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114) at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161) at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189) at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2549) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002) ... 26 more This is from test case made for c/J testsuite. Your code printed data similar to yours
[28 Jan 2012 0:40]
Sveta Smirnova
test case for c/J testsuite
Attachment: bug63947.java (text/x-java), 889 bytes.
[28 Jan 2012 1:13]
Mark Matthews
Given how Java handles OOM, there's not a whole lot that can be done when this condition happens. We can maybe have the driver try to forcibly close the socket, which will cause MySQL to rollback any pending transaction, but there is no guarantee that this can happen in a normal way because any allocation of memory required to close the socket may fail (because the VM is out of memory), and it may fail in code that is not under the driver's control (i.e. java.net, java.lang). If anything the solution proposed here should *not* throw SQLException, it should not try and allocate any memory, and it should re-throw the OOM error as errors should be handled differently than checked exceptions. Java applications should generally treat OOM as a fatal error, and terminate the JVM, because no *known* progress can be made once this condition happens.
[30 Jan 2012 8:36]
Tonci Grgin
Thank you Sveta and Mark.
[12 Mar 2014 13:21]
Alexander Soklakov
Marked as Won't fix until we realize that something could be done.
[19 Mar 2014 14:10]
Alexander Soklakov
It's decided to leave it in Verified state.
Description: If OutOfMemoryException is thrown when reading the results from the server, the driver throws an SQLException. If the client code then tries to do rollback, the driver waits for the server response indefinitely (or time specified by socketTimeout, if set): "main" prio=6 tid=0x000000000021b800 nid=0x161c runnable [0x000000000260e000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(Unknown Source) at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:158) at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189) - locked <0x000000000aaee2a0> (a com.mysql.jdbc.util.ReadAheadInputStream) at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2549) at com.mysql.jdbc.MysqlIO.readPacket(MysqlIO.java:662) at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:416) at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2631) at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1800) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2221) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2618) - locked <0x000000000aaf2308> (a com.mysql.jdbc.JDBC4Connection) at com.mysql.jdbc.ConnectionImpl.rollbackNoChecks(ConnectionImpl.java:4833) at com.mysql.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:4719) - locked <0x000000000aaf2308> (a com.mysql.jdbc.JDBC4Connection) at test.TestOOM.run(TestOOM.java:67) at test.TestOOM.main(TestOOM.java:18) Server thread stays in state 'sleep' at this point: show full processlist Id User Host db Command Time State Info 16 root localhost:54222 oom_test Sleep 35 null 18 root localhost:54226 mysql Query 0 null show full processlist Under these conditions it might be better to close the connection forcibly than wait indefinitely. How to repeat: Run the test program test.TestOOM with limited heap size (-Xmx8m -Xms8m) and Log4J in classpath: -------------------------------------------------------------------------------- package test; import java.sql.Connection; import java.sql.DriverManager; import java.sql.ResultSet; import java.sql.SQLException; import java.sql.Statement; import java.util.Properties; import org.apache.log4j.Logger; public class TestOOM { private static Logger logger = Logger.getLogger(TestOOM.class); public static void main(String[] args) { new TestOOM().run(); } public void run() { Connection c = null; try { logger.debug("run - enter"); Class.forName("com.mysql.jdbc.Driver"); String url = "jdbc:mysql://127.0.0.1:3306/mysql"; Properties config = new Properties(); config.setProperty("user", "test_user"); config.setProperty("password", "test_password"); c = DriverManager.getConnection(url, config); c.setAutoCommit(false); execute(c, "create schema if not exists oom_test"); execute(c, "use oom_test"); execute(c, "create or replace view test(a, b) as select 0, 1 union all select 1, 0"); StringBuilder qb = new StringBuilder("select * from "); int rc = 15; for (int i = 1; i <= rc; i++) { qb.append("test r"); qb.append(i); if (i < rc) { qb.append(", "); } } logger.info("-- " + qb.toString()); logger.info("executing query..."); execute(c, qb.toString()); logger.info("connection closed ? " + c.isClosed()); logger.info("rolling back..."); c.rollback(); logger.info("is closed ? " + c.isClosed()); execute(c, "drop schema if exists oom_test"); } catch (Throwable e) { e.printStackTrace(); } finally { doClose(c); logger.debug("run - exit"); } } private void execute(Connection c, String q) throws SQLException { Statement st = null; try { st = c.createStatement(); boolean hasResultSet = st.execute(q); ResultSet rs = null; if (hasResultSet) { rs = st.getResultSet(); rs.close(); } else { int uc = st.getUpdateCount(); logger.info("update count: " + uc); } while(true) { if (st.getMoreResults()) { rs = st.getResultSet(); rs.close(); continue; } int uc = st.getUpdateCount(); if (uc == -1) { break; } logger.info("update count: " + uc); } } catch (SQLException e) { e.printStackTrace(); } catch (OutOfMemoryError e) { e.printStackTrace(); } finally { doClose(st); } } private void doClose(Connection c) { try { if (c != null) { c.close(); } } catch (SQLException e) { logger.error(e.getMessage()); } } private void doClose(Statement s) { try { if (s != null) { s.close(); } } catch (SQLException e) { logger.error(e.getMessage()); } } } Suggested fix: Real fix would be the one that allowed user code to keep connection alive and execute rollback. The patch proposed here just closes the connection forcibly: diff --git a/src/com/mysql/jdbc/ConnectionImpl.java b/src/com/mysql/jdbc/ConnectionImpl.java index 6278022..27b8deb 100644 --- a/src/com/mysql/jdbc/ConnectionImpl.java +++ b/src/com/mysql/jdbc/ConnectionImpl.java @@ -2667,7 +2667,18 @@ public class ConnectionImpl extends ConnectionPropertiesImpl implements sqlEx.initCause(ex); throw sqlEx; - } finally { + } catch (OutOfMemoryError ex) { + cleanup(ex); + + SQLException sqlEx = SQLError.createSQLException( + Messages.getString("Connection.OutOfMemoryError"), + SQLError.SQL_STATE_COMMUNICATION_LINK_FAILURE, getExceptionInterceptor()); + + sqlEx.initCause(ex); + + throw sqlEx; + } + finally { if (getMaintainTimeStats()) { this.lastQueryFinishedTime = System.currentTimeMillis(); } diff --git a/src/com/mysql/jdbc/LocalizedErrorMessages.properties b/src/com/mysql/jdbc/LocalizedErrorMessages.properties index eb74f8d..c0d4ff3 100644 --- a/src/com/mysql/jdbc/LocalizedErrorMessages.properties +++ b/src/com/mysql/jdbc/LocalizedErrorMessages.properties @@ -433,6 +433,7 @@ Connection.UnableToConnectWithRetries=Could not create connection to database se Attempted reconnect {0} times. Giving up. Connection.UnexpectedException=Unexpected exception encountered during query. Connection.UnhandledExceptionDuringShutdown=Unexpected exception during server shutdown. +Connection.OutOfMemoryError=Connection closed forcibly due to memory allocation failure. Transaction resolution unknown. # # ConnectionProperty Categories