Search code examples
hikaricp

Log warning: Thread starvation or clock leap detected (housekeeper delta=springHikariConnectionPool)

I'm using HikariCP 2.4.6 and at Tomcat 8 startup, I get a warning message:

01-Aug-2016 11:18:01.599 INFO [RMI TCP Connection(4)-127.0.0.1] org.apache.catalina.core.ApplicationContext.log Initializing Spring FrameworkServlet 'Spring MVC Dispatcher Servlet'
[2016-08-01 11:18:01,654] Artifact blueberry:war exploded: Artifact is deployed successfully
[2016-08-01 11:18:01,655] Artifact blueberry:war exploded: Deploy took 33,985 milliseconds
Aug 01 2016 11:26:52.802 AM [DEV] (HikariPool.java:614)
WARN : com.zaxxer.hikari.pool.HikariPool - 9m13s102ms - Thread starvation or clock leap detected (housekeeper delta=springHikariConnectionPool).

I don't see any other errors or issues reading/writing from the DB. Is this something to be concerned about? I tried searching around, but no luck.

We're also using Hibernate 4.3.8.Final over MySQL 5 and the MySQL 5.1.39 connector with Spring 4.1.0.RELEASE. We're working to upgrade to Hibernate 5 and will see whether this goes away, but don't know whether that will matter.

Solution

  • There's a good rundown of why clock leap detections might legitimately occur. To quote the external link by Brett Woolridge:

    This runs on the housekeeper thread, which executes every 30 seconds. If you are on Mac OS X, the clockSource is System.currentTimeMillis(), any other platform the clockSource is System.nanoTime(). Both in theory are monotonically increasing, but various things can affect that such as NTP servers. Most OSes are designed to handle backward NTP time adjustments to preserve the illusion of the forward flow of time.

    This code is saying, if time moves backwards (now < previous), or if time has "jumped forward" more than two housekeeping periods (more than 60 seconds), then something strange is likely going on.

    A couple of things might be going on:

    1. You could be running in a virtual container (VMWare, AWS, etc.) that for some reason is doing a particularly poor job of maintaining the illusion of the forward flow of time.

    2. Because other things occur in the housekeeper thread -- specifically, closing idle connections -- it is possible that for some reason closing connections is blocking the housekeeper thread for more than two housekeeping periods (60 seconds).

    3. The server is so busy, with all CPUs pegged, that thread starvation is occurring, which is preventing the housekeeper thread from running for more than two housekeeping periods.

    Considering these, maybe you can provide additional context.

    EDIT: Note that this is based on HikariCP 2.4.1 code. Make sure you are running the most up-to-date version available.

    (It also looks like the parameters were updated on the warning statement in the latest code.)