mqtt-io icon indicating copy to clipboard operation
mqtt-io copied to clipboard

High CPU load in polling mode (40-60%)

Open hacker-cb opened this issue 2 years ago • 14 comments

Describe the bug

I'm running mqtt-io on Amlogic A113X in polling mode (CPU does not support interrupts) and it take around 40-60% CPU load

Expected behavior

Expect CPU load around 1-2%

Config

mqtt:
  host: x.x.x.x
  user: xxxx
  password: xxxx
  topic_prefix: mqtt-io
  ha_discovery:
    enabled: yes

# GPIO
gpio_modules:
    - name: gpio
      module: gpiod

digital_inputs:
    - name: button
      module: gpio
      pin: 10
      poll_interval: 0.1
      ha_discovery:
           component: binary_sensor
           name: GPIO Button

    - name: input1
      module: gpio
      pin: 46
      poll_interval: 0.1
      ha_discovery:
           component: binary_sensor
           name: GPIO Input1
    - name: input2
      module: gpio
      pin: 45
      poll_interval: 0.1
      ha_discovery:
           component: binary_sensor
           name: GPIO Input2
    - name: input3
      module: gpio
      pin: 44
      poll_interval: 0.1
      ha_discovery:
           component: binary_sensor
           name: GPIO Input3
    - name: input4
      module: gpio
      pin: 43
      poll_interval: 0.1
      ha_discovery:
           component: binary_sensor
           name: GPIO Input4

digital_outputs:
    - name: output1
      module: gpio
      pin: 30
      initial: low
      publish_initial: true
      ha_discovery:
          component: switch
          name: GPIO Output1
    - name: output2
      module: gpio
      pin: 29
      initial: low
      publish_initial: true
      ha_discovery:
          component: switch
          name: GPIO Output2
    - name: output3
      module: gpio
      pin: 28
      initial: low
      publish_initial: true
      ha_discovery:
          component: switch
          name: GPIO Output3

Hardware

  • Platform: Amlogic A113X (ARM Cortex-A53) quad-core up to 1.5GHz
  • Connected hardware: none

System:

  • OS: Armbian aarch64
  • Python version: Python 3.8.10
  • User you're running as: root
  • Using a virtualenv?: no

hacker-cb avatar Sep 15 '21 12:09 hacker-cb

Hello, I can report of the same issue with Raspberry Pi:

As you can see the CPU usage is high and the RAM consumption is growing over time: Bildschirmfoto_2021-10-05_18-15-11 Bildschirmfoto_2021-10-05_18-17-43

I confirmed that mqtt-io is the process consuming all that RAM and causing about 40-50% CPU load by logging into the RPi and checking with htop. Killing the process dropped both values to nearly 1-3%.

Config

mqtt:
  host: xxx
  port: 8883
  user: xxx
  password: xxx
  topic_prefix: wohnzimmer
  reconnect_delay: 5
  reconnect_count: 999
  ha_discovery:
    enabled: no
  tls:
    enabled: yes
    ca_certs: /root/xxx1.crt
    certfile: /root/xxx2.crt
    keyfile: /root/xxx.pem

gpio_modules:
  - name: rpi
    module: raspberrypi
    cleanup: true

digital_inputs:
  - name: Schalter_01
    module: rpi
    pin: 14
    on_payload: "on"
    off_payload: "off"
    pulldown: true
    retain: true
    poll_interval: 0.1

  - name: Schalter_02
    module: rpi
    pin: 15
    on_payload: "on"
    off_payload: "off"
    pulldown: true
    retain: true
    poll_interval: 0.1

  - name: Schalter_03
    module: rpi
    pin: 23
    on_payload: "on"
    off_payload: "off"
    pulldown: true
    retain: true
    poll_interval: 0.1

  - name: Schalter_04
    module: rpi
    pin: 18
    on_payload: "on"
    off_payload: "off"
    pulldown: true
    retain: true
    poll_interval: 0.1

digital_outputs:
#1
  - name: xxx01
    module: rpi
    pin: 11
    initial: "low"
    publish_initial: true
    retain: true

#2
  - name: xxx02
    module: rpi
    pin: 17
    initial: "low"
    publish_initial: true
    retain: true

#3
  - name: xxx03
    module: rpi
    pin: 22
    initial: "low"
    publish_initial: true
    retain: true

#4
  - name: xxx04
    module: rpi
    pin: 9
    initial: "low"
    publish_initial: true
    retain: true

