Dsmr-reader: Retentie wordt niet toegepast op DsmrReading class

[swerveshot]

Follow-up van issue #469. Hierbij lijken de retentie instellingen wel te worden toegepast op ElectricityConsumption en GasConsumption maar niet op DsmrReading.

Omgeving

• DSMR-reader version: v1.16
• Hardware: Odroid U3
• DSMR protocol: v4
• Retentie ingesteld op: Discard most readings after one month

Reproduceren issue

• Waarschijnlijk slecht te reproduceren. Verwacht dat dit een issue is met mijn specifieke installatie.
• Kwestie van wachten tot de retentie instellingen 's nachts worden toegepast.
• Wellicht prettig als dit op de een of andere manier handmatig zou kunnen worden gestart. Anders kost het iedere keer een dag voor ik verder kan troubleshooten.

[dennissiemensma]

Bedankt voor je issue. Ik was niet in de gelegenheid om eerder te reageren, ik ben pas net weer thuis. Ik denk dat ik voor dit issue even een aftakking maak met wat extra logging, zodat je die lokaal kan draaien om te zien wat die exact doet, en wellicht de oorzaak toont waarom de metingentabel niet wordt opgeschoond.

[swerveshot]

Geen probleem hoor @dennissiemensma. Ben al lang blij dat je zoveel tijd neemt voor het verhelpen van dit issue. Menig bedrijf rekent een flinke som geld voor het niveau van support die je via GitHub levert. Dus hulde daarvoor! Als je een nieuwe branch hebt hou ik me van harte aanbevolen. Hoop dat ik zo iets kan bijdragen aan het verbeteren van je project.

Voor de volledigheid, dit is het resultaat van de afgelopen cleanup (die van gisteren was gecrashed omdat de disk vol liep).

/var/log/supervisor/dsmr_backend.log.1:Retention | Cleaning up: 2018-04-09 02:00:00+00:00 (ElectricityConsumption)
/var/log/supervisor/dsmr_backend.log.1:Retention | Cleaning up: 2018-04-09 02:00:00+00:00 (GasConsumption)
/var/log/supervisor/dsmr_backend.log.1:Retention | Cleaning up: 2018-04-09 03:00:00+00:00 (ElectricityConsumption)
/var/log/supervisor/dsmr_backend.log.1:Retention | Cleaning up: 2018-04-09 03:00:00+00:00 (GasConsumption)
/var/log/supervisor/dsmr_backend.log.1:Retention | Cleaning up: 2018-04-09 04:00:00+00:00 (ElectricityConsumption)
/var/log/supervisor/dsmr_backend.log.1:Retention | Cleaning up: 2018-04-09 04:00:00+00:00 (GasConsumption)
/var/log/supervisor/dsmr_backend.log.1:Retention | Cleaning up: 2018-04-09 05:00:00+00:00 (ElectricityConsumption)
/var/log/supervisor/dsmr_backend.log.1:Retention | Cleaning up: 2018-04-09 05:00:00+00:00 (GasConsumption)
/var/log/supervisor/dsmr_backend.log.1:Retention | Cleaning up: 2018-04-09 06:00:00+00:00 (ElectricityConsumption)
/var/log/supervisor/dsmr_backend.log.1:Retention | Cleaning up: 2018-04-09 06:00:00+00:00 (GasConsumption)
/var/log/supervisor/dsmr_backend.log.3:Retention | Cleaning up: 2018-04-09 01:00:00+00:00 (ElectricityConsumption)
/var/log/supervisor/dsmr_backend.log.3:Retention | Cleaning up: 2018-04-09 01:00:00+00:00 (GasConsumption)
/var/log/supervisor/dsmr_backend.log.4:Retention | Cleaning up: 2018-04-09 00:00:00+00:00 (GasConsumption)

dsmrreader=# select count(*) from dsmr_datalogger_dsmrreading;
  count
---------
 9944238
(1 row)

dsmrreader=# select count(*) from dsmr_consumption_electricityconsumption;
 count
-------
 39920
(1 row)

dsmrreader=# select count(*) from dsmr_consumption_gasconsumption;
 count
-------
 11473
(1 row)

[dennissiemensma]

