Hikaricp: [question] Why HikariCP doesn't forcefully close abandoned connections?

[mohsen]

#### Environment
HikariCP version: HikariCP-2.4.6.jar
JDK version     : 1.8.0_121
Database        : MariaDB 10.1.21
Driver version  : mysql-connector-java-5.1.38.jar
-----------------------------------------------------------------------------------------

I have a web application with the following configuration. I'm going out of connection on average every two weeks in a medium-traffic website.

<bean id="internalDataSource" class="com.mysql.jdbc.jdbc2.optional.MysqlDataSource">
    <property name="user" value="${db.username}" />
    <property name="password" value="${db.password}" />
    <property name="URL" value="${db.url}" />
    <property name="cachePrepStmts" value="true" />
    <property name="prepStmtCacheSize" value="250" />
    <property name="prepStmtCacheSqlLimit" value="2048" />
    <property name="autoSlowLog" value="false" />
    <property name="logSlowQueries" value="true" />
    <property name="slowQueryThresholdMillis" value="10000" />
    <property name="dumpQueriesOnException" value="true" />
</bean>

<bean id="dataSource" class="com.zaxxer.hikari.HikariDataSource" destroy-method="close">
    <property name="dataSource" ref="internalDataSource" />
    <property name="metricRegistry" ref="metricRegistry" />
    <property name="maxLifetime" value="1800000" /> <!-- 30 minutes -->
    <property name="minimumIdle" value="1" />
    <property name="maximumPoolSize" value="10" />
    <property name="connectionTimeout" value="30000" />
    <property name="poolName" value="myConnPool" />
    <property name="leakDetectionThreshold" value="45000" />
    <property name="registerMbeans" value="true" />
</bean>

Here is the related exception part:

    Caused by: java.sql.SQLTransientConnectionException: myConnPool - Connection is not available, request timed out after 15765ms.
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:196)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:147)
        at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:99)
        at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
        at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:386)
        at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:84)

When this happens, no open connection can be seen on MySQL/MariaDB process list. Is there any chance to either forcefully close abandoned connections (and return them to the pool), or log the full stacktrace of the leaked connection (without DEBUG log level enabled)?

[billoneil]

Why can't you enable debug logging?

On Sat, Mar 18, 2017 at 11:57 AM, mohsen [e-mail] wrote:

Environment

HikariCP version: HikariCP-2.4.6.jar
JDK version : 1.8.0_121
Database : MariaDB 10.1.21

Driver version : mysql-connector-java-5.1.38.jar

I have a web application with the following configuration. I'm going out
of connection on average every two weeks in a medium-traffic website.

Here is the related exception part:

Caused by: java.sql.SQLTransientConnectionException: myConnPool - Connection is not available, request timed out after 15765ms.
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:196)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:147)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:99)
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:386)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:84)

When this happens, no open connection can be seen on MySQL/MariaDB process
list. Is there any chance to either forcefully close abandoned connections
(and return them to the pool), or log the full stacktrace of the leaked
connection (without DEBUG log level enabled)?

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/brettwooldridge/HikariCP/issues/843, or mute the
thread
https://github.com/notifications/unsubscribe-auth/AE9tUnEo0zc4HcmhTbEL4LDag1GgSl8Fks5rm_7PgaJpZM4MhdML
.

[brettwooldridge]

If you enable the leakDetectionThreshold HikariCP will log the leak at WARN level, so you shouldn't need DEBUG logging for that.

However, debug logging is not particularly noisy, and will give you logs showing connection acquisition and retirement. You can even configure you logging to send com.zaxxer.hikari to a separate log file, if you do find it generates too many logs.

[mohsen]

If you enable the leakDetectionThreshold HikariCP will log the leak at WARN level, so you shouldn't need DEBUG logging for that.

Thanks for the answer. Seems to be a configuration issue in my logback config file. I added HikariCP package to the logback config file and I can see some INFO and WARN logs now.

Can HikariCP auto-close abandoned connections and return them to the pool? I can see nothing related to closing connetion in ProxyLeakTask.

[brettwooldridge]

@mohsen HikariCP does not close abandoned connections; to do so would be to cover up an application bug. If you need a pool that wipes your b*tt for you, you can try Tomcat. 😛 HikariCP can point out the source of the leak for you, but it won't sweep it under the rug.

[mohsen]

@brettwooldridge
Sorry to bring up this issue again. I'm a bit confused about the meaning of a leaked connection. According to documentation, setting leakDetectionThreshold causes to log (WARN) stacktrace of the leaked connection, after threshold is passed and connection is not closed (returned back to the pool).

If I'm correct, a leaked connection is the source of going out of connection issue. Someone gets a connection and holds it too much and and do not return it back to the pool. Tomcat CP will close this connection (according to your comment) and HikariCP will just prints stacktrace of the current state of thread holding the connection.

Confusion here is that when I'm going out of connection, all logged leaked connection stack traces are just waiting for a connection from the pool:

org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
        at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:35)
        at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:115)
        at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:145)
        at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:263)
        at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:271)
        at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:203)
        at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:56)

And here is the code for org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection():

public Connection getConnection() throws SQLException {
    if ( !available ) {
        throw new HibernateException( "Provider is closed!" );
    }
    return useCredentials ? dataSource.getConnection( user, pass ) : dataSource.getConnection();
}

the last line of the method (source of exception) is just trying to acquire a connection from the pool. What does it mean? A leaked connection means a thread which cannot get a new connection or a thread which held a connection too much?

[jnehlmeier]

@mohsen The stack traces tells you who has obtained the connection that now has been leaked. Basically when any thread calls getConnection() and leak detection is enabled then HikariCP will create a new exception to capture the stack trace to the getConnection() call and remembers it. Once the leak detection threshold is reached that remembered exception will be logged.

So your stack trace means that Hibernate has obtained a connection from your pool but that connection has not been closed by Hibernate within the time you have specified for the leak detection threshold. Maybe you forgot to close the Hibernate session / EntityManager once your application code is done?