Cancel statements before closing when destroying unreturned connection after timeout

[adangel]

Hi,

we ran into the following issue: We use c3p0 with "unreturnedConnectionTimeout", we use mysql and we have a very long running query, that triggers the "unreturnedConnectionTimeout". The query is of course a bug in the application. However, the query is not cancelled and continues - both in the application thread and the mysql server - still using resources. While c3p0 reports "0" busy connections after the message "A checked-out resource is overdue, and will be destroyed", the connection is still alive.

I traced it down to the following two threads: "http-bio-8080-exec-14" is the thread that executes the query and waits for the results. This one is actively using the database connection. The other thread is C3P0's helper thread which is trying to destroy the connection. But it's blocked inside mysql's jdbc connector while trying to get hold of the connection.

I added a call to "cancel" before closing the statement. This is implemented for the mysql connector as a "KILL QUERY " statement which terminates the connection.
This seems to be working. Of course, you get a couple of exceptions (e.g. "No operations allowed after connection closed" and hibernate "could not extract ResultSet"), but at least the
connection is released both on client and server.
The cancel is called on any "uncachedActiveStatements" - which is most times empty. There seems to be only statements in it, when the statements are indeed still active. Otherwise they have been already closed and removed. So there should be no impact on returning the connection to the pool via a regular close().

The cancel implementation in mysql connector uses a new connection, so there might be still cases, when the server wouldn't allow additional connections and cancel/KILL QUERY can't be executed.

I've observed this issue now for uncached statements. There might be a similar issue for cached statements, although the closing of the statements is deferred until the connetion is free. But the connection is not returned into the pool in time, so it can be considered as broken, and a cancel should then be called for the cached statements as well.

Is this even a problem, that should be fixed by the connection pool or should this be rather fixed by the JDBC driver (in that case, mysql)?

In order to reproduce the issue, you can use this query: "SELECT SLEEP(10000)". I got with this query the exact same behavior as with the real query.

Regards,
Andreas

