Calendar Modul: lange Ladezeit und 98% CPU

[Amenophis86]

Code Auswählen Erweitern

2017.05.24 08:01:38 2: Calendar KL.Anja: update in progress, process aborted.
2017.05.24 08:02:51 2: Calendar KL.Anja: update in progress, process aborted.
2017.05.24 08:03:22 4: Calendar KL.Anja: Updating...
2017.05.24 08:03:22 4: Calendar KL.Anja: Getting data from URL <hidden>
2017.05.24 08:03:24 2: Calendar KL.Anja: update in progress, process aborted.

Habe die neue Datei mal ausprobiert und bekomme immer, dass der Prozess abgebrochen wird. Habe dann mal verbose auf 5 gesetzt, allerdings keine wirklichen weiteren Informationen.

[Dr. Boris Neubert]

Habe die neue Datei mal ausprobiert und bekomme immer, dass der Prozess abgebrochen wird. Habe dann mal verbose auf 5 gesetzt, allerdings keine wirklichen weiteren Informationen.

Process aborted kommt, wenn zeitlich ein neues Kalenderupdate ausgelöst wird und das laufende Update noch nicht abgearbeitet ist. Das ist normal und richtig. Bitte mal einen Lauf mit verbose 5 machen und das Log hier posten.

[Amenophis86]

da kann aber trotzdem etwas nicht stimmen:

Code Auswählen Erweitern

2017.05.24 08:01:38 2: Calendar KL.Anja: update in progress, process aborted.
2017.05.24 08:02:51 2: Calendar KL.Anja: update in progress, process aborted.
2017.05.24 08:03:22 4: Calendar KL.Anja: Updating...
2017.05.24 08:03:22 4: Calendar KL.Anja: Getting data from URL <hidden>
2017.05.24 08:03:24 2: Calendar KL.Anja: update in progress, process aborted.
2017.05.24 11:17:51 4: Calendar KL.Anja: Updating...
2017.05.24 11:17:51 4: Calendar KL.Anja: Getting data from URL <hidden>
2017.05.24 11:17:54 2: Calendar KL.Anja: update in progress, process aborted.

habe ein Update jetzt nochmal manuell angestoßen und es kommt immer wieder direkt aborted.

Dann habe ich einen restart durch geführt und es zerschießt mir das Memory:

Code Auswählen Erweitern

2017.05.24 11:18:55 4: Calendar KL.Anja: Wakeup
2017.05.24 11:18:55 4: Calendar KL.Anja: Updating...
2017.05.24 11:18:55 4: Calendar KL.Anja: Getting data from URL <hidden>
2017.05.24 11:19:02 4: Calendar KL.Anja: parsing data asynchronously (PID= 734)
2017.05.24 11:19:03 4: Calendar KL.Anja: still waiting (read: no data).
2017.05.24 11:19:04 4: Calendar KL.Anja: still waiting (read: no data).
2017.05.24 11:19:05 4: Calendar KL.Anja: still waiting (read: no data).
2017.05.24 11:19:06 4: Calendar KL.Anja: still waiting (read: incomplete data).
Out of memory!

[Amenophis86]

Fehler von mir. Habe vergessen auf der Testversion ein Update der SubProcess.pm zu machen, danach war der Fehler weg. Gefühlt dauert es jetzt aber länger. Habe dir nochmal die neusten Prof Dateien geschickt Boris.

[Dr. Boris Neubert]

Hallo,

die letzten Änderungen beschleunigen die eigentliche Arbeit nicht - da ist aus meiner Sicht keine Performance mehr rauszukitzeln.

Die Änderungen sorgen aber dafür, dass nicht nur das Herunterladen der ical-Datei vom Server sondern auch dessen Umwandlung in die internen Datenstrukturen im Hintergrund erfolgen.

In anderen Worten: FHEM sollte nicht mehr die 10 Sekunden blockieren, die es bei Dir braucht, um den Kalender zu verarbeiten. Kannst Du das bitte bestätigen?

Kann das auch bitte noch jemand anderes probieren, bevor ich das neue Modul in den größeren Test gebe?

Viele Grüße
Boris

[Amenophis86]

