Calendar Update verursacht Freeze

Begonnen von webdandy, 17 Oktober 2019, 18:10:04

Vorheriges Thema - Nächstes Thema

Otto123

Hallo Boris,

na klar bin schon dabei. Ich mache dazu ein neues FHEM, dauert also einen Moment :)

Gruß Otto
Viele Grüße aus Leipzig  ⇉  nächster Stammtisch an der Lindennaundorfer Mühle
RaspberryPi B B+ B2 B3 B3+ ZeroW,HMLAN,HMUART,Homematic,Fritz!Box 7590,WRT3200ACS-OpenWrt,Sonos,VU+,Arduino nano,ESP8266,MQTT,Zigbee,deconz

Dr. Boris Neubert

#16
Hallo,

leider ist das Calendar-Modul voll von Debug-Meldungen und nicht alle funktionieren nach dem Einkommentieren. Bitte findet anbei eine Variante mit Debugging, die funktioniert und sehr große Logs schreibt.

Dank der Hilfe von Otto meine ich aber die Ursache für die lange Verarbeitungsdauer zu kennen: es sind die BYDAY-Regeln, die sehr viel Zeit für die Umsetzung in Termine benötigen.

Ich muss mir das auf Optimierungspotential ansehen, kann aber nichts versprechen. Der Code ist komplex.

Viele Grüße
Boris


EDIT: Release Candidate am Ende des Themas.
Globaler Moderator, Developer, aktives Mitglied des FHEM e.V. (Marketing, Verwaltung)
Bitte keine unaufgeforderten privaten Nachrichten!

Dr. Boris Neubert

Profiling ist eine tolle Sache. Auf dem Bild erkennt man, wo die Zeit beim Verarbeiten von Ottos Kalender verblasen wird (Core i7-4790K @ 4 GHz).

Bin von einer Lösung noch weit entfernt.
Globaler Moderator, Developer, aktives Mitglied des FHEM e.V. (Marketing, Verwaltung)
Bitte keine unaufgeforderten privaten Nachrichten!

Dr. Boris Neubert

Hallo,

Dank Fabians Unterstützung konnten wir bei Fabians Kalender folgendes herausfinden:
- Der Kalender enthält sehr viele Termine und Serien in der Vergangenheit.
- Der Zeitaufwand entsteht durch die Verarbeitung dieser Termine.
- attr <name> cutoffOlderThan 10d führt zu einer radikalen Beschleunigung.

Viele Grüße
Boris
Globaler Moderator, Developer, aktives Mitglied des FHEM e.V. (Marketing, Verwaltung)
Bitte keine unaufgeforderten privaten Nachrichten!

webdandy

Zitat von: Dr. Boris Neubert am 20 Oktober 2019, 19:58:02
Hallo,

Dank Fabians Unterstützung konnten wir bei Fabians Kalender folgendes herausfinden:
- Der Kalender enthält sehr viele Termine und Serien in der Vergangenheit.
- Der Zeitaufwand entsteht durch die Verarbeitung dieser Termine.
- attr <name> cutoffOlderThan 10d führt zu einer radikalen Beschleunigung.

Viele Grüße
Boris
Hallo Boris,
vielen Dank für Deine eifrige Unterstützung und vor allem der Lösungsfindung.
Viele Grüße
Fabian

Otto123

#20
Hallo Boris,
Respekt Boris, mit Deiner Schätzung von "halb so lange" lagst Du "daneben"  ;) - nur noch ein Drittel der alten Zeit auf dem Raspberry B
Neu definiert, erster Durchlauf, reload 57_Calendar.pm gemacht, zweiter Durchlauf :)
define PraxisTest Calendar ical file /home/pi/test.ics 86400
attr PraxisTest room Abfall
attr PraxisTest verbose 5


2019.10.20 22:48:31 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:48:32 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:48:33 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:48:34 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:48:35 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:48:37 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:48:38 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:48:39 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:48:40 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:48:41 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:48:42 4: Calendar PraxisTest: got result from asynchronous parsing.
2019.10.20 22:48:42 4: Calendar PraxisTest: asynchronous parsing finished.
2019.10.20 22:48:43 4: Calendar PraxisTest: merging data
2019.10.20 22:48:50 4: Calendar PraxisTest: 1212 records processed, 1212 new, 0 known, 0 modified, 0 changed.
2019.10.20 22:48:50 4: Calendar PraxisTest: creating calendar events
2019.10.20 22:52:15 4: Calendar PraxisTest: Checking times...
2019.10.20 22:52:16 4: Calendar PraxisTest: process ended.
2019.10.20 22:52:16 1: [Freezemon] freez: possible freeze starting at 22:48:43, delay is 213.607 possibly caused by: tmr-Calendar_PollChild(PraxisTest) tmr-CUL_HM_procQs(N/A)
...
2019.10.20 22:53:12 1: PERL WARNING: Subroutine new redefined at ./FHEM/57_Calendar.pm line 398.
...
2019.10.20 22:53:26 4: Calendar PraxisTest: Updating...
2019.10.20 22:53:26 4: Calendar PraxisTest: Getting data from file /home/pi/test.ics
2019.10.20 22:53:27 5: Calendar PraxisTest: file retrieval successful
2019.10.20 22:53:27 4: Calendar PraxisTest: parsing data asynchronously (PID= 9857)
2019.10.20 22:53:27 5: Calendar PraxisTest: control passed back to main loop.
2019.10.20 22:53:28 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:53:29 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:53:30 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:53:31 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:53:32 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:53:33 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:53:34 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:53:35 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:53:36 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:53:38 4: Calendar PraxisTest: still waiting (read: no data).
2019.10.20 22:53:39 4: Calendar PraxisTest: got result from asynchronous parsing.
2019.10.20 22:53:39 4: Calendar PraxisTest: asynchronous parsing finished.
2019.10.20 22:53:40 4: Calendar PraxisTest: merging data
2019.10.20 22:53:46 4: Calendar PraxisTest: 1212 records processed, 1212 new, 0 known, 0 modified, 0 changed.
2019.10.20 22:53:47 4: Calendar PraxisTest: creating calendar events
2019.10.20 22:54:53 4: Calendar PraxisTest: Checking times...
2019.10.20 22:54:53 4: Calendar PraxisTest: process ended.
2019.10.20 22:54:54 1: [Freezemon] freez: possible freeze starting at 22:53:40, delay is 74.083 possibly caused by: tmr-Calendar_PollChild(PraxisTest) tmr-CUL_HM_procQs(N/A)


