WARN: HikariPool-1 - Thread starvation or clock leap detected

ZZa year ago

I'm running Traccar using Docker (traccar/traccar:5.10-ubuntu image) on Ubuntu 22.04 host (1GB RAM, 1 CPU). My traccar container is talking to mysql container on the same host and same Docker network. I believe this server specs should be enough to track 1 device like what I'm doing.

For basic monitoring, I set up UptimeRobot to monitor my Traccar's port. Since then, I noticed that my Traccar will be down at least once per day for 30 minutes to 1 hour per session. Sometimes it happened twice per day.

While I'm not a Java or Traccar expert, I'm not 100% sure what's going on. Below are the Traccar logs I captured before, during and after the "down" event reported by UptimeRobot.

Questions:

  • Am I doing anything wrong here?
  • Is there anything can be improved in Traccar codebase itself?

Logs:

# Note: I've excluded all lines related to the protocol that I'm using for privacy - happy to share the full logs to Traccar team if needed
Common labels: {"filename":"/opt/traccar/logs/tracker-server.log","job":"traccarlogs"}
Line limit: "1000 (105 returned)"
Total bytes processed: "488  kB"


2024-01-09 21:30:56.405	2024-01-09 13:29:28  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m4s441ms686µs53ns).
2024-01-09 22:01:56.205	2024-01-09 13:31:09  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=4m51s395ms893µs420ns).
2024-01-09 22:01:56.692	2024-01-09 13:36:11  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=51s82ms876µs987ns).
2024-01-09 22:01:57.253	2024-01-09 13:38:19  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=2m7s519ms714µs920ns).
2024-01-09 22:01:57.262	2024-01-09 13:39:47  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m28s161ms694µs436ns).
2024-01-09 22:01:57.387	2024-01-09 13:40:53  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m6s303ms862µs894ns).
2024-01-09 22:01:58.479	2024-01-09 13:42:10  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m16s372ms84µs462ns).
2024-01-09 22:02:13.488	2024-01-09 13:43:43  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m33s804ms388µs285ns).
2024-01-09 22:49:15.937	2024-01-09 13:45:05  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m21s540ms775µs921ns).
2024-01-09 22:49:15.937	2024-01-09 13:45:01  INFO: user: 1, report: trips, from: 2024-01-08 16:00, to: 2024-01-09 15:59, devices: [3], groups: []
2024-01-09 22:49:15.937	2024-01-09 13:46:51  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m46s621ms89µs536ns).
2024-01-09 22:49:15.937	2024-01-09 13:48:23  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m31s584ms214µs419ns).
2024-01-09 22:49:15.937	2024-01-09 13:49:34  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m10s892ms792µs571ns).
2024-01-09 22:49:15.937	2024-01-09 13:51:02  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m27s304ms529µs116ns).
2024-01-09 22:49:15.937	2024-01-09 13:52:19  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m18s121ms902µs984ns).
2024-01-09 22:49:15.937	2024-01-09 13:54:42  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=2m23s120ms716µs48ns).
2024-01-09 22:49:15.938	2024-01-09 13:56:05  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m22s419ms286µs898ns).
2024-01-09 22:49:15.938	2024-01-09 13:56:57  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=47s47ms749µs441ns).
2024-01-09 22:49:15.938	2024-01-09 13:57:46  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=54s743ms553µs325ns).
2024-01-09 22:49:15.938	2024-01-09 14:00:25  WARN: Authentication error - HikariPool-1 - Connection is not available, request timed out after 30342ms (total=2, active=1, idle=1, waiting=1) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < Storage:49 < ...)
2024-01-09 22:49:15.938	2024-01-09 14:00:28  WARN: Scheduled reports error - HikariPool-1 - Connection is not available, request timed out after 131016ms (total=1, active=1, idle=0, waiting=5) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < TaskReports:76 < ...)
2024-01-09 22:49:15.938	2024-01-09 14:00:26  WARN: Update device status error - HikariPool-1 - Connection is not available, request timed out after 30214ms (total=1, active=1, idle=0, waiting=1) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:110 < ConnectionManager:268 < ...)
2024-01-09 22:49:15.938	2024-01-09 14:01:29  WARN: / - HikariPool-1 - Connection is not available, request timed out after 78004ms (total=2, active=2, idle=0, waiting=1) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < Storage:49 < ...)
2024-01-09 22:49:15.939	2024-01-09 14:01:29  WARN: / - HikariPool-1 - Connection is not available, request timed out after 43266ms (total=2, active=2, idle=0, waiting=0) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < Storage:49 < ...)
2024-01-09 22:49:15.939	2024-01-09 14:01:29  WARN: / - HikariPool-1 - Connection is not available, request timed out after 33118ms (total=1, active=1, idle=0, waiting=2) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < Storage:49 < ...)
2024-01-09 22:49:15.939	2024-01-09 14:01:29  WARN: / - HikariPool-1 - Connection is not available, request timed out after 30728ms (total=1, active=1, idle=0, waiting=0) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < Storage:49 < ...)
2024-01-09 22:49:15.939	2024-01-09 14:01:30  WARN: / - HikariPool-1 - Connection is not available, request timed out after 30933ms (total=2, active=2, idle=0, waiting=0) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < Storage:49 < ...)
2024-01-09 22:49:15.940	2024-01-09 14:01:30  WARN: / - HikariPool-1 - Connection is not available, request timed out after 36781ms (total=1, active=1, idle=0, waiting=3) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < Storage:49 < ...)
2024-01-09 22:49:15.940	2024-01-09 14:01:38  WARN: / - HikariPool-1 - Connection is not available, request timed out after 43072ms (total=1, active=1, idle=0, waiting=3) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < Storage:49 < ...)
2024-01-09 22:49:15.940	2024-01-09 14:01:44  INFO: [T8cec2848] error - HikariPool-1 - Connection is not available, request timed out after 30516ms (total=2, active=2, idle=0, waiting=1) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < CommandsManager:108 < ...)
2024-01-09 22:49:15.940	2024-01-09 14:04:16  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=53s427ms916µs414ns).
2024-01-09 22:49:15.940	2024-01-09 14:07:38  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=3m6s661ms231µs785ns).
2024-01-09 22:49:15.940	2024-01-09 14:08:56  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m33s148ms491µs432ns).
2024-01-09 22:49:15.940	2024-01-09 14:11:10  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=2m14s915ms12µs403ns).
2024-01-09 22:49:15.941	2024-01-09 14:12:01  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=50s18ms237µs655ns).
2024-01-09 22:49:15.941	2024-01-09 14:13:22  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m21s564ms648µs641ns).
2024-01-09 22:49:15.941	2024-01-09 14:14:14  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=51s715ms120µs688ns).
2024-01-09 22:49:15.941	2024-01-09 14:14:33  WARN: Scheduled reports error - HikariPool-1 - Connection is not available, request timed out after 30913ms (total=2, active=2, idle=0, waiting=0) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < TaskReports:76 < ...)
2024-01-09 22:49:15.941	2024-01-09 14:15:01  WARN: Unable to release Session Session@34477eb{id=node0z2fghdp25htl5dzn4rtevhco0,x=node0z2fghdp25htl5dzn4rtevhco0.node0,req=0,res=true} - InterruptedException (...)
2024-01-09 22:49:15.941	2024-01-09 14:15:50  WARN: Scheduled reports error - HikariPool-1 - Connection is not available, request timed out after 33672ms (total=2, active=2, idle=0, waiting=0) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < TaskReports:76 < ...)
2024-01-09 22:49:15.941	2024-01-09 14:16:20  WARN: / - HikariPool-1 - Connection is not available, request timed out after 30630ms (total=2, active=2, idle=0, waiting=1) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < Storage:49 < ...)
2024-01-09 22:49:15.941	2024-01-09 14:16:45  INFO: [T320b8689] connected
2024-01-09 22:49:15.941	2024-01-09 14:17:34  WARN: Scheduled reports error - HikariPool-1 - Connection is not available, request timed out after 36188ms (total=2, active=2, idle=0, waiting=0) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < TaskReports:76 < ...)
2024-01-09 22:49:15.942	2024-01-09 14:18:17  INFO: [T8cec2848] error - HikariPool-1 - Connection is not available, request timed out after 35495ms (total=2, active=2, idle=0, waiting=0) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < Storage:49 < ...)
2024-01-09 22:49:15.942	2024-01-09 14:19:06  WARN: Scheduled reports error - HikariPool-1 - Connection is not available, request timed out after 30823ms (total=2, active=2, idle=0, waiting=0) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < TaskReports:76 < ...)
2024-01-09 22:49:15.943	2024-01-09 14:20:27  WARN: Scheduled reports error - HikariPool-1 - Connection is not available, request timed out after 30597ms (total=2, active=2, idle=0, waiting=0) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < TaskReports:76 < ...)
2024-01-09 22:49:15.943	2024-01-09 14:21:49  WARN: Scheduled reports error - HikariPool-1 - Connection is not available, request timed out after 30745ms (total=2, active=2, idle=0, waiting=0) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < TaskReports:76 < ...)
2024-01-09 22:49:15.943	2024-01-09 14:23:07  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=45s774ms876µs804ns).
2024-01-09 22:49:15.943	2024-01-09 14:23:24  WARN: Scheduled reports error - HikariPool-1 - Connection is not available, request timed out after 30651ms (total=2, active=2, idle=0, waiting=2) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < TaskReports:76 < ...)
2024-01-09 22:49:15.943	2024-01-09 14:24:00  WARN: Find device error - HikariPool-1 - Connection is not available, request timed out after 31107ms (total=2, active=2, idle=0, waiting=0) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < Storage:49 < ...)
2024-01-09 22:49:15.943	2024-01-09 14:25:09  WARN: Scheduled reports error - mysql: Temporary failure in name resolution - UnknownHostException (...)
2024-01-09 22:49:15.943	2024-01-09 14:24:17  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m10s372ms773µs960ns).
2024-01-09 22:49:15.943	2024-01-09 14:27:38  WARN: / - HikariPool-1 - Connection is not available, request timed out after 30617ms (total=2, active=2, idle=0, waiting=1) - SQLTransientConnectionException (... < QueryBuilder:67 < *:140 < DatabaseStorage:72 < Storage:49 < ...)
2024-01-09 22:49:15.943	2024-01-09 14:27:44  WARN: Unknown device - 9170580535 (183.171.81.37)
2024-01-09 22:49:15.943	2024-01-09 14:28:23  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=4m5s724ms939µs523ns).
2024-01-09 22:49:15.943	2024-01-09 14:28:34  WARN: Scheduled reports error - mysql: Temporary failure in name resolution - UnknownHostException (...)
2024-01-09 22:49:15.944	2024-01-09 14:29:31  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m8s356ms332µs818ns).
2024-01-09 22:49:15.944	2024-01-09 14:29:54  WARN: Scheduled reports error - mysql: Temporary failure in name resolution - UnknownHostException (...)
2024-01-09 22:49:15.944	2024-01-09 14:30:27  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=55s338ms473µs385ns).
2024-01-09 22:49:15.944	2024-01-09 14:31:09  WARN: Scheduled reports error - mysql: Temporary failure in name resolution - UnknownHostException (...)
2024-01-09 22:49:15.944	2024-01-09 14:31:45  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m18s846ms418µs646ns).
2024-01-09 22:49:15.944	2024-01-09 14:32:29  WARN: Find device error - mysql: Temporary failure in name resolution - UnknownHostException (...)
2024-01-09 22:49:15.944	2024-01-09 14:33:40  WARN: handleException / java.net.UnknownHostException: mysql: Temporary failure in name resolution
2024-01-09 22:49:15.944	2024-01-09 14:34:05  WARN: Scheduled reports error - mysql: Temporary failure in name resolution - UnknownHostException (...)
2024-01-09 22:49:15.944	2024-01-09 14:33:56  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=2m10s218ms516µs878ns).
2024-01-09 22:49:15.945	2024-01-09 14:33:32  WARN: Unknown device - 9170580535 (183.171.81.37)
2024-01-09 22:49:15.945	2024-01-09 14:35:01  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m5s107ms948µs681ns).
2024-01-09 22:49:15.945	2024-01-09 14:35:46  WARN: Database error - mysql: Temporary failure in name resolution - UnknownHostException (...)
2024-01-09 22:49:15.945	2024-01-09 14:36:17  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m16s131ms230µs986ns).
2024-01-09 22:49:15.945	2024-01-09 14:36:17  WARN: Find device error - mysql: Temporary failure in name resolution - UnknownHostException (...)
2024-01-09 22:49:15.945	2024-01-09 14:37:13  WARN: HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=55s796ms101µs79ns).
2024-01-09 22:49:15.945	2024-01-09 14:37:49  WARN: Scheduled reports error - mysql: Temporary failure in name resolution - UnknownHostException (...)
2024-01-09 22:49:15.945	2024-01-09 14:48:30  INFO: Operating system name: Linux version: 5.15.0-91-generic architecture: amd64
2024-01-09 22:49:15.946	2024-01-09 14:48:31  INFO: Java runtime name: OpenJDK 64-Bit Server VM vendor: AdoptOpenJDK version: 11.0.11+9
2024-01-09 22:49:15.946	2024-01-09 14:48:31  INFO: Memory limit heap: 989mb non-heap: 0mb
2024-01-09 22:49:15.946	2024-01-09 14:48:31  INFO: Character encoding: UTF-8 charset: UTF-8
2024-01-09 22:49:15.946	2024-01-09 14:48:31  INFO: Version: 5.10
2024-01-09 22:49:15.946	2024-01-09 14:48:31  INFO: Starting server...
2024-01-09 22:49:15.946	2024-01-09 14:48:31  INFO: HikariPool-1 - Starting...
2024-01-09 22:49:15.946	2024-01-09 14:48:34  INFO: HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@4fa06f52
2024-01-09 22:49:15.947	2024-01-09 14:48:34  INFO: HikariPool-1 - Start completed.
2024-01-09 22:49:15.947	2024-01-09 14:48:34  INFO: Clearing database change log checksums
2024-01-09 22:49:15.947	2024-01-09 14:48:34  INFO: Successfully acquired change log lock
2024-01-09 22:49:15.947	2024-01-09 14:48:35  INFO: Successfully released change log lock
2024-01-09 22:49:15.947	2024-01-09 14:48:42  INFO: Reading from traccar.DATABASECHANGELOG
2024-01-09 22:49:15.948	2024-01-09 14:48:43  INFO: Reading from traccar.DATABASECHANGELOG
2024-01-09 22:49:15.948	2024-01-09 14:48:43  INFO: Reading from traccar.DATABASECHANGELOG
2024-01-09 22:49:15.948	2024-01-09 14:48:44  INFO: UPDATE SUMMARY
2024-01-09 22:49:15.948	2024-01-09 14:48:44  INFO: Run:                          0
2024-01-09 22:49:15.948	2024-01-09 14:48:44  INFO: Previously run:              45
2024-01-09 22:49:15.948	2024-01-09 14:48:44  INFO: Filtered out:                 0
2024-01-09 22:49:15.948	2024-01-09 14:48:44  INFO: -------------------------------
2024-01-09 22:49:15.948	2024-01-09 14:48:44  INFO: Total change sets:           45
2024-01-09 22:49:15.948	
2024-01-09 22:49:15.948	2024-01-09 14:48:44  INFO: Update summary generated
2024-01-09 22:49:15.949	2024-01-09 14:48:44  INFO: Successfully released change log lock
2024-01-09 22:49:15.949	2024-01-09 14:48:44  INFO: Command execution complete
2024-01-09 22:49:15.949	2024-01-09 14:48:47  INFO: jetty-11.0.18; built: 2023-10-27T02:14:36.036Z; git: 5a9a771a9fbcb9d36993630850f612581b78c13f; jvm 11.0.11+9
2024-01-09 22:49:15.950	2024-01-09 14:48:47  INFO: Started o.t.w.@3aa6884a{/,null,AVAILABLE}
2024-01-09 22:49:15.950	2024-01-09 14:48:47  INFO: Session workerName=node0
2024-01-09 22:49:15.950	2024-01-09 14:48:49  WARN: JAXBContext implementation could not be found. WADL feature is disabled.
2024-01-09 22:49:15.950	2024-01-09 14:48:50  INFO: Started o.e.j.s.ServletContextHandler@7b4a48e0{/,null,AVAILABLE}
2024-01-09 22:49:15.950	2024-01-09 14:48:50  INFO: Started ServerConnector@aa5aee8{HTTP/1.1, (http/1.1)}{0.0.0.0:8082}
2024-01-09 22:49:15.951	2024-01-09 14:48:50  INFO: Started Server@a2b97b0{STARTING}[11.0.18,sto=0] @23178ms
2024-01-09 23:00:51.002	2024-01-09 15:00:50  INFO: [T840d3a75] connected

