HABApp
HABApp copied to clipboard
spacemanspiff2007
High CPU load after MQTT connection lost
If the MQTT connection is lost, the CPU load increases a lot. Even if connection is restored, the high load remains. It needs to restart HABApp to drop the level again.
HABApp Version 24.02.0 OpenHAB version 4.1.1 (Release Build)
2024-03-23 12:35:20.006 [INFO ] [HABApp.connection.mqtt ] - Disconnected
2024-03-23 12:35:21.029 [INFO ] [HABApp.connection.mqtt ] - Connecting to 192.168.43.7:1883
2024-03-23 12:35:21.042 [INFO ] [HABApp.connection.mqtt ] - Disconnected
2024-03-23 12:35:23.057 [INFO ] [HABApp.connection.mqtt ] - Connecting to 192.168.43.7:1883
2024-03-23 12:35:23.068 [INFO ] [HABApp.connection.mqtt ] - Disconnected
2024-03-23 12:35:27.080 [INFO ] [HABApp.connection.mqtt ] - Connecting to 192.168.43.7:1883
2024-03-23 12:35:27.088 [INFO ] [HABApp.connection.mqtt ] - Disconnected
2024-03-23 12:35:35.112 [INFO ] [HABApp.connection.mqtt ] - Connecting to 192.168.43.7:1883
2024-03-23 12:35:35.122 [INFO ] [HABApp.connection.mqtt ] - Disconnected
2024-03-23 12:35:51.136 [INFO ] [HABApp.connection.mqtt ] - Connecting to 192.168.43.7:1883
2024-03-23 12:35:51.145 [INFO ] [HABApp.connection.mqtt ] - Disconnected
2024-03-23 12:36:23.159 [INFO ] [HABApp.connection.mqtt ] - Connecting to 192.168.43.7:1883
2024-03-23 12:36:23.168 [INFO ] [HABApp.connection.mqtt ] - Disconnected
2024-03-23 12:37:11.184 [INFO ] [HABApp.connection.mqtt ] - Connecting to 192.168.43.7:1883
2024-03-23 12:37:11.192 [INFO ] [HABApp.connection.mqtt ] - Disconnected
2024-03-23 12:38:23.208 [INFO ] [HABApp.connection.mqtt ] - Connecting to 192.168.43.7:1883
2024-03-23 12:38:23.216 [INFO ] [HABApp.connection.mqtt ] - Disconnected
2024-03-23 12:40:11.233 [INFO ] [HABApp.connection.mqtt ] - Connecting to 192.168.43.7:1883
2024-03-23 12:40:16.247 [INFO ] [HABApp.connection.mqtt ] - Disconnected
2024-03-23 12:42:58.262 [INFO ] [HABApp.connection.mqtt ] - Connecting to 192.168.43.7:1883
2024-03-23 12:43:01.397 [INFO ] [HABApp.connection.mqtt ] - Disconnected
2024-03-23 12:47:04.413 [INFO ] [HABApp.connection.mqtt ] - Connecting to 192.168.43.7:1883
2024-03-23 12:47:04.430 [INFO ] [HABApp.connection.mqtt ] - Connection successful
<manual restart of HABApp>
2024-03-24 11:53:02.350 [INFO ] [HABApp ] - HABApp Version 24.02.0
2024-03-24 11:53:02.558 [INFO ] [HABApp.connection.mqtt ] - Connecting to 192.168.43.7:1883
2024-03-24 11:53:02.592 [INFO ] [HABApp.connection.mqtt ] - Connection successful
2024-03-24 11:53:02.833 [INFO ] [HABApp.connection.openhab ] - Connected to OpenHAB version 4.1.1 (Release Build)
[2024-03-23 12:25:55,247] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.0>
[2024-03-23 12:26:55,256] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.1>
[2024-03-23 12:27:55,269] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.1>
[2024-03-23 12:28:55,270] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.1>
[2024-03-23 12:29:55,277] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.1>
[2024-03-23 12:30:55,290] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.1>
[2024-03-23 12:31:55,296] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.1>
[2024-03-23 12:32:55,302] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.1>
[2024-03-23 12:33:55,311] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.0>
[2024-03-23 12:34:55,325] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.1>
[2024-03-23 12:35:55,325] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.4>
[2024-03-23 12:36:55,332] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.8>
[2024-03-23 12:37:55,335] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.9>
[2024-03-23 12:38:55,342] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 1.0>
[2024-03-23 12:39:55,359] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 1.0>
[2024-03-23 12:40:55,366] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 1.0>
[2024-03-23 12:41:55,381] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 1.0>
[2024-03-23 12:42:55,397] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 1.0>
[2024-03-23 12:43:55,402] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 1.0>
[2024-03-23 12:44:55,413] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 1.0>
[2024-03-23 12:45:55,434] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 1.0>
[2024-03-23 12:46:55,438] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 0.9>
[2024-03-23 12:47:55,447] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 1.0>
[2024-03-23 12:48:55,462] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 1.1>
[2024-03-23 12:49:55,450] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 1.2>
[2024-03-23 12:50:55,463] [HABApp.EventBus ] INFO | num_Server_CPU_Load1: <ItemStateUpdatedEvent name: num_Server_CPU_Load1, value: 1.1>
Please not that the data shown in the graph is transferred over that MQTT connection, so there is a gap while the connection is lost.
Do you observe this issue without rules or can you provide a minimal working example that shows that behavior? I'll try to reproduce this issue in the meantime.
I tried to reproduce that behavior but did not succeed so far. But I can say that I've seen it already several times.
Here is an example, what my rules do: the just publish sometimes some data to the main server. There are four rules which do similar things. ups.zip
There is one rule which sends data with a higher frequency, but that was deactivated when that problem occurred.
The configuration is nothing special:
mqtt:
connection:
identifier: HABApp_Zunge # ClientId that is used to uniquely identify this client on the mqtt broker.
host: '192.168.43.7' # Connect to this host. Empty string ("") disables the connection.
port: 1883
user: 'xxx'
password: 'xyz'
tls:
enabled: false # Enable TLS for the connection
ca cert: . # Path to a CA certificate that will be treated as trusted
insecure: true # Validate server hostname in server certificate
subscribe:
qos: 0 # Default QoS for subscribing
topics:
- - '#'
-
publish:
qos: 0 # Default QoS when publishing values
retain: false # Default retain flag when publishing values
general:
listen_only: false # If True HABApp does not publish any value to the broker
HABApp Version 24.02.0 OpenHAB version 4.1.1 (Release Build)
I confirm the problem, but I also can’t reproduce it, since it manifests itself over time.
I was more concerned about the fact of the periodic disconnection from MQTT, and not the processor load. Fortunately, I managed to find out that the disconnection occurs at a high load on the MQTT server from another application. So I would not refuse the keepalive option in the MQTT section of Habapp settings.
However, something is still wrong, because immediately after reconnecting to the MQTT server, Habapp completely loads one processor core for about a minute, and even after that it does not immediately catch mqtt events, sometimes with a lag of several tens of seconds (compared to zigbee2mqtt log). In case this is important: my MQTT server is quite loaded - about 2000 topics, 10K messages in 5 minutes.
As I said, I still can’t reproduce the problem, since the high load on MQTT from another application appears over time, due to a mem leakage or smth, however, since I did not change anything, as soon as this happens, I could remove the rules with MqttItem, and watch. My rules are quite simple though, here's example:
import HABApp
from HABApp.mqtt.items.mqtt_item import MqttItem
from HABApp.openhab.items import PlayerItem, StringItem
from HABApp.openhab.events import ItemStateChangedEvent, ItemStateChangedEventFilter, ItemCommandEvent, ItemCommandEventFilter
from HABApp.core.events import ValueUpdateEvent, ValueUpdateEventFilter, OrFilterGroup
import logging
from kimiHome.common_values import *
log = logging.getLogger('HABApp.ScYt')
log.info('------------ ScYt Reload -------------')
class ScYt_player(HABApp.Rule):
def __init__(self, scyt_prefix, mqtt_topic):
log.info(f'Youtube player item for {scyt_prefix}')
super().__init__()
self.player = PlayerItem.get_item(scyt_prefix + '_player')
self.title = StringItem.get_item(scyt_prefix + '_title')
self.artist = StringItem.get_item(scyt_prefix + '_artist')
self.mqtt_command = MqttItem.get_create_item(f'{mqtt_topic}/command')
self.mqtt_title = MqttItem.get_create_item(f'{mqtt_topic}/title')
self.mqtt_status = MqttItem.get_create_item(f'{mqtt_topic}/status')
self.listen_event(self.player,
self.command_received,
OrFilterGroup(
ItemCommandEventFilter(),
ItemStateChangedEventFilter()
)
)
self.listen_event(self.mqtt_title, self.title_received, ValueUpdateEventFilter())
self.listen_event(self.mqtt_status, self.status_received, ValueUpdateEventFilter())
def command_received(self, event: ItemCommandEvent|ItemStateChangedEvent):
log.debug(f'Command received: {event.value}')
if event.value == 'PLAY' and self.mqtt_status.get_value() == 'Paused':
self.mqtt_command.publish('play')
elif event.value == 'PAUSE' and self.mqtt_status.get_value() == 'Playing':
self.mqtt_command.publish('pause')
elif event.value == 'NEXT':
self.mqtt_command.publish('next')
elif event.value == 'PREVIOUS':
self.mqtt_command.publish('previous')
def title_received(self, event: ValueUpdateEvent):
log.debug(f'Title received: {event.value}')
if ' - ' in event.value:
artist_title = event.value.split(' - ')
else:
artist_title = ['-', event.value]
self.artist.oh_post_update(artist_title[0])
self.title.oh_post_update(artist_title[1])
def status_received(self, event: ValueUpdateEvent):
log.debug(f'Status received: {event.value}')
if event.value == 'Paused' and self.player.get_value() == 'PLAY':
self.player.oh_post_update_if('PAUSE', ne=True)
elif event.value == 'Playing' and self.player.get_value() == 'PAUSE':
self.player.oh_post_update_if('PLAY', ne=True)
yt_player = ScYt_player('YouTube', 'kimiHome/audio/YouTube_player')
I've just published 24.8.1 which upgrades the mqtt dependencies. If I remember correctly there was a fix for a possible race condition - maybe you are hitting that?
Please let me know if the issue still exists with 24.8.1