Da ja auch immer mal die Frage steht: Lohnt sich der Umstieg auf neue Hardware? Hier die Ergebnisse des gleichen Tests auf einem Pi3+:
Der Pi3B+ ist bei dieser Aufgabe in etwa 10 mal schneller als der Pi1B
2019.10.21 09:52:55 4: Calendar PraxisTest: Updating...
2019.10.21 09:52:55 4: Calendar PraxisTest: Getting data from file /home/pi/test.ics
2019.10.21 09:52:55 5: Calendar PraxisTest: file retrieval successful
2019.10.21 09:52:55 4: Calendar PraxisTest: parsing data asynchronously (PID= 23492)
2019.10.21 09:52:55 5: Calendar PraxisTest: control passed back to main loop.
2019.10.21 09:52:56 4: Calendar PraxisTest: got result from asynchronous parsing.
2019.10.21 09:52:56 4: Calendar PraxisTest: asynchronous parsing finished.
2019.10.21 09:52:56 4: Calendar PraxisTest: merging data
2019.10.21 09:52:57 4: Calendar PraxisTest: 1212 records processed, 1212 new, 0 known, 0 modified, 0 changed.
2019.10.21 09:52:57 4: Calendar PraxisTest: creating calendar events
2019.10.21 09:53:18 4: Calendar PraxisTest: Checking times...
2019.10.21 09:53:18 4: Calendar PraxisTest: process ended.

2019.10.21 09:54:21 1: PERL WARNING: Subroutine new redefined at ./FHEM/57_Calendar.pm line 398.

2019.10.21 09:54:39 4: Calendar PraxisTest: Updating...
2019.10.21 09:54:39 4: Calendar PraxisTest: Getting data from file /home/pi/test.ics
2019.10.21 09:54:39 5: Calendar PraxisTest: file retrieval successful
2019.10.21 09:54:39 4: Calendar PraxisTest: parsing data asynchronously (PID= 23516)
2019.10.21 09:54:39 5: Calendar PraxisTest: control passed back to main loop.
2019.10.21 09:54:40 4: Calendar PraxisTest: got result from asynchronous parsing.
2019.10.21 09:54:40 4: Calendar PraxisTest: asynchronous parsing finished.
2019.10.21 09:54:40 4: Calendar PraxisTest: merging data
2019.10.21 09:54:40 4: Calendar PraxisTest: 1212 records processed, 1212 new, 0 known, 0 modified, 0 changed.
2019.10.21 09:54:40 4: Calendar PraxisTest: creating calendar events
2019.10.21 09:54:47 4: Calendar PraxisTest: Checking times...
2019.10.21 09:54:47 4: Calendar PraxisTest: process ended.

Jetzt wirken die attribute cutoffLaterThan 30d und cutoffOlderThan 1d auch nochmal kräftig! Wenn ich den Log hier richtig interpretiere reduziert sich die blockierende Zeit auf 2 sec, bei einer gesamten Zeit von 4 sec. Und scheinbar bewirkt cutoffOlderThan stärker als in dem Versuch am 19. mit nur dem neuen attribute cutoffLaterThan ?
2019.10.21 10:23:57 4: Calendar PraxisTest: Updating...
2019.10.21 10:23:57 4: Calendar PraxisTest: Getting data from file /home/pi/test.ics
2019.10.21 10:23:58 5: Calendar PraxisTest: file retrieval successful
2019.10.21 10:23:58 4: Calendar PraxisTest: parsing data asynchronously (PID= 23592)
2019.10.21 10:23:58 5: Calendar PraxisTest: control passed back to main loop.
2019.10.21 10:23:59 4: Calendar PraxisTest: got result from asynchronous parsing.
2019.10.21 10:23:59 4: Calendar PraxisTest: asynchronous parsing finished.
2019.10.21 10:23:59 4: Calendar PraxisTest: merging data
2019.10.21 10:23:59 4: Calendar PraxisTest: 11 records processed, 11 new, 0 known, 0 modified, 0 changed.
2019.10.21 10:23:59 4: Calendar PraxisTest: creating calendar events
2019.10.21 10:24:01 4: Calendar PraxisTest: Checking times...
2019.10.21 10:24:01 4: Calendar PraxisTest: process ended.


Danke und Viele Grüße

Otto
Viele Grüße aus Leipzig  ⇉  nächster Stammtisch an der Lindennaundorfer Mühle
RaspberryPi B B+ B2 B3 B3+ ZeroW,HMLAN,HMUART,Homematic,Fritz!Box 7590,WRT3200ACS-OpenWrt,Sonos,VU+,Arduino nano,ESP8266,MQTT,Zigbee,deconz

Dr. Boris Neubert

Super!

Anbei noch die aktuelle Version mit dieser Verbesserung.
Globaler Moderator, Developer, aktives Mitglied des FHEM e.V. (Marketing, Verwaltung)
Bitte keine unaufgeforderten privaten Nachrichten!