HikariCP and active connections in Postgresql

[mantesat]

Hi all, Brett,

I'm using HikariCP for the past month, transitioning from BoneCP to remedy some leak connection problems. I'm using Hikari with Postgresql, Spring and Hibernate, and I'm printing some MBean statistics about the active/idle connections. As reported by Hikari pool MBean, active connections slowly but steadily increase. However, when running

select query, state, state_change from pg_stat_activity

to the postgresql, all connections are reported as idle.

I'm sure that when the active connections reach the max pool size, the application will freeze. Which one reports the correct status of the connections, Hikari or postgresql? Is there a way to see which query is running on the active connections from Hikari?

Thanks in advance
mantesat, Greece

[brettwooldridge]

Could you add total connections to your monitoring? What it looks like to me from what you've reported, is a connection leak whereby some thread is taking connections but not returning them. Can you enable leak detection (eg. leakDetectionThreshold=30000)?

Reviewing the code, everything seems correct.

[mantesat]

I've already done this, and also I've enabled the leak detection (let me mention that I'm running version 1.3.9 because of the bug of MBean pool names in 1.4.0 release. I'll probably compile a version from the latest code myself, in order to find the cause of the leak). As of now, printing the Mbean statistics gives me this:

HikariCP Statistics. IdleConnections: 4, ActiveConnections: 16, TotalConnections: 20, ThreadsAwaitingConnection: 0

this means that soon all 4 idle connection will become active, and the pool will get exhausted.

This is what the sql query about database statistics gives me:

"SELECT 1";"idle";"2014-07-12 06:15:07.739973+03"
"SELECT 1";"idle";"2014-07-12 06:15:42.106493+03"
"COMMIT";"idle";"2014-07-12 06:14:03.238993+03"
"SELECT 1";"idle";"2014-07-11 23:21:49.29712+03"
"COMMIT";"idle";"2014-07-11 23:35:19.23725+03"
"COMMIT";"idle";"2014-07-11 23:35:19.059254+03"
"COMMIT";"idle";"2014-07-11 23:21:49.1957+03"
"COMMIT";"idle";"2014-07-12 17:55:32.78174+03"
"SELECT 1";"idle";"2014-07-12 06:14:03.76456+03"
"SELECT 1";"idle";"2014-07-12 15:12:54.288188+03"
"COMMIT";"idle";"2014-07-11 16:47:02.426132+03"
"SELECT 1";"idle";"2014-07-11 16:20:42.383651+03"
"SELECT 1";"idle";"2014-07-11 16:20:42.384655+03"
"SELECT 1";"idle";"2014-07-11 16:47:03.356027+03"
"COMMIT";"idle";"2014-07-12 06:15:41.130054+03"
"SELECT 1";"idle";"2014-07-12 15:12:54.286323+03"
"SELECT 1";"idle";"2014-07-12 06:15:07.74065+03"
"SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL READ COMMITTED";"idle";"2014-07-12 17:54:43.93452+03"
"SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL READ COMMITTED";"idle";"2014-07-12 17:55:13.934658+03"

you can see the last sql run on a connection, the connection status according to postgresql, and the time it run. All connections last queries are either SELECT 1 or COMMIT, and only four of them have run recently (local time 17.55). These must be the connections that Hikary reports as idle. However, all 20 connections are marked by postgresql as idle. Also, there are some connections that are a day old, and haven't expired (probably because Hikari considers them as active).

So, there must be something that is making Hikari think that these connections are active, and not retiring them or making them available, espesially since last queries run on these connections are the SELECT 1 or COMMIT queries.

[brettwooldridge]

When you said "I've enabled the leak detection ... I'll probably compile a version from the latest code myself, in order to find the cause of the leak", does that mean that leak detection reported a leak?

You are correct that HikariCP reports connections that are "out of the pool" as "active", whether or not they are active from the database perspective or not. Basically, from the pool perspective a connection is in one of two states: in the pool (idle), or out of the pool (active).

[brettwooldridge]

If leak detection is reporting a leak, it should be logging a full stacktrace at warn level. This stacktrace should indicate the point in code where getConnection() was called, but a corresponding close() was not called.

[mantesat]

Leak detection is enabled, but no stacktrace is thrown. Actually, active connections reported by the MBean slowly but steadily increase.

If total connections managed from the pool are (in my case) 20, and active connections are actually out of the pool, this means that idle connections are decreasing to a point that there are no more available. There is where the app will stall. In my code, there is no call to getConnection(), everything from the database view is managed from Hibernate/Spring (Hibernate version 3.6.10 final).

