search

dsmrreader / dsmr-reader

DSMR-telegram reader & data visualizer for hobbyists. Free for non-commercial use.
https://dsmr-reader.readthedocs.io
Other
460 stars 95 forks source link

Slow live graphs #1069

Closed Konijntjes-nl closed 4 years ago

Konijntjes-nl commented 4 years ago

DSMR-reader versie: v4.1 Type RaspberryPi or server: intel nuc celeron N2820 ( Ubuntu 20.04.1 ) Standaardinstallatie of Docker: Standaard DSMR-protocol slimme meter v4/v5: V5 - Landis+Gyr E360 SMR 5.0

Na de update van v4.1 gaat de cpu verbruik van 1 core naar 100% als je de live graphs opend. Het duurt 20/30 seconden voordat er iets in de live graphs komt

Het process van de webinterface heeft hier last van. Hier is een screenshot van htop htop

dennissiemensma commented 4 years ago

Bedankt voor je melding. Dit kan door verschillende oorzaken komen, maar ik vermoed dat het door de hoeveelheid data komt.

Kan het zijn dat je in de instellingen van de grafieken een (relatief) hoog percentage hebt ingesteld?

/admin/dsmr_frontend/frontendsettings/1/change/

(onderaan de screenshot) Selection_005

Een andere oorzaak kan zijn dat je zoveel gegevens hebt dat de database er te traag van wordt of dat er indexes in de database missen. Dat is wat lastiger te achterhalen, maar je kunt in ieder geval kijken of je database absurd groot is:

sudo su - postgres
psql dsmrreader

SELECT nspname || '.' || relname AS "relation",
    pg_size_pretty(pg_total_relation_size(C.oid)) AS "total_size"
  FROM pg_class C
  LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace)
  WHERE nspname NOT IN ('pg_catalog', 'information_schema')
    AND C.relkind <> 'i'
    AND nspname !~ '^pg_toast'
  ORDER BY pg_total_relation_size(C.oid) DESC
  LIMIT 20;

Als daar niets uitkomt zullen we even verder moeten zoeken.

Konijntjes-nl commented 4 years ago

Als ik hem op x % zet van 1 uur dan gaat het "goed". De cpu gaat nog wel naar 100% maar het laden gaat wel sneller ( 2/4 seconds ).

Dit is de output van de postgres db

public.dsmr_datalogger_dsmrreading | 1647 MB public.dsmr_consumption_electricityconsumption | 106 MB public.dsmr_consumption_gasconsumption | 2192 kB public.dsmr_stats_hourstatistics | 256 kB public.dsmr_datalogger_meterstatistics | 248 kB public.dsmr_weather_temperaturereading | 232 kB public.dsmr_backend_scheduledprocess | 120 kB public.django_session | 64 kB public.auth_user | 64 kB public.django_admin_log | 64 kB public.django_migrations | 64 kB public.dsmr_frontend_notification | 64 kB public.dsmr_datalogger_dataloggersettings | 56 kB public.dsmr_stats_electricitystatistics | 56 kB public.auth_permission | 56 kB public.dsmr_stats_daystatistics | 56 kB public.dsmr_consumption_energysupplierprice | 40 kB public.django_content_type | 40 kB public.auth_user_groups | 32 kB public.dsmr_mqtt_jsondaytotalsmqttsettings | 32 kB

Ook een downgrade naar 4.0 gedaan. Probleem blijft als de tijd op 24 uur staat.

dennissiemensma commented 4 years ago

Je hebt veel metingen, zie ik maar ook weer niet zo absurd veel. Je kunt sowieso even kijken of je nog indexes mist in je database. 

sudo su - postgres
psql dsmrreader

En dan onderstaande commands. Onderaan de output staan dan de indexes. Kijk of ze overeen komen (qua veldnamen/aantallen) met degene die ik hier onder zet:

\dS dsmr_datalogger_dsmrreading;

...
Indexes:
    "dsmr_datalogger_dsmrreading_pkey" PRIMARY KEY, btree (id)
    "dsmr_datalogger_dsmrreading_9d090a40" btree (processed)
    "dsmr_datalogger_dsmrreading_timestamp_1f7020d1_uniq" btree ("timestamp")