Ich muss es nochmal versuchen die Tage, aber ich meine, dass FHEM trotzdem blockiert hat beim Update des Kalenders. Verstehe ich dich richtig, dass FHEM eigentlich nicht mehr blockieren sollte, also der gesamte Update Prozess NonBlocking verlaufen sollte?

[Dr. Boris Neubert]

Hallo,

Teile des Prozesses blockieren noch immer im asynchronen Modus. Den Auswertungen des Profilings zufolge sind diese aber nicht so langläufig wie jene Teile, die ich nebenläufig zum FHEM-Hauptprozess bearbeiten lasse.

Bitte finde anbei einen Kandidaten mit noch etwas mehr Logging und einem Attribut, um das Update zu steuern.

update sync|async|none
Wenn dieses Attribut nicht gesetzt ist oder wenn es auf sync gesetzt ist, findet die Verarbeitung des Kalenders im Vordergrund statt. Große Kalender werden FHEM auf langsamen Systemen blockieren. Wenn das Attribut auf async gesetzt ist, findet die Verarbeitung im Hintergrund statt, und FHEM wird während der Verarbeitung nicht blockieren. Wenn dieses Attribut auf none gesetzt ist, wird der Kalender überhaupt nicht aktualisiert.

Bitte setze

Code Auswählen Erweitern

attr global verbose 3
attr DeinKalender update async
attr DeinKalender verbose 5

Bei mir sieht das wie folgt im Log aus:

Code Auswählen Erweitern

2017.06.04 08:14:39 4: Calendar C: Wakeup
2017.06.04 08:14:39 4: Calendar C: Updating...
2017.06.04 08:14:39 4: Calendar C: Getting data from URL <hidden>
2017.06.04 08:14:39 4: Calendar C: parsing data asynchronously (PID= 10258)
2017.06.04 08:14:39 5: Calendar C: control passed back to main loop.
2017.06.04 08:14:40 4: Calendar C: got result from asynchronous parsing.
2017.06.04 08:14:40 4: Calendar C: asynchronous parsing finished.
2017.06.04 08:14:40 4: Calendar C: merging data
2017.06.04 08:14:40 4: Calendar C: 203 records processed, 0 new, 203 known, 0 modified, 0 changed.
2017.06.04 08:14:40 4: Calendar C: creating calendar events
2017.06.04 08:14:40 4: Calendar C: Checking times...
2017.06.04 08:14:40 4: Calendar C: process ended.

Zwischen den Meldungen control passed back to main loop. und got result from asynchronous parsing. sollte FHEM NICHT blockieren. Bitte poste auf jeden Fall mal diesen Teil des Logs. Profiler-Ergebnisse brauche ich keine mehr.

Viele Grüße
Boris

[Amenophis86]

Es läuft zumindest schon mal ohne Fehler. Auf dem Pi1 hängt er kurz beim Parsen der Daten vermutlich, zumindest, sobald er Daten empfängt. Denke auf einem P2 dürfte man dies schon nicht mehr merken. Apptime wirft folgendes aus:

Code Auswählen Erweitern

ame                                     function                               max  count    total  average maxDly TS Max call     param Max call
tmr-Calendar_PollChild                   HASH(0x2063158)                      13303     10    26266  2626.60     67 04.06. 23:27:36 HASH(KL.Anja)
tmr-FW_closeInactiveClients                                                       1      1        1     1.00      2 04.06. 23:27:03
FHEM.Backup                              dummy_Set                                0      2        0     0.00      0
Import                                   dummy_Set                                0      2        0     0.00      0
KL.Anja                                  Calendar_Get                             0      2        0     0.00      0
KL.Anja                                  Calendar_Set                            19     10       36     3.60      0 04.06. 23:26:19 HASH(KL.Anja); KL.Anja; update
Logfile                                  FileLog_Log                              0     12        0     0.00      0
Logfile                                  FileLog_Set                              3      2        6     3.00      0 04.06. 23:26:15 HASH(Logfile); Logfile; ?
WEB                                      FW_Notify                                0     12        0     0.00      0
WEB                                      FW_Read                                 17     32       88     2.75      0 04.06. 23:27:18 HASH(WEB)
WEB                                      FW_Set                                   0      2        0     0.00      0
WEB_192.168.2.10_57944                   FW_Read                                 48      1       48    48.00      0 04.06. 23:26:39 HASH(WEB_192.168.2.10_57944)
WEB_192.168.2.10_57957                   FW_Read                                101     15      655    43.67      0 04.06. 23:27:18 HASH(WEB_192.168.2.10_57957)
WEB_192.168.2.10_57965                   FW_Read                                 68      4      122    30.50      0 04.06. 23:27:42 HASH(WEB_192.168.2.10_57965)
WEB_192.168.2.10_57968                   FW_Read                                  0      1        0     0.00      0
WEBphone                                 FW_Notify                                0     12        0     0.00      0
WEBphone                                 FW_Set                                   0      2        0     0.00      0
WEBtablet                                FW_Notify                                0     12        0     0.00      0
WEBtablet                                FW_Set                                   0      2        0     0.00      0
eventTypes                               eventTypes_Notify                        2     12        6     0.50      0 04.06. 23:27:36 HASH(eventTypes); HASH(KL.Anja)
eventTypes                               eventTypes_Set                           0      2        0     0.00      0

