MySQL, Hibernate 4.3.6+ HikariCP configuration

[Timothy Sandberg]

I'm new to HikariCP.  I'm trying to implement the latest HikariCP configuration. I'm dealing with MySQL. 

Implementing the new configuration has brought me this:

org.hibernate.QueryTimeoutException: Could not open connection
1426891         at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:83)

So, i'm trying to fix my time out issue by adding some configuration: 

        <property name="hibernate.hikari.idleTimeout">60000</property> //minutes

        <property name="hibernate.hikari.maximumPoolSize">10</property> 

        <property name="hibernate.hikari.maxLifeTime">30000</property>

        <property name="hibernate.hikari.poolName">TimConnPool</property>

This configuration, I believe fired this a hibernate configuration exception at runtime.

So how exactly do I configure this for Hibernate?  Thanks,

[Johan Dahlberg]

I have the same problem in my Play Framework 2.4 application.

persistence.xml:

<persistence xmlns="http://xmlns.jcp.org/xml/ns/persistence"

             xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

             xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/persistence http://xmlns.jcp.org/xml/ns/persistence/persistence_2_1.xsd"

             version="2.1">

    <persistence-unit name="defaultPersistenceUnit" transaction-type="RESOURCE_LOCAL">

        <provider>org.hibernate.jpa.HibernatePersistenceProvider</provider>

        <non-jta-data-source>DefaultDS</non-jta-data-source>

        <properties>

            <property name="hibernate.dialect" value="org.hibernate.dialect.MySQL5Dialect"/>

            <property name="hibernate.enable_lazy_load_no_trans" value="true" />

            <property name="hibernate.format_sql" value="true" />

            <property name="hibernate.hbm2ddl.auto" value="validate"/>

            <property name="hibernate.max_fetch_depth" value="5" />

            <property name="hibernate.show_sql" value="false" />

        </properties>

    </persistence-unit>

</persistence>

My error:

2015-07-29 15:42:16,822 - [warn] o.h.e.j.s.SqlExceptionHelper - SQL Error: 0, SQLState: null
2015-07-29 15:42:16,822 - [error] o.h.e.j.s.SqlExceptionHelper - Timeout after 120000ms of waiting for a connection.
2015-07-29 15:42:16,854 - [error] application - 

! @6n1ehgfdj - Internal server error, for (GET) [/index] ->

play.api.http.HttpErrorHandlerExceptions$$anon$1: Execution exception[[QueryTimeoutException: Could not open connection]]
    at play.api.http.HttpErrorHandlerExceptions$.throwableToUsefulException(HttpErrorHandler.scala:265) ~[play_2.11-2.4.2.jar:2.4.2]
    at play.api.http.DefaultHttpErrorHandler.onServerError(HttpErrorHandler.scala:191) ~[play_2.11-2.4.2.jar:2.4.2]
    at play.api.GlobalSettings$class.onError(GlobalSettings.scala:179) [play_2.11-2.4.2.jar:2.4.2]
    at play.api.DefaultGlobal$.onError(GlobalSettings.scala:212) [play_2.11-2.4.2.jar:2.4.2]
    at play.api.http.GlobalSettingsHttpErrorHandler.onServerError(HttpErrorHandler.scala:94) [play_2.11-2.4.2.jar:2.4.2]
Caused by: javax.persistence.QueryTimeoutException: Could not open connection
    at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1725) ~[hibernate-entitymanager-4.3.10.Final.jar:4.3.10.Final]
    at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) ~[hibernate-entitymanager-4.3.10.Final.jar:4.3.10.Final]
    at org.hibernate.jpa.internal.QueryImpl.getResultList(QueryImpl.java:458) ~[hibernate-entitymanager-4.3.10.Final.jar:4.3.10.Final]
    at org.hibernate.jpa.criteria.compile.CriteriaQueryTypeQueryAdapter.getResultList(CriteriaQueryTypeQueryAdapter.java:67) ~[hibernate-entitymanager-4.3.10.Final.jar:4.3.10.Final]
    at dao.AbstractDAO.findMany(AbstractDAO.java:92) ~[classes/:na]
