Dsmr-reader: python3 command - cpu usage 99%

[mkruiver]

After installing DSMR-reader on my Pi3, the cpu usage of the dsmr user spikes to 99%. The cpu load of the python3 command rises to 99% for about one second, drops off to 0.7,% only to rise back up to 90% within 1-2 seconds. This seems related to telegram readouts? This does not seem normal and other users have reported way lower cpu usage, even on a Pi2. Can you assist in debugging?

[dennissiemensma]

Hi, thank you for reporting this issue.

• Can you see which python3 process is hogging? Is it dsmr_datalogger?
• Can you dump the output of the top command here?
• Can you install and run htop (sudo apt-get install htop) and dump that output as well? (screenshot is easiest I guess)

[Jeltel]

I had the same behaviour just yet. After a reboot the backend as well as the datalogger are one second nothing, the next 100%.
A reboot solved it.

[dennissiemensma]

Did you save a dump of the top output?

I cannot reproduce this myself, so I'm relying on input :]

[Jeltel]

Nope. Next time I will.

[mkruiver]

I have some data, usage seems a bit lower since rebooting, but still.

https://kruiver.stackstorage.com/s/txJEgTSyKFVpJPn

https://kruiver.stackstorage.com/s/v1V8R0I7CYSbPjC

https://kruiver.stackstorage.com/s/tG7wFlZsjK9H1CX

Also, about 50% of all telegrams are rejected due to bad CRC:

TELEGRAM READINGS
Total reading count
The number of P1 DSMR telegrams read and stored in the application. 34,043
Number of rejected telegrams due to invalid CRC checksum 34,650

[dennissiemensma]

Thanks for providing this info, it's very helpful!

The dsmr_datalogger process shouldn't consume that much CPU. But it does not stale your system at the time of the screenshots. You can see in top that both your load (0.62) is very low and cpu idle (77.4%) is high (doing nothing), but that's only systeem wide and those numbers are good.

However, 50% telegram rejection is ridiculous and it definitely indicates that something is wrong with the connection to your smart meter. Another user with a 5 meter long cable didn't even seem to have that much rejection, by far.

If half of the data is corrupt than it might also explain why the datalogger is hogging. It constantly seeks for the start and endings of telegrams, but if they can't be found it might hammer the connection a bit.

Can you describe how your smart meter is connected to your Pi? Or whatever solution you are running?
You might want to check for any power adapters near the cable, as they can cause jamming to the signal.

[mkruiver]

Hiermee
https://www.sossolutions.nl/slimme-meter-kabel

Just replugged the connection and rebooted the pi, no change. The cable 'trajectory' is free of interference.

[dennissiemensma]

Can you tail the output of the dsmr_datalogger command for 30 seconds or so? I'd like to see the output, as it should be logging what it reads as well.

• Tailing logs: sudo supervisorctl tail -f dsmr_datalogger

Please remove the serial numbers of your devices before posting the logs here. They are long strings of (~34) digits. If you have a smart gas meter as well, there are two serial numbers per telegram.

[Jeltel]

For reference: I'm using the same cable.

[dennissiemensma]

I'm using one of their cables as well, but I've only had 1 rejected telegram out of 33600+ readings in the past days.

[Jeltel]

I have 42 errors out of 192.950 (way more than you btw)

[dennissiemensma]

Yeah, but it's only 0,02 % of your total readings so still nice... :]

[mkruiver]

TELEGRAM READINGS
Total reading count
The number of P1 DSMR telegrams read and stored in the application. 44,224
Number of rejected telegrams due to invalid CRC checksum 46,351

TELEGRAM READINGS
Total reading count
The number of P1 DSMR telegrams read and stored in the application. 44,314
Number of rejected telegrams due to invalid CRC checksum 46,432

log is here:
https://kruiver.stackstorage.com/s/jbqHbPb7y2RFmbj

Let me know if I filtered the wrong items, I think I also filtered some timestamps :)

[dennissiemensma]

I think I know what's wrong! You have the privilege of running a smart meter with the latest DSMR-firmware, version 5. I have not seen that before yet, only heard that they were installed now.

The telegram is starting with:
1-3:0.2.8(50) (v5.0)

While I'm having:
1-3:0.2.8(42) (v4.2)

Could you email me an unfiltered telegram to github @ dennissiemensma.nl? Then I can analyze it to see whether the version-difference is causing this, and possibly fix it as well.

[dennissiemensma]