Since the last queries called on the active connections are the SELECT 1 and COMMIT queries, why are these connections stay out of the pool? Are these queries called from HikariCP?

[brettwooldridge]

It would be useful to see both your Spring and Hibernate configurations. You keep hypothesizing that at some point your app will stall, but has it? Why don't you set maxPoolSize to something low, like 5 or 8 and see if you can make the application stall.

[mantesat]

Yes, it has stalled once with HikariCP (actually its a production system, so letting it crash doesn't make a good impression on the customers ;) ). For now I'm silently rebooting the server when load is low and active connections are high. Stalling took about two or three days usage with Hikari. Same thing also happened a lot of times using BoneCP, stalls after 3-5 days of usage, depending on the system load.

This is how I register a Hikari datasource bean to Spring:

        dataSource = new HikariDataSource();
        ((HikariDataSource) dataSource).setDataSourceClassName("org.postgresql.ds.PGSimpleDataSource");
        ((HikariDataSource) dataSource).addDataSourceProperty("user",
                ((HikariDataSource) adminDataSource).getDataSourceProperties().getProperty("user"));
        ((HikariDataSource) dataSource).addDataSourceProperty("password",
                ((HikariDataSource) adminDataSource).getDataSourceProperties().getProperty("password"));
        ((HikariDataSource) dataSource).addDataSourceProperty("serverName",
                ((HikariDataSource) adminDataSource).getDataSourceProperties().getProperty("serverName"));
        ((HikariDataSource) dataSource).addDataSourceProperty("portNumber",
                ((HikariDataSource) adminDataSource).getDataSourceProperties().getProperty("portNumber"));
        ((HikariDataSource) dataSource).addDataSourceProperty("databaseName", dbName);
        ((HikariDataSource) dataSource).setConnectionTimeout(30000);
        ((HikariDataSource) dataSource).setAutoCommit(true);
        ((HikariDataSource) dataSource).setIdleTimeout(60000);
        ((HikariDataSource) dataSource).setMaxLifetime(1800000);
        ((HikariDataSource) dataSource).setLeakDetectionThreshold(15000);
        ((HikariDataSource) dataSource).setMaximumPoolSize(20);
        ((HikariDataSource) dataSource).setPoolName(serviceID+"_DBPool");
        ((HikariDataSource) dataSource).setRegisterMbeans(true);

        ((HikariDataSource) dataSource).setUsername(username);
        ((HikariDataSource) dataSource).setPassword(passwd);


    daoContext.getBeanFactory().registerSingleton("dataSource", dataSource);

And these are the hibernate config parameters, at the spring application context:

            <prop key="hibernate.jdbc.batch_size">0</prop>
            <prop key="hibernate.connection.autocommit">false</prop>
            <prop key="hibernate.dialect">org.hibernatespatial.postgis.PostgisDialect</prop>
            <prop key="javax.persistence.validation.mode">none</prop>

Also, I'm using an initial datasource bean, whose properties (username/password) I copy to create client datasources (the server is actually implemented as a service provider for many "server" (=customer) instances. This is the initial Hikari CP bean:

<bean id="hikariConfig" class="com.zaxxer.hikari.HikariConfig">  
  <property name="dataSourceProperties" >
    <props>
        <prop key="user">admin</prop>
        <prop key="password">admin</prop>
        <prop key="databaseName">master</prop>
        <prop key="portNumber">5432</prop>
        <prop key="serverName">127.0.0.1</prop>
    </props>
  </property>  
  <property name="dataSourceClassName"   
            value="org.postgresql.ds.PGSimpleDataSource" />  

</bean>  

<bean id="dataSource" class="com.zaxxer.hikari.HikariDataSource" singleton = "true">  
      <constructor-arg ref="hikariConfig" />  
</bean>

That's all. I hope it clears some things up.

[brettwooldridge]

Couple of suggestions.

Synchronize some of the configuration parameters just to eliminate variables. Should autocommit be true or false? It is false in one config, true in another, and unspecified in the third (default true). I assume you want false. It should be the same everywhere.

Turn on debug logging for package com.zaxxer.hikari. It is not "noisy" at all. It should log one line every 30 seconds showing the pool state (total, in-use, avail, thread waiting). Maybe with application or hibernate/spring logging interspersed, when a connection appears to "leak" you may be able to pinpoint what was going on in those other components.

The fact that it is also occurring with BoneCP makes me suspect the cause is elsewhere, but lets follow the trail and see where it leads.

[mantesat]

After a day's testing (I left the system intentionally to crash for a second time, and it did), I changed all autocommit configurations to autocommit=true, in order to make sure hibernate takes up the responsibility to "close" the connections in uses. Things have improved considerably, now after some time active conenctions decrease to zero or stay stable, depending on the load of the system. However, I got a leak stack trace (that may show that indeed everything was related to Hibernate):

WARNING: Connection leak detection triggered, stack trace follows
java.lang.Exception
at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:81)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
at gr.cognity.dbutils.dbaccess.DBAccess.execQuery(DBAccess.java:341)
at gr.cognity.dbutils.dbaccess.DBAccess.execQuery(DBAccess.java:330)
at gr.cognity.logistics.callcenter.server.CallCenterServiceImpl.getCustomer(CallCenterServiceImpl.java:788)
at gr.cognity.logistics.callcenter.server.CallCenterServiceImpl.getDAO(CallCenterServiceImpl.java:298)
at sun.reflect.GeneratedMethodAccessor317.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:561)
at com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:545)
at com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:507)
at gr.cognity.logistics.callcenter.server.GwtRpcController.processCall(GwtRpcController.java:43)