#5  
  - name: xxx05
    module: rpi
    pin: 10
    initial: "low"
    publish_initial: true
    retain: true

#6
  - name: xxx06
    module: rpi
    pin: 24
    initial: "low"
    publish_initial: true
    retain: true

#7
  - name: xxx07
    module: rpi
    pin: 7
    initial: "low"
    publish_initial: true
    retain: true

#8
  - name: xxx08
    module: rpi
    pin: 25
    initial: "low"
    publish_initial: true
    retain: true

#9
  - name: xxx09
    module: rpi
    pin: 8
    initial: "low"
    publish_initial: true
    retain: true

#10  
  - name: xxx10
    module: rpi
    pin: 27
    initial: "low"
    publish_initial: true
    retain: true

#11 
  - name: xxx11
    module: rpi
    pin: 2
    initial: "low"
    publish_initial: true
    retain: true

#12 
  - name: xxx12
    module: rpi
    pin: 3
    initial: "low"
    publish_initial: true
    retain: true
 
 #13
  - name: xxx13
    module: rpi
    pin: 4
    initial: "low"
    publish_initial: true
    retain: true

Hardware:

  • Platform: Raspberry Pi 1B
  • connected hardware: input and output relais

System:

  • OS: OpenWRT 21.02 (Linux Wohnzimmer 5.4.143 #0 Tue Aug 31 22:20:08 2021 armv6l GNU/Linux) & Debian Bullseye Chroot
  • Python version: Python 3.9.2
  • User: root
  • virtualenv: no

Especially the growing consumption of RAM is a concern, I assume there is a memory leak or more likely a circle reference confusing the garbage collector.

Expected behavior

Polling by a single-configuration-script, resembling similar behavior to the configuration above, takes about 3-4% CPU and 3-4% of RAM, so there is substantial overhead: Bildschirmfoto_2021-10-09_09-41-14 I would expect mqtt-io to consume just a little bit more RAM and CPU since it is a lot more versatile.

Edit: Wrote a script to check how low the RAM and CPU could be to narrow down what might be the issue.

Torxgewinde avatar Oct 05 '21 16:10 Torxgewinde

Same issue, 55-65% CPU load

MrC0nst avatar Dec 02 '21 15:12 MrC0nst

Hi there, I got the same issue on a fresh install

Hardware

  • Raspberry Pi 1B
  • Piface Digital (Version 1)

System

  • OS: Raspberry OS (2021-10-30-raspios-bullseye-armhf-lite)
  • Python Version 3.9.2
  • User: pi / same behaviour when starting as root with supervisor

mqtt-io starting takes about 1-2 minutes (90-100% CPU load) and then takes about 70% CPU load

/usr/bin/python3 -m mqtt_io /home/pi/mqtt_io/config.yml

Config

mqtt:
  host: smarthome.local
  port: 8883
  user: mqtt-heaterpi
  topic_prefix: heaterpi/piface
  tls:
    enabled: true
    ca_certs: /home/pi/mqtt_io/iobroker_ca.crt
    certfile: /home/pi/mqtt_io/mqtt-heaterpi.crt
    keyfile: /home/pi/mqtt_io/mqtt-heaterpi.key
gpio_modules:
  - name: piface2
    module: piface2
digital_inputs:
  - name: input_1
    module: piface2
    pin: 0
  - name: input_2
    module: piface2
    pin: 1
  - name: input_3
    module: piface2
    pin: 2
  - name: input_4
    module: piface2
    pin: 3
  - name: input_5
    module: piface2
    pin: 4
  - name: input_6
    module: piface2
    pin: 5
  - name: input_7
    module: piface2
    pin: 6
  - name: input_8
    module: piface2
    pin: 7
digital_outputs:
  - name: output_1
    module: piface2
    pin: 0
  - name: output_2
    module: piface2
    pin: 1
  - name: output_3
    module: piface2
    pin: 2
  - name: output_4
    module: piface2
    pin: 3
  - name: output_5
    module: piface2
    pin: 4
  - name: output_6
    module: piface2
    pin: 5
  - name: output_7
    module: piface2
    pin: 6
  - name: output_8
    module: piface2
    pin: 7

mqtt-io works as expected

griesi avatar Jan 07 '22 11:01 griesi

Try disabling logging, or set it to higher level like this:

logging:
  version: 1
  loggers:
    mqtt_gpio:
      level: WARN

It helped me to bring CPU usage of mqqt_io to below 10%.

monte-monte avatar Jan 29 '22 21:01 monte-monte

Try disabling logging, or set it to higher level like this:

logging:
  version: 1
  loggers:
    mqtt_gpio:
      level: WARN

It helped me to bring CPU usage of mqqt_io to below 10%.

Nothing was changed in CPU load. It is still around 50% of one core.

hacker-cb avatar Jan 31 '22 12:01 hacker-cb

Try disabling logging, or set it to higher level like this:

logging:
  version: 1
  loggers:
    mqtt_gpio:
      level: WARN

It helped me to bring CPU usage of mqqt_io to below 10%.

Sorry, CPU-Load is still around 70-80% on my setup.

@monte-monte Are you sure with that syntax? Shouldn't module name be 'mqtt_io' not 'mqtt_gpio'? I also tried this with no success.

griesi avatar Jan 31 '22 18:01 griesi

@griesi yes you are right, but for some reason the way I wrote it worked too, logging stopped. For me I see 6-12% cpu usage after restartting mqtt_io, but it gradually creeps up to 30+%. I don't know how or why.

monte-monte avatar Jan 31 '22 23:01 monte-monte

Hi all - I don't have a particular problem with high CPU usage, but I've definitely got a memory leak. On my Raspberry Pi Model B+ (granted, pretty old) running Raspbian 11 (Bullseye), fully patched, it's leaking about 20% per day.

Pi_RAM

Pi_CPU

Here's my config, for reference:

mqtt:
  host: 192.168.x.y
  port: 1883
  user: mqtt
  password: password
  topic_prefix: pi4/garage
  client_id: pi-4-mqttio
  ha_discovery:
    enabled: yes
    name: pi-4 MQTT IO

# GPIO
gpio_modules:
  # Use the Raspberry Pi built-in GPIO
  - name: rpi
    module: raspberrypi

digital_outputs:
  # GPIO 4 is connected to the garage door manual button
  - name: garage_door_4
    module: rpi
    pin: 4
    inverted: true
    retain: true
    initial: high
    ha_discovery:
      name: Garage door
      device_class: switch

  # Pin 22 is connected to the security PIR relay
  - name: garage_pir_22
    module: rpi
    pin: 22
    inverted: false
    retain: true
    ha_discovery:
      name: Garage PIR
      device_class: switch

digital_inputs:
  # Pin 19 is connected to the workshop door
  - name: workshop_door_19
    module: rpi
    pin: 19
    pullup: true
    pulldown: true
    inverted: false
    retain: true
    ha_discovery:
      name: Workshop door
      device_class: door

  # Pin 26 is connected to the garage door
  - name: garage_door_26
    module: rpi
    pin: 26
    pullup: true
    pulldown: true
    inverted: false
    retain: true
    ha_discovery:
      name: Garage door
      device_class: garage_door

andystewart999 avatar Feb 11 '22 09:02 andystewart999

Hi, after changing the hardware from Raspberry Pi 1 which is a single core system with PiFace 1 board to Raspberry Pi 2 which is a quad core system with much more compute power with PiFace 2 board the Problem with CPU usage seemed to be gone.

I guess the hardware of that pretty old Raspberry is just too old and too weak for mqtt_io. I don't think it is about the PiFace board which imho is basically the same hardware.

Indeed I'm seeing the same issue with memory consumption of the mqtt_io process.

image

I worked around this by restarting the process once a day by the supervisor daemon which is controlling the process as you can see on the image.

griesi avatar Mar 26 '22 09:03 griesi

Opened a new Issue regarding the memory leak.

In my case the issue with CPU load is resolved by changing the hardware platform from Raspberry Pi1 to Raspberry Pi2.

@hacker-cb: What about your issue with your Amlogic A113X (ARM Cortex-A53) which should at least perform as well as the Raspberry Pi 2.

@MrC0nst @monte-monte: What kind of hardware are you using?

griesi avatar Mar 26 '22 10:03 griesi

Model : Raspberry Pi Model B Rev 2

MrC0nst avatar Mar 26 '22 12:03 MrC0nst

Good idea to separate the issues of high-CPU-load and memory-leak.

As shown with the simple script the old hardware itself is easily able to handle MQTT and GPIOs at a few percent CPU load. I would expect mqtt-io to be a little above such a bare minimum script, but not as much as it is right now. The first/second RPI is still "good enough" for such tasks.

I assume there must be a debugging option for Python to see which function is consuming so many CPU cycles and perhaps narrow down the memory-leak.

Torxgewinde avatar Mar 27 '22 17:03 Torxgewinde

The rate at which CPU load increases over time is correlated with lower interval time.

I have two nodes (study, lounge), specs are:

  • RPi 3 model B Rev 1.2
  • kernel 4.19.122-2-osmc (OSMC)
  • python 3.7.3
  • mqtt-io (2.2.6)

pip freeze:

Adafruit-DHT==1.4.0
asyncio-mqtt==0.8.1
backoff==1.11.1
Cerberus==1.3.4
memory-profiler==0.60.0
mqtt-io==2.2.6
paho-mqtt==1.6.1
pkg-resources==0.0.0
psutil==5.9.0
PyYAML==5.4.1
typing-extensions==3.10.0.2

image

On the left the CPU load on both lounge and study nodes had been climbing identically.

Around 2022-05-14 14:10:45 I set the study interval to 30s and the lounge interval to 60s and restarted mqtt-io on both nodes. The result is CPU load rising faster on the study node.

(Spikes in the study load ~3am are Kodi scanning for new media.)

Interactive Grafana snapshot

This is the config for the study node:

mqtt:
  host: pixie3
  topic_prefix: mqtt-io/study
  ha_discovery:
    enabled: yes

sensor_modules:
  - name: dht
    module: dht22
    type: AM2302
    pin: 4

sensor_inputs:
  - name: dht_study_temperature
    module: dht
    type: temperature
    interval: 30
    ha_discovery:
      device_class: temperature
      unit_of_measurement: '°C'
  - name: dht_study_humidity
    module: dht
    type: humidity
    interval: 30
    ha_discovery:
      device_class: humidity
      unit_of_measurement: '%'

logging:
  version: 1
  loggers:
    mqtt_gpio:
      level: WARN

markferry avatar May 16 '22 16:05 markferry

On an RPi 1 Model B Rev 2 cpu load rises quickly. (mqtt-io service was configured to restart every 8hrs as a workaround).

image

Over the same time period memory usage is nearly static (~0.6MB over 6hours) :

image

Going to git bisect and see if I can find a regression.

markferry avatar May 17 '22 09:05 markferry

Any luck with this issue ? I have the exact same problem on my RPI. After a while mqtt-io just uses all the CPU.

gmsoft-tuxicoman avatar Nov 30 '22 12:11 gmsoft-tuxicoman

are there any updates? my RPI3b runs out of memory every week and the cpu load is constantly 50% which is causing other services to respond slowly.

notacoderjustauser avatar Dec 17 '22 17:12 notacoderjustauser

While not ideal, restarting (the service) is an effective workaround. (Use cron or systemd's RuntimeMaxSec)

markferry avatar Dec 21 '22 07:12 markferry

@markferry : I gave the suggestion to reboot a thumbs down, just because it does not address the main issue. I appreciate your comments though.

I am still hoping someone might have an idea what is eating the RAM. Perhaps it is indeed the garbage collector which is confused, but I am not experienced with Python to track this down or follow up this idea.

Torxgewinde avatar Dec 24 '22 09:12 Torxgewinde

Hi, the same issue (CPU load) on my instalation: MQTT IO: Current version: 0.1.3 Raspberry Pi 4

Each fall down of value on the graph, is connected with only restart add-on mqtt-io:

image

At the moment I have only one DS18B20 sensor (1-wire) and one digital out.

piotruscilko avatar Jan 09 '23 20:01 piotruscilko

With all respect to MQTT-IO, now that I've discovered (v. late!) D1 Minis and ESPHome I plan to migrate to that platform for simple switch and sensor management.

Having said that, until the resources issue I did love MQTT-IO...

Get Outlook for iOShttps://aka.ms/o0ukef


From: upiter @.> Sent: Tuesday, January 10, 2023 7:57:17 AM To: flyte/mqtt-io @.> Cc: andystewart999 @.>; Comment @.> Subject: Re: [flyte/mqtt-io] High CPU load in polling mode (40-60%) (#236)

Hi, the same issue (CPU load) on my instalation: MQTT IO: Current version: 0.1.3 Raspberry Pi 4

Each fall down of value on the graph, is connected with only restart add-on mqtt-io:

[image]https://emea01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fuser-images.githubusercontent.com%2F98715772%2F211405644-a6b9440a-d03b-45fa-a42e-87a2ae946e50.png&data=05%7C01%7C%7Cf18446a0d1ae405d77ab08daf2841819%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C638088946397789864%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=sCONGxJ3SYQwj7u2UHHr54iiTPMcfu3Yg%2BtyRDGXDaY%3D&reserved=0

At the moment I have only one DS18B20 sensor (1-wire) and one digital out.

— Reply to this email directly, view it on GitHubhttps://emea01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fflyte%2Fmqtt-io%2Fissues%2F236%23issuecomment-1376303215&data=05%7C01%7C%7Cf18446a0d1ae405d77ab08daf2841819%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C638088946397789864%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=hHPjhbCgN2vTyfptdWWq%2BEVLDgroKc1TMU4XHkzIyDI%3D&reserved=0, or unsubscribehttps://emea01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAEMUTCN3LAMB6X5Q475PIVLWRR3S3ANCNFSM5ECLGPIA&data=05%7C01%7C%7Cf18446a0d1ae405d77ab08daf2841819%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C638088946397789864%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=gTYDOACuEhyQUqX4zZi8oBH1AOFUZ7eI5OSZvrCo7Is%3D&reserved=0. You are receiving this because you commented.Message ID: @.***>

andystewart999 avatar Jan 09 '23 21:01 andystewart999

Currently I only have a digital input (polling) and a digital output on my mqtt-io for investigation and I don't see the performance issue since 4 days. Can someone confirm that? That would point to the sensor code sections for further investigation.

BenjiU avatar Jan 10 '23 08:01 BenjiU

I can cut out part of the code for sensor, for few days to check it.

piotruscilko avatar Jan 10 '23 19:01 piotruscilko

I did recognize some change in the behaviour. 3 weeks ago i had issues with memory usage which was increasing. now i have high CPU load, about 20% on my rpi3b

1741 root 20 0 68944 17888 3468 S 19.1 1.9 9h53:05 python3 -m mqtt_io /opt/config_piwiremqtt.yml

my Config: ` mqtt: host: "MYIP" port: 1883 user: homeassistant password: "MYPWD" topic_prefix: energy ha_discovery: enabled: yes

#w1 input pin 4 sensor_modules:

  • name: ds1 module: ds18b type: DS18B20 address: 3c7be38106af # 24,8C Ruecklauf Heizung

pin: 4

  • name: ds2 module: ds18b type: DS18B20 address: 3cfef649d946 # 25,2C Vorlauf Heizung

pin: 4

  • name: ds3 module: ds18b type: DS18B20 address: 3c03f6499bd4 # 30,6C Vorlauf Warmwasser

sensor_inputs:

  • name: RL_Heizung module: ds1 interval: 120

  • name: VL_Heizung module: ds2 interval: 120

  • name: VL_Warmwasser module: ds3 interval: 120 `

notacoderjustauser avatar Jan 11 '23 08:01 notacoderjustauser

I can cut out part of the code for sensor, for few days to check it.

After first day it looks to be stable (but we will see during longer period):

image

piotruscilko avatar Jan 11 '23 14:01 piotruscilko

I have been doing a bit of profiling and debugging, it seems that each time a value is read, a 'transient_task' is created in the mqtt_io/server.py.

As far as I can see, those tasks should be removed when done but it's not happening.

https://github.com/flyte/mqtt-io/blob/f48e5b1207671cda92def18b2df5d776d3bd68f5/mqtt_io/server.py#L1075

In the above function, the for loop is taking more and more time as the transient_task list grows. I don't know why self.transient_tasks.remove(task) isn't called. More debugging is needed.

gmsoft-tuxicoman avatar Jan 13 '23 08:01 gmsoft-tuxicoman

I've had mqtt-io running for 3 days with the fix in #301 and the CPU is still low. It seems to be the right fix.

gmsoft-tuxicoman avatar Jan 16 '23 09:01 gmsoft-tuxicoman

image

Looks good. Nice work!

markferry avatar Jan 16 '23 11:01 markferry

grafik

unfortunately for me the issue seems not to be solved. i there anything a user has to do beside of updating the raspberry?

notacoderjustauser avatar Jan 16 '23 15:01 notacoderjustauser

grafik

unfortunately for me the issue seems not to be solved. i there anything a user has to do beside of updating the raspberry?

Did you install from Guy's branch?

(It isn't released yet so you'd need to clone Guy's repo, checkout the fix-high-cpu branch then pip install . or something to that effect.)

markferry avatar Jan 16 '23 15:01 markferry

oh ok, so i will wait for the release.

notacoderjustauser avatar Jan 16 '23 15:01 notacoderjustauser