Caused by: org.hibernate.QueryTimeoutException: Could not open connection
    at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:83) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]
    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:235) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]
Caused by: java.sql.SQLTimeoutException: Timeout after 120000ms of waiting for a connection.
    at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:227) ~[HikariCP-2.3.7.jar:na]
    at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:182) ~[HikariCP-2.3.7.jar:na]
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:93) ~[HikariCP-2.3.7.jar:na]
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]
    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

/Johan

[Brett Wooldridge]

Does the error always occur, or occasionally occur? Can you enable debug logging for the com.zaxxer.hikari package and look for any diagnostic logs that might indicate the cause?

[Johan Dahlberg]

Not every time, but I got this:

Don't understand how 10 could be used since this is local and I only have one tab. How can I increase the pool?

/Johan

2015-07-30 13:08:10,638 - [info] application - User 'jo...@dahlberg.co' logged in with the following user agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/40.0.2214.115 Safari/537.36

2015-07-30 13:08:10,638 - [error] c.Application - Test 2a - 2ae41892-46c4-42d7-b971-c525c0737338

2015-07-30 13:08:10,638 - [error] c.Application - Test 2a2 -2ae41892-46c4-42d7-b971-c525c0737338

2015-07-30 13:08:10,639 - [debug] p.a.mvc.Cookies - Couldn't decode the Cookie header containing: 

2015-07-30 13:08:10,644 - [debug] application - Remote address: 127.0.0.1

2015-07-30 13:08:10,644 - [error] application - currentSessionId: 2ae41892-46c4-42d7-b971-c525c0737338

2015-07-30 13:08:16,486 - [debug] c.z.h.p.HikariPool - Before cleanup pool stats HikariPool-0 (total=10, inUse=10, avail=0, waiting=1)

2015-07-30 13:08:16,486 - [debug] c.z.h.p.HikariPool - After cleanup pool stats HikariPool-0 (total=10, inUse=10, avail=0, waiting=1)

2015-07-30 13:08:16,486 - [debug] c.z.h.p.HikariPool - After fill pool stats HikariPool-0 (total=10, inUse=10, avail=0, waiting=1)

2015-07-30 13:08:46,486 - [debug] c.z.h.p.HikariPool - Before cleanup pool stats HikariPool-0 (total=10, inUse=10, avail=0, waiting=1)

2015-07-30 13:08:46,486 - [debug] c.z.h.p.HikariPool - After cleanup pool stats HikariPool-0 (total=10, inUse=10, avail=0, waiting=1)

2015-07-30 13:08:46,487 - [debug] c.z.h.p.HikariPool - After fill pool stats HikariPool-0 (total=10, inUse=10, avail=0, waiting=1)

2015-07-30 13:09:16,486 - [debug] c.z.h.p.HikariPool - Before cleanup pool stats HikariPool-0 (total=10, inUse=10, avail=0, waiting=1)

2015-07-30 13:09:16,486 - [debug] c.z.h.p.HikariPool - After cleanup pool stats HikariPool-0 (total=10, inUse=10, avail=0, waiting=1)

2015-07-30 13:09:16,487 - [debug] c.z.h.p.HikariPool - After fill pool stats HikariPool-0 (total=10, inUse=10, avail=0, waiting=1)

2015-07-30 13:09:46,486 - [debug] c.z.h.p.HikariPool - Before cleanup pool stats HikariPool-0 (total=10, inUse=10, avail=0, waiting=1)

2015-07-30 13:09:46,486 - [debug] c.z.h.p.HikariPool - After cleanup pool stats HikariPool-0 (total=10, inUse=10, avail=0, waiting=1)