\dS dsmr_consumption_electricityconsumption;

...
Indexes:
    "dsmr_consumption_electricityconsumption_pkey" PRIMARY KEY, btree (id)
    "dsmr_consumption_electricityconsumption_read_at_key" UNIQUE CONSTRAINT, btree (read_at)
    "dsmr_consumption_electrici_phase_power_current_l1_3d9fd70d" btree (phase_power_current_l1)
    "dsmr_consumption_electrici_phase_voltage_l1_72e3c8f8" btree (phase_voltage_l1)
    "dsmr_consumption_electrici_phase_voltage_l2_917726c7" btree (phase_voltage_l2)
    "dsmr_consumption_electrici_phase_voltage_l3_1a9d7c37" btree (phase_voltage_l3)
    "dsmr_consumption_electricityc_currently_delivered_5bf9be2d_uniq" btree (currently_delivered)
    "dsmr_consumption_electricityco_currently_returned_5f91fed7_uniq" btree (currently_returned)
    "dsmr_consumption_electricityconsumption_2241f8ee" btree (phase_currently_delivered_l2)
    "dsmr_consumption_electricityconsumption_5714c500" btree (phase_currently_delivered_l1)
    "dsmr_consumption_electricityconsumption_e90842a6" btree (phase_currently_delivered_l3)

\dS dsmr_consumption_gasconsumption;

...
Indexes:
    "dsmr_consumption_gasconsumption_pkey" PRIMARY KEY, btree (id)
    "dsmr_consumption_gasconsumption_read_at_key" UNIQUE CONSTRAINT, btree (read_at)
dennissiemensma commented 4 years ago

Een ander ding wat je kunt doen is in de log van de Gunicorn (web)server kijken:

/var/log/supervisor/dsmr_webinterface.log

Doorgaans staan er niet veel inhoudelijke foutmeldingen in, maar wie weet.

dennissiemensma commented 4 years ago

En als je helemaal de diepte in wilt duiken, kun je kijken naar de stappen van dit comment: https://github.com/dennissiemensma/dsmr-reader/issues/973#issuecomment-617894061

Met strace ga je dan zien welke systemcalls het webinterface-proces precies doet en waar die (mogelijk) op hangt. Maar dat is wel een vrij harde manier van debugging.

Konijntjes-nl commented 4 years ago

Persoonlijk zie ik niks raars in de database indexes. Kom wel het onderstaande tegen in de logging van de db

2020-08-07 07:07:08.436 UTC [8286] dsmrreader@dsmrreader STATEMENT:  SELECT "dsmr_datalogger_dataloggersettings"."id", "dsmr_datalogger_dataloggersettings"."input_method", "dsmr_datalogger_dataloggersettings"."dsmr_version", "dsmr_datalogger_dataloggersettings"."serial_port", "dsmr_datalogger_dataloggersettings"."network_socket_address", "dsmr_datalogger_dataloggersettings"."network_socket_port", "dsmr_datalogger_dataloggersettings"."process_sleep", "dsmr_datalogger_dataloggersettings"."log_telegrams", "dsmr_datalogger_dataloggersettings"."restart_required" FROM "dsmr_datalogger_dataloggersettings" WHERE "dsmr_datalogger_dataloggersettings"."id" = 1 LIMIT 21

Geen idee of dat iets kan zijn

Als ik strace gebruik zie ik van de onderstaande meldingen langskomen. 

mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb0b2542000

Zelf ben ik niet erg bekend met debugging.

dennissiemensma commented 4 years ago

Bedankt. Het is inderdaad erg diep en lastig om te zien als je niet weet wat je zoekt. Waar ik naar zoek is eigenlijk een bepaalde systeem-call in trace waarop die lijkt te hangen.

Als je het proces in trace volgt en dan in DSMR-reader die webpagina opent, blijft die dan constant vele regels met output spammen? Of, zie je hem voor enkele seconden, of langer, wachten/hangen op iets?

