🙋 enabling MQTT slows down the processed readings

[rkuijer]

Description

For 2 days I started to play with DSMR-Reader. First setting up de docker connecting to MariaDB with, time zone info, and a small eureka moment I have readings. OK next step is adding the MQTT connection to the Mosquitto broker on my HASS installation. Now the fun part starts when I enable MQTT I will get after some time the following messages

• Process behind schedule: Calculate quarter hour electricity peaks
• Process behind schedule: Generate consumption data

When I look at the DSMR Reading I see a long list of not processed items.

I also tried slowing it down and increased the datalogger process sleep to 10 s but still not OK

When I disable MQTT everything is OK even with Datalogger process sleep of 5.

I see MQTT messages appear when I check with MQTT explorer so the connection is working.

Attached is some debug logging: xirixiz-dsmr-reader-docker.csv

DSMR-reader version

v5.9

DSMR-reader platform

Docker (e.g. Xirixiz)

Debug info dump

DSMR-READER
    App / Python / Database                                                            v5.9 / v3.11.1 / mysql
    BE sleep / DL sleep / Retention / Override                                     1.0s / 5.0s / 672h / False
    Latest telegram version read / Parser settings                                                 "50" / "4"

DATA
    Telegrams total (est.)                                                                        ??? (mysql)
    Consumption records electricity / gas (est.)                                    ??? (mysql) / ??? (mysql)

UNRESOLVED ISSUES
    Approximately None readings stored, consider data cleanup (if not already enabled)                                     now
    Process behind schedule: Calculate quarter hour electricity peaks                          27 minutes ago
    Process behind schedule: Generate consumption data                                         32 minutes ago

[dennissiemensma]

Bedankt voor je melding. Normaal gesproken zou het verwerken/versturen van MQTT weinig invloed moeten hebben. Mits die het kan bijbenen.

Ik zie wel dat je queue volloopt: MQTT: Rejecting message for topic due to maximum queue size (5000) Maar dat kan ook een gevolg zijn en niet de oorzaak.

Check of deze wel leegloopt als je MQTT aanzet:

• admin/dsmr_mqtt/message/

En anders kun je deze wat lager zetten dan de default van 5000: https://dsmr-reader.readthedocs.io/en/v5/reference/env-settings.html#dsmrreader-mqtt-max-messages-in-queue

• DSMRREADER_MQTT_MAX_MESSAGES_IN_QUEUE=100

[rkuijer]

@dennissiemensma bedankt voor je snelle reactie!

Waneer ik kijk bij admin/dsmr_mqtt/message/ -> 4,504 Outgoing MQTT messages dat lijkt mij inderdaad niet ok. Ik zal de queue grote eens naar benede zetten en kijken wat er gebeurt.

De docker draait op een Synolgy NAS DS918+ mijn HASS draait op een RPi4 binnen het zelfde netwerk als mijn NAS. Wanner ik een ping doe root@dsmr_reader_docker:/app# ping 192.168.15.214 Dan is de response ook OK 64 bytes from 192.168.15.214: seq=0 ttl=63 time=0.425 ms

Waarom zou hij de berichten niet kunnen afleveren is dus eigenlijk de vraag.

Resultaten: Met een queue grote van 100 heeft hij 87 Outgoing MQTT messages Het aantal DSMR readings die hij nu achterloopt is maar 2 a 3 en stabiel. Ik zie af en toe de melding voorbij komen over dat de MQTT queue vol is het status scherm

Bijgevoegd de debug logging met een queue van 100 xirixiz-dsmr-reader-docker.csv

[dennissiemensma]

Je kunt de backend-sleep nog wat lager zetten dan de standaard:

dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s

Via de admin interface kan die omlaag naar een halve seconde denk ik. En anders kan die direct in de DB wel op nul gezet worden, maar denk niet dat dat nodig is.

Het versturen en acken van een MQTT bericht lijkt verder snel zat, ~2 a 3 ms.

[rkuijer]

Dezelfde resultaten, zelfs met een sleeping van 0.5 en ook met 0.1

[dennissiemensma]

Het lijkt erop dat het verwerken van de telegrammen relatief traag gaat. Dit duurt bijna 3 seconden:

2022-12-29T16:58:32.037316104Z,stdout,"2022-12-29 17:58:32,036 DEBUG    services     compact                         194 | Compact: Waiting for newer readings before grouping data...
2022-12-29T16:58:32.032840004Z,stdout,"2022-12-29 17:58:32,032 DEBUG    services     compact                         211 | Compact: Processed reading: 2756 @ 2022-12-29 17:56:34+01:00
2022-12-29T16:58:30.948815905Z,stdout,"2022-12-29 17:58:30,947 DEBUG    services     compact                         211 | Compact: Processed reading: 2755 @ 2022-12-29 17:56:23+01:00
2022-12-29T16:58:30.445656154Z,stdout,"2022-12-29 17:58:30,445 DEBUG    services     compact                         211 | Compact: Processed reading: 2754 @ 2022-12-29 17:56:15+01:00
2022-12-29T16:58:29.079840982Z,stdout,"2022-12-29 17:58:29,079 DEBUG    services     compact                         211 | Compact: Processed reading: 2753 @ 2022-12-29 17:56:08+01:00

Ter vergelijking:

2022-12-29 18:54:28,066 DEBUG    services     compact                         211 | Compact: Processed reading: 19481684 @ 2022-12-29 18:53:04+01:00
2022-12-29 18:54:28,082 DEBUG    services     compact                         211 | Compact: Processed reading: 19481685 @ 2022-12-29 18:53:24+01:00
2022-12-29 18:54:28,097 DEBUG    services     compact                         211 | Compact: Processed reading: 19481686 @ 2022-12-29 18:53:34+01:00
2022-12-29 18:54:28,113 DEBUG    services     compact                         211 | Compact: Processed reading: 19481687 @ 2022-12-29 18:53:44+01:00
2022-12-29 18:54:28,128 DEBUG    services     compact                         211 | Compact: Processed reading: 19481688 @ 2022-12-29 18:53:54+01:00

Alleen weet ik niet waar het aan kan liggen.

[rkuijer]

Het verwerken is dat inclusief het ophalen van de telegram bij de remote logger? Want die zit wel in een appart vlan. Maar ik kan met niet voorstellen dat dit een probleem is. Ping vanuit de docker laat wel wat onstabiel gedrag zien maar niks in de buurt van secondes

seq=0 ttl=126 time=2.248 ms                                                                               
seq=1 ttl=126 time=4.024 ms                                                                               
seq=2 ttl=126 time=71.782 ms                                                                              
seq=3 ttl=126 time=4.005 ms                                                                               
seq=4 ttl=126 time=4.735 ms                                                                               
seq=5 ttl=126 time=3.132 ms                                                                               
seq=6 ttl=126 time=2.092 ms                                                                               
seq=7 ttl=126 time=22.602 ms                                                                              
seq=8 ttl=126 time=5.236 ms                                                                               
seq=9 ttl=126 time=9.625 ms

Als jij het al niet weet Dennis wie dan wel? Wat kan ik nog doen?

[dennissiemensma]

Het verwerken van de telegrammen gebeurt los van het uitlezen, maar wel in hetzelfde proces als de MQTT-verwerking.

Het maakt het vooral lastig omdat ik geen referentie heb voor je van vergelijkbare problemen. Je bent de eerste die dit specifieke issue meldt en het kan aan hardware, software of iets anders liggen. Normaal gesproken is de datagrootte oorzaak nummer 1, maar als je slechts 2 dagen bezig bent heb je amper data.

Je kunt nog kort benchmarken in de situatie met en zonder MQTT aan en dan de logs delen. Alleen zul je dan wel even de MQTT-queue moeten leeggooien voor een goede vergelijking. In de admin-pagina kun je op de plek waar je die queue ziet ze bulk selecteren en met de dropdown daarboven verwijderen.

Je kunt dan ook vrij makkelijk zien hoe snel het weer opstopt. En of het verwerken van de metingen in beide situaties traag is of niet.

[rkuijer]

OK, de volgende logging. Situatie, alle MQTT zaken uitgezet en ook de connectie met de broker. Alle outgoing messages verwijderd Docker gestopt log level op debug gezet en dan de docker weer gestart. xirixiz-dsmr-reader-docker.csv

Het valt ook op dat het aantal DSMR readings per minuut hoger is in deze situatie, rond de 8

Wanneer ik de MQTT zaken weer aanzet zijn het maar 1 tot 3 metingen

[dennissiemensma]

Dank voor proberen. En wat is de logging als MQTT aan staat, maar er (nog) geen queue van berichten is? Want als de datalogger daar onder lijdt, is er wellicht iets anders niet helemaal lekker.

In principe zijn er twee achtergrondprocessen: de datalogger die alleen (onverwerkte) metingen opslaat en meer niet. En de backend-proces dat al het andere werk periodiek doet.

De MQTT-taak kan lijden onder een traag backend-proces, maar een datalogger-proces zou gewoon altijd z'n ding moeten kunnen doen.

[rkuijer]

Hoi Dennis, omdat het de bedoelling was om dit als tussendoor projectje te doen heb ik dit even in de ijskast gezet. De docker image heb ik nog bewaard en de database ook dus ik kan hem later altijd nog aanslingeren als ik er zelf ook meer tijd voor heb. Omdat er nu geen duidelijke richting is en geen algemeen probleem die meerdere mensen ervaren sluit ik hem voor nu.

[dennissiemensma]

Prima, toch bedankt voor het melden!

[rkuijer]

@dennissiemensma toch een kleine opmerking. Door een update van HA kwam de volgende bug naar boven https://jira.mariadb.org/browse/MDEV-25020 van de MariaDB van de standaard package van Synology. Zou het kunnen zijn dat het gedrag wat ik zag hier mee te maken zou hebben?

Op het ogenblik heb ik geen tijd om dit te testen.

[dennissiemensma]

Het zou kunnen, al denk ik dat het wel een ander type ID is. Om het zeker te weten zou je eigenlijk de database zelf moeten profielen en per query checken.