2015-07-30 13:09:46,487 - [debug] c.z.h.p.HikariPool - After fill pool stats HikariPool-0 (total=10, inUse=10, avail=0, waiting=1)

2015-07-30 13:10:10,645 - [debug] c.z.h.p.HikariPool - Timeout failure pool stats HikariPool-0 (total=10, inUse=10, avail=0, waiting=0)

2015-07-30 13:10:10,646 - [warn] o.h.e.j.s.SqlExceptionHelper - SQL Error: 0, SQLState: null

2015-07-30 13:10:10,646 - [error] o.h.e.j.s.SqlExceptionHelper - Timeout after 120001ms of waiting for a connection.

2015-07-30 13:10:10,665 - [error] application - 

! @6n1l4j3n7 - Internal server error, for (GET) [/] ->

 

play.api.http.HttpErrorHandlerExceptions$$anon$1: Execution exception[[QueryTimeoutException: Could not open connection]]

at play.api.http.HttpErrorHandlerExceptions$.throwableToUsefulException(HttpErrorHandler.scala:265) ~[play_2.11-2.4.2.jar:2.4.2]

at play.api.http.DefaultHttpErrorHandler.onServerError(HttpErrorHandler.scala:191) ~[play_2.11-2.4.2.jar:2.4.2]

at play.api.GlobalSettings$class.onError(GlobalSettings.scala:179) [play_2.11-2.4.2.jar:2.4.2]

at play.api.DefaultGlobal$.onError(GlobalSettings.scala:212) [play_2.11-2.4.2.jar:2.4.2]

at play.api.http.GlobalSettingsHttpErrorHandler.onServerError(HttpErrorHandler.scala:94) [play_2.11-2.4.2.jar:2.4.2]

Caused by: javax.persistence.QueryTimeoutException: Could not open connection

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1725) ~[hibernate-entitymanager-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) ~[hibernate-entitymanager-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.jpa.internal.QueryImpl.getSingleResult(QueryImpl.java:524) ~[hibernate-entitymanager-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.jpa.criteria.compile.CriteriaQueryTypeQueryAdapter.getSingleResult(CriteriaQueryTypeQueryAdapter.java:71) ~[hibernate-entitymanager-4.3.10.Final.jar:4.3.10.Final]

at dao.AbstractDAO.findOne(AbstractDAO.java:143) ~[classes/:na]

Caused by: org.hibernate.QueryTimeoutException: Could not open connection

at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:83) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:235) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

Caused by: java.sql.SQLTimeoutException: Timeout after 120001ms of waiting for a connection.

at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:227) ~[HikariCP-2.3.7.jar:na]

at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:182) ~[HikariCP-2.3.7.jar:na]

at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:93) ~[HikariCP-2.3.7.jar:na]

at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

2015-07-30 13:10:16,486 - [debug] c.z.h.p.HikariPool - Before cleanup pool stats HikariPool-0 (total=10, inUse=9, avail=1, waiting=0)

2015-07-30 13:10:16,486 - [debug] c.z.h.p.HikariPool - After cleanup pool stats HikariPool-0 (total=10, inUse=9, avail=1, waiting=0)

2015-07-30 13:10:16,487 - [debug] c.z.h.p.HikariPool - After fill pool stats HikariPool-0 (total=10, inUse=9, avail=1, waiting=0)

[Johan Dahlberg]

Hi again!

I found how I configure the pool size. The default with bonecp was 30*5 so that explains why the problems occurred now.

I started spamming small requests and a pool with 100 connections filled up fast as well and I left it untouched for two minutes and no connections released. Is hikaricp configured by default to keep connections alive? Because all 100 is marked as inUse even though every request except the last was successful in 1 second.

/Johan

[Johan Dahlberg]

Hi again!

I've done some more testing:

I have tried to configure maxLifetime to 5 minutes and leakDetectionThreshold to 8 minutes and this is the events that occur during the eleven minutes after I start my server.

14.26: 12 page requests

