Extreme CPU-Last bei "if" seit Update

[Hardlife]

Hallo liebe Com!

Ich weiß nicht, ob das hier die richtige Untergruppe ist, aber in den Developement-Foren darf ich klarerweise nicht posten...
Da mein Problem mit Automatisierung zusammenhängt (Fehler-Ursache dürfte aber woanders liegen?), finden sich hier sicher kompetente Leute, dir mir vielleicht helfen können

Falls ein Moderator ein passenders Unterforum empfiehlt, bitte einfach dorthin verschieben. Danke.

Sorry für den langen Post, aber ich wollte den Umstand gleich möglichst umfassend darstellen, um Euch lästige Fragen zu ersparen.

Kurz zu meinem Problem:

• Mein FHEM läuft auf einem Raspberry Pi 2 unter Raspbian Wheezy und ist meist recht aktuell (FHEM und Raspbian)
• Problem besteht erst seit heutigem Update
• vor Update war alles total in Ordnung (mein letztes Update war ca vor einem Monat oder so)
• momentan arbeite ich wieder mit einem Backup - da ist alles wieder in Ordnung
• sobald meine Bewegungsmelder ein "if" triggern, steigt die CPU-Last in die Decke und verleibt dort mindestens ein paar Minuten
• um einen derartigen Fehler auszulösen, genügen schon einfachste Bedingungsabfragen
• scheinbar liegt es (zumindest für meine Augen) am "syscall" "clone" - siehe strace unten

Hat sich in letzter Zeit was geändert bei der Behandlung von if-Abfragen oder so?

Auszugsweise zu meinem System:
Ich habe Bewegungsmelder eingebunden:
(entprellt habe ich die Melder im Arduino-Sketch - der Arduino sendet nur alle 10 Sekunden, falls selber Melder auslöst))

Code Auswählen Erweitern

define PIR_3_Kueche AliRF 04EDE9
attr PIR_3_Kueche IODev Arduino_nano_433
attr PIR_3_Kueche alias Bewegungsmelder Küche Real-Device
attr PIR_3_Kueche group Bewegungsmelder
attr PIR_3_Kueche model China_PIR_433_MHz
attr PIR_3_Kueche subType motionDetector

Aus diversen Gründen triggert der eigentliche Melder (oben) nur einen Dummy (mit dem ich alle weiteren Prozesse steuere):

Code Auswählen Erweitern

### STATE per notify in DUMMY übertragen schreiben (wenn Bewegung, dann setze STATE auf "motion")
define n_PIR_3_Kueche_STATE_motion_setzen_bei_Bewegung notify PIR_3_Kueche:motion.* {fhem("set Dummy_PIR_3_Kueche motion")}
attr n_PIR_3_Kueche_STATE_motion_setzen_bei_Bewegung group notify_Bewegungsmelder

Code Auswählen Erweitern

### Dummy
# Mit dem Dummy wird von da an gearbeitet, das Real-Device ist nur der "Trigger-Erbringer"
define Dummy_PIR_3_Kueche dummy
attr Dummy_PIR_3_Kueche alias Bewegungsmelder Küche
attr Dummy_PIR_3_Kueche group Bewegungsmelder
attr Dummy_PIR_3_Kueche model China_PIR_433_MHz
attr Dummy_PIR_3_Kueche subType motionDetector

Auf dem Dummy hängen dann die dieversen Aktionen (hier zum Beispiel ein milight-LED-Stripe, der je nach Tageszeit geschaltet wird):
Ob der Code sehr schön ist, oder noch optimiert werden kann, sei bitte mal dahingestellt - er funktionierte.
Anregungen zur Verbesserung nehme ich natürlich immer gierig auf, aber hier wollte ich Euch nicht damit belästigen.
Per DOIF hab ichs auch schon versucht, wird aber auch nicht gerade einfacher für die CPU...

Code Auswählen Erweitern