Konijntjes-nl commented 4 years ago

web-24h.log web-1h.log web-6h.log

Heb in de bijlage de strace logging gedaan. Deze zijn op basis van 1/6/24 uur zichtbaar op de grafiek.

Als hij bezig is "hangt" die stil regel 8427 van de 24uurs logging.

Die van 24 uur heb ik moeten stoppen omdat niks meer reageerde. Onderstaande melding is dan zichtbaar in de logging van de webinterface.

[2020-08-08 01:23:59 +0200] [8736] [CRITICAL] WORKER TIMEOUT (pid:20095)

dennissiemensma commented 4 years ago

Bedankt voor de info. Ik denk dat het dan simpel weg om teveel data gaat. Die hint van je in de 24 uurs log zegt veel.

De regel erna is namelijk:

20095 sendto(9, "HTTP/1.0 200 OK\r\nServer: gunicorn/20.0.4\r\nDate: Fri, 07 Aug 2020 23:22:00 GMT\r\nConnection: close\r
\nContent-Type: application/json\r\nX-Content-Type-Options: nosniff\r\nX-Frame-Options: DENY\r\nContent-Length: 1452315\r
\nVary: Accept-Language\r\nContent-Language: en\r\n\r\n", 258, 0, NULL, 0) = 258

20095 sendto(9, "{\"latest_delta_id\": 392556, \"read_at\": [\"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", 
\"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", 
\"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", \"Fri 1:21\", 
\"Fri 1:22\", \"Fri 1:22\", \"Fri 1:22\", \"Fri 1:22\", \"Fri 1:22\", \"Fri 1:22\", \"Fri 1:22\", \"Fri 1:22\", \"Fri 1:22\", \"Fri 1:22\", \"Fri 1:22\", 
\"Fri"..., 1452315, 0, NULL, 0) = 1452315

En dat stuurt die naar je browser. Interessant is Content-Length: 1452315, namelijk de grootte van de dataset. Dat is 1,4 MB en behoorlijk fors. Ik vermoed dat de webserver heel lang bezig is met het ophalen van die data en het mappen naar JSON (een manier van doorgeven aan je browser).

Nou hoeft dat niet een probleem te zijn wanneer je hardware het aankan. Gezien je geen Pi gebruikt weet ik niet hoe de performance zich verhoudt.

Ik denk dat je tegen een situatie aan loopt die ik zelf nog niet eerder heb gezien. Kan het zijn dat je:

Datalogger settings

Selection_001

Consumption settings Selection_002

dennissiemensma commented 4 years ago

Ter vergelijking, in je 1h log staat een Content-Length: 62839. Dat is 63 kB. Voor je beeld is dat een wereld van verschil, ten opzichte van de 1,4 MB van de 24h log.

Konijntjes-nl commented 4 years ago

Bovenstaande aanpassingen gedaan maar hebben geen effect op de "live graph". Heb een nieuwe db gemaakt en ingeladen ./deploy.sh dan laat hij wel direct. Lijkt me dan dat de database gewoon te veel data heeft. Zou de Retention configuration het probleem oplossen ?

Wat wel vreemd is dat ik bij 3.x geen probleem had. De dat voordat 4.1 uitkwam ben ik naar 4.0 gegaan en op de dag van 4.1 naar 4.1. Nu zit ik dan op 4.1.1

Wat ik wel zie bij "Status" is het volgende in rood. En die is al sinds 4.0 rood Incoming telegrams/readings : It has been a while since the latest telegram was read.

dennissiemensma commented 4 years ago

Bedankt voor je update. Zie je op het dashboard ook geen recente telegrammen? Want dan werkt de datalogger wellicht niet (goed). Je kunt sowieso even kijken of sudo supervisorctl restart all het euvel oplost. Dit staat overigens wel los van je andere probleem denk ik.

Wat betreft de hoeveelheid data, zie ook deze pagina in de docs daarover. Daar staat ook hoe je de hoeveelheid inkomende en opgeslagen data kunt verminderen.

dennissiemensma commented 4 years ago

Als aanvulling kun je de queries in dit comment gebruiken om te zien hoeveel metingen je (per maand) hebt: https://github.com/dennissiemensma/dsmr-reader/issues/1071#issuecomment-670690844

Ter indicatie van de hoeveelheid data.

Konijntjes-nl commented 4 years ago

Onderstaande screenshot is van mijn dashboard.

image

De restart heeft de melding niet weggehaald. Tevens ook niet met een volledige reboot. Datalogger sleep staat nu op 5. Als ik dat aan zet loopt de "Readings with invalid CRC" op. Als die op 0.5 staat loopt deze niet op. Zou mijn installatie gewoon defect zijn ?

Retentie veranderd na een week verwijderen. Hoelang zou dat moeten duren voordat ik dat terug zie in de grote van de database ?

dennissiemensma commented 4 years ago

Hmmm dat is vreemd. Houd hem dan voor nu maar even laag.

Het opschonen kun je volgen met de queries uit mijn vorige comment. Je zou al vrij snel moeten zien dat er steeds minder opgeslagen worden. De exacte snelheid hangt af van je hardware.

Konijntjes-nl commented 4 years ago

Mocht het intressant zijn watch -n1 "cat /proc/interrupts"

image

dennissiemensma commented 4 years ago

Bedankt voor de tip, alleen weet ik niet zo goed waar ik naar kijk en wat ik zoek. Heb je een toelichting? Wellicht kan ik er iets door verbeteren.

Konijntjes-nl commented 4 years ago

Dacht aangezien je het over interrucpts had dat het relevante data was.

Mijn database is momenteel 1462 gb met een retentsie van een week en andere aanpassingen die aangegeven zijn. Lijkt me niet veel kleiner te worden.

Htop image

iotop

image

Dit is tijdens het opvragen van 24 uur. IO technisch lijkt het geen probleem te zijn.

Vind het wel vreemd dat 1 core van de cpu dicht getrokken word. Terwijl die sneller zou moeten zijn dat een Rpi 3/4.

dennissiemensma commented 4 years ago

Bedankt voor je update. Wat betreft IO en CPU kan ik het wel enigzins verklaren.

De database kan heel snel alle metingen opzoeken en teruggeven aan de applicatie (vanzelfsprekend de specialiteit van de DB).

Vervolgens moeten alle metingen (per grafiek) gesplitst en omgezet worden naar JSON. Daar zit (blijkbaar, maar begrijpelijk) een hoop CPU/tijd in. En dat is ook terug te zien aan je eerdere tests met de verschillende intervallen.

dennissiemensma commented 4 years ago

@Konijntjes-nl heeft bovenstaande je nog verder geholpen?

Konijntjes-nl commented 4 years ago

Na enkele dagen heeft het probleem zich opgelost. Dit na de aanpassing van groeperen per minuut. Had ook voor de zekerheid ook de NUC een keer opnieuw geinstalleerd.

dsmrreader=# select date_trunc('month', timestamp) as month, count(id) as total from dsmr_datalogger_dsmrreading group by month order by month desc; month | total ------------------------+-------- 2020-08-01 00:00:00+00 | 309299 2020-07-01 00:00:00+00 | 1488 2020-06-01 00:00:00+00 | 1438 2020-05-01 00:00:00+00 | 260 (4 rows)

dsmrreader=# select date_trunc('month', read_at) as month, count(id) as total from dsmr_consumption_electricityconsumption group by month order by month desc; month | total ------------------------+------- 2020-08-01 00:00:00+00 | 99234 2020-07-01 00:00:00+00 | 1488 2020-06-01 00:00:00+00 | 1438 2020-05-01 00:00:00+00 | 260

dennissiemensma commented 4 years ago

Oke dank voor de terugkoppeling! Dan vermoed ik dat het de hoeveelheid data is die teveel is. Goed voor mij om te weten dat dat in sommige gevallen voor deze issues kan zorgen.

dennissiemensma commented 4 years ago

Mocht je trouwens nog andere issues hebben, laat vooral weten!