Traccar config:

<?xml version='1.0' encoding='UTF-8'?>

<!DOCTYPE properties SYSTEM 'http://java.sun.com/dtd/properties.dtd'>

<properties>

    <entry key='config.default'>./conf/default.xml</entry>

    <!--

    This is the main configuration file. All your configuration parameters should be placed in this file.

    Default configuration parameters are located in the "default.xml" file. You should not modify it to avoid issues
    with upgrading to a new version. Parameters in the main config file override values in the default file. Do not
    remove "config.default" parameter from this file unless you know what you are doing.

    For list of available parameters see following page: https://www.traccar.org/configuration-file/

    -->

    <entry key='database.driver'>com.mysql.cj.jdbc.Driver</entry>
    <entry key='database.url'>jdbc:mysql://redacted/redacted?zeroDateTimeBehavior=round&amp;serverTimezone=UTC&amp;allowPublicKeyRetrieval=true&amp;useSSL=false&amp;allowMultiQueries=true&amp;autoReconnect=true&amp;useUnicode=yes&amp;characterEncoding=UTF-8&amp;sessionVariables=sql_mode=''</entry>
    <entry key='database.user'>redacted</entry>
    <entry key='database.password'>redacted</entry>
    <entry key='filter.enable'>true</entry>
    <entry key='filter.distance'>5</entry>

</properties>
Anton Tananaeva year ago

I see some connection timeouts. There's definitely something going on with the database connection.

ZZa year ago

@Anton Tananaev - which line? Just curious.

Anton Tananaeva year ago

Not timeouts exactly, but I meant these:

Temporary failure in name resolution