Daher würde ich sagen, dass es schon deutlich besser geworden ist. Die Wartezeit war wesentlich länger vorher. Wobei ich es nicht genau gemessen habe, aber rein vom Gefühl her.

[slupus]

Hallo Boris,

ich konnte folgendes beobachten: Im synchronen Modus ist die CPU Auslastung meines Pi1 durchgängig bei ca. 97%. Im asynchronen Modus sind es zunächst 1-2 Prozesse, die eine Auslastung von ca. 70-90% erzeugen. FHEM ist dabei nicht blockiert.
Somit würde ich den Test positiv bewerten. Vielen Dank für deine Bemühungen!

Bei mir scheint nun das Problem die große Anzahl der Events zu sein. Ab dem Punkt creating calendar events ist die Auslastung bei ca. 97% und FHEM ist blockiert. Das mag aber auch am Pi1 liegen.

Grüße Sören

[Dr. Boris Neubert]

Danke für Deinen Test.

Bei mir scheint nun das Problem die große Anzahl der Events zu sein. Ab dem Punkt creating calendar events ist die Auslastung bei ca. 97% und FHEM ist blockiert. Das mag aber auch am Pi1 liegen.

Das entspricht den Erwartungen. Der Abgleich der Termine aus dem Update mit den Terminen vom vorigen Update dauert halt auch eine Weile.

[Amenophis86]

Han gesehen, dass du die neue Version eingecheckt hast. Ich danke dir fürs bearbeiten des Problems.

[sTaN]

Hallo Zusammen,

nach einem update all von FHEM erhalte ich unter anderem folgende Fehlermeldung:

Code Auswählen Erweitern

2017.06.12 13:28:00 1: PERL WARNING: Use of uninitialized value $t in numeric lt (<) at ./FHEM/57_Calendar.pm line 1924.
2017.06.12 13:27:59 1: Calendar TRCalendar: retrieved no or empty data
2017.06.12 13:27:59 1: Calendar TRCalendar: retrieval failed with error message read from https://calendar.google.com:443 timed out

Vielleicht hat hier noch jemand einen Tipp oder das gleiche Problem?

Gruß
sTaN

[Amenophis86]

Kann es sein, dass du einen Eintrag ohne Anfangs-/Enddatum hast? Ich meine da war mal was in der Richtung.

[sTaN]

Puh, dass ist natürlich schwer zu sagen. Es gibt einige Einträge in dem Kalender  Bekommt man das irgendwie komfortabel im Google Kalender raus?
Ich sehe auch grad, dass ich das Problem im April schon mal im entsprechenden Thread geposted hatte, zumindest was die TimeOut Meldung angeht, bisher allerdings ohne eine Rückmeldung.

Das PERL Warning ist jetzt aber neu nach dem Update. Fehler erscheinen auch nach einem RPI Neustart.

[Dr. Boris Neubert]

Hi,

die Warnung kommt vermutlich, weil der Kalender leer ist. Muss ich ansehen und könnte Hinweise geben, ist aber erst mal unschädlich.

Ich habe auch das Problem, dass ich manchmal kein Ergebnis zurück bekomme beim HTTP- Request zu Google. Das geht aber bald wieder. Wie ist es bei Dir?

Viele Grüße
Boris