### Küchen-LEDs ###
# Reihenfolge:
# - Früh
# - Tag (Montag bis Freitag - an Feiertagen und Urlaub)
# - Tag (Nur Freitag Nachmittag)
# - Abend
# - Nacht
# - Ausschaltverzögerung
define Kueche_LED_Stripe_mit_Bewegungsmelder_PIR_3_Kueche notify Dummy_PIR_3_Kueche:motion.* {\
if ((ReadingsVal("Kueche_LED_Stripe","state","") eq "off") && ($hms gt "05:30:01" and $hms lt "08:30:00") && (ReadingsVal("Urlaubs_Status_abwesend","state","") eq "NEIN")) {fhem("set Kueche_LED_Stripe HSV 130,100,100;; defmod Kueche_LED_Stripe_mit_Bewegungsmelder_PIR_3_Kueche_aus at +00:02:00 set Kueche_LED_Stripe off");;}\
elsif ((ReadingsVal("Kueche_LED_Stripe","state","") eq "off") && ($hms gt "08:30:01" and $hms lt "16:30:00") && (ReadingsVal("Urlaubs_Status_abwesend","state","") eq "NEIN") && (ReadingsVal("Ecomodus_Status","state","") eq "NORMAL") && ((ReadingsVal("Urlaubs_Status_anwesend","state","") eq "JA") || (ReadingsVal("Urlaubs_Status_Mario_alleine_anwesend","state","") eq "JA") || (ReadingsVal("Feiertags_Status","state","") eq "JA") || (ReadingsVal("Freier_Tag_Status","state","") eq "JA") || (ReadingsVal("12_Stunden_Frei_Status","state","") eq "JA") || (ReadingsVal("36_Stunden_Frei_Status","state","") eq "JA") || ($we)) ) {fhem("set Kueche_LED_Stripe HSV 330,100,100;; defmod Kueche_LED_Stripe_mit_Bewegungsmelder_PIR_3_Kueche_aus at +00:02:00 set Kueche_LED_Stripe off");;}\
elsif ((ReadingsVal("Kueche_LED_Stripe","state","") eq "off") && ($hms gt "12:30:01" and $hms lt "16:30:00") && ($wday == 5) && (ReadingsVal("Urlaubs_Status_abwesend","state","") eq "NEIN") && (ReadingsVal("Ecomodus_Status","state","") eq "NORMAL") && (ReadingsVal("Urlaubs_Status_anwesend","state","") eq "NEIN") && (ReadingsVal("Urlaubs_Status_Mario_alleine_anwesend","state","") eq "NEIN") && (ReadingsVal("Feiertags_Status","state","") eq "NEIN") && (ReadingsVal("Freier_Tag_Status","state","") eq "NEIN") && (ReadingsVal("12_Stunden_Frei_Status","state","") eq "NEIN") && (ReadingsVal("36_Stunden_Frei_Status","state","") eq "NEIN")) {fhem("set Kueche_LED_Stripe HSV 330,100,100;; defmod Kueche_LED_Stripe_mit_Bewegungsmelder_PIR_3_Kueche_aus at +00:02:00 set Kueche_LED_Stripe off");;}\
elsif ((ReadingsVal("Kueche_LED_Stripe","state","") eq "off") && ($hms gt "16:30:01" and $hms lt "22:30:00") && (ReadingsVal("Urlaubs_Status_abwesend","state","") eq "NEIN")) {fhem("set Kueche_LED_Stripe HSV 4,100,80;; defmod Kueche_LED_Stripe_mit_Bewegungsmelder_PIR_3_Kueche_aus at +00:02:00 set Kueche_LED_Stripe off");;}\
elsif ((ReadingsVal("Kueche_LED_Stripe","state","") eq "off") && ($hms gt "22:30:01" or $hms lt "05:30:00") && (ReadingsVal("Urlaubs_Status_abwesend","state","") eq "NEIN")) {fhem("set Kueche_LED_Stripe HSV 257,100,45;; defmod Kueche_LED_Stripe_mit_Bewegungsmelder_PIR_3_Kueche_aus at +00:02:00 set Kueche_LED_Stripe off");;}\
elsif ((defined($defs{'Kueche_LED_Stripe_mit_Bewegungsmelder_PIR_3_Kueche_aus'})) && (ReadingsVal("Urlaubs_Status_abwesend","state","") eq "NEIN")) {fhem("defmod Kueche_LED_Stripe_mit_Bewegungsmelder_PIR_3_Kueche_aus at +00:02:00 set Kueche_LED_Stripe off");;}\
}
attr Kueche_LED_Stripe_mit_Bewegungsmelder_PIR_3_Kueche group notify_Bewegungsmelder


Zu meinem Problem:
Sogar sehr triviale trigger treiben die CPU-Last in unbekannte Höhen und blockieen FHEM für Minuten
zum Beispiel dieses einfache Schnipsel:
(Mit obigem Lichtsteuerungschnipsel kriegt sich der Pi fast gar nicht mehr ein - es dauert ca 15 Minuten, bis die CPU-Last wieder fällt)

Code Auswählen Erweitern

define n_PIR_3_Kueche_STATE_motion_setzen_bei_Bewegung notify PIR_3_Kueche:motion.* {fhem("set Dummy_PIR_3_Kueche motion")}

