Datalogger telegram processing loopt precies 1 minuut achter?

[oetelaar24]

Hoi!

Ik gebruik naar volle tevredenheid DSMR al een paar jaar. Fantastisch programma!

Nu heb ik een vraag mbt het processen van de Telegram berichten. Ik gebruik een DSMR docker image in een VM. Daarnaast een remote datalogger op een RBPi3B+ die via een P1 kabel aan mijn slimme meter hangt. Alles lijkt naar behoren te werken, echter merk ik dat het processen van de Telegrams ongeveer precies één minuut vertraagt zijn. De timestamp die ik zie in de mqtt berichten lijken dit te bevestigen.

De reden waarom ik op zoek ben naar (near) realtime data, is omdat ik probeer om een duidelijk beeld te krijgen van het actuele stroomverbruik van mijn woning op het moment dat de zonnepanelen stroom terugleveren. Hiervoor moet ik de data uit de inverter (opgewerkte stroom) minus de DSMR data voor teruggeleverde stroom per gelijk tijdsinterval verrekenen. Als de data uit DSMR echter 1 minuut oud is, en die van de inverter niet, dan krijg ik scheve uitkomsten...

Is er een manier om ervoor te zorgen dat DSMR de Telegrams direct verwerkt en doorzet naar MQTT zonder vertraging?

Groeten, -Bart

[dennissiemensma]

Bedankt voor je vraag. Er zijn meerdere dingen die een rol kunnen spelen. Ik zou beginnen bij de interne klok van je slimme meter.

DSMR-reader gebruikt de datumtijd uit het telegram (dus volgens de slimme meter) als waarheid, maar dat is in de praktijk niet altijd de huidige tijd. Het verschilt soms van enkele seconden tot zelfs een minuut. Ik weet niet of het tijdstip uit de slimme meter het moment van meten is of gewoon het moment van versturen (waarbij de slimme meter klok kan afwijken van de systeemtijd van waar DSMR-reader op draait).

Het makkelijkste om dit te checken is om de derde regel van het laatste telegram in /admin/dsmr_datalogger/meterstatistics/ in de gaten te houden. Hieronder de laatste 6 cijfers dat het tijdstip is: 18:51:21 S(ummer time):

...
0-0:1.0.0(210510185121S)
...

Op een terminal van je VM kun je dan dit ernaast leggen om te zien wat het verschil is:

watch -n0.5 date

Je ziet het overigens ook wel op het dashboard van DSMR-reader bij het laatste telegram bovenin: bijvoorbeeld 28 seconds ago.

Kan het zijn dat dat al een grote afwijking heeft?

[oetelaar24]

Inderdaad. Daar is de afwijking ook te zien, zowel in de timestamp van de laatste telegram als op het dashboard ( Latest update received a minute ago ) Wat mij vooral ook opviel, was dat de readings die je ziet in /admin/dsmr_datalogger/dsmrreading/ pakweg de laatste 22 nog een rood kruis hebben staan in de "processed" kolom. Maar bij nader inzien, zie ik daar ook dat de nieuwste een minuut afwijkt van de huidige systeemtijd (die zelfs nog geprocessed moet worden).

Als ik je goed begrijp, dan zou het enkel gaan om een afwijking in weergave van tijd van de meter. Maar als ik de waarden via MQTT verkregen uit DSMR probeer te vergelijken met die op de display van de slimme meter zelf. Dan lukt me dat niet echt....

[oetelaar24]

Schiet me wat tebinnen. Ik draai wel nog een verouderd datalogger script van: https://github.com/trizz/dsmr-remote-datalogger Zou dat nog een oorzaak kunnen hebben?

[dennissiemensma]

Inderdaad. Daar is de afwijking ook te zien, zowel in de timestamp van de laatste telegram als op het dashboard ( Latest update received a minute ago )

Mooi, dat verklaart in ieder geval het visuele gedeelte qua tijdstip. De volgende stap is kijken waar de vertraging in MQTT zit.

Het hangt er vooral vanaf welke databron je gebruikt. Ik neem aan dat je een van de 3 telegram bronnen gebruikt in /admin/dsmr_mqtt/? Zo ja, dan maakt het niet uit of een telegram "verwerkt" is, dat is puur voor de aggregatie in DSMR-reader zelf.

MQTT-berichten die gequeued worden door DSMR-reader (in dit geval door de datalogger), worden in de eerstvolgende "run" van het backend-proces in DSMR-reader verstuurd. Op welke waarde staat de backend-sleep in /admin/dsmr_backend/backendsettings/?

[dennissiemensma]

Sinds vanavond is DSMR-reader v4.16 overigens beschikbaar, met wijzigingen voor MQTT. Dus wellicht wil je ook updaten naar die versie. MQTT wordt er niet sneller door, maar wel beter te debuggen.

Update: Ik zie nu pas dat je eerder aangaf Docker te gebruiken. In dat geval is het even wachten op een nieuwe Docker build door Xirixiz denk ik. Maar goed, het is geen vereiste voor nu, meer om eventueel later het debuggen te versimpelen.

[oetelaar24]

Thanks voor je uitgebreide hulp! Ik gebruik inderdaad (Data source) Telegram: Split topic (zoals aangegeven in de homeassistant guide). Goed om te weten dat het zo werkt.

De backend-sleep staat op dit moment op 1.0, ik had deze setting ook al gevonden en al eens mee "gespeeld" door 'm op 0.2 en op 0.0 te zetten en kort getest, maar ik zag er geen verandering in gedrag door. Misschien moet ik langer wachten voor het effect zichtbaar is?

[dennissiemensma]

Schiet me wat tebinnen. Ik draai wel nog een verouderd datalogger script van: https://github.com/trizz/dsmr-remote-datalogger Zou dat nog een oorzaak kunnen hebben?

Nog in reactie hier op: Ik denk overigens dat het niet veel uit maakt. Zolang je telegrammen binnenkrijgt via dat oude script zou ik er zelf vooral niet aan zitten. Mocht het ooit stukgaan, dan kun je tzt wel besluiten om te "upgraden" naar de laatste versie (of niet). De kans is namelijk groter dat je het sloopt, dan dat het er sneller van wordt.

[dennissiemensma]

Ik zou beginnen met debuggen van MQTT en als je daar niets in kan vinden, dan de logs van de datalogger en MQTT naast elkaar leggen om te zien hoelang de "vertraging" is. Uiteraard los van het tijdstip in het telegram zelf, want daar heb ik nog wel een oplossing voor, maar je moet eerst kijken of het pad van meting uitlezen tot MQTT vlot genoeg is.

Voor nu kun je het beste debug-logging inschakelen in DSMR-reader: https://dsmr-reader.readthedocs.io/en/latest/how-to/troubleshooting/enabling-debug-logging.html Via Docker is het denk ik gewoon een envvar en dan een restart van de container vermoed ik.

[dennissiemensma]

Daarna zul je opzoek moeten naar de log van het backend proces. Ik weet niet precies waar die in docker staat, maar wellicht is dit een hint: https://github.com/xirixiz/dsmr-reader-docker/issues/171#issuecomment-776933247

Als je daar een tail -f op doet, dan zou je exact moeten kunnen zien wat DSMR-reader doet. Het kan helpen om de backend-sleep in dat geval even tijdelijk of 5 of 10 seconden te zetten, zodat je iets beter ziet wat die doet.

[dennissiemensma]

In de logs zelf ben je dan op zoek naar statements die beginnen met MQTT: .... Als je nog DSMR-reader v4.15.2 (of ouder) gebruikt dan staat er wel wat informatie in, maar niet compleet.

Dit is in de laatste release uitgebreid, zodat je exact kan zien welk bericht in de queue gaat en wanneer die verzonden wordt. Dat laatste wordt dus wel beinvloed door de backend-sleep, maar als die al op 1 seconde stond, dan zul je daar weinig kunnen winnen. Het gaat er dan om of je kunt zien hoe snel het queuen en versturen gaat. Queuen zou direct bij binnenkomen meting in DSMR-reader moeten gebeuren.

Vandaar dat een upgrade naar v4.16 aan te raden is, wanneer beschikbaar en mogelijk.

[oetelaar24]

Blijkbaar was het docker-image snel klaar. Ik draai nu al v4.16 :-D

Ik heb debuglogging aangezet en dit is een voorbeeld van wat ik voorbij zie komen in de backend log:

2021-05-10 21:51:05,646 | DEBUG    broker.initialize_client:27 | MQTT: Initializing MQTT client for "xy.zzz:1883"
2021-05-10 21:51:05,647 | DEBUG    broker.initialize_client:44 | MQTT: Using insecure connection (no TLS)
2021-05-10 21:51:05,650 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending CONNECT (u1, p1, wr0, wq0, wf0, c1, k60) client_id=b'DSMR-reader'
2021-05-10 21:51:05,653 | DEBUG    services.initialize_client:21 | INFLUXDB: Integration disabled in settings (or due to an error previously)
2021-05-10 21:51:05,653 | DEBUG    dsmr_backend.initialize:25 | Persistent clients initialized: [<class 'paho.mqtt.client.Client'>]
2021-05-10 21:51:05,653 | DEBUG    mixins.run_loop:65 | dsmr_backend.management.commands.dsmr_backend: Starting infinite command loop...
2021-05-10 21:51:05,655 | DEBUG    schedule.execute_scheduled_processes:28 | SP: 0 backend service(s) ready to run
2021-05-10 21:51:05,659 | DEBUG    persistent_clients.run:30 | CLIENTS: Running 1 active client(s)
2021-05-10 21:51:05,662 | INFO     broker.run:71 | MQTT: Processing 17 message(s)
2021-05-10 21:51:05,662 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#209007) for dsmr/reading/id: 59659909
2021-05-10 21:51:05,662 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m1), 'b'dsmr/reading/id'', ... (8 bytes)
2021-05-10 21:51:05,662 | DEBUG    broker.run:84 | MQTT: Waiting for message (#209007) to be marked published
2021-05-10 21:51:05,662 | DEBUG    broker.run:88 | MQTT: Deleting published message (#209007) from queue
2021-05-10 21:51:05,663 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#209006) for dsmr/reading/phase_currently_delivered_l1: 0.497
2021-05-10 21:51:05,664 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m2), 'b'dsmr/reading/phase_currently_delivered_l1'', ... (5 bytes)
2021-05-10 21:51:05,664 | DEBUG    broker.run:84 | MQTT: Waiting for message (#209006) to be marked published
2021-05-10 21:51:05,664 | DEBUG    broker.run:88 | MQTT: Deleting published message (#209006) from queue
2021-05-10 21:51:05,665 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#209005) for dsmr/reading/electricity_currently_delivered: 0.497
2021-05-10 21:51:05,665 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m3), 'b'dsmr/reading/electricity_currently_delivered'', ... (5 bytes)
2021-05-10 21:51:05,665 | DEBUG    broker.run:84 | MQTT: Waiting for message (#209005) to be marked published
2021-05-10 21:51:05,665 | DEBUG    broker.run:88 | MQTT: Deleting published message (#209005) from queue
2021-05-10 21:51:05,666 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#209004) for dsmr/reading/timestamp: 2021-05-10T19:50:03Z
2021-05-10 21:51:05,666 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m4), 'b'dsmr/reading/timestamp'', ... (20 bytes)
2021-05-10 21:51:05,667 | DEBUG    broker.run:84 | MQTT: Waiting for message (#209004) to be marked published
2021-05-10 21:51:05,667 | DEBUG    broker.run:88 | MQTT: Deleting published message (#209004) from queue
2021-05-10 21:51:05,668 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#209003) for dsmr/meter-stats/voltage_swell_count_l3: None
2021-05-10 21:51:05,668 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m5), 'b'dsmr/meter-stats/voltage_swell_count_l3'' (NULL payload)
2021-05-10 21:51:05,668 | DEBUG    broker.run:84 | MQTT: Waiting for message (#209003) to be marked published
2021-05-10 21:51:05,668 | DEBUG    broker.run:88 | MQTT: Deleting published message (#209003) from queue
2021-05-10 21:51:05,669 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#209002) for dsmr/meter-stats/voltage_swell_count_l2: None
2021-05-10 21:51:05,669 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m6), 'b'dsmr/meter-stats/voltage_swell_count_l2'' (NULL payload)
2021-05-10 21:51:05,669 | DEBUG    broker.run:84 | MQTT: Waiting for message (#209002) to be marked published
2021-05-10 21:51:05,669 | DEBUG    broker.run:88 | MQTT: Deleting published message (#209002) from queue
2021-05-10 21:51:05,670 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#209001) for dsmr/meter-stats/voltage_sag_count_l3: None
2021-05-10 21:51:05,670 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m7), 'b'dsmr/meter-stats/voltage_sag_count_l3'' (NULL payload)
2021-05-10 21:51:05,670 | DEBUG    broker.run:84 | MQTT: Waiting for message (#209001) to be marked published
2021-05-10 21:51:05,670 | DEBUG    broker.run:88 | MQTT: Deleting published message (#209001) from queue
2021-05-10 21:51:05,671 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#209000) for dsmr/meter-stats/voltage_sag_count_l2: None
2021-05-10 21:51:05,672 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m8), 'b'dsmr/meter-stats/voltage_sag_count_l2'' (NULL payload)
2021-05-10 21:51:05,672 | DEBUG    broker.run:84 | MQTT: Waiting for message (#209000) to be marked published
2021-05-10 21:51:05,672 | DEBUG    broker.run:88 | MQTT: Deleting published message (#209000) from queue
2021-05-10 21:51:05,673 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#208999) for dsmr/reading/id: 59659908
2021-05-10 21:51:05,673 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m9), 'b'dsmr/reading/id'', ... (8 bytes)
2021-05-10 21:51:05,673 | DEBUG    broker.run:84 | MQTT: Waiting for message (#208999) to be marked published
2021-05-10 21:51:05,673 | DEBUG    broker.run:88 | MQTT: Deleting published message (#208999) from queue
2021-05-10 21:51:05,674 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#208998) for dsmr/reading/phase_currently_returned_l3: None
2021-05-10 21:51:05,674 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m10), 'b'dsmr/reading/phase_currently_returned_l3'' (NULL payload)
2021-05-10 21:51:05,674 | DEBUG    broker.run:84 | MQTT: Waiting for message (#208998) to be marked published
2021-05-10 21:51:05,674 | DEBUG    broker.run:88 | MQTT: Deleting published message (#208998) from queue
2021-05-10 21:51:05,676 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#208997) for dsmr/reading/phase_currently_returned_l2: None
2021-05-10 21:51:05,676 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m11), 'b'dsmr/reading/phase_currently_returned_l2'' (NULL payload)
2021-05-10 21:51:05,676 | DEBUG    broker.run:84 | MQTT: Waiting for message (#208997) to be marked published
2021-05-10 21:51:05,676 | DEBUG    broker.run:88 | MQTT: Deleting published message (#208997) from queue
2021-05-10 21:51:05,677 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#208996) for dsmr/reading/phase_currently_delivered_l3: None
2021-05-10 21:51:05,677 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m12), 'b'dsmr/reading/phase_currently_delivered_l3'' (NULL payload)
2021-05-10 21:51:05,677 | DEBUG    broker.run:84 | MQTT: Waiting for message (#208996) to be marked published
2021-05-10 21:51:05,677 | DEBUG    broker.run:88 | MQTT: Deleting published message (#208996) from queue
2021-05-10 21:51:05,678 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#208995) for dsmr/reading/phase_currently_delivered_l2: None
2021-05-10 21:51:05,678 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m13), 'b'dsmr/reading/phase_currently_delivered_l2'' (NULL payload)
2021-05-10 21:51:05,679 | DEBUG    broker.run:84 | MQTT: Waiting for message (#208995) to be marked published
2021-05-10 21:51:05,679 | DEBUG    broker.run:88 | MQTT: Deleting published message (#208995) from queue
2021-05-10 21:51:05,679 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#208994) for dsmr/reading/phase_currently_delivered_l1: 0.499
2021-05-10 21:51:05,680 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m14), 'b'dsmr/reading/phase_currently_delivered_l1'', ... (5 bytes)
2021-05-10 21:51:05,680 | DEBUG    broker.run:84 | MQTT: Waiting for message (#208994) to be marked published
2021-05-10 21:51:05,680 | DEBUG    broker.run:88 | MQTT: Deleting published message (#208994) from queue
2021-05-10 21:51:05,681 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#208993) for dsmr/reading/electricity_currently_delivered: 0.499
2021-05-10 21:51:05,681 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m15), 'b'dsmr/reading/electricity_currently_delivered'', ... (5 bytes)
2021-05-10 21:51:05,681 | DEBUG    broker.run:84 | MQTT: Waiting for message (#208993) to be marked published
2021-05-10 21:51:05,681 | DEBUG    broker.run:88 | MQTT: Deleting published message (#208993) from queue
2021-05-10 21:51:05,682 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#208992) for dsmr/reading/electricity_delivered_1: 5819.958
2021-05-10 21:51:05,682 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m16), 'b'dsmr/reading/electricity_delivered_1'', ... (8 bytes)
2021-05-10 21:51:05,682 | DEBUG    broker.run:84 | MQTT: Waiting for message (#208992) to be marked published
2021-05-10 21:51:05,682 | DEBUG    broker.run:88 | MQTT: Deleting published message (#208992) from queue
2021-05-10 21:51:05,684 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#208991) for dsmr/reading/timestamp: 2021-05-10T19:50:02Z
2021-05-10 21:51:05,684 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending PUBLISH (d0, q0, r1, m17), 'b'dsmr/reading/timestamp'', ... (20 bytes)
2021-05-10 21:51:05,684 | DEBUG    broker.run:84 | MQTT: Waiting for message (#208991) to be marked published
2021-05-10 21:51:05,684 | DEBUG    broker.run:88 | MQTT: Deleting published message (#208991) from queue
2021-05-10 21:51:05,689 | WARNING  broker.signal_reconnect:102 | MQTT: Client no longer connected. Signaling restart to reconnect...
2021-05-10 21:51:05,690 | ERROR    persistent_clients.run:37 | CLIENTS: Run error: MQTT: Client no longer connected
2021-05-10 21:51:05,691 | WARNING  dsmr_backend._check_restart_required:46 | Detected backend restart required, stopping process...
2021-05-10 21:51:05,691 | INFO     mixins.run_once:96 | dsmr_backend.management.commands.dsmr_backend: [i] Detected StopInfiniteRun exception
2021-05-10 21:51:05,692 | INFO     mixins._stop:128 | dsmr_backend.management.commands.dsmr_backend: Exiting on next run...
2021-05-10 21:51:05,692 | DEBUG    mixins.run_loop:73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-05-10 21:51:06,693 | DEBUG    persistent_clients.terminate:42 | CLIENTS: Terminating 1 client(s)
2021-05-10 21:51:06,693 | DEBUG    broker.on_log:146 | MQTT: (Paho on_log) Sending DISCONNECT
2021-05-10 21:51:06,694 | DEBUG    broker.on_disconnect:132 | MQTT: (Paho on_disconnect) 0
2021-05-10 21:51:06,694 | DEBUG    mixins.handle:55 | dsmr_backend.management.commands.dsmr_backend: Exited

Ik zie er niet direct iets mis gaan. backend-sleep stond hier overigens nog op 1 seconde.

[dennissiemensma]

Oke mooi dat je dat werkend heb. Nu ben je op zoek naar een manier om zowel deze log in de gaten te houden als de log van de datalogger.

Dan kun je zien hoelang het duurt voordat je het bericht dat je in de datalogger ziet verschijnen vervolgens in de MQTT log ziet. Want dan kun je de conclusie trekken of er nog een (te grote) vertraging in DSMR-reader zit of niet.

Het makkelijkste is om 1 veld in de gaten te houden wat constant verandert en uniek is, dus de datumtijd (los van of die inhoudelijk klopt).

MQTT

Voor de MQTT log zou je zoiets kunnen doen:

tail -f naam_backend_logfile | grep 'Publishing queued message' | grep 'dsmr/reading/timestamp'

Je ziet dan als het goed is alleen deze regels:

2021-05-10 21:51:05,684 | DEBUG    broker.run:74 | MQTT: Publishing queued message (#208991) for dsmr/reading/timestamp: 2021-05-10T19:50:02Z

Datalogger

Voor de log van de remote datalogger weet ik niet precies hoe dat er uit ziet, maar ik lees wel dit: https://github.com/trizz/dsmr-remote-datalogger#usage

Log files are being written to /etc/dsmr_logs in the container. Override this location if you want to keep logfiles between containers or have easy access to them: -v /path/on/host:/etc/dsmr_logs

Als daar de ruwe telegrammen in komen die die leest, kun je die ook tailen en dan greppen op het datumtijd veld:

tail -f logfile | grep '0-0:1.0.0'

---

Als het goed is kun je nu beide logfiles volgens en kun je goed zien wanneer je een datumtijd in de datalogger-logfile ziet en hoelang het (ongeveer) duurt voordat je die in de andere log van uitgaande MQTT-berichten ziet. Ik zou verwachten dat daar hooguit enkele seconden tussen zit.

[dennissiemensma]

Je zou trouwens in DSMR-reader ook deze tijdelijk aan kunnen zetten, zonder hem daadwerkelijk uit te lezen uit je MQTT broker: /admin/dsmr_mqtt/rawtelegrammqttsettings/

Dat is het ruwe telegram en dan is het wellicht nog extra gemakkelijk om beide logs naast elkaar te leggen en te zien wanneer een telegram gelezen wordt en wanneer die verstuurd wordt via MQTT.

[dennissiemensma]

Ik zie trouwens onderaan je log:

MQTT: Client no longer connected. Signaling restart to reconnect...

Ik zie niet zo 1-2-3 een oorzaak, maar had je daar zelf iets herstart? En zo nee, zie je die foutmelding vaker?

[oetelaar24]

De remote datalogger geeft dit als ik de telegram dump door de code even aan te passen:

`[2021-05-10 21:22:41,436 - ERROR] Sent telegram: /Ene5\XS210 ESMR 5.0

1-3:0.2.8(50) 0-0:1.0.0(210510232138S) 0-0:96.1.1(4530303437303030303339383935363138) 1-0:1.8.1(005820.913kWh) 1-0:1.8.2(003249.568kWh) 1-0:2.8.1(001079.282kWh) 1-0:2.8.2(002366.589kWh) 0-0:96.14.0(0001) 1-0:1.7.0(00.499kW) 1-0:2.7.0(00.000kW) 0-0:96.7.21(00030) 0-0:96.7.9(00002) 1-0:99.97.0(1)(0-0:96.7.19)(200414110128S)(0000000199s) 1-0:32.32.0(00002) 1-0:32.36.0(00000) 0-0:96.13.0() 1-0:32.7.0(236.0V) 1-0:31.7.0(002A) 1-0:21.7.0(00.499kW) 1-0:22.7.0(00.000kW) 0-2:24.1.0(003) 0-2:96.1.0(4730303539303033383132313837353138) 0-2:24.2.1(210510232000S)(02261.943m3) !DF3E`

Dat doet me dan toch vermoeden dat de timestamp van de telegrams uit de P1 al afwijken?

De waarde in 1-0:21.7.0, is het actuele verbruik, toch? Zou ik die direct moeten kunnen vergelijken met wat ik op het LCD van de slimme meter kan zien bij actueel verbruik?

Okay, ik heb even de log naast de meter gehouden, maar omdat het verbruik steeds een klein beetje schommelde was het lastig om te zien wat de vertraging is tussen de Meter's LCD waarde en de DSMR Datalogger Telegram... Gelukkig had ik een remote schakelbare hoge load (een elektrische oven), waarmee ik duidelijk kan zien wanneer de nieuwe belasting/change doorkomt... Er zit een 4-5sec vertraging tussen LCD en Telegram-data... Dat is mogelijk normaal/te verwachten? Maar nowhere near die ongeveer 1 minuut dus. Dus dat lijkt te bevestigen dat de timestamp van de slimme meter zelf afwijkt van de actuele tijd... Dat wordt dus even bellen met de leverancier, of de override inschakelen?

[dennissiemensma]

Ik denk dat je het inhoudelijke tijdstip als laatste moet tacklen. Voor nu ben je eerst op zoek naar hoelang het duurt van het verbruik (~4 seconden dus) tot het telegram uitlezen in de datalogger totdat het telegram verstuurd wordt via MQTT. Want als dat alsnog te lang duurt, kun je overriden wat je wilt, je krijgt dan nog steeds geen real-time data. En daar was je naar op zoek toch? Of dat uberhaupt via de slimme meter/dsmrreader snel genoeg kan?

[dennissiemensma]

Overigens synchroniseert de klok in de slimme meter wel af en toe, maar dat is dus het minste probleem en kun je idd in dsmrreader (of je script dat MQTT uitleest) overschrijven.

[oetelaar24]

Ik denk dat je het inhoudelijke tijdstip als laatste moet tacklen. Voor nu ben je eerst op zoek naar hoelang het duurt van het verbruik (~4 seconden dus) tot het telegram uitlezen in de datalogger totdat het telegram verstuurd wordt via MQTT. Want als dat alsnog te lang duurt, kun je overriden wat je wilt, je krijgt dan nog steeds geen real-time data. En daar was je naar op zoek toch? Of dat uberhaupt via de slimme meter/dsmrreader snel genoeg kan?

Nou, dat issue van die 4 seconden is dus al zichtbaar tussen de LCD op de Meter zelf, en de debug-output van de datalogger script op de pi die met de meter verbonden is... Ik weet niet wat ik daar nog aan kan doen...

Edit: True, ik zou graag real-time data hebben, maar is dat mogelijk?

[oetelaar24]

Ik zie trouwens onderaan je log:

MQTT: Client no longer connected. Signaling restart to reconnect...

Ik zie niet zo 1-2-3 een oorzaak, maar had je daar zelf iets herstart? En zo nee, zie je die foutmelding vaker?

Ik heb hier nog even naar gekeken, en zag deze melding ook wel in de logs van de vorige versie, maar nu komt ie elke 2 sec voor. Daarvoor alleen bij herstart van de MQTT server..

De melding is trouwens in v4.16 iets anders: 2021-05-11 10:12:37,876 | ERROR persistent_clients.run:37 | CLIENTS: Run error: MQTT: Client no longer connected

Ik zie dat ook terug in mijn Mosquitto logs, continue een nieuwe login. Is dat niet wat zonde van de overhead om telkens een nieuwe verbinding op te zetten en weer af te tuigen, elke seconde?

[dennissiemensma]

Nou, dat issue van die 4 seconden is dus al zichtbaar tussen de LCD op de Meter zelf, en de debug-output van de datalogger script op de pi die met de meter verbonden is... Ik weet niet wat ik daar nog aan kan doen...

Ik ben nog steeds benieuwd naar de totale tijd tussen de datalogger en MQTT, dus los van het display. Had je die ook al kunnen meten?

Want als daar ook nog (veel) vertraging in zit dan valt daar wellicht nog wat te winnen.

[dennissiemensma]

Ik zie dat ook terug in mijn Mosquitto logs, continue een nieuwe login. Is dat niet wat zonde van de overhead om telkens een nieuwe verbinding op te zetten en weer af te tuigen, elke seconde?

Dit is ook niet hoe het hoort te werken. Ik zie nu dat dat een bijeffect is van de rework. Ik zal het fixen en een patch release maken.

Workaround voor nu is om Quality of Service 2 te gebruiken.

[oetelaar24]

Nou, dat issue van die 4 seconden is dus al zichtbaar tussen de LCD op de Meter zelf, en de debug-output van de datalogger script op de pi die met de meter verbonden is... Ik weet niet wat ik daar nog aan kan doen...

Ik ben nog steeds benieuwd naar de totale tijd tussen de datalogger en MQTT, dus los van het display. Had je die ook al kunnen meten?

Want als daar ook nog (veel) vertraging in zit dan valt daar wellicht nog wat te winnen.

Zojuist nog even naast elkaar gehouden. Ik kijk dan naar een dump van het Telegram door de datalogger op de pi (extra logregel in het script) versus de timestamp in het MQTT topic via MQTT Explorer. Daar zie ik, als er al een vertraging is, hooguit een halve seconde tussen zitten. (Dit is al met de workaround van QOS 2)

[dennissiemensma]

Oke dat is mooi om te horen! Dat betekent dat het erop lijkt dat je uiteindelijk slechts met een vertraging van 4, 5, 6 seconden moet werken tov het display. Niet helemaal realtime, maar ook zeker werkbaar toch?

De minuut vertraging die je ervaart bestaat dan vooral uit het verschil in interne klok van de meter tov systeemtijd. Het is dan aan jezelf om te kijken of je het tijdstip wilt laten overschrijven door DMSR-reader of dat dat uberhaupt niet nodig is. Dat laatste hangt denk ik af van hoe je exact de verwerking doet van de gegevens tussen je inverter en uit DSMR-reader.

[dennissiemensma]

En QoS level 2 is trouwens ook vrij zwaar, omdat er vier netwerkberichten heen en weer gaan voordat 1 MQTT-bericht gepubliceerd is.

Na de fix release kun je weer QoS 0 gebruiken, hoewel ik denk dat dat (op een stabiel netwerk) hooguit eerder milliseconden scheelt dan bijvoorbeeld een seconde oid. Maar dat kun je dan later proberen.

[oetelaar24]

Ja, ik denk wel dat het werkbaar, is, maar om de berekeningen zo goed mogelijk kloppend te maken. Zou ik natuurlijk een meting van mijn inverter en de slimme meter van hetzelfde tijdstip moeten hebben om dit te kunnen verrekenen. Zeker wanneer er bv een wolk voorbijkomt, of het verbruik omhoog of omlaag schiet, is een skew van 4-6 seconden in elk geval voor die tijdspanne quircky..

Ik gebruik uiteindelijk Home Assistant om alles samen te laten komen, en daar maak ik ook die verrekening van (solar.opgewekteEnergie - dsmr.teruggeleverdeEnergie). Als ik de meting van de solar inverter bv zou kunnen vertragen met die 4-6 sec delay die ik ervaar tussen de meter en hass, dan ben ik er :) Alleen heb ik nog geen mogelijkheid gevonden om dat te doen... Of heb je wellicht plannen om met DSMR in de toekomst ook solar-inverters uit te lezen? :-P

[dennissiemensma]

Ik zit niet heel diep in deze materie qua teruglevering/verbruik in de praktijk (ik heb zelf geen teruglevering), maar je zou ook nog naar PVOutput kunnen kijken. Er zijn gebruikers die daar zowel netto verbruik uit DSMR-reader als bruto teruglevering van de omvormer naar uploaden en daar "iets" mee laten doen of er iets uithalen. Je zou nog o.a. #9 kunnen doorlezen (ergens in het midden staan overigens 87 comments ingeklapt). En ook iets met een "vertraging" bij uploaden naar PVOutput, zodat die er rekening mee houdt, maar wellicht zat dat in een andere topic/issue en mogelijk was daar ook jaarlijkse bijdrage/donatie aan PVOutput nodig. Hoe dan ook wel leuk om even door te lezen.

Verder is het interessant om te weten dat bij onze zuiderburen vanaf volgend jaar iets per kwartier gemeten/gerekend wordt. Ik zit niet helemaal (meer) in de stof en kijk er in het najaar weer naar, maar hier staat het in #1084. Het gaat natuurlijk niet op voor NL, maar ongeacht wat je plannen of bedoelingen zijn met je realtime data, geeft het je wellicht nog andere inzichten of ideeen.

[dennissiemensma]

Of heb je wellicht plannen om met DSMR in de toekomst ook solar-inverters uit te lezen? :-P

En nee, dit is bewust buiten DSMR-reader gehouden om te voorkomen dat het zo groot en ononderhoudbaar wordt, dat het project uiteindelijk verzandt in iets wat "oppervlakkig veel dingen doet". Plus dat ik daar dus meer een rol zie in PVOutput, een platform helemaal gericht op teruglevering en alles. Ik richt me dan liever op specifieke features, direct gerelateerd aan het uitlezen van de slimme meter en ondersteun wat generieke methodes om data te exporteren, zoals MQTT.

[oetelaar24]

Groot gelijk heb je. Interessante materie! Ik ga me er eens in verdiepen. Hartelijk dank!

[dennissiemensma]

De fix voor het onbedoeld herstarten in QoS 0 zit nu als het goed is in release v4.16.1

[oetelaar24]

Ik heb zojuist geupgrade naar v4.16.1. Uit nieuwsgierigheid ben ik nog even de logfiles gaan controleren. Inderdaad op QoS 0 wordt deze melding niet meer gelogd.

Wel zie ik in dezelfde log (dsmr_backend.log) veel meldingen verschijnen: message_info.is_published() True message_info.is_published() True message_info.is_published() True message_info.is_published() True message_info.is_published() True message_info.is_published() True message_info.is_published() True message_info.is_published() True message_info.is_published() True message_info.is_published() True message_info.is_published() True

In dsmr_datalogger.log wordt overigens ook continue gelogt: Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging

Ik stel de vraag even omdat ik me afvraag of dit verwacht gedrag is? Ik kan me voorstellen dat deze logging niet veel meerwaarde heeft en dus een negatieve impact kan hebben op performance en disk usage?

[dennissiemensma]

Bedankt voor je melding. Dat is een debug-statement die ik gebruikt heb voor het schrijven van de tests gisteravond en die is per ongeluk meegekomen. Ik zal er een fix-release voor maken.