What does this mean Thread Starvation or clock leap detected

[ohnooo]

Hi,

I am trying out HikariCP pooling. I am using Tomcat localhost and my config is direct copy from the docs

pom.xml

<dependency>
        <groupId>mysql</groupId>
        <artifactId>mysql-connector-java</artifactId>
        <version>5.1.39</version>
    </dependency>
    <dependency>
        <groupId>com.zaxxer</groupId>
        <artifactId>HikariCP</artifactId>
        <version>2.4.7</version>
    </dependency>
    <dependency>
        <groupId>org.hibernate</groupId>
        <artifactId>hibernate-core</artifactId>
        <version>4.3.11.Final</version>
    </dependency>

applicationContext.xml

<bean id="hikariConfig" class="com.zaxxer.hikari.HikariConfig">
   <property name="poolName" value="springHikariCP" />
            <property name="connectionTestQuery" value="SELECT 1" />
            <property name="dataSourceClassName"
                value="com.mysql.jdbc.jdbc2.optional.MysqlDataSource" />
            <property name="dataSourceProperties">
                <props>
                    <prop key="url">jdbc:mysql://localhost:3306/unicare_test</prop>
                    <prop key="user">xxxxx</prop>
                    <prop key="password">xxxxx</prop>
                </props>
            </property>
        </bean>
        <bean id="dataSource" class="com.zaxxer.hikari.HikariDataSource"
            destroy-method="close">
            <constructor-arg ref="hikariConfig" />
        </bean>
<bean id="sessionFactory"
            class="org.springframework.orm.hibernate4.LocalSessionFactoryBean">
            <property name="dataSource" ref="dataSource"></property>
            <property name="hibernateProperties">
                <props>
                    <prop key="hibernate.dialect">org.hibernate.dialect.MySQLDialect</prop>
                    <prop key="hibernate.connection.useUnicode">true</prop>
                    <prop key="hibernate.connection.characterEncoding">UTF-8</prop>
                    <prop key="hibernate.connection.charSet">UTF-8</prop>
                    <prop key="hibernate.show_sql">true</prop>
                    <prop key="org.hibernate.jdbc">TRACE</prop>
                </props>
            </property>
            <property name="packagesToScan">
                <list>
                    <value>com.app.books</value>
                </list>
            </property>
        </bean>

WARN - 1h35m13s114ms - Thread starvation or clock leap detected (housekeeper delta=springHikariCP).

What does this mean and how to fix?

[brettwooldridge]

Nothing to worry about. Looks like you are running on a laptop, and it went to sleep. Nothing to fix configuration-wise.

[patric-r]

I also noticed this several times on server systems which definitely didn't went to sleep:

2m36s172ms20?s75ns - Thread starvation or clock leap detected (housekeeper delta=HikariPool - default).

[brettwooldridge]

2m36s starvation is significant. If the system did not enter sleep, and you are sure of that, there are only two possibilities that I can see.

One, this is a virtual machine that is configured to synchronize its clock from the host. In which case, the solution is to run ntpd (Linux) or w32time (windows) in the VM.

Two, there was actually a 2+ minute starvation event. In which case, you need to monitor the CPU and figure out what is creating the load.

[patric-r]

Today I saw this on a developer windows machine (no VM).
Not sure if this is related at all, but it happened during the execution of a very long running Statement.

After 50 minutes of executing that statement, the above mentioned warning appeared.
The application itself did not cause significant cpu load, it had been waiting for the Statement to return.
Although I cannot rule it out completely, it's very unlikely that the machine was "CPU-stalled" for more than 2 minutes.

[adornala]

I also have the same problem. After running process for a while I am getting this
2017-06-06 17:39:34.170 WARN 2152 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=54s566ms151µs86ns).

[brettwooldridge]

Virtual machine? Laptop?

[adornala]

It's in the laptop. Reason I put in here is as patric-r said. I am trying to index my relational database with elasticsearch, since it takes sometime around 50min mark I start getting this warning. Application services stops responding! You think it's problem due to my configuration Brett! Till 40 -4 5 min Application runs perfectly fine.

[brettwooldridge]

The CPU is going into deep sleep mode. Turn off power saving/sleep during the operation.

[2606441095]

I also have the same problem. After running process for a while I am getting this payprod-core-hikari-pool - Thread starvation or clock leap detected (housekeeper delta=3h36m56s61ms486µs9ns). So I can't get a Connection, it throws * org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: payprod-core-hikari-pool - Connection is not available, request timed out after 935119ms*. How should I solve it?