Was ich bisher unternommen habe:
Im fhem-Log findet sich nichts (auch nicht mit "verbose 5)"

Auszug aus "top":

Code Auswählen Erweitern

top - 13:30:59 up 2 days, 18:50,  3 users,  load average: 1,12, 1,69, 1,61
Tasks: 133 total,   2 running, 131 sleeping,   0 stopped,   0 zombie
%Cpu(s): 26,3 us,  0,5 sy,  0,0 ni, 73,0 id,  0,2 wa,  0,0 hi,  0,0 si,  0,0 st
KiB Mem:    948016 total,   881980 used,    66036 free,    86016 buffers
KiB Swap:        0 total,        0 used,        0 free,   362984 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND                                                                                                         
24463 fhem      20   0 60732  57m 5716 R 100,1  6,2  17:53.11 perl                                                                                                           
24442 root      20   0  4700 2544 2116 R   0,7  0,3   0:10.71 top

Auszug aus "strace":

Code Auswählen Erweitern

strace -c -p 24463
Process 24463 attached - interrupt to quit

^CProcess 24463 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
99.91    0.046814        3901        12           clone
  0.09    0.000043           0      1305           gettimeofday
  0.00    0.000000           0        55           read
  0.00    0.000000           0        63           write
  0.00    0.000000           0         6           open
  0.00    0.000000           0        34         2 close
  0.00    0.000000           0        10         5 kill
  0.00    0.000000           0        10           pipe
  0.00    0.000000           0        82        26 ioctl
  0.00    0.000000           0        17        11 wait4
  0.00    0.000000           0        20        16 _llseek
  0.00    0.000000           0        57           select
  0.00    0.000000           0         2           nanosleep
  0.00    0.000000           0        38           rt_sigaction
  0.00    0.000000           0         4           rt_sigprocmask
  0.00    0.000000           0      1227           stat64
  0.00    0.000000           0        10           fstat64
  0.00    0.000000           0        20           fcntl64
  0.00    0.000000           0         6           accept
  0.00    0.000000           0         4           sendto
  0.00    0.000000           0         6           setsockopt
------ ----------- ----------- --------- --------- ----------------
100.00    0.046857                  2988        60 total

[rudolfkoenig]

Im fhem-Log findet sich nichts (auch nicht mit "verbose 5)"

Dann ist vmtl. die Festplatte voll. Wenn du meinst, dass da fuer dich nichts verwertbares drin steht, dann solltest du es trotzdem anhaengen, vlt. kann jemand damit was anfangen. Am besten mit gesetzten "attr global mseclog".

[Hardlife]

Hallo!


Vielen Dank für die rasche Reaktion und Unterstützung.

Dann ist vmtl. die Festplatte voll

Eigentlich nicht, aber Du hast Recht, ich hätt den Log gleich anhängen können.
Nur weil ich mit meinem *fachkundigen* Auge nichts entdecke, heißt das noch lange nichts 

Ich habe den Log gleich mal angehängt.
Habe auf verbose 5 geschaltet und auch das andere Attribut angewandt.
Ab der Stelle "2017.02.04 20:10:00.657" gehts los.
Ich habe bis 20:10 gewartet und bin dann mal durch die Wohnung um alle Melder auszulösen.

Ergebnis:
CPU-Last schnellte wie erwartet rauf und ein paar Minuten ging Nichts mehr.


Vielen Dank vorab,
Hardlife

[rudolfkoenig]

createNotifyHash dauert bei dir 4.3sec, vmtl. ist das der Grund. Sie wird nach jedem define oder modify durchgefuehrt.
Kannst du bitte ein "list .* NOTIFYDEV" hier anhaengen, oder, noch besser, die komplette fhem.cfg?

Kurzfristige Linderung des Problems (aka Workaround):"defmod/modify XX at +YY ZZ" nach "sleep YY; ZZ" umbauen. Wobei YY von HH:MM:SS nach Sekunden zu konvertieren ist.

[Hardlife]

Hi!


Danke schön.

Im Anhang der list-Auszug...

Die gesamte fhem.cfg anzuhängen könnte etwas dauern. Ist es unbedingt notwendig?
Meine .cfg hat ca. 570 Kilobyte und ich müsste erst alle Adressen und Passwörter finden und entfernen.
(Nicht falsch verstehen, ist kein Misstrauen, aber das alles öffentlich hochzuladen wäre doch etwas unvorsichtig)

Workaround:
Heisst das, ich müsste

Code Auswählen Erweitern

defmod Adventskranz_mit_Bewegungsmelder_PIR_1_Wohnzimmer_aus at +00:02:00 set Adventskranz_ein_aus_Dummy off
so abändern

Code Auswählen Erweitern

sleep 120; set Adventskranz_ein_aus_Dummy off
Oder verstehe ich was falsch?

Dann verlüre ich jedoch den Vorteil von defmod/modify, und genau darum ginge es bei meinen Einsatzzwecken.
Die Einschaltdauer verlängert sich mit jedem trigger, ohne den Funkverkehr zu belasten.


Danke,
Hardlife

[Hardlife]

Ich habe auf die schnelle mal den unkritischen Bereich mit den Bewegungsmeldern aus der Config rausgeschnitten.
(siehe Anhang)

Vielleicht hilft ja das schon bei der Suche.

Ich weiß jedoch nicht, ob der Fehler auch bei den anderen defmod´s auftritt.
Mir fällt er eben gerade bei den Bewegungsmeldern extrem auf...

[rudolfkoenig]

Das Problem ist aus dem "list" Output ersichtlich: du hast 441 Definitionen die Events auswerten, und vermutlich noch viel mehr Definitionen insgesamt.

Um solche Installationen wie deine zu optimieren gibt es das sog. NOTIFYDEV: wenn es gesetzt ist, dann werden diese "Auswerter" nur fuer Events von dem passenden Geraet aufgerufen. Leider muss dafuer die interne Struktu nach jedem define/modify neu erstellt werden (createNotifyDev)

Neuerdings werden fuer NOTIFYDEV auch Regexp Ausdruecke (die mit .*) zugelassen, dafuer werden alle Definitionen in der Schleife geprueft, was in deinem Fall zu einer merkbaren Bremse geworden ist.

Damit ich dein Fall "zurueckoptimieren" kann, braeuchte ich die Definition aller Geraete, allerdings wuerden mir die "define" Zeilen aus fhem.cfg reichen, diese vom Passwort zu befreien sollte einfacher sein.

[Hardlife]

Kein Problem, ich setze mich dran und reiche die fhem.cfg heute oder morgen nach.

Danke nochmal für Deine Unterstützung.

[Hardlife]

Sodale, ging doch flotter als gedacht... 

Anbei nun meine (bereinigte) fhem.cfg und meine 99_myutils.pm dazu.
Begriffe/Daten, die ich ersetzt habe, wurden mit der Buchstabenfolge "BLABLA" ersetzt, falls Du in den Dateien danach suchen möchtest.

Kurz noch zu meiner Ehrenrettung:

• Ich weiß, daß die config locker noch 15 - 20 % Optimierungspotential hergibt (Ablaufoptimierung - die #Kommentare sind mir erst mal schnuppe)
• ständig bin ich am verbessern und in der Vergangenheit habe ich bereits 3 große "Reinigungsrunden" über die config gefahren, weitere sind geplant
• es ist eben leider ein über 2 Jahre gewachsenes System
• begonnen hat alles mit 3 Baumarkt-Steckdosen und mein Kenntnisstand war damals dementsprechend
• die config hatte schon Mal über 800kB 

Ich weiß, es wird empfohlen, über das Frontend zu konfigurieren, aber Abstraktes kann ich mir leichter vorstellen, wenn ich den Code vor mir habe.
Da verbinden sich dann all die Teile zu einem "großen Zahnräderwerk"...


Liebe Grüße,
Hardlife

[rudolfkoenig]

Ich habe createNtfyHash neu geschrieben, und damit die Geschwindigkeit etwa verdoppelt (bei mir von 370ms auf 170ms). Weiterhin wird bei modify von einem Geraet, was kein NotifyFn hat (wie at), diese Funktion nicht mehr aufgerufen.

[Hardlife]

Hi!

Danke für die Mühe.

- Mit einem Update würde ich also bereits die neue Version erhalten?
- Wenn ich den Vorpost richtig verstanden habe, sollte man .* nach Möglichkeit weitestgehend vermeiden?


LG,
Hardlife

[rudolfkoenig]

- Mit einem Update würde ich also bereits die neue Version erhalten?

Ja, wie ueblich morgen ab 8, oder ab sofort per SVN

- Wenn ich den Vorpost richtig verstanden habe, sollte man .* nach Möglichkeit weitestgehend vermeiden?

Du kannst statt .* eine explizite Aufzaehlung verwenden, das duerfte in Deinem Fall (68 notify/etc mit .*, 862 Definitionen, langsamer Hardware) pro createNtfyHash Aufruf mit dem neuen Code geschaetzt 10-20% (0.2-0.4sec) bringen. Ich vermute, dass du nach dem Patch keine Probleme hast, wenn doch, wuerde ich eher in einem schnelleren Hardware investieren. Mein 7 Jahre alter Laptop war ohne Optimierung 12-mal schneller, damit merkt man das Problem gar nicht, man muss messen.

[Hardlife]

Danke nochmal für die tolle Unterstützung.

Nun läufts wieder optimal. 
Sehr performat alles.

Und danke für den Wink mit dem .*
Hab ich mir zu Herzen genommen und die Definitionen bereits geändert.