High CPU load for 20mins under 0.48 and 0.49

Configuration
1

I experienced this once under 0.48, but I was trying out gstreamer which introduced similar problems on its own. So I dropped back to an sd image with just 0.47 on it, and everything worked fine for several days, but after upgrading to 0.49 yesterday morning I got another period of high cpu at 19:40 GMT, that lasted for about 20 minutes.

There is nothing useful in the HA log, except that it was taking a long time time to do things

2017-07-25 19:21:39 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-25 19:24:37 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-25 19:24:41 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-25 19:24:47 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-25 19:27:26 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-25 19:39:56 WARNING (MainThread) [homeassistant.components.sensor] Updating command_line sensor took longer than the scheduled update interval 0:01:00
2017-07-25 19:39:56 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating workday binary_sensor took longer than the scheduled update interval 0:00:30
2017-07-25 19:39:56 WARNING (MainThread) [homeassistant.components.sensor] Updating darksky sensor took longer than the scheduled update interval 0:00:30
2017-07-25 19:39:56 WARNING (MainThread) [homeassistant.components.sensor] Updating systemmonitor sensor took longer than the scheduled update interval 0:00:30
2017-07-25 19:39:56 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-25 19:39:56 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.mosquitto_status is taking over 10 seconds
2017-07-25 19:39:56 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.dark_sky_cloud_coverage is taking over 10 seconds
2017-07-25 19:40:14 WARNING (MainThread) [homeassistant.core] Unable to remove unknown listener <function async_track_point_in_utc_time.<locals>.point_in_time_listener at 0xae651348>
2017-07-25 19:40:21 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:05:00
2017-07-25 19:40:21 WARNING (MainThread) [homeassistant.components.sensor] Updating command_line sensor took longer than the scheduled update interval 0:01:00
2017-07-25 19:40:21 WARNING (MainThread) [homeassistant.components.sensor] Updating darksky sensor took longer than the scheduled update interval 0:00:30
2017-07-25 19:40:21 WARNING (MainThread) [homeassistant.components.sensor] Updating systemmonitor sensor took longer than the scheduled update interval 0:00:30
2017-07-25 19:40:23 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-25 19:40:23 WARNING (MainThread) [homeassistant.helpers.entity] Update of binary_sensor.naospc is taking over 10 seconds
2017-07-25 19:40:23 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.appdaemon_status is taking over 10 seconds
2017-07-25 19:40:23 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.dark_sky_precip_probability is taking over 10 seconds
2017-07-25 19:40:26 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-25 19:40:29 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-25 19:40:31 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-25 19:40:31 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.open_files is taking over 10 seconds
2017-07-25 20:26:53 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.dark_sky_cloud_coverage is taking over 10 seconds
2017-07-25 21:53:47 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-26 06:31:25 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-26 06:31:42 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.dark_sky_cloud_coverage is taking over 10 seconds
2017-07-26 07:37:10 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-26 07:37:22 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-26 08:11:53 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-26 08:11:59 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-26 08:12:40 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-26 08:13:35 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-07-26 08:13:36 WARNING (MainThread) [homeassistant.components.sensor] Updating darksky sensor took longer than the scheduled update interval 0:00:30
2017-07-26 08:13:36 WARNING (MainThread) [homeassistant.components.sensor] Updating systemmonitor sensor took longer than the scheduled update interval 0:00:clock1030:

The only extra thing in /var/log/syslog is this, at the end of the period

Jul 25 19:40:14 raspberrypi hass[2325]: WARNING:homeassistant.core:Unable to remove unknown listener <function async_track_point_in_utc_time.<locals>.point_in_time_listener at 0xae651348>

Has anyone experienced something similar, or have any insights as to what is happening?

2

This also seems to correlate with something eating up some memory, which was released when I restarted HA

912×928 116 KB

3

After adding a bit more logging, I have discovered that this coincides with a large number of MQTT messages coming from my light sensor around dusk. It seems that the later versions of HA have a hard time handling this.

Adding some debounce code to the light sensor sketch just moved up my priority list.

4

hi,
not wanting to bump this unnecessarily but you’re just about the only one posting about the Unable to remove unknown listener i am experiencing also lately.
I also have a rather extensive mqtt setup, so was keen to know if you ever managed to resolve this? If so, how? Especially interested in your ;debounce code’…

cheers,
Marius

5

The problem was the light sensor sending too many MQTT messages at once. I just made sure that a maximum of one message is sent every second. I can look it up if you need, but there isn’t much to it.

6

please if you have spare moment, let me know what you did. I just might need such a simple thing.

Maybe this coincides with some other issues, web sockets, max messages, etc i see every now and then.

Cheers,
Marius

7

This is my light sensor sending code. I’m really not sure how it will help you though.

  if (mqttClient.connected()) {
    //Light level
    // Only send once a second to avoid spamming when light 
    // level is on the limit
    if (now < lastDarkMessage // Check for wrap around
        ||
        now > (lastDarkMessage + 1000)
        || firsttime == true) {
      boolean currentLight = (digitalRead(LIGHT_LEVEL_PIN) == HIGH);
      if (lightlevel && !currentLight) {
        sendMQTT("sensor/433/dark", "OFF", false);
        lightlevel = currentLight;
        lastDarkMessage = now;
      } else if (!lightlevel && currentLight) {
        sendMQTT("sensor/433/dark", "ON", false);
        lightlevel = currentLight;
        lastDarkMessage = now;
      } else if (firsttime == true) {
        sendMQTT("sensor/433/dark", currentLight?"ON":"OFF", false);
        lightlevel = currentLight;
        lastDarkMessage = now;
      }
    }