Ik denk dat je in dit geval het beste alvast handmatig een opschoning kan doen.
Zorg er wel voor dat je tenminste 1 goede database-backup hebt.

sudo su - postgres
psql dsmrreader

# Dit kan even duren:
delete from dsmr_datalogger_dsmrreading where timestamp < localtimestamp - interval '4 week' and processed = true;

De schijfruimte wordt niet direct door postgresql vrijgegeven, dit kun je forceren met een vacuumdb.

sudo su - postgres

# Dit kan even duren, want hij doet volgens mij een rebuild van elke tabel, 
# zonder alle verwijderde rijen. 
# Dit is de aggresieve methode, vergelijkbaar met mysql's optimize table:
vacuumdb -f -v -z -d dsmrreader

[swerveshot]

Stap 1: Backup

Een backup...... right. Eens kijken hoeveel data er in die database staat (top 20 tabellen). :scream:

                               relation                                |  size
-----------------------------------------------------------------------+---------
 public.dsmr_datalogger_dsmrreading                                    | 1013 MB
 public.dsmr_datalogger_dsmrreading_pkey                               | 455 MB
 public.dsmr_datalogger_dsmrreading_timestamp_1f7020d1                 | 455 MB
 public.dsmr_datalogger_dsmrreading_processed_add8a852                 | 272 MB
 public.dsmr_consumption_electricityconsumption                        | 13 MB
 public.dsmr_consumption_electrici_phase_currently_delivered__9998ce55 | 4696 kB
 public.dsmr_consumption_electrici_phase_currently_delivered__0315221e | 4680 kB
 public.dsmr_consumption_electrici_currently_returned_b7a910c8         | 4656 kB
 public.dsmr_consumption_electrici_phase_currently_delivered__21a515a7 | 4640 kB
 public.dsmr_consumption_electrici_currently_delivered_0f28e53a        | 4608 kB
 public.dsmr_consumption_electricityconsumption_pkey                   | 3688 kB
 public.dsmr_consumption_electricityconsumption_read_at_key            | 3688 kB
 public.dsmr_consumption_gasconsumption                                | 1856 kB
 public.dsmr_consumption_gasconsumption_pkey                           | 744 kB
 public.dsmr_consumption_gasconsumption_read_at_key                    | 744 kB
 pg_toast.pg_toast_2618                                                | 376 kB
 public.dsmr_stats_hourstatistics                                      | 192 kB
 public.dsmr_weather_temperaturereading                                | 144 kB
 public.dsmr_weather_temperaturereading_read_at_key                    | 80 kB
 public.dsmr_weather_temperaturereading_pkey                           | 80 kB

En hoeveel vrije ruimte heb ik momenteel op mijn 8GB grote eMMC module?

Filesystem                     Size  Used Avail Use% Mounted on
/dev/mmcblk0p2                 7.1G  6.7G  115M  99% /

Eeehm, hoe werkte dat ook al weer met een CIFS mount onder linux? :sweat_smile:

Heb nog wel wat ruimte op mijn NAS.

Uiteindelijk viel het toch aardig mee. Een backup met gzip is maar 84,3MB groot. Onwaarschijnlijk klein, maar een zcat laat toch gewoon data zien. Wel 10.054.837 regels in totaal, komt aardig in de buurt van het totale aantal readings. Daarvan staat de teller nu op 9.994.289.

Stap 2: Handmatige database cleanup

Poging 1: FAIL

Na een succesvolle backup werd het tijd om de delete statement uit te voeren. Heb deze 1-op-1 overgenomen en daar moest mijn arme Odroid wel even op zwoegen voor ik weer een prompt terug kreeg en helaas niet met het gewenste resultaat.

dsmrreader=# delete from dsmr_datalogger_dsmrreading where timestamp < localtimestamp - interval '4 week' and processed = true;
delete from dsmr_datalogger_dsmrreading where timestamp < localtimestamp - interval '4 week' and processed = true;
delete from dsmr_datalogger_dsmrreading where timestamp < localtimestamp - interval '4 week' and processed = true;
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
The connection to the server was lost. Attempting reset: Failed.
!> delete from dsmr_datalogger_dsmrreading where timestamp < localtimestamp - interval '4 week' and processed = true;
You are currently not connected to a database.
!> delete from dsmr_datalogger_dsmrreading where timestamp < localtimestamp - interval '4 week' and processed = true;
You are currently not connected to a database.
!>