This didn't seam to leave a connection "active", everything returned to normal.

Anyway, things seem to be ok for now, and Hikari seems to perform as it should. I'll stress it for a week to see how it goes.

Thanks Brett for your comments and for this good CP library!

[brettwooldridge]

Getting all the various layers of libraries to agree on responsibilities (to commit, or close, etc.) is sometimes tricky...

The Hibernate leak stack trace was probably just a connection that was out of the pool for more than your 15 second threshold. It may well have been returned 1 or 2 seconds later, given that most of your queries seem to be executing well under that limit.

I'm going to close this for now, but feel free to re-open it if looks like it is not resolved.

[brettwooldridge]

Have you tried with auto-commit turned off across the board? Auto-commit is usually considered undesirable (it prevents defining a larger unit-of-work and increases load on the DB).

[mantesat]

Brett, apologies for re-posting to this after a long time, seems not to be resolved (although latest versions have considerably improved things). From statistics, it seems that slowly but steadily, active connections tend to increase. I don't know if anyone has already reported such behavior, I'll try to use it from source code and find out why connections stay marked as active. Any suggestions are welcomed!

[zsoca8711]

We have the same issue, since we have moved to Hikari on our postgres databases, we have frequent (once every 1-2 weeks) issues, the database runs out of connections. Restarting the tomcats using Hikari fixes the issue.

Code sample:

HikariConfig config = new HikariConfig(dcAccessDetails.getDetailsAsPropertiesForHikari());
        config.setIdleTimeout(180000);
        config.setMaxLifetime(1800000);
        config.setInitializationFailFast(true);
        config.setConnectionTestQuery("SELECT current_timestamp");

public Properties getDetailsAsPropertiesForHikari(){
        Properties props = new Properties();
        props.setProperty("dataSourceClassName", DatabaseUtil.POSTGRES_DATASOURCE_CLASS);
        props.setProperty("dataSource.user", this.dcDbUser);
        props.setProperty("dataSource.password", this.dcDbPassword);
        props.setProperty("dataSource.databaseName", this.dcDbDatabaseName);
        props.setProperty("dataSource.serverName", this.dcDbServer);

        return props;
    }

[prostobog]

I have a similar issue with Hibernate+Postgresql:
http://stackoverflow.com/questions/32968530/hikaricp-connection-is-not-available

[ghost]

How can convert HikariDataSource to PGSimpleDataSoaurce?

[brettwooldridge]

@arlampin This is not the right issue thread for that question. The answer is here.

[flojdek]

Has this issue been resolved? I don't see any obvious resolution on the thread. Am I missing something?

[jnehlmeier]

IMHO it is a library configuration issue. I use EclipseLink (JPA) + HikariCP + Postgres without any additional library like Spring. EntityManger instance is created inside a servlet filter (which results in obtaining a connection) and that EntityManager instance is closed in that same filter after the request is done (which releases the connection to the pool).

So it not really an issue with HikariCP.

[ghost]

Thanck you very much. Alex Parincu On Thursday, April 27, 2017, 9:28:48 PM GMT+3, Jens Nehlmeier <notifications@github.com> wrote: IMHO it is a library configuration issue. I use EclipseLink (JPA) + HikariCP + Postgres without any additional library like Spring. EntityManger instance is created inside a servlet filter (which results in obtaining a connection) and that EntityManager instance is closed in that same filter after the request is done (which releases the connection to the pool). So it not really an issue with HikariCP. — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

[wotbstars]

This issue is real. I am confirming that is is reproducible without hibernate and spring. Just plain JDBC.
Postgres is flooded with "SHOW default_transaction_read_only" queries (Hikary 3.3.1)