14.27: total=100, inUse=24, avail=46, waiting=0

14.28: 15 page requests

14.29: total=100, inUse=54, avail=46, waiting=0

14.34: Connection leak detection triggered for connections

14.35: total=100, inUse=54, avail=46, waiting=0

14.36: Connection leak detection triggered for connections

14.37: total=100, inUse=54, avail=46, waiting=0

During this time idle timeout caused the available to be shutdown after 2 minutes without problem.

Shouldn't those 54 be killed after maxLifetime?

/Johan

[Brett Wooldridge]

Hi Johan,

It looks strange to me.  To answer your last question first, HikariCP will never kill inUse connections, even at maxLifetime.  If a connection reaches maxLifetime while in use it will be killed as soon as it comes back to the pool.

The fact that leak detection is triggering is a big red flag.  Leak detection should be logging stacktraces, to show you where the allocation callsites are.  If you are on Java 7 or above, I also recommend upgrading to HIkariCP 2.4.0, as it has some improved logging among other changes.

This looks like either a misconfiguration in Hibernate, or strange interaction between Hiberante and Play.  You might get better troubleshooting help over on the Play group.  If Hibernate or Play needs to hang onto more than 20 connections right out of the gates, something definitely feels wrong.

-Brett

[Johan Dahlberg]

I am on Java 8 so yes. But I can't find 2.4 here:

http://mvnrepository.com/artifact/com.zaxxer/HikariCP

Is 2.4 hosted somewhere else?

The logged didn't give any help direct but maybe someone in the Play group can read anything from it.

2015-07-30 15:53:15,421 - [warn] c.z.h.p.LeakTask - Connection leak detection triggered for connection com.mysql.jdbc.JDBC4Connection@53b6a428, stack trace follows

java.lang.Exception: Apparent connection leak detected

at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:63) ~[hibernate-core-4.3.10.Final.jar:4.3.10.Final]

It looks like no connection is closed actually.

/Johan

[Brett Wooldridge]

Try here:

http://search.maven.org/#search%7Cga%7C1%7Chikaricp

It may have something to do with Hibernate connection release modes.  It seems like the default should do the right thing (?).  This discussion might also be useful.  If you do need to use JTA, you'll need to look at something like Bitronix instead of HikariCP for your datasource.

[Johan Dahlberg]

We use RESOURCE_LOCAL, i didn't succeed with updating to 2.4. I need to figure out how to do that.

<persistence xmlns="http://xmlns.jcp.org/xml/ns/persistence"

             xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

             xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/persistence http://xmlns.jcp.org/xml/ns/persistence/persistence_2_1.xsd"

             version="2.1">

    <persistence-unit name="defaultPersistenceUnit" transaction-type="RESOURCE_LOCAL">

        <provider>org.hibernate.jpa.HibernatePersistenceProvider</provider>

        <non-jta-data-source>DefaultDS</non-jta-data-source>

        <properties>

            <property name="hibernate.dialect" value="org.hibernate.dialect.MySQL5Dialect"/>

            <property name="hibernate.enable_lazy_load_no_trans" value="true" />

            <property name="hibernate.format_sql" value="true" />

            <property name="hibernate.hbm2ddl.auto" value="validate"/>

            <property name="hibernate.max_fetch_depth" value="5" />

            <property name="hibernate.show_sql" value="false" />

        </properties>

    </persistence-unit>

</persistence>

/Johan

[Johan Dahlberg]

I also got the same error as Dotta in this GitHub issue when trying to use 2.4 in my project.

https://github.com/brettwooldridge/HikariCP/issues/360

/Johan

[sachin walia]

Johan,

I use HikariCP 2.4 as well however I am using with PostgreSQL. Also I don't use play native DB plugin as the requirement was to provide credentials in encrypted format. If it helps I can share that code with you as I believe it is free from all such abstractions that may have been an issue in your case.

thanks,

Sachin Walia