Helaas, dit was de druppel voor wat betreft de vrije ruimte op mijn eMMC module.

Filesystem                     Size  Used Avail Use% Mounted on
/dev/mmcblk0p2                 7.1G  6.8G  912K 100% /

Op zich begrijpelijk aangezien een database een transactie log bijhoudt en dit een shitload wijzigingen produceert wat de schijf doet vol lopen.

Poging 2: PARTIAL SUCCESS

Uiteindelijk herstelde het systeem zich weer en had ik ook weer wat ruimte vrij. Vreemd genoeg nog meer dan toen ik startte.

Filesystem                     Size  Used Avail Use% Mounted on
/dev/mmcblk0p2                 7.1G  6.7G  151M  98% /

Dan maar eens kijken hoeveel regels de delete query wil opschonen.

dsmrreader=# select count(*) from dsmr_datalogger_dsmrreading where timestamp < localtimestamp - interval '4 week' and processed = true;
  count
---------
 7891678
(1 row)

OK, dat is best een hoop. Dus volgende stap; probeer een kleinere set data te verwijderen met de volgende query.

DELETE FROM dsmr_datalogger_dsmrreading
WHERE id IN (
    SELECT id
    FROM dsmr_datalogger_dsmrreading
    where timestamp < localtimestamp - interval '4 week' and processed = true
    ORDER BY id
    LIMIT 1000
);

Dat werkt en de disk is niet direct vol. Dus dan een vacuumdb proberen. Eeeeen, dat werkt ook niet.

INFO:  vacuuming "public.dsmr_datalogger_dsmrreading"
vacuumdb: vacuuming of database "dsmrreader" failed: ERROR:  could not extend file "base/16385/34152": No space left on device
HINT:  Check free disk space.

De tabel waar het vacuuming process het langst op blijft steken is public.dsmr_datalogger_dsmrreading. Als ik jouw opmerking over vacuumdb lees dan zou deze de tabellen opnieuw opbouwen. En aangezien de bewuste tabel ongeveer 1GB groot is heb ik daar wel een issue.