Daemon Thread [C3P0PooledConnectionPoolManager[identityToken->z8kfsx93ehuwad110i19b|5f242704]-HelperThread-#2]
    owns: com.mchange.v2.c3p0.impl.NewPooledConnection  (id=128)    
    owns: java.lang.Object  (id=124)    
    waiting for: com.mysql.jdbc.JDBC4Connection  (id=131)
    com.mysql.jdbc.JDBC4PreparedStatement(com.mysql.jdbc.PreparedStatement).realClose(boolean, boolean) line: 3018  
    com.mysql.jdbc.JDBC4PreparedStatement(com.mysql.jdbc.StatementImpl).close() line: 577   
    com.mchange.v2.c3p0.impl.NewPooledConnection.cleanupUncachedStatements(java.util.List) line: 752    
    com.mchange.v2.c3p0.impl.NewPooledConnection.close(java.lang.Throwable, boolean) line: 618  
    com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(boolean) line: 255    
    com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(java.lang.Object, boolean) line: 621 
    com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run() line: 1024 
    com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run() line: 696    

Daemon Thread [http-bio-8080-exec-14]
    owns: com.mysql.jdbc.util.ReadAheadInputStream  (id=201)    
    owns: com.mysql.jdbc.JDBC4Connection  (id=131)  
    owns: org.apache.tomcat.util.net.SocketWrapper<E>  (id=202) 
    java.net.SocketInputStream.socketRead0(java.io.FileDescriptor, byte[], int, int, int) line: not available [native method]   
    java.net.SocketInputStream.read(byte[], int, int, int) line: 152    
    java.net.SocketInputStream.read(byte[], int, int) line: 122 
    com.mysql.jdbc.util.ReadAheadInputStream.fill(int) line: 112    
    com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(byte[], int, int) line: 159    
    com.mysql.jdbc.util.ReadAheadInputStream.read(byte[], int, int) line: 187   
    com.mysql.jdbc.MysqlIO.readFully(java.io.InputStream, byte[], int, int) line: 3158  
    com.mysql.jdbc.MysqlIO.reuseAndReadPacket(com.mysql.jdbc.Buffer, int) line: 3615    
    com.mysql.jdbc.MysqlIO.reuseAndReadPacket(com.mysql.jdbc.Buffer) line: 3604 
    com.mysql.jdbc.MysqlIO.checkErrorPacket(int) line: 4149 
    com.mysql.jdbc.MysqlIO.sendCommand(int, java.lang.String, com.mysql.jdbc.Buffer, boolean, java.lang.String, int) line: 2615 
    com.mysql.jdbc.MysqlIO.sqlQueryDirect(com.mysql.jdbc.StatementImpl, java.lang.String, java.lang.String, com.mysql.jdbc.Buffer, int, int, int, boolean, java.lang.String, com.mysql.jdbc.Field[]) line: 2776 
    com.mysql.jdbc.JDBC4Connection(com.mysql.jdbc.ConnectionImpl).execSQL(com.mysql.jdbc.StatementImpl, java.lang.String, int, com.mysql.jdbc.Buffer, int, int, boolean, java.lang.String, com.mysql.jdbc.Field[], boolean) line: 2840  
    com.mysql.jdbc.JDBC4PreparedStatement(com.mysql.jdbc.PreparedStatement).executeInternal(int, com.mysql.jdbc.Buffer, boolean, boolean, com.mysql.jdbc.Field[], boolean) line: 2082   
    com.mysql.jdbc.JDBC4PreparedStatement(com.mysql.jdbc.PreparedStatement).executeQuery() line: 2212   
    com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery() line: 1392    
    org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(java.sql.PreparedStatement) line: 79 
    org.hibernate.loader.custom.CustomLoader(org.hibernate.loader.Loader).getResultSet(java.sql.PreparedStatement, org.hibernate.engine.spi.RowSelection, org.hibernate.dialect.pagination.LimitHandler, boolean, org.hibernate.engine.spi.SessionImplementor) line: 2062   
    org.hibernate.loader.custom.CustomLoader(org.hibernate.loader.Loader).executeQueryStatement(java.lang.String, org.hibernate.engine.spi.QueryParameters, boolean, java.util.List<org.hibernate.loader.Loader.AfterLoadAction>, org.hibernate.engine.spi.SessionImplementor) line: 1859   
    org.hibernate.loader.custom.CustomLoader(org.hibernate.loader.Loader).executeQueryStatement(org.hibernate.engine.spi.QueryParameters, boolean, java.util.List<org.hibernate.loader.Loader.AfterLoadAction>, org.hibernate.engine.spi.SessionImplementor) line: 1838 
    org.hibernate.loader.custom.CustomLoader(org.hibernate.loader.Loader).doQuery(org.hibernate.engine.spi.SessionImplementor, org.hibernate.engine.spi.QueryParameters, boolean, org.hibernate.transform.ResultTransformer) line: 906  
    org.hibernate.loader.custom.CustomLoader(org.hibernate.loader.Loader).doQueryAndInitializeNonLazyCollections(org.hibernate.engine.spi.SessionImplementor, org.hibernate.engine.spi.QueryParameters, boolean, org.hibernate.transform.ResultTransformer) line: 348   
    org.hibernate.loader.custom.CustomLoader(org.hibernate.loader.Loader).doList(org.hibernate.engine.spi.SessionImplementor, org.hibernate.engine.spi.QueryParameters, org.hibernate.transform.ResultTransformer) line: 2550   
    org.hibernate.loader.custom.CustomLoader(org.hibernate.loader.Loader).doList(org.hibernate.engine.spi.SessionImplementor, org.hibernate.engine.spi.QueryParameters) line: 2536  
    org.hibernate.loader.custom.CustomLoader(org.hibernate.loader.Loader).listIgnoreQueryCache(org.hibernate.engine.spi.SessionImplementor, org.hibernate.engine.spi.QueryParameters) line: 2366    
    org.hibernate.loader.custom.CustomLoader(org.hibernate.loader.Loader).list(org.hibernate.engine.spi.SessionImplementor, org.hibernate.engine.spi.QueryParameters, java.util.Set, org.hibernate.type.Type[]) line: 2361  
    org.hibernate.loader.custom.CustomLoader.list(org.hibernate.engine.spi.SessionImplementor, org.hibernate.engine.spi.QueryParameters) line: 340  
    org.hibernate.internal.SessionImpl.listCustomQuery(org.hibernate.loader.custom.CustomQuery, org.hibernate.engine.spi.QueryParameters) line: 1752    
    org.hibernate.internal.SessionImpl(org.hibernate.internal.AbstractSessionImpl).list(org.hibernate.engine.query.spi.sql.NativeSQLQuerySpecification, org.hibernate.engine.spi.QueryParameters) line: 232 
    org.hibernate.internal.SQLQueryImpl.list() line: 157    
    org.hibernate.ejb.QueryImpl<X>.getResultList() line: 268    

[swaldman]

hi.

thanks very much. the modification in the pull request looks very reasonable. i want to give the broader issue a bit more thought. i'm traveling, so it will be a few days, alas...

thank you again.

[adangel]

Calling cancel on the statement is of course a bit risky - at least for mysql it means, that the connection is dropped. So you should have a proper connection test configured to not have stale connections in the pool.

The method where I added call to cancel is the same, that is called during a regular close of a connection. I didn't see in my (short) testing a case, where uncachedActiveStatements was not empty (except of course for my long running query). I don't know if we can make the assumption, in case close is called and there are still uncachedActiveStatements existing, that these statements can always be "cancelled" - with the effect that the connection is destroyed afterwards.

If this assumption doesn't hold true, we maybe need to differ the cases, when a unreturned connection is closed or when a regular connection closing occurs.
Another way to mitigate the risk is, to guard this with a feature toggle.

Let me know, whether I should adjust the pull request.

Thanks!