Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

High CPU load after MQTT connection lost #443

Open
UrsusS opened this issue Mar 24, 2024 · 4 comments
Open

High CPU load after MQTT connection lost #443

UrsusS opened this issue Mar 24, 2024 · 4 comments

Comments

@UrsusS
Copy link

UrsusS commented Mar 24, 2024

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.
grafik
@spacemanspiff2007
Copy link
Owner

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.

@UrsusS
Copy link
Author

UrsusS commented Mar 24, 2024

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

@kimifish
Copy link

kimifish commented Jul 5, 2024 •
edited
Loading

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')

@spacemanspiff2007
Copy link
Owner

spacemanspiff2007 commented Aug 1, 2024 •
edited
Loading

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@kimifish @spacemanspiff2007 @UrsusS