[adornala]

Hi.. You must be doing a stateful transaction. This is how I debugged it.

1. Use JRecorder to see if your heap is getting too high for this application.
2. If so there is a tool called Eclipse Memory analyzing tool use it to analyze your problem.
3. Look for the cause and resolve the issue.

Hope this helps. This is how I fixed it.

[brettwooldridge]

3h36m56s61ms?! Your computer must be going into sleep mode. There is no way a thread in a normally running system could be starved for so long. Either that or something is messing with the system clock (unlikely).

[mdbudnick]

I found this issue running Tomcat servers on a virtual Kubernetes cluster. I was getting status 80 connection refused from all the endpoints, and intermittently the services would briefly work. This thread's message was the only thing out of the ordinary I could find in the logs.

My theory is that the machine did not have enough resources for the threads because when I did not start all of the services in the cluster I had no issue. Therefore, it may be a lack of resource issue.

[mmamane]

I concur with @Coroecram. We just encountered these messages with java.lang.OutOfMemoryError.

[milosonator]

@Coroecram what is the magnitude of your reported delta, and did you find any cause or solution? We're seeing the same issue in a similar setup (45s delta).

[gpqhl0071]

I also encountered the same warning, but it has no effect on my scheduled task. The only problem is that I found that my scheduled task was retriggered during this time period.

2020-04-23 12:58:55.903 WARN 3228 --- [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=8m44s242ms).

[ssavva05]

In my case I got this error Initially and then heap overflow. I increase the Heap and Stack size and it got away. But in my case, I run a class that overflow the stock heap size.

[mdbudnick]

@milosonator Sorry, this has been so long ago I really don't know the exact conditions.

[fengyueqiao]

