search

ebaauw / homebridge-hue

Homebridge plugin for Philips Hue
Apache License 2.0
898 stars 91 forks source link

Logs being flooded with heartbeat drift warnings for Hue and Weather plugins #969

Closed jsiegenthaler closed 3 years ago

jsiegenthaler commented 3 years ago

Issue

The homebridge logs are being flooded with a lot of heartbeat drift messages, see log snippet below Note that I recently updated my newest Philips Hue bridge on 15.04.2021 to SW 1944102110, I am unsure if this is relevant.

Using Philips Hue bridge SW 1944102110 homebridge-hue v0.13.5 homebridge v1.3.4 homebridge-config-ui-x v4.41.0 Raspbian GNU/Linux Buster (10) Node.js v14.16.1 Npm v6.14.12

Log Messages

[17/04/2021, 10:34:28] [Weather] warning: heartbeat 54784, drift 289
[17/04/2021, 10:34:29] [Weather] warning: heartbeat 54785, drift 273
[17/04/2021, 10:34:30] [Weather] warning: heartbeat 54786, drift 263
[17/04/2021, 10:34:31] [Weather] warning: heartbeat 54787, drift 255
[17/04/2021, 10:34:34] [Hue] heartbeat 54785, drift 316
[17/04/2021, 10:34:34] [Weather] warning: heartbeat 54790, drift 366
[17/04/2021, 10:34:34] [Hue] heartbeat 54786, drift 312
[17/04/2021, 10:34:35] [Weather] warning: heartbeat 54791, drift 341
[17/04/2021, 10:34:35] [Hue] heartbeat 54787, drift 284
[17/04/2021, 10:34:36] [Weather] warning: heartbeat 54792, drift 317
[17/04/2021, 10:34:36] [Hue] heartbeat 54788, drift 260
[17/04/2021, 10:34:37] [Weather] warning: heartbeat 54793, drift 270
[17/04/2021, 10:34:40] [Hue] heartbeat 54791, drift 367
[17/04/2021, 10:34:41] [Hue] heartbeat 54792, drift 344
[17/04/2021, 10:34:41] [Hue] heartbeat 54793, drift 312
[17/04/2021, 10:34:42] [Weather] warning: heartbeat 54798, drift 327
[17/04/2021, 10:34:42] [Hue] heartbeat 54794, drift 269
[17/04/2021, 10:34:43] [Weather] warning: heartbeat 54799, drift 306
[17/04/2021, 10:34:44] [Weather] warning: heartbeat 54800, drift 285
[17/04/2021, 10:34:45] [Weather] warning: heartbeat 54801, drift 267
[17/04/2021, 10:34:46] [Weather] warning: heartbeat 54802, drift 275
[17/04/2021, 10:34:47] [Weather] warning: heartbeat 54803, drift 254
[17/04/2021, 10:34:50] [Hue] heartbeat 54801, drift 367
[17/04/2021, 10:34:51] [Hue] heartbeat 54802, drift 341
[17/04/2021, 10:34:51] [Hue] heartbeat 54803, drift 306
[17/04/2021, 10:34:52] [Weather] warning: heartbeat 54808, drift 339
[17/04/2021, 10:34:52] [Hue] heartbeat 54804, drift 282
[17/04/2021, 10:34:53] [Weather] warning: heartbeat 54809, drift 297
ebaauw commented 3 years ago

The message indicates that the scheduled heartbeat is triggered more than 0.25 seconds late. This could indicate an overloaded system, or an ill-behaving plugin blocking the NodeJS main thread (typically by doing synchronous I/O).

jsiegenthaler commented 3 years ago

Thanks, good to know. I'll disable my plugins one by one and report the culprit here

jsiegenthaler commented 3 years ago

Hi @ebaauw I isolated the overload to the homebridge-cmd4 v3.5.1 plugin. CPU load was 50% constantly with Cmd4 enabled, and dropped to 0% with the odd blip to 2% when Cmd4 was disabled.

I'll advise the plugin developer of this issue.