Gezien het tijdstip (2 uur 's nachts) hou ik er voor nu even mee op. Ga er morgen nog eens over nadenken hoe ik dit verder kan oplossen. Misschien is dit ook wel de reden waarom de retentie van de DsmrReading überhaupt niet wordt toegepast.

To be continued.

[swerveshot]

Nog een laatste update voor ik er ECHT mee ophoud. Na de laatste pogingen om de database issues te verhelpen zie ik de disk space steeds weer afnemen naar 0 en dan weer terugkeren naar ~150MB. Dus postgresql lijkt echt totaal de weg kwijt. Ik reboot de machine maar een keer en ga dan pitten.

[swerveshot]

Poging 3: succes! :tada:

Nieuwe dag; nieuwe inzichten. Waarom zou ik me beperken tot de productie machine als ik ook de housekeeping kan doen op een willekeurige andere PostgreSQL installatie.

1. Heb een VM opgetuigd om de database backup (gemaakt met pg_dump dsmrreader | gzip > somefile.gz) op terug te zetten. Vervolgens de stappen van de dsmr-reader installatiehandleiding gevolgd.

sudo sudo -u postgres createuser -DSR dsmrreader
sudo sudo -u postgres createdb -O dsmrreader dsmrreader
sudo sudo -u postgres psql -c "alter user dsmrreader with password 'dsmrreader';"

1. Daarna het delete statement uitgevoerd voor de cleanup zoals in jouw instructie, gevolgd door de vacuumdb. Allemaal met succes.
2. Vervolgens een nieuwe database backup gemaakt en op de productie machine een DROP DATABASE dsmrreader; gedaan en de opgeschoonde database terug gezet. Heb het twee keer moeten doen omdat ik niet eerst alle supervisor taken van tevoren had gekilled. Maar het resultaat is er wel; een succesvolle restore zonder foutmeldingen.
3. Ten slotte de supervisor processen weer gestart en de webinterface opgevraagd. Alles draait naar behoren en ik zit op de 2.078.073 readings. Ook de Django administration pagina's doen het nog prima. Mijn oorspronkelijke doel om de API calls te versnellen is ook bereikt. Krijg nu tussen de 1 en 1,5 seconden resultaat. En als kers op de taart kan nu het debuggen van de geautomatiseerde cleanup van dsmr readings weer verder gaan en heb ik bovendien eea. over PostgreSQL geleerd.

[dennissiemensma]

Bedankt voor al je updates en probeersels! Er waren nog wel alternatieven om uit te proberen, maar deze methode werkt zo ook wel.
Je hebt overigens vacuumdb een volgende keer niet nodig als je de database ergens anders gaat opschonen, want wanneer je een database-dump maakt, worden alle verwijderde rijen niet meegenomen.

• Je kunt nu even afwachten of de readings aanstaande nacht wél opgeschoond worden.

• Mocht je toch een DSMR v5 meter hebben (elke seconde een meting), dan kun je nog overwegen om de datalogger wat minder hard te laten loggen, bijvoorbeeld elke 5 seconden. Je kunt dan DSMRREADER_DATALOGGER_SLEEP = 5 toevoegen aan dsmrreader/settings.py en de datalogger herstarten met sudo supervisorctl restart dsmr_datalogger. Uiteindelijk houd je minder metingen over, waardoor de API-calls ook weer sneller worden. Maar het is aan jou of dat nodig/gewenst is.

[swerveshot]

Nou, het database onderhoud lijkt resultaat te hebben.

grep -e '^Retention.*DsmrReading' /var/log/supervisor/dsmr_backend.log*
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 06:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 07:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 08:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 09:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 10:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 11:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 12:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 13:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 14:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 15:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 16:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 17:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 18:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 19:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 20:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 21:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 22:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-10 23:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-11 00:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-11 01:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-11 02:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-11 03:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-11 04:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-11 05:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.2:Retention | Cleaning up: 2018-04-11 06:00:00+00:00 (DsmrReading)
/var/log/supervisor/dsmr_backend.log.4:Retention | Cleaning up: 2018-04-10 06:00:00+00:00 (DsmrReading)

De timestamps zijn zo te zien van de readings die worden opgeschoond. De log files zijn namelijk vrij recent.

ll /var/log/supervisor/dsmr_backend.log*
-rw-r--r-- 1 root root 2695086 May  9 23:33 /var/log/supervisor/dsmr_backend.log
-rw-r--r-- 1 root root 5242910 May  9 18:35 /var/log/supervisor/dsmr_backend.log.1
-rw-r--r-- 1 root root 5242881 May  9 08:55 /var/log/supervisor/dsmr_backend.log.2
-rw-r--r-- 1 root root 5242912 May  8 23:03 /var/log/supervisor/dsmr_backend.log.3
-rw-r--r-- 1 root root 5242935 May  8 13:23 /var/log/supervisor/dsmr_backend.log.4
-rw-r--r-- 1 root root 5272497 May  8 01:29 /var/log/supervisor/dsmr_backend.log.5

Dus ja, wat kunnen we hier nu uit concluderen? Zou de delta te groot geweest zijn? Zou de diskspace de root cause geweest zijn?

Anyway, ik ben blij dat het werkt. Denk dat ik zelfs de retentie nog terug ga schroeven naar een week. Want ik zou eigenlijk niet weten waarom ik langer nodig heb.

[dennissiemensma]

Bedankt voor je terugkoppeling. Ik denk dan dat de diskspace inderdaad het euvel geweest is. Dat is goed voor mij om te weten, mocht iemand anders hier nog tegenaan lopen. Voor nu laat ik dit dan voor wat het is, als het nu goed lijkt te werken.

De timestamps zijn inderdaad van de uren die opgeschoond worden. Het proces laat van elk uur de eerst en laatste meting staan dacht ik.

Mocht je toch nog ergens tegenaan lopen dan hoor ik het graag.

[swerveshot]

Ja prima toch? Ben ook blij om te weten dat een eenvoudige delete statement voor nood gebruikt kan worden. Zou ik niet zelf geprobeerd hebben omdat ik de database structuur niet ken.

Dank voor je hulp @dennissiemensma, je bent een topper!