| Bug #90240 | Possible memory leak in JDBC42PreparedStatement | ||
|---|---|---|---|
| Submitted: | 28 Mar 2018 10:04 | Modified: | 16 Apr 2018 16:05 |
| Reporter: | Cristian Ghezzi | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | Connector / J | Severity: | S1 (Critical) |
| Version: | 5.1.46 | OS: | Ubuntu (Ubuntu 16.04.4 LTS) |
| Assigned to: | CPU Architecture: | x86 (GNU/Linux 4.4.0-1052-aws x86_64) | |
[29 Mar 2018 8:48]
Cristian Ghezzi
Last night I had another out of memory but the application didn't stop.
After dumping the heap it managed to recover on its own after struggling a bit. Probably this happens regularly until, after a few days, it can't recover and stops with a full 2GB heap.
Hoping it is of some use, this is the stack trace in the tomcat log:
java.lang.OutOfMemoryError: Java heap space
Dumping heap to /mypath/tomcat1-outofmemory-dump ...
Exception in thread "AsyncFileHandlerWriter-1510467688" java.lang.OutOfMemoryError: Java heap space
Exception in thread "Tomcat JDBC Pool Cleaner[1044036744:1522223439517]" Heap dump file created [1733517203 bytes in 253.544 secs]
java.lang.OutOfMemoryError: Java heap space
at java.util.Arrays.copyOf(Arrays.java:3332)
at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:124)
at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:448)
at java.lang.StringBuilder.append(StringBuilder.java:136)
at org.apache.juli.OneLineFormatter.format(OneLineFormatter.java:138)
at java.util.logging.StreamHandler.publish(StreamHandler.java:211)
at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:116)
at java.util.logging.Logger.log(Logger.java:738)
at java.util.logging.Logger.doLog(Logger.java:765)
at java.util.logging.Logger.logp(Logger.java:931)
at org.apache.juli.logging.DirectJDKLog.log(DirectJDKLog.java:180)
at org.apache.juli.logging.DirectJDKLog.warn(DirectJDKLog.java:133)
at org.apache.tomcat.jdbc.pool.ConnectionPool.abandon(ConnectionPool.java:558)
at org.apache.tomcat.jdbc.pool.ConnectionPool.checkAbandoned(ConnectionPool.java:985)
at org.apache.tomcat.jdbc.pool.ConnectionPool$PoolCleaner.run(ConnectionPool.java:1452)
at java.util.TimerThread.mainLoop(Timer.java:555)
at java.util.TimerThread.run(Timer.java:505)
(log4j) WARN org.hibernate.engine.jdbc.spi.SqlExceptionHelper: SQL Error: 0, SQLState: S1000
(log4j) ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper: java.lang.OutOfMemoryError: Java heap space
(log4j) WARN org.hibernate.engine.jdbc.spi.SqlExceptionHelper: SQL Error: 0, SQLState: S1000
(log4j) ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper: java.lang.OutOfMemoryError: Java heap space
(log4j) WARN org.hibernate.engine.jdbc.spi.SqlExceptionHelper: SQL Error: 0, SQLState: 08001
(log4j) ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper: Could not create connection to database server. Attempted reconnect 3 times. Giving up.
This is the trace in the application log:
o.s.t.i.TransactionInterceptor - Application exception overridden by rollback exception
java.lang.OutOfMemoryError: Java heap space
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3515)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3462)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3903)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:871)
at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1999)
at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:3413)
at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:471)
at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:3115)
at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:2344)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2739)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2486)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966)
at sun.reflect.GeneratedMethodAccessor132.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.tomcat.jdbc.pool.interceptor.AbstractQueryReport$StatementProxy.invoke(AbstractQueryReport.java:210)
at com.sun.proxy.$Proxy43.executeQuery(Unknown Source)
at sun.reflect.GeneratedMethodAccessor132.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)
at com.sun.proxy.$Proxy43.executeQuery(Unknown Source)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:60)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.getResultSet(AbstractLoadPlanBasedLoader.java:419)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:191)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:121)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:86)
at org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader.load(AbstractLoadPlanBasedEntityLoader.java:167)
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:4087)
at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:508)
at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:478)
[29 Mar 2018 12:12]
Cristian Ghezzi
Passing the latest heap dump through Eclipse Memory Analyzer gave me the following stack trace. I print only the start because after the first line it is identical to what I already posted. The thread org.apache.tomcat.util.threads.TaskThread @ 0x82c954c8 ajp-apr-8019-exec-6 keeps local variables with total size 1.288.871.992 (87,23%) bytes. The memory is accumulated in one instance of "java.lang.Object[]" loaded by "<system class loader>". ajp-apr-8019-exec-6 at java.lang.OutOfMemoryError.<init>()V (OutOfMemoryError.java:48) at com.mysql.jdbc.MysqlIO.nextRowFast([Lcom/mysql/jdbc/Field;IZIZZZ)Lcom/mysql/jdbc/ResultSetRow; (MysqlIO.java:2173) at com.mysql.jdbc.MysqlIO.nextRow([Lcom/mysql/jdbc/Field;IZIZZZLcom/mysql/jdbc/Buffer;)Lcom/mysql/jdbc/ResultSetRow; (MysqlIO.java:1992) at com.mysql.jdbc.MysqlIO.readSingleRowSet(JIIZ[Lcom/mysql/jdbc/Field;)Lcom/mysql/jdbc/RowData; (MysqlIO.java:3413) at com.mysql.jdbc.MysqlIO.getResultSet(Lcom/mysql/jdbc/StatementImpl;JIIIZLjava/lang/String;Z[Lcom/mysql/jdbc/Field;)Lcom/mysql/jdbc/ResultSetImpl; (MysqlIO.java:471) at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(Lcom/mysql/jdbc/StatementImpl;IIIZLjava/lang/String;Lcom/mysql/jdbc/Buffer;ZJ[Lcom/mysql/jdbc/Field;)Lcom/mysql/jdbc/ResultSetImpl; (MysqlIO.java:3115) at com.mysql.jdbc.MysqlIO.readAllResults(Lcom/mysql/jdbc/StatementImpl;IIIZLjava/lang/String;Lcom/mysql/jdbc/Buffer;ZJ[Lcom/mysql/jdbc/Field;)Lcom/mysql/jdbc/ResultSetImpl; (MysqlIO.java:2344) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(Lcom/mysql/jdbc/StatementImpl;Ljava/lang/String;Ljava/lang/String;Lcom/mysql/jdbc/Buffer;IIIZLjava/lang/String;[Lcom/mysql/jdbc/Field;)Lcom/mysql/jdbc/ResultSetInternalMethods; (MysqlIO.java:2739) at com.mysql.jdbc.ConnectionImpl.execSQL(Lcom/mysql/jdbc/StatementImpl;Ljava/lang/String;ILcom/mysql/jdbc/Buffer;IIZLjava/lang/String;[Lcom/mysql/jdbc/Field;Z)Lcom/mysql/jdbc/ResultSetInternalMethods; (ConnectionImpl.java:2486) at com.mysql.jdbc.PreparedStatement.executeInternal(ILcom/mysql/jdbc/Buffer;ZZ[Lcom/mysql/jdbc/Field;Z)Lcom/mysql/jdbc/ResultSetInternalMethods; (PreparedStatement.java:1858) ... continues ...
[29 Mar 2018 12:44]
Chiranjeevi Battula
Hello Cristian, Thank you for the bug report. Could you please provide repeatable test case (exact steps, sample code etc. - please make it as private if you prefer) to confirm this issue at our end? Please try with MySQL connector 5.1.45 or 5.1.44 versions and let us know if memory leak happening. Thanks, Chiranjeevi.
[3 Apr 2018 8:23]
Cristian Ghezzi
I downgraded to 5.1.45 but I got the same OutOfMemoryError in MysqlIO.nextRowFast
[3 Apr 2018 10:51]
Chiranjeevi Battula
Hello Cristian, Thank you for your feedback. Please note that in order to proceed further/confirm this issue at our end we need a reproduciable test case. Could you please provide repeatable test case (exact steps, sample code etc. - please make it as private if you prefer) to confirm this issue at our end? Thanks, Chiranjeevi.
[16 Apr 2018 16:05]
Cristian Ghezzi
It was an application error loading too many rows in memory, nothing to do with the connector.
Description: I have a production application running in Tomcat that goes in Out of Memory producing a heap dump. Eclipse Memory Analyzer says: One instance of "com.mysql.jdbc.JDBC42ResultSet" loaded by "org.apache.catalina.loader.WebappClassLoader @ 0x807e9428" occupies 1.468.564.840 (88,62%) bytes. The memory is accumulated in one instance of "java.lang.Object[]" loaded by "<system class loader>". IBM HeapAnalyzer shows the following object allocation: 1.028.733.160 (76,28%) [152] 17 org/apache/tomcat/jdbc/pool/ConnectionPool 0x809edaa0 |- 1.028.624.296 (76,28%) [72] 7 java/util/concurrent/LinkedBlockingQueue 0x809ede78 |- 1.028.507.256 (76,27%) [32] 1 java/util/concurrent/LinkedBlockingQueue$Node 0x809edeb8 |- 1.028.507.224 (76,27%) [32] 2 java/util/concurrent/LinkedBlockingQueue$Node 0x9d9f5018 |- 1.028.394.208 (76,26%) [128] 9 org/apache/tomcat/jdbc/pool/PooledConnection 0x876948f8 |- 1.026.515.320 (76,12%) [2.248] 230 com/mysql/jdbc/JDBC4Connection 0x87694950 |- 1.026.251.592 (76,1%) [32] 2 java/util/concurrent/CopyOnWriteArrayList 0x87699790 |- 1.026.251.496 (76,1%) [8] 1 array of java/lang/Object 0x9daf87d8 |- 1.026.251.488 (76,1%) [400] 18 com/mysql/jdbc/JDBC42PreparedStatement 0x9d9bc280 |- 1.026.245.032 (76,1%) [272] 10 com/mysql/jdbc/JDBC42ResultSet 0xd9a304e0 |- 1.026.221.048 (76,1%) [40] 3 com/mysql/jdbc/RowDataStatic 0xd9a304c0 |- 1.026.221.008 (76,1%) [32] 1 java/util/ArrayList 0x9da4dae8 |- 1.026.220.976 (76,1%) [14.585.840] 1.756.312 array of java/lang/Object 0xd9ccb518 I can provide the heap dump if needed. Versions: mysql-connector-java-5.1.46.jar Apache Tomcat/8.0.46 java-8-openjdk-amd64 1.8.0_151-8u151-b12-0ubuntu0.16.04.2-b12 mysql 5.7.21-0ubuntu0.16.04.1-log (Ubuntu) How to repeat: I don't know how to reproduce the problem. It happens after a week or so in a production system with 7000 daily unique users. Suggestions are welcome. I can enable specific logs if needed.