Hikaricp: HikariPool.getConnection freezes in certain circumstances

[Bhashit]

Hi,

I have been happily using Hikari for more than a year. Yesterday, I ran into a strange problem. My connection pool is getting initialized fine. But when Hibernate tries to get a connection via dataSource.getConnection, it freezes indefinitely. I have tried to make the connectionTimeout parameter very large to see if this was a resource issue. But the getConnection times out regardless of the timeout period.

Another interesting thing is that the the same code is working perfectly fine on one of the two identical machines in terms of software. The only significant difference between the two machines is that one has only one core (where it is not working) and the other has 8 cores (where it is working).

The various versions of libraries/tools that I am using are:

1. Play Framework 2.4.2 (with hikari has the default pool)
2. Hibernate 5 (recently upgraded from 4.3.8)
3. Postgres 9.4
4. Ubuntu 14.04
5. Oracle JDK 1.8.0_45

This is my config in play:

  logSql=true
  dataSourceClassName=org.postgresql.ds.PGSimpleDataSource
  connectionTestQuery="SELECT 1"
  initializationFailFast=true
  maximumPoolSize=10
  autoCommit=false
  dataSource {
    user=xxxxxx
    password=xxxxxx
    databaseName=xxxxxxx
    serverName=localhost
  }

I took the thread dump using jstack while hibernate was blocked, the relevant parts of which look like this:

 "ForkJoinPool-1-worker-1" #46 daemon prio=5 os_prio=0 tid=0x00007f0945f68000 nid=0xd29 waiting on condition [0x00007f093444e000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for  <0x00000000d1727b08> (a com.zaxxer.hikari.util.QueuedSequenceSynchronizer$Synchronizer)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedLongSynchronizer.doAcquireSharedNanos(AbstractQueuedLongSynchronizer.java:815)
    at java.util.concurrent.locks.AbstractQueuedLongSynchronizer.tryAcquireSharedNanos(AbstractQueuedLongSynchronizer.java:1106)
    at com.zaxxer.hikari.util.QueuedSequenceSynchronizer.waitUntilSequenceExceeded(QueuedSequenceSynchronizer.java:92)
    at com.zaxxer.hikari.util.ConcurrentBag.borrow(ConcurrentBag.java:159)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:182)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:163)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:85)
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
    at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess.obtainConnection(JdbcEnvironmentInitiator.java:180)
    at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:68)
    at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:35)
   at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.initiateService(StandardServiceRegistryImpl.java:88)

And here's the debug-log while hibernate seems to be stuck:

[info] c.z.h.HikariDataSource - HikariPool-0 - is starting.
[debug] c.z.h.p.PoolElf - HikariPool-0 - Connection.setNetworkTimeout() is not supported (org.postgresql.jdbc4.Jdbc4Connection.getNetworkTimeout()I)
[debug] c.z.h.p.HikariPool - HikariPool-0 - Added connection org.postgresql.jdbc4.Jdbc4Connection@26ccc54a
[debug] c.z.h.p.PoolElf - HikariPool-0 - Reset (autoCommit) on connection org.postgresql.jdbc4.Jdbc4Connection@26ccc54a
[debug] c.z.h.p.HikariPool - HikariPool-0 - Added connection org.postgresql.jdbc4.Jdbc4Connection@319e194b
[debug] c.z.h.p.HikariPool - HikariPool-0 - Added connection org.postgresql.jdbc4.Jdbc4Connection@3f59e108
[debug] c.z.h.p.HikariPool - HikariPool-0 - Added connection org.postgresql.jdbc4.Jdbc4Connection@3b66723b
[debug] c.z.h.p.HikariPool - HikariPool-0 - Added connection org.postgresql.jdbc4.Jdbc4Connection@7e64eb33
[debug] c.z.h.p.HikariPool - HikariPool-0 - Added connection org.postgresql.jdbc4.Jdbc4Connection@3ff1e1f5
[debug] c.z.h.p.HikariPool - HikariPool-0 - Added connection org.postgresql.jdbc4.Jdbc4Connection@4fd016a2
[debug] c.z.h.p.HikariPool - HikariPool-0 - Added connection org.postgresql.jdbc4.Jdbc4Connection@47af42c9
[debug] c.z.h.p.HikariPool - HikariPool-0 - Added connection org.postgresql.jdbc4.Jdbc4Connection@1e4b147c
[debug] c.z.h.p.HikariPool - HikariPool-0 - Added connection org.postgresql.jdbc4.Jdbc4Connection@2e05a009
[debug] c.z.h.p.HikariPool - After fill pool HikariPool-0 stats (total=10, active=0, idle=10, waiting=0)
[debug] c.z.h.p.PoolElf - HikariPool-0 - Reset (autoCommit) on connection org.postgresql.jdbc4.Jdbc4Connection@319e194b
[debug] c.z.h.p.PoolElf - HikariPool-0 - Reset (autoCommit) on connection org.postgresql.jdbc4.Jdbc4Connection@26ccc54a
[debug] c.z.h.p.PoolElf - HikariPool-0 - Statement.setQueryTimeout() is not supported (Method org.postgresql.jdbc4.Jdbc4Statement.setQueryTimeout(int) is not yet implemented.)
HikariConnectionProxy@360951608 wrapping org.postgresql.jdbc4.Jdbc4Connection@26ccc54a
[debug] c.z.h.p.HikariPool - Before cleanup pool HikariPool-0 stats (total=10, active=10, idle=0, waiting=1)
[debug] c.z.h.p.HikariPool - After cleanup  pool HikariPool-0 stats (total=10, active=10, idle=0, waiting=1)
[debug] c.z.h.p.HikariPool - Before cleanup pool HikariPool-0 stats (total=10, active=10, idle=0, waiting=1)
[debug] c.z.h.p.HikariPool - After cleanup  pool HikariPool-0 stats (total=10, active=10, idle=0, waiting=1)
[debug] c.z.h.p.HikariPool - Before cleanup pool HikariPool-0 stats (total=10, active=10, idle=0, waiting=1)
[debug] c.z.h.p.HikariPool - After cleanup  pool HikariPool-0 stats (total=10, active=10, idle=0, waiting=1)
[debug] c.z.h.p.HikariPool - Before cleanup pool HikariPool-0 stats (total=10, active=10, idle=0, waiting=1)
[debug] c.z.h.p.HikariPool - After cleanup  pool HikariPool-0 stats (total=10, active=10, idle=0, waiting=1)
[debug] c.z.h.p.HikariPool - Before cleanup pool HikariPool-0 stats (total=10, active=10, idle=0, waiting=1)
[debug] c.z.h.p.HikariPool - After cleanup  pool HikariPool-0 stats (total=10, active=10, idle=0, waiting=1)
[debug] c.z.h.p.HikariPool - Before cleanup pool HikariPool-0 stats (total=10, active=10, idle=0, waiting=1)
[debug] c.z.h.p.HikariPool - After cleanup  pool HikariPool-0 stats (total=10, active=10, idle=0, waiting=1)

The surprising thing is that when I create a pool using the same config in the scala console (in the same project using sbt console) and call the getConnection, it seems to work fine.

I am not yet sure what's the problem. Looking into it. Looking at the thread dump, it looks like it could be related to concurrency since the thread seems to be getting stuck at ConcurrentBag.borrow.

[Shredder121]

I am also looking into this (from before the weekend), could you maybe share what Java version and vendor you use? (e.g. java -version)

[brettwooldridge]

@Bhashit @Shredder121 I recommend enabling the _leakDetectionThreshold_. When I see total=10, active=10, idle=0, waiting=1 that looks to me like something took 10 connections out of the pool and never returned them. Consequently, the next caller is _"waiting"_, and would indeed be blocked in ConcurrentBag.borrow() until it times out or someone gives back a connection.

It could also be that a single thread requires more than 10 connections to perform some task ... in which case, obviously, a pool with a maximum of 10 connections is going to lockup.

Either way, the _leakDetectionThreshold_ should hopefully shed some light on the issue.

EDIT: additionally, timestamp and thread-name would be useful in the logs.

[Shredder121]

How high would you set it for testConnectionRetries()?

I have not pinpointed the exact cause, but I know that Windows + Oracle JDK 8 exhibits the issue (as of this writing I use 1.8.0_60 and I cannot build and test HikariCP, it blocks on the aforementioned test _EDIT: this means 100% cpu usage.._).

Windows + OpenJDK 8 (_EDIT: as of this writing 1.8.0_45, going to investigate 1.8.0_51 soon_) miraculously does work (which is what I use), but a colleague has the issue, and students also have the issue.

@Bhashit What setup do you use?

@brettwooldridge If you need anything in particular I can repro it for you.

[Bhashit]

@Shredder121 I have Ubuntu 14.04 with Oracle JDK 1.8.0_45.

@brettwooldridge Thanks for the pointers. I'll look into them. I think under the time pressure, I was looking at the wrong things. WIll do some more experiments and report back.

[Bhashit]

@brettwooldridge Sorry to have bothered you, thanks for the help. Setting the pool size handles the issue. However, I'll look into why the original pool size is working on a multi-core machine and not working on a single-core machine. This could probably lead to some issue in play or hibernate. WIll also find report back the results of enabling leakDetectionThreshold.

[Shredder121]

Confirming, OpenJDK 1.8.0_51 also exhibits the issue on my machine.

So between 1.8.0_45 and 1.8.0_51 something must have been introduced that triggers this on certain setups.
N.B. @Bhashit I have a multi-core machine, so strange that it works for you.

[brettwooldridge]

@Shredder121 It is very curious. To be honest, I have never built under Windows. But I just installed Oracle JDK 1.8_60 64-bit on a Windows 10 machine, and the build ran to completion:

Tests run: 97, Failures: 0, Errors: 0, Skipped: 0

[INFO]
[INFO] --- jacoco-maven-plugin:0.7.4.201502262128:report (post-unit-test) @ HikariCP ---
[INFO] Analyzed bundle 'HikariCP' with 46 classes
[INFO]
[INFO] --- maven-bundle-plugin:2.5.3:bundle (default-bundle) @ HikariCP ---
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 02:43 min
[INFO] Finished at: 2015-09-17T17:01:14+09:00
[INFO] Final Memory: 28M/153M
[INFO] ------------------------------------------------------------------------
C:\Users\Brett\Documents\HikariCP>

EDIT: The long build time is due to all of the maven dependency downloads. Also note this was a fresh clone of the dev branch.

C:\Users\Brett\Documents\HikariCP>java -version
java version "1.8.0_60"
Java(TM) SE Runtime Environment (build 1.8.0_60-b27)
Java HotSpot(TM) 64-Bit Server VM (build 25.60-b23, mixed mode)

[Shredder121]

It is even more curious, since as a sanity check I retried OpenJDK 1.8.0_45 again, and it now also blocks.

[Shredder121]

I'll look again later

[Bhashit]

@brettwooldridge @Shredder121 I just tested after enabling the leakDetectionThreshold and it started working. I mean, it didn't freeze. Then, just to check, I removed leakDetectionThreshold and tried again, and again it worked; on that same single core machine. The spurious nature of this issue definitely points to something concurrency related. Hibernate is taking one connection from the pool at the beginning to manage/validate the schema and that apparently takes a few seconds. Although, why it would take 10 connections simultaneously from the pool is something I'll have to look into. I'll report if I find anything else.

[brettwooldridge]

@Shredder121 Not to get too esoteric, but what CPU do you have? HikariCP isn't going anything "tricky" (no use of sun.misc.Unsafe for example), but it does rely heavily on the Java Memory Model, including _happens-before_ semantics, store/store and load/store barriers, etc.

It is certainly possible that there is a bug in HikariCP, but I consider equally possible a bug in the hotspot compiler on a particular CPU. Hotspot generates very specific, and sometimes esoteric, instructions (lock; addl $0,0(%%esp) anyone?) in order to implement the JMM as efficiently as possible on a particular CPU.

[Shredder121]

Haswell-based Intel Core i7 Intel(R) Core(TM) i7-4700MQ CPU @ 2.40GHz.

My colleague used to have an Intel Celeron (W500 he said?), and it worked, he now also has an i7 5500 that exhibits the same behavior.
Can't say for the students. (also remind me to update this with details later, but it's probably also i7)

Note: interpreted mode also blocks and uses 100%.

[brettwooldridge]

@Shredder121 Interesting point on interpreted mode.

[brettwooldridge]

@Shredder121 you just set this line in the pom.xml for the surefire plugin right?

<argLine>-Xint</argLine>

Still works here (unfortunately?).

[Shredder121]

Hmm. it's maybe good to have said this earlier, I was testing on the HikariCP-2.4.1 tag.
With the dev branch, it's harder to reproduce, since the HikariPool constructor finishes quicker.

At least, the problem I saw the most is the HouseKeeper used to have time between
this.houseKeepingExecutorService.scheduleAtFixedRate(new HouseKeeper(), ...);
and
initializeConnections();
to fill the connections. And unluckily there were always interleaved checks, and it wouldn't return from either call.

Could you maybe at least verify that HikariCP-2.4.1 exhibits this behavior? (just for my conscience)

I'll at least build HikariCP and see what it does outside of the test.

Oh by the way, I really like the project, so kudos.

[Shredder121]

Still blocks, spits more output than with HikariCP-2.4.1

It returns connections that are 'not operating'(<- not sure, so don't hold it against me), so it spits
2015-09-17 12:25:42,859 [http-apr-8082-exec-1] [] WARN c.zaxxer.hikari.pool.ProxyConnection - hikariCP - Connection com.mysql.jdbc.JDBC4Connection@71218193 marked as broken because of SQLSTATE(08003), ErrorCode(0) [] a lot.
Accompanied by Hibernate stacktraces in the error stream.

[brettwooldridge]

@Shredder121 Just tested and had no issue with 2.4.1. Intel i7 3770. Is it always one particular test?

[Shredder121]

Updated processor of colleague,

My colleague used to have an Intel Celeron (W500 he said?), and it worked, he now also has an i7 5500 that exhibits the same behavior.

Anyway, it's always TestConnectionTimeoutRetry.testConnectionRetries().

And as I said (don't know if you saw it) our project still fails even with the dev version.

[brettwooldridge]

I don't suppose you have a Linux box handy?

[Shredder121]

I have a DigitalOcean droplet yes, but why?
I also have a Linux vm.

[brettwooldridge]

I was wondering if similar CPU but different OS exhibits the behavior. Not important.

If you comment out the @Test line before _testConnectionRetries()_, and let the other tests in that class run, does it still occur?

[Shredder121]

I have already done that, the issue doesn't occur I think (although it was the release tag).
There is however a different issue then, the sleepQuietly() doesn't sleep enough, but that is more an issue with native parking of threads on Windows I suppose.

I'll retry it with the dev branch excluding that test.

[Shredder121]

My DigitalOcean droplet has an Intel Xeon cpu, so it might be a little too different.
I can still try though, if that sounds good to you?

[brettwooldridge]

@Shredder121 It's really too much to expect, setting up on your droplet. The fact that it can be isolated to that test will be a big help narrowing it down.

[Shredder121]

Yeah, a quick look (not too difficult) on my droplet it doesn't block, it uses OpenJDK 1.8.0_45-internal, Ubuntu 15.04.
Anyway, just mentioning that reproducing it on our app is easier, I can also customize logback.xml to only print Hikari output.
What is your suggested next step? Maybe you can prepare a branch with debug statements?
I'll then paste the output in the commit comments.

[brettwooldridge]

@Shredder121 I just pushed two small changes to the experimental branch.

First, if you can checkout, and run as-is I would be interested to see if the behavior has changed. That will be just the change in ConcurrentBag.

Next, if you _do_ still observe the hang, add -Dcom.zaxxer.hikari.useAtomicLongSequence=true to your argLine for surefire in the pom, and run the test again.

Curious if either has an impact.

EDIT: I'd pay a kings ransom to repro. on my box! Unfortunately, my Windows is in a VM, as I develop on a Mac, and I suspect that might be affecting the behavior.

[brettwooldridge]

@Shredder121 Sorry, I was on the train ealier and somehow missed this comment. That is a big clue... looking into it.

EDIT: Obviously that is a _live_ environment, not the junit test right?

[brettwooldridge]

@Shredder121 Sorry for the spam. Re: this comment, are you saying that there used to be multiple runs of the housekeeper (at 30 second intervals) before/while initializeConnections() was running? That seems strange to me...

How many connections are starting up? Maybe seeing the pool config might turn on a light...

[Shredder121]

The spitting output is not the junit test no, as of right now (sanity check) dev is harder to reproduce.
I won't be surprised if this timing issue is a function of uptime or something.

On another note, seeing how you named your commit, Windows has the most timing issues when run in power saving or at least when the cpu speed is toned down, so maybe you could try that?
(Maybe it's unaffected since it's a VM, but it's worth a try)

[Shredder121]

I don't mind being a debugger for you, or supplying output etc, although I have a little more time tonight (CEST).

[Shredder121]

As of the configuration, there are two HikariCP pools, one for the main database and one for a database with information (manual, common information etc).

The information database pool fails to start.

<bean id="hikariConfig" class="com.zaxxer.hikari.HikariConfig">
    <property name="poolName" value="hikariCP" />
    <property name="driverClassName" value="com.mysql.jdbc.Driver" />
    <property name="jdbcUrl" value="${db.jdbcUrl}" />
    <property name="dataSourceProperties">
        <props>
            <prop key="user">${db.user}</prop>
            <prop key="password">${db.password}</prop>
            <prop key="rewriteBatchedStatements">true</prop>
            <prop key="useUnicode">yes</prop>
            <prop key="characterEncoding">UTF-8</prop>
        </props>
    </property>

    <property name="maximumPoolSize" value="4" />
    <property name="idleTimeout" value="600000" />
</bean>
<bean id="dataSource" class="com.zaxxer.hikari.HikariDataSource" destroy-method="close">
    <constructor-arg ref="hikariConfig" />
</bean>

<bean id="hikariConfigInfo" class="com.zaxxer.hikari.HikariConfig">
    <property name="poolName" value="infoHikariCP" />
    <property name="driverClassName" value="com.mysql.jdbc.Driver" />
    <property name="jdbcUrl" value="${infodb.jdbcUrl}" />
    <property name="dataSourceProperties">
        <props>
            <prop key="user">${infodb.user}</prop>
            <prop key="password">${infodb.password}</prop>
            <prop key="rewriteBatchedStatements">true</prop>
            <prop key="useUnicode">yes</prop>
            <prop key="characterEncoding">UTF-8</prop>
        </props>
    </property>

    <property name="maximumPoolSize" value="1" />
    <property name="idleTimeout" value="600000" />
</bean>
<bean id="dataSourceInfo" class="com.zaxxer.hikari.HikariDataSource" destroy-method="close">
    <constructor-arg ref="hikariConfigInfo" />
</bean>

I have tried setting the infoHikariCP pool's maximumPoolSize to 3 to see if it was simply a too low ceiling, but it still occurs.

Since going to dev, the main pool also spits a lot of error output, but the application does work (so how many Connections say they don't work I don't know).

This is injected via Spring, but I suppose that it shouldn't be an issue?

[Shredder121]

I'll try to reproduce the error in the junit test again, so unless otherwise noted, I mean the junit test from now on.

[brettwooldridge]

@Shredder121 With respect to your production pools and the MySQL connection closes, those appear to be occurring due to the server-side closing the connection. You might try tighening the timeouts a bit:

 <property name="idleTimeout" value="300000" />
 <property name="maxLifetime" value="600000" />

I believe the two issues (junit test and MySQL eviction) are likely separate.

[Shredder121]

This is considering the application again.

Tried the config, issue still persists.

Note that only 'some' Windows users have this issue, Linux and Mac colleagues are fine, production is fine as well.
We had explicitly used a pretty high timeout, since there are a lot of applications on the servers, so we chose high timeout, low number of connections.

For reference, some output:

2015-09-17 16:24:07,876 [http-apr-8082-exec-6] [] INFO  com.zaxxer.hikari.HikariDataSource - hikariCP - is starting. []
2015-09-17 16:24:08,452 [http-apr-8082-exec-6] [] INFO  com.zaxxer.hikari.HikariDataSource - infoHikariCP - is starting. []
2015-09-17 16:25:49,290 [http-apr-8082-exec-6] [] ERROR o.h.tool.hbm2ddl.SchemaUpdate - HHH000319: Could not get database metadata []
java.sql.SQLTransientConnectionException: infoHikariCP - Connection is not available, request timed out after 30001ms.
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197) ~[HikariCP-2.4.2-SNAPSHOT.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:146) ~[HikariCP-2.4.2-SNAPSHOT.jar:na]
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:83) ~[HikariCP-2.4.2-SNAPSHOT.jar:na]
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.tool.hbm2ddl.SuppliedConnectionProviderConnectionHelper.prepare(SuppliedConnectionProviderConnectionHelper.java:51) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.tool.hbm2ddl.SchemaUpdate.execute(SchemaUpdate.java:219) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.tool.hbm2ddl.SchemaUpdate.execute(SchemaUpdate.java:203) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:522) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1859) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl$4.perform(EntityManagerFactoryBuilderImpl.java:852) [hibernate-entitymanager-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl$4.perform(EntityManagerFactoryBuilderImpl.java:845) [hibernate-entitymanager-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.boot.registry.classloading.internal.ClassLoaderServiceImpl.withTccl(ClassLoaderServiceImpl.java:398) [hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl.build(EntityManagerFactoryBuilderImpl.java:844) [hibernate-entitymanager-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.jpa.HibernatePersistenceProvider.createContainerEntityManagerFactory(HibernatePersistenceProvider.java:152) [hibernate-entitymanager-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.ejb.HibernatePersistence.createContainerEntityManagerFactory(HibernatePersistence.java:67) [hibernate-entitymanager-4.3.8.Final.jar:4.3.8.Final]
    at org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.createNativeEntityManagerFactory(LocalContainerEntityManagerFactoryBean.java:288) [spring-orm-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.afterPropertiesSet(AbstractEntityManagerFactoryBean.java:310) [spring-orm-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1541) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1479) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:521) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:458) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:295) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:223) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:292) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1117) [spring-context-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:922) [spring-context-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:479) [spring-context-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:389) [spring-web-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:294) [spring-web-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:112) [spring-web-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:5017) [catalina.jar:7.0.63]
    at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5531) [catalina.jar:7.0.63]
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150) [catalina.jar:7.0.63]
    at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901) [catalina.jar:7.0.63]
    at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877) [catalina.jar:7.0.63]
    at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652) [catalina.jar:7.0.63]
    at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:677) [catalina.jar:7.0.63]
    at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:552) [catalina.jar:7.0.63]
    at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1717) [catalina.jar:7.0.63]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
    at org.apache.tomcat.util.modeler.BaseModelMBean.invoke(BaseModelMBean.java:301) [tomcat-coyote.jar:7.0.63]
    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819) [na:1.8.0_45]
    at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801) [na:1.8.0_45]
    at org.apache.catalina.manager.ManagerServlet.check(ManagerServlet.java:1516) [catalina.jar:7.0.63]
    at org.apache.catalina.manager.ManagerServlet.deploy(ManagerServlet.java:912) [catalina.jar:7.0.63]
    at org.apache.catalina.manager.ManagerServlet.doGet(ManagerServlet.java:371) [catalina.jar:7.0.63]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:624) [servlet-api.jar:na]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:731) [servlet-api.jar:na]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [catalina.jar:7.0.63]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.63]
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat7-websocket.jar:7.0.63]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.63]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.63]
    at org.apache.catalina.filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:108) [catalina.jar:7.0.63]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.63]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.63]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) [catalina.jar:7.0.63]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) [catalina.jar:7.0.63]
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:614) [catalina.jar:7.0.63]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) [catalina.jar:7.0.63]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina.jar:7.0.63]
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:957) [catalina.jar:7.0.63]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [catalina.jar:7.0.63]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423) [catalina.jar:7.0.63]
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079) [tomcat-coyote.jar:7.0.63]
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:620) [tomcat-coyote.jar:7.0.63]
    at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:2516) [tomcat-coyote.jar:7.0.63]
    at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:2505) [tomcat-coyote.jar:7.0.63]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_45]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_45]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-coyote.jar:7.0.63]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
2015-09-17 16:25:49,463 [http-apr-8082-exec-6] [] ERROR o.h.tool.hbm2ddl.SchemaUpdate - HHH000299: Could not complete schema update []
java.sql.SQLTransientConnectionException: infoHikariCP - Connection is not available, request timed out after 30001ms.
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197) ~[HikariCP-2.4.2-SNAPSHOT.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:146) ~[HikariCP-2.4.2-SNAPSHOT.jar:na]
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:83) ~[HikariCP-2.4.2-SNAPSHOT.jar:na]
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.tool.hbm2ddl.SuppliedConnectionProviderConnectionHelper.prepare(SuppliedConnectionProviderConnectionHelper.java:51) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.tool.hbm2ddl.SchemaUpdate.execute(SchemaUpdate.java:219) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.tool.hbm2ddl.SchemaUpdate.execute(SchemaUpdate.java:203) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:522) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1859) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl$4.perform(EntityManagerFactoryBuilderImpl.java:852) [hibernate-entitymanager-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl$4.perform(EntityManagerFactoryBuilderImpl.java:845) [hibernate-entitymanager-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.boot.registry.classloading.internal.ClassLoaderServiceImpl.withTccl(ClassLoaderServiceImpl.java:398) [hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl.build(EntityManagerFactoryBuilderImpl.java:844) [hibernate-entitymanager-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.jpa.HibernatePersistenceProvider.createContainerEntityManagerFactory(HibernatePersistenceProvider.java:152) [hibernate-entitymanager-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.ejb.HibernatePersistence.createContainerEntityManagerFactory(HibernatePersistence.java:67) [hibernate-entitymanager-4.3.8.Final.jar:4.3.8.Final]
    at org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.createNativeEntityManagerFactory(LocalContainerEntityManagerFactoryBean.java:288) [spring-orm-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.afterPropertiesSet(AbstractEntityManagerFactoryBean.java:310) [spring-orm-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1541) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1479) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:521) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:458) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:295) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:223) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:292) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194) [spring-beans-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1117) [spring-context-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:922) [spring-context-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:479) [spring-context-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:389) [spring-web-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:294) [spring-web-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:112) [spring-web-3.2.4.RELEASE.jar:3.2.4.RELEASE]
    at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:5017) [catalina.jar:7.0.63]
    at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5531) [catalina.jar:7.0.63]
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150) [catalina.jar:7.0.63]
    at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901) [catalina.jar:7.0.63]
    at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877) [catalina.jar:7.0.63]
    at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652) [catalina.jar:7.0.63]
    at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:677) [catalina.jar:7.0.63]
    at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:552) [catalina.jar:7.0.63]
    at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1717) [catalina.jar:7.0.63]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
    at org.apache.tomcat.util.modeler.BaseModelMBean.invoke(BaseModelMBean.java:301) [tomcat-coyote.jar:7.0.63]
    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819) [na:1.8.0_45]
    at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801) [na:1.8.0_45]
    at org.apache.catalina.manager.ManagerServlet.check(ManagerServlet.java:1516) [catalina.jar:7.0.63]
    at org.apache.catalina.manager.ManagerServlet.deploy(ManagerServlet.java:912) [catalina.jar:7.0.63]
    at org.apache.catalina.manager.ManagerServlet.doGet(ManagerServlet.java:371) [catalina.jar:7.0.63]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:624) [servlet-api.jar:na]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:731) [servlet-api.jar:na]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [catalina.jar:7.0.63]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.63]
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat7-websocket.jar:7.0.63]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.63]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.63]
    at org.apache.catalina.filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:108) [catalina.jar:7.0.63]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.63]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.63]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) [catalina.jar:7.0.63]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) [catalina.jar:7.0.63]
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:614) [catalina.jar:7.0.63]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) [catalina.jar:7.0.63]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina.jar:7.0.63]
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:957) [catalina.jar:7.0.63]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [catalina.jar:7.0.63]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423) [catalina.jar:7.0.63]
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079) [tomcat-coyote.jar:7.0.63]
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:620) [tomcat-coyote.jar:7.0.63]
    at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:2516) [tomcat-coyote.jar:7.0.63]
    at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:2505) [tomcat-coyote.jar:7.0.63]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_45]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_45]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-coyote.jar:7.0.63]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]

[brettwooldridge]

@Shredder121 for the production side, can you enable debug logging? Maybe direct it to a different file if it is too chatty.

[Shredder121]

Yeah, I have been having trouble reproducing it in the tests since Thursday after lunch, initially I thought that it could be easier to reproduce in the morning (short uptime or something) but no.

I can enable debug logging, although it will be too chatty and noisy since there are two pools.

I'll see what I can do.
For now have a good weekend, I'll get some results then.

[Shredder121]

Okay Brett,
First of all, you were right with the two distinct issues, I turned on debug logging, and saw something fishy. I saw a couple of these before the startup timed out:

2015-09-20 17:30:39,613 [Hikari housekeeper (pool infoHikariCP)] [] DEBUG com.zaxxer.hikari.pool.HikariPool - Before cleanup    pool infoHikariCP stats (total=1, active=1, idle=0, waiting=1) []
2015-09-20 17:30:39,613 [Hikari housekeeper (pool infoHikariCP)] [] DEBUG com.zaxxer.hikari.pool.HikariPool - After cleanup pool infoHikariCP stats (total=1, active=1, idle=0, waiting=1) []

So I turned on leak detection, and saw this:

2015-09-20 17:30:20,454 [Hikari housekeeper (pool infoHikariCP)] [] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for connection com.mysql.jdbc.JDBC4Connection@1e797f0b, 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.8.Final.jar:4.3.8.Final]
    at org.jadira.usertype.spi.shared.AbstractUserTypeHibernateIntegrator.use42Api(AbstractUserTypeHibernateIntegrator.java:80) ~[usertype.spi-3.2.0.GA.jar:na]
    at org.jadira.usertype.spi.shared.AbstractUserTypeHibernateIntegrator.integrate(AbstractUserTypeHibernateIntegrator.java:61) ~[usertype.spi-3.2.0.GA.jar:na]
    at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:312) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
    at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1859) ~[hibernate-core-4.3.8.Final.jar:4.3.8.Final]
etc..

Turns out the code just gets the connection, but doesn't close it (return it to the pool).

So that's one issue solved, you can close this.

I will however see if I can reproduce the infinite loop again.

Shall I make another issue for that (initially closed and reopen it when I find anything)?

Thanks for your support anyway!

[Shredder121]

Nice!
Saw that you reported this already, which shows me that we are on a very old version.
Have a good day!

[AstroFlash]

Hi.

Just to mention that another possible situation that can lead to threads stuck on

- parking to wait for  <0x00000000d1727b08> (a com.zaxxer.hikari.util.QueuedSequenceSynchronizer$Synchronizer)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)

is a out of memory issue. (on normal situation, you should see plain old "java.lang.OutOfMemoryError" before look a what the threads are doing but due to a complicate situation, I looker for the errors after the thread dump and looking at this discussion) .

[bhooshanmore]

I have implemented Hikari connection with java configuration the code is below
HikariConfig sqlConfig = new HikariConfig();
sqlConfig.setDataSourceClassName(WebAppListener.getContextParameter(DB_DRIVER_STRING));
sqlConfig.addDataSourceProperty("url", WebAppListener.getContextParameter(DB_CONNECTION_STRING));
sqlConfig.addDataSourceProperty("user", WebAppListener.getContextParameter(DB_USER_NAME));
sqlConfig.addDataSourceProperty("password", WebAppListener.getContextParameter(DB_PASSWORD));
sqlConfig.setLeakDetectionThreshold(TimeUnit.SECONDS.toMillis(30));
sqlConfig.setValidationTimeout(TimeUnit.MINUTES.toMillis(1));
sqlConfig.setMaximumPoolSize(POOL_SIZE);
sqlConfig.setMinimumIdle(0);
sqlConfig.setMaxLifetime(TimeUnit.MINUTES.toMillis(2)); // 120 seconds

            sqlConfig.setIdleTimeout(TimeUnit.MINUTES.toMillis(1)); // minutes
            sqlConfig.setConnectionTimeout(TimeUnit.MINUTES.toMillis(5));
            sqlConfig.setPoolName(POOL_NAME);
            sqlConfig.setAutoCommit(true);
            sqlConfig.setInitializationFailFast(false);

            dataSource = new HikariDataSource(sqlConfig);

            sqlConfig.setConnectionTestQuery("/* ping */ SELECT 1");
            if (null != connection) {
                log.info("webAppListener.java :Hikari ::NEW Connection successful! : " + connection.hashCode());
            }
            else {
                connection = dataSource.getConnection();
            }

but when i deployed my application it give this kind of log :

15-Sep-2016 13:34:28.553 WARNING [http-nio-8084-exec-1658] org.apache.catalina.loader.WebappClassLoader.clearReferencesThreads The web application [/HIKARI_PROJ] appears to have started a thread named [HikariConnPool housekeeper] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
java.lang.Thread.run(Thread.java:745)

My application is run without any interruption on development server,please help me in this i was search on internet but i don't get any solution for this.

[patric-r]

Do you close/shutdown the pool on servlet context shutdown?

[bhooshanmore]

Yes i closed connection with shutdown method while servlet destroyed.Is there any mistake or anything is missing ..??

[patric-r]

You need to close allHikariDataSource instances using HikariDataSource.close().

[bhooshanmore]

yes i have call this in following manner :

public void contextDestroyed(ServletContextEvent evt) {
    if (connection != null) {
        try {
            freeConnection();
        }
        catch (SQLException ex) {
            log.info("webAppListener.java :SQLException While contextDestroyed() !: ");
        }
    }
}

public static void freeConnection() throws SQLException {
try {
// log.info(timer);
log.info("-------------- Statr: Hikari Connection Details :Before Close-------------------");
log.info(" | Leaked Detection : | " + dataSource.getLeakDetectionThreshold());
log.info(" | Get Max life time: | " + dataSource.getMaxLifetime());
log.info(" | Get max Pool size: | " + dataSource.getMaximumPoolSize());
log.info("-------------- End: Hikari Connection Details :Before Close---------------------");

        log.info("DIFCRRMV1 Hikari ::Connection release successful!");
    }
    catch (Throwable t) {
        log.error("webAppListener.java : Exception while freeConnection() : ", t);
    }
    finally {
        connection.close();
        dataSource.close();
    }

}

Also got this kind of exception 👎

WARN com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for ConnectionID:1, stack trace follows
java.lang.Exception: Apparent connection leak detected
at com.deloitte.ifc.WebAppListener.getConnection(WebAppListener.java:186)
at com.deloitte.ifc.WebAppListener.contextInitialized(WebAppListener.java:106)
at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4760)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5184)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
at org.apache.catalina.core.StandardContext.reload(StandardContext.java:3780)
at org.apache.catalina.manager.ManagerServlet.reload(ManagerServlet.java:984)
at org.apache.catalina.manager.ManagerServlet.doGet(ManagerServlet.java:345)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:618)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:725)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:393)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:108)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:615)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:136)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:610)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:526)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1078)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:655)
at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:222)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1566)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1523)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)

and warning :
WARN com.zaxxer.hikari.pool.HikariPool - IFCConnPool - Thread starvation or clock leap detected (housekeeper delta=42m1s214ms769µs47ns).

After redeploying project i got this Hikari CP summary which i printed in logs 👍

2016-09-15 16:53:09 INFO com.deloitte.ifc.WebAppListener - -------------- Statr: Hikari Connection Details :Before Close-------------------
2016-09-15 16:53:09 INFO com.deloitte.ifc.WebAppListener - | Leaked Detection : | 30000
2016-09-15 16:53:09 INFO com.deloitte.ifc.WebAppListener - | Get Max life time: | 120000
2016-09-15 16:53:09 INFO com.deloitte.ifc.WebAppListener - | Get max Pool size: | 10
2016-09-15 16:53:09 INFO com.deloitte.ifc.WebAppListener - -------------- End: Hikari Connection Details :Before Close---------------------

[brettwooldridge]

@bhooshanmore Wow, so much going on here.

First this one, _"Thread starvation or clock leap detected (housekeeper delta=42m1s214ms769µs47ns)"_ ... that is caused by running this on computer that went to sleep (like a laptop), or on a virtual machine that was suspended while the pool was running.

Second this one:

WARN com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for ConnectionID:1, stack trace follows
java.lang.Exception: Apparent connection leak detected
at com.deloitte.ifc.WebAppListener.getConnection(WebAppListener.java:186)
at com.deloitte.ifc.WebAppListener.contextInitialized(WebAppListener.java:106)

Why are you creating a Connection in contextInitialized()? That is going to hang around for the life of the WAR (until the WAR is undeployed or the server is shutdown). _And that is what is causing the leaked connection warning._ That certainly explains your freeConnection() call in contextDestroyed() which had me totally confused.

Why are you creating the HikariDataSource in WebAppListener? You can certainly do that, but you are in a Tomcat container, so why not define it in your web application's _context.xml_? Or if you want a pool shared across web applications, define it in the _server.xml_.

See here:
https://codedump.io/share/x8fRlvg0FxSq/1/why-hikaricp-creates-new-connection-for-every-web-app-in-tomcat-on-startup

And here:
https://github.com/brettwooldridge/HikariCP/wiki/JNDI-DataSource-Factory-(Tomcat,-etc.)

[bhooshanmore]

Dear @brettwooldridge many thanks for respond 👍 👍 and correct me 💯 .I used same method as you suggest me and its really working perfectly without memory leakage.I have created Hikari connection at the time of server start up using WebAppListener and make that connection as singleTone so single connection will used in whole application ,make me correct if my approach is wrong .
Also i need one more help that how to config HikariCP with log4j so i can track everything (also SQL is possible) ,i used Normal SQL without any JPA 🎱

[jameskandau]

@brettwooldridge am getting this and then the application freezes . What is the problem?
2019-06-04 14:26:08,864 [DEBUG] [] [HikariPool-1 housekeeper] [c.zaxxer.hikari.pool.HikariPool] - HikariPool-1 - Pool stats (total=20, active=0, idle=20, waiting=0)