2020-06-23 19:12:00,690 DEBUG (PoolBase.java:147)[HikariPool-1 housekeeper]- HikariPool-1 - Closing connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@3a3f4750 failed java.sql.SQLNonTransientConnectionException: [Cloudera][JDBC](10060) Connection has been closed. at com.cloudera.impala.exceptions.ExceptionConverter.toSQLException(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.closeConnection(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.abortInternal(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.close(Unknown Source) at com.zaxxer.hikari.pool.PoolBase.quietlyCloseConnection(PoolBase.java:143) at com.zaxxer.hikari.pool.HikariPool.lambda$closeConnection$1(HikariPool.java:451) at java.util.concurrent.ThreadPoolExecutor$CallerRunsPolicy.rejectedExecution(ThreadPoolExecutor.java:2038) at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830) at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379) at com.zaxxer.hikari.pool.HikariPool.closeConnection(HikariPool.java:450) at com.zaxxer.hikari.pool.HikariPool.softEvictConnection(HikariPool.java:615) at com.zaxxer.hikari.pool.HikariPool.lambda$createPoolEntry$2(HikariPool.java:486) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2020-06-23 19:12:00,691 DEBUG (HikariPool.java:517)[HikariPool-1 housekeeper]- HikariPool-1 - Fill pool skipped, pool is at sufficient level. 2020-06-23 19:12:00,691 WARN (HikariPool.java:787)[HikariPool-1 housekeeper]- HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=17m1s952ms571µs377ns). 2020-06-23 19:12:00,692 DEBUG (HikariPool.java:421)[HikariPool-1 housekeeper]- HikariPool-1 - Pool stats (total=4, active=0, idle=4, waiting=0) 2020-06-23 19:12:00,692 DEBUG (HikariPool.java:517)[HikariPool-1 housekeeper]- HikariPool-1 - Fill pool skipped, pool is at sufficient level. 2020-06-23 19:12:00,692 DEBUG (PoolBase.java:134)[HikariPool-1 housekeeper]- HikariPool-1 - Closing connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@4309df21: (connection has passed maxLifetime) 2020-06-23 19:12:01,025 DEBUG (HikariPool.java:728)[HikariPool-1 connection adder]- HikariPool-1 - Added connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@34b395a2 2020-06-23 19:12:01,459 DEBUG (HikariPool.java:728)[HikariPool-1 connection adder]- HikariPool-1 - Added connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@758e9f99 2020-06-23 19:16:11,058 DEBUG (PoolBase.java:147)[HikariPool-1 connection closer]- HikariPool-1 - Closing connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@3f685b9f failed java.sql.SQLNonTransientConnectionException: [Cloudera][JDBC](10060) Connection has been closed. at com.cloudera.impala.exceptions.ExceptionConverter.toSQLException(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.closeConnection(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.abortInternal(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.close(Unknown Source) at com.zaxxer.hikari.pool.PoolBase.quietlyCloseConnection(PoolBase.java:143) at com.zaxxer.hikari.pool.HikariPool.lambda$closeConnection$1(HikariPool.java:451) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2020-06-23 19:16:11,058 DEBUG (HikariPool.java:517)[HikariPool-1 connection closer]- HikariPool-1 - Fill pool skipped, pool is at sufficient level. 2020-06-23 19:16:11,058 DEBUG (PoolBase.java:134)[HikariPool-1 connection closer]- HikariPool-1 - Closing connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@57502b63: (connection has passed maxLifetime) 2020-06-23 19:28:00,690 DEBUG (PoolBase.java:147)[HikariPool-1 housekeeper]- HikariPool-1 - Closing connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@4309df21 failed java.sql.SQLNonTransientConnectionException: [Cloudera][JDBC](10060) Connection has been closed. at com.cloudera.impala.exceptions.ExceptionConverter.toSQLException(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.closeConnection(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.abortInternal(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.close(Unknown Source) at com.zaxxer.hikari.pool.PoolBase.quietlyCloseConnection(PoolBase.java:143) at com.zaxxer.hikari.pool.HikariPool.lambda$closeConnection$1(HikariPool.java:451) at java.util.concurrent.ThreadPoolExecutor$CallerRunsPolicy.rejectedExecution(ThreadPoolExecutor.java:2038) at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830) at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379) at com.zaxxer.hikari.pool.HikariPool.closeConnection(HikariPool.java:450) at com.zaxxer.hikari.pool.HikariPool.softEvictConnection(HikariPool.java:615) at com.zaxxer.hikari.pool.HikariPool.lambda$createPoolEntry$2(HikariPool.java:486) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2020-06-23 19:28:00,691 DEBUG (HikariPool.java:517)[HikariPool-1 housekeeper]- HikariPool-1 - Fill pool skipped, pool is at sufficient level. 2020-06-23 19:28:00,693 WARN (HikariPool.java:787)[HikariPool-1 housekeeper]- HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=16m1ms667µs120ns). 2020-06-23 19:28:00,693 DEBUG (HikariPool.java:421)[HikariPool-1 housekeeper]- HikariPool-1 - Pool stats (total=5, active=0, idle=5, waiting=0) 2020-06-23 19:28:00,694 DEBUG (HikariPool.java:517)[HikariPool-1 housekeeper]- HikariPool-1 - Fill pool skipped, pool is at sufficient level. 2020-06-23 19:28:00,694 DEBUG (PoolBase.java:134)[HikariPool-1 housekeeper]- HikariPool-1 - Closing connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@2625637d: (connection has passed maxLifetime) 2020-06-23 19:28:01,108 DEBUG (HikariPool.java:728)[HikariPool-1 connection adder]- HikariPool-1 - Added connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@1db905ff 2020-06-23 19:31:58,770 DEBUG (PoolBase.java:147)[HikariPool-1 connection closer]- HikariPool-1 - Closing connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@57502b63 failed java.sql.SQLNonTransientConnectionException: [Cloudera][JDBC](10060) Connection has been closed. at com.cloudera.impala.exceptions.ExceptionConverter.toSQLException(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.closeConnection(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.abortInternal(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.close(Unknown Source) at com.zaxxer.hikari.pool.PoolBase.quietlyCloseConnection(PoolBase.java:143) at com.zaxxer.hikari.pool.HikariPool.lambda$closeConnection$1(HikariPool.java:451) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2020-06-23 19:31:58,772 DEBUG (PoolBase.java:134)[HikariPool-1 connection closer]- HikariPool-1 - Closing connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@166d2158: (connection has passed maxLifetime) 2020-06-23 19:31:59,210 DEBUG (HikariPool.java:728)[HikariPool-1 connection adder]- HikariPool-1 - Added connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@1387dfb7 2020-06-23 19:31:59,210 DEBUG (HikariPool.java:421)[HikariPool-1 connection adder]- HikariPool-1 - After adding stats (total=5, active=0, idle=5, waiting=0) 2020-06-23 19:43:48,402 DEBUG (PoolBase.java:147)[HikariPool-1 housekeeper]- HikariPool-1 - Closing connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@2625637d failed java.sql.SQLNonTransientConnectionException: [Cloudera][JDBC](10060) Connection has been closed. at com.cloudera.impala.exceptions.ExceptionConverter.toSQLException(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.closeConnection(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.abortInternal(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.close(Unknown Source) at com.zaxxer.hikari.pool.PoolBase.quietlyCloseConnection(PoolBase.java:143) at com.zaxxer.hikari.pool.HikariPool.lambda$closeConnection$1(HikariPool.java:451) at java.util.concurrent.ThreadPoolExecutor$CallerRunsPolicy.rejectedExecution(ThreadPoolExecutor.java:2038) at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830) at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379) at com.zaxxer.hikari.pool.HikariPool.closeConnection(HikariPool.java:450) at com.zaxxer.hikari.pool.HikariPool.softEvictConnection(HikariPool.java:615) at com.zaxxer.hikari.pool.HikariPool.lambda$createPoolEntry$2(HikariPool.java:486) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2020-06-23 19:43:48,403 DEBUG (HikariPool.java:517)[HikariPool-1 housekeeper]- HikariPool-1 - Fill pool skipped, pool is at sufficient level. 2020-06-23 19:43:48,403 WARN (HikariPool.java:787)[HikariPool-1 housekeeper]- HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=15m47s710ms139µs13ns). 2020-06-23 19:43:48,404 DEBUG (HikariPool.java:421)[HikariPool-1 housekeeper]- HikariPool-1 - Pool stats (total=4, active=0, idle=4, waiting=0) 2020-06-23 19:43:48,404 DEBUG (HikariPool.java:517)[HikariPool-1 housekeeper]- HikariPool-1 - Fill pool skipped, pool is at sufficient level. 2020-06-23 19:43:48,404 DEBUG (PoolBase.java:134)[HikariPool-1 housekeeper]- HikariPool-1 - Closing connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@34b395a2: (connection has passed maxLifetime) 2020-06-23 19:43:49,069 DEBUG (HikariPool.java:728)[HikariPool-1 connection adder]- HikariPool-1 - Added connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@273fe02c 2020-06-23 19:43:49,569 DEBUG (HikariPool.java:728)[HikariPool-1 connection adder]- HikariPool-1 - Added connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@6602ea17 2020-06-23 19:47:50,578 DEBUG (PoolBase.java:147)[HikariPool-1 connection closer]- HikariPool-1 - Closing connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@166d2158 failed java.sql.SQLNonTransientConnectionException: [Cloudera][JDBC](10060) Connection has been closed. at com.cloudera.impala.exceptions.ExceptionConverter.toSQLException(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.closeConnection(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.abortInternal(Unknown Source) at com.cloudera.impala.jdbc.common.SConnection.close(Unknown Source) at com.zaxxer.hikari.pool.PoolBase.quietlyCloseConnection(PoolBase.java:143) at com.zaxxer.hikari.pool.HikariPool.lambda$closeConnection$1(HikariPool.java:451) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2020-06-23 19:47:50,579 DEBUG (HikariPool.java:517)[HikariPool-1 connection closer]- HikariPool-1 - Fill pool skipped, pool is at sufficient level. 2020-06-23 19:47:50,579 DEBUG (PoolBase.java:134)[HikariPool-1 connection closer]- HikariPool-1 - Closing connection com.cloudera.impala.impala.jdbc41.ImpalaJDBC41Connection@7af13fae: (connection has passed maxLifetime)
closeConnect time too long can also cause "Thread starvation"

[ChaminW]

Having the same issue in an AWS ECS container. Couldn't be due to sleep. Previously the CPU resources were highly utilized(90-100%). Even after providing enough resources, it gives the same error.
It would be really great if someone can shed some light on this.

[brettwooldridge]

The number one cause of this issue is excessive garbage collection. If you are seeing starvation logs indicating delays of more than a few tens of seconds it is unlikely to be caused by excessive CPU -- though that is still a possibility.

I highly recommend that you enable GC (garbage collection) logging. GC logging will show garbage collection times as well has memory statistics such has how much memory was available before and after the GC. When the memory gets extremely low in the JVM, the JVM will spend all of its time in GC; pausing application threads as it does so.

See this page: https://www.baeldung.com/java-verbose-gc

(Note: the example JVM arguments on that page use the -XX:+UseSerialGC flag, do not use this flag, it is merely in the blog for demonstration purposes)

If you are running on Java 11 or greater on Linux then I strongly recommend looking into the new ZGC collector:

https://www.baeldung.com/jvm-zgc-garbage-collector

(enabled by the -XX:+UnlockExperimentalVMOptions -XX:+UseZGC flags)

But, I recommend doing so after fully investing your current GC configuration with the logging referenced above.