Bedankt voor het opsturen van de gegevens. Helaas krijg ik ze lokaal in mijn testomgeving ook niet werkend (tot nu toe twee metingen daaruit gepakt) qua CRC-checksum. Het gekke is dat de data verder goed lijkt.

Ik heb tevens in de documentatie van Netbeheer gekeken: Dutch Smart Meter Requirements v5.0.2 Final P1.pdf. Maar daar kon ik ook niet zo 1-2-3 iets zien dat anders is.

Wat ook nog een dingetje is is dat er blijkbaar wel goede telegrammen aankomen, die door de CRC-check komen. Ik denk dat er nog meer logging nodig is en daarnaast zal ik ervoor zorgen dat de CRC-check handmatig uitgezet kan worden (#224).
Het is mij nu namelijk niet helemaal duidelijk of je oorspronkelijke probleem (CPU-verbruik) komt doordat DSMR v5 de metingen elke seconde stuurt of door de falende CRC-check.

Overigens mag er uberhaupt ondersteuning komen voor het vaker opslaan van gasmetingen, dat doe ik via #221.

Ik zal komende dagen werken aan een nieuwe patch (v1.5.2) die mogelijk wat meer opheldering geeft.

[ThinkPadNL]

Misschien is de methode voor de CRC gewijzigd? Bij DSMR4 is dat crc16 dacht ik, wellicht dat het bij DSMR5 anders is?

Wel gaaf trouwens, vooral dat je gas elke minuut doorkrijgt is wel erg handig met inregelen van CV-ketel bijv. Op die manier kun je een stuk hogere resolutie krijgen.

[dennissiemensma]

Zie de docs in mijn vorige comment. Voor zover ik kan zien wijken ze niet af qua CRC. Alleen geeft de reporter aan dat 50% van de data faalt en de logs maken daar nu geen onderscheid in. Ik wil graag weten waar dat in zit, omdat ik het voorbeeld in de docs ook niet gevalideerd krijg (en ik niet weet of die CRC-proof is).

[dennissiemensma]

Ik heb nu #224 klaar en daar zit o.a. veel betere logging in. Hiermee is als het goed is exact te zien welke telegrammen geldig zijn en welke niet. En mogelijk ook waarom.

Dit draait nu een dagje bij mij in productie en wanneer dat goed gaat komt de patch uit (waarschijnlijk morgen dus), samen met wat andere kleine dingetjes.

[dennissiemensma]

@mkruiver de patch met de logging is klaar. Wil je upgraden naar v1.5.2?

Vervolgens zou je hiermee betere logs moeten inzien:

sudo su - dsmr

tail -f logs/dsmrreader.log 

(CTRL + C om het tailen af te breken)

Je ziet daar als het goed is metingen in een wat raar formaat verschijnen. Dat is base64 en zorgt ervoor dat alle data exact wordt bewaard zoals het binnenkomt (inclusief eventuele rare tekens).

Ik ben benieuwd of je daar ook foutmetingen ziet. Omdat ik het niet hier kan reproduceren zie ik overal:
Received telegram (base64 encoded): b'blablablablabla'

Foutmeldingen verwacht ik in dit formaat:
Rejected telegram (base64 encoded): b'blablablablabla'

Gecombineerd met een van deze meldingen daaronder:

• Content or CRC data not found
• CRC mismatch: X (telegram) != Y (calculated)

Wil je eens een kijken of dat ook gebeurt? En zo ja, zowel een goede als foute meting mailen?

[dennissiemensma]

Ik heb overigens (los van het CRC-probleem) nu ook een beter vermoeden waar die hoge CPU-usage vandaan komt.

De datalogger is gemaakt voor DSMR v4 en die stuurt elke 10 seconden een bericht. Dus de datalogger opent de seriele verbinding, leest gegevens en sluit hem weer.
Dat gaat prima wanneer dat elke 10 seconden is. Alleen in DSMR v5 denk ik dat de overhead van het openen van de seriele verbinding te veel is, omdat hij dat élke seconde doet. En dat soort operaties (I/O) zijn vaak relatief zwaar.

Ik ga dit in #221 meenemen zodat de verbinding (langer) open blijft.

[mkruiver]

Ik heb net ge-update en het lijkt dat de rejected telegram count (CRC-failed) nu ineens naar de 80% is gegaan ipv 50%. Log file zal ik mailen.

[dennissiemensma]

Bedankt voor de logs. Ik kijk er morgen naar, idem voor MinderGas. Ik zag in ieder geval al (even snel) logregels met zowel 'goede' als 'foute' telegrams dus ik ben benieuwd.

Momenteel ben ik wat minder fit dus morgen nieuwe kansen.

[mkruiver]

ok, beterschap en bedankt voor je dev-werk!

[mkruiver]

Even though the CRC-failed count increased, the cpu-load is down to 3% after upgrading from 1.5 to 1.5.2. I am now going to try 1.5.3.

CPU load is still low in 1.5.3. The number of CRC rejects is still at 70% or something.

[dennissiemensma]

Wat betreft de falende CRC's, ik ben er ook uit wat het is. Het lijkt erop dat de datalogger, in een hoop gevallen, twee telegrammen elkaar laat overlappen. Hieronder zie je de vergelijking tussen twee van je telegrammen, links een goede rechts een 'foute'.

Blauwe/oranje highlights zijn de verschillen en een deel heb ik zelf geselecteerd in het oranje. En dat oranje gedeelte is eigenlijk exact het gedeelte waardoor de validatie fout gaat. Het is dubbele data.

Ik heb alleen geen verklaring waarom dit gebeurt. Vermoedelijk door het constant openen en sluiten van de verbinding. Alleen dan nog zou ik niet verwachten dat de seriele kabel simpelweg een telegram afbreekt en verdergaat met de volgende.

Vermoedelijk zit de oplossing in oa dit comment en het ticketnummer daarin.

In een van de eerdere patches is er ook de mogelijkheid om CRC uit te zetten. Wanneer bovenstaande situatie voorkomt zonder CRC-check gaat het goed zie ik. Want de DSMR-parser leest van boven naar beneden en overschrijft (onbewust) dubbele waarden. Alleen kan ik je niet aanraden om CRC uit te zetten, want het is alsnog mogelijk dat er foute data binnenkomt, los van dit probleem.

Kun je aangeven in hoeverre er nu wel data binnenkomt? Blijft er tenminste 1 meting per minuut 'goed', zodat je in ieder geval enigzins inzage hebt in de gegevens?

[mkruiver]

Ja er komt nog wel data binnen, worst case is 1-2 per minuut, meestal wat meer gelukkig!

[dennissiemensma]

Ik heb waarschijnlijk een oplossing voor eerdergenoemd probleem in patch v1.5.4. Laat maar weten of dat helpt.

[mkruiver]

CPU load is laag in 1.5.4 en de afgelopen paar minuten zijn er geen CRC failed telegrams meer bijgekomen! Win!

[dennissiemensma]

Fijn om te horen. Tot slot:

• Je kunt de teller van de gefaalde telegrammen resetten op 0 met:

sudo -u postgres psql dsmrreader -c "update dsmr_datalogger_meterstatistics set rejected_telegrams = 0 where id = 1;"

• Houd even goed je disk space in de gaten (df -h). Doordat dit project officieel (nog) geen DSMR v5 ondersteunt, kan het zijn dat je database sneller volloopt. Je krijgt namelijk tot 10 x zoveel metingen binnen als waar ik ooit rekening mee heb gehouden. Technisch maakt dat overigens niet uit, maar het kan wel invloed hebben op bijvoorbeeld je SD-kaart.

[mkruiver]

Top, al meer dan 24 uur geen rejected telegrams meer, de teller staat nog
steeds op 0 (of eigenlijk, niet in beeld)!

On Jan 13, 2017 09:06, "Dennis Siemensma" [e-mail] wrote:

Fijn om te horen. Tot slot:

• Je kunt de teller van de gefaalde telegrammen resetten op 0 met:

sudo -u postgres psql dsmrreader -c "update dsmr_datalogger_meterstatistics
set rejected_telegrams = 0 where id = 1;"

• Houd even goed je disk space in de gaten (df -h). Doordat dit
  project officieel geen DSMR v5 ondersteunt, kan het zijn dat je database
  sneller volloopt. Je krijgt namelijk tot 10 x zoveel metingen binnen als
  waar ik ooit rekening mee heb gehouden. Technisch maakt dat overigens niet
  uit, maar het kan wel invloed hebben op bijvoorbeeld je SD-kaart.

—
You are receiving this because you modified the open/close state.
Reply to this email directly, view it on GitHub
https://github.com/dennissiemensma/dsmr-reader/issues/212#issuecomment-272384358,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ADp5__XVRAMPmn551J_2po6KVCXRdjGWks5rRzCKgaJpZM4LZdPr
.