Systemlast eines notify

[VolkerGBenner]

Ich frage mich gerade wie hoch die Systemlast eines einzelnen notify ist (Speicher- und/oder Prozessorlast) und daraus resultierend, ob es eine Obergrenze für die Zahl der eingesetzten notifies gibt, bis es spürbar die Performanz belastet.

Bevor ich da jetzt selber empirisch ran gehe, frage ich lieber erstmal nach, ob es da schon Erfahrungen zu gibt.

Gruß
Volker

[PatrickR]

Hi!

Ich frage mich gerade wie hoch die Systemlast eines einzelnen notify ist (Speicher- und/oder Prozessorlast) und daraus resultierend, ob es eine Obergrenze für die Zahl der eingesetzten notifies gibt, bis es spürbar die Performanz belastet.

Uff, da hast Du Dir ein Thema ausgesucht. Eine Obergrenze für Notifys in Form einer festen Anzahl kann es aus meiner Sicht nicht geben. Notifys laufen nicht dauerhaft (wie ein Prozess oder Thread) sondern deren Code wird exakt dann ausgeführt, wenn ein Event auftritt, auf das das NOTIFYDEV des jeweiligen Notifys matcht. Sonst wird überhaupt kein Code ausgeführt. Trifft beides zu, hängt die Systemlast davon ab, wie umfangreich der Code des jeweiligen Notifys ist bzw. der Codezweig, der das aktuelle Event bearbeitet.

Aus den genannten Gründen ist die eigentlich spannendere Frage, wie lange ein jeweiliges Notify die Eventverarbeitung von FHEM aufhält. Das findest Du sehr gut mit apptime raus:

Code Auswählen Erweitern

active-timers: 90; max-active timers: 118; max-timer-load: 17  min-tmrHandlingTm: 0.0ms; max-tmrHandlingTm: 3033.5ms; totAvgDly: 11.1ms

 name                                    function                              max    count      total  average  maxDly  avgDly TS Max call    param Max call
 [...]
 N_HmIP_Sabotage__alert                  notify_Exec                            17  5970199  419941.28    0.07    0.00    0.00 06.01. 18:29:58 HASH(N_HmIP_Sabotage__alert); HASH(UG.AZ.Steckdosen01bis12)
Hier siehst Du, dass mein Notify N_HmIP_Sabotage__alert seit dem Start von Apptime 5970199 mal aufgerufen wurde und FHEM insgesamt 419941.28ms "aufgehalten" hat. Du siehst aber auch, dass es maximal 17ms pro Ausführung benötigt hat und durchschnittlich sogar nur 0.07ms. D. h. es wird sehr oft ausgeführt aber die Ausführung geht sehr schnell.

Bedeutet: Schau, dass die Notifys sehr genau matchen, insbesondere auf den Gerätenamen und optimiere den Code.

/Edit:
Der Speicherverbrauch eines Notify sollte auch überschaubar sein. Mit list bekommst Du eine sehr grobe Idee davon, was für das jeweilige Notify im Speicher rumliegt. Insgesamt würde ich mir über Notifys und auch Watchdogs keine Gedanken machen. Da gibt es schon ganz andere Dickschiffe, DOIF z. B.

Patrick

[VolkerGBenner]

Viele Dank für das Input. Schon sehr aufschlussreich.

Was die eigentliche Frage auch etwas eingrenzt. Die Verarbeitung der notify-Anweisungen kommt ja, wie du schon schriebst, nur zum Tragen, wenn es getriggert wurde. Das ist überschaubar.

Was mich also präziser beschäftigt ist, wie das eigentliche Triggern bei notifies funktioniert und ob die Anzahl der notifies überhaupt einen Einfluss auf diesen Prozess hat.

Wie ist der Ablauf, wenn ein Ereignis eintritt, damit das notify erfährt, dass es reagieren muss. Ich nehme an, die Antwort liegt irgendwie in der fhem.pl vergraben, aber um das im Detail zu verstehen sind meine Perl-Kenntnisse noch zu oberflächlich.

 

[PatrickR]

Hi!

Wie ist der Ablauf, wenn ein Ereignis eintritt, damit das notify erfährt, dass es reagieren muss. Ich nehme an, die Antwort liegt irgendwie in der fhem.pl vergraben, aber um das im Detail zu verstehen sind meine Perl-

Wenn ein Event kommt, prüft fhem.pl, welche Geräte (z. B. Notifys) sich dafür interessieren. Ursprünglich war es so, dass alle(!) Geräte, die Events verarbeiten, durchiteriert wurden und dann ihrerseits selbst entscheiden konnten, was sie mit dem Event anstellen (oftmals: nichts). Nun hat Rudi(?) vor einiger Zeit NOTIFYDEV eingeführt. Das ist vereinfacht gesagt ein Katalog, mit dem fhem.pl an Hand des Devices, dass das Event wirft prüfen kann, welche Geräte, die auf Events hören, überhaupt ein Interesse haben könnten. Das heisst, dass nur noch ein deutlich kleinerer Teil an "Kandidaten" überhaupt ausgeführt werden.

Ich hoffe, das bringt etwas Licht ins Dunkel.

/Edit:
Wenn Du es nachlesen möchtest:
https://svn.fhem.de/trac/browser/trunk/fhem/fhem.pl ab Zeile 3881. Ab Zeile 3895 wird über die o. g. Kandidaten iteriert, indem deren NotifyFn aufgerufen wird. Der Code für die NOTIFYDEV-Optimierung ist allerdings etwas über fhem.pl verteilt und verbirgt sich im Codeblock in ntfyHash.

/Edit2:
Mist, Udo war schneller. Und ausführlicher.

Patrick

[betateilchen]

Wenn Du Dein FHEM für kurze Zeit auf verbose 5 stellst, kannst Du eigentlich schön beobachten, wie das alles abläuft.

Du betrachtest das Thema viel zu einseitig, wenn Du diese Frage nur auf notify begrenzt, der der gesamte Ablauf gilt für alle device types, die auf irgendwas, das in FHEM passiert, reagieren wollen.

Jedes device registriert sich bei FHEM in einer Tabelle und teilt so mit, dass es gerne über Änderungen informiert werden möchte. Bei dieser Registrierung kann ein bestimmtes device auch relativ genau bestimmen, über welche Art von Änderung es informiert werden möchte. Beispielsweise "alle Änderungen an device A" oder "alle Änderungen von reading X in den devices E,F und G". Im Prinzip ist das die regex, die Du (bleiben wir beim notify) dort im define angibst.

fhem.pl startet bei jeder Änderung (aka: event) die "notify loop" und prüfen, welche devices über die eingetretene Änderung informiert werden möchte.

Was da genau passiert: Ein Modul-type registriert beim erstmaligen Laden (i.d.R. beim define des ersten devices dieses TYPE) den Namen einer NotifyFn(), die im Modul selbst ausprogrammiert ist.

Diese NotifyFn() wird dann für alle devices aufgerufen, die sich als "Empfänger" der Änderung registriert haben.

Ich nehme an, die Antwort liegt irgendwie in der fhem.pl vergraben

Naja, "vergraben" würde ich das nicht nennen.
Das Ganze passiert in der internen Funktion DoTrigger() und um den prinzipiellen Ablauf, den ich gerade beschrieben habe, dort wiederzufinden, braucht man keine tiefgreifenden perl Kenntnisse.

Code Auswählen Erweitern

    if($attr{global}{verbose} >= 5) {
      Log 5, "Starting notify loop for $dev, " . scalar(@{$hash->{CHANGED}}) .
        " event(s), first is " . escapeLogLine($hash->{CHANGED}->[0]);
    }
    createNtfyHash() if(!%ntfyHash);
    $hash->{NTFY_TRIGGERTIME} = $now; # Optimize FileLog
    my $ntfyLst = (defined($ntfyHash{$dev}) ? $ntfyHash{$dev} : $ntfyHash{"*"});
    foreach my $n (@{$ntfyLst}) {
      next if(!defined($defs{$n}));     # Was deleted in a previous notify
      my $r = CallFn($n, "NotifyFn", $defs{$n}, $hash);
      $ret .= " $n:$r" if($r);
    }
    delete($hash->{NTFY_TRIGGERTIME});
    Log 5, "End notify loop for $dev";

Die Logmeldungen am Anfang und Ende dieses Codeblocks sind der Grund, warum ich eingangs empfohlen habe, den Loglevel mal auf 5 zu stellen und dann ins Log zu schauen. Da findet man das schön wieder.

Grundsätzlich solltest Du Dir aber als Anwender über solche Internas von FHEM keine allzu großen Gedanken machen. Da wird schon vieles von FHEM selbst soweit opimiert, dass es sinnvoll und ressourcenschonend abläuft.

Einfache Regel: je konkreter eine "Bedingung" (aka: regex) vom Anwender definiert wird, z.B. in notify, FileLog oder auch in einem userReading, umso besser ist das. Denn alle diese Aktionen (und die vieler anderer Module auch) basieren auf dem gleichen Benachrichtigungsablauf.


Für die Korinthenkacker:
Ja, mir ist klar, dass das Ganze natürlich noch etwas komplexer abläuft.
Aber die eigentliche Frage "wie erfährt ein notify, dass es reagieren muss" sollte damit verständlich beschrieben sein.

[betateilchen]

/Edit2:
Mist, Udo war schneller. Und ausführlicher.

Ja, aber mein Schreiben hat eben etwas länger gedauert als Deine ursprüngliche "Kurzantwort" 

[Damian]

Hier mal ein konkretes Beispiel, um ein Gefühl für den geringen Overhead zu bekommen.

Die Abarbeitung eines notifys ist in Bruchteilen einer Millisekunde erlegt. Ob es bei jedem Event des Systems aufgerufen wird oder nicht siehst du am Internal NOTIFYDEV.

Dort stehen die Regex-Angaben der Devices, durch deren Events es vom fhem-Hauptprozess aufgerufen wird. Ist kein NOTIFYDEV-Internal im notify gesetzt, weil die Regex "ungünstig" war, muss das notify-Device sich jedes Event anschauen und selbst auswerten. Das dauert in der Regel ein paar Bruchteile einer Millisekunde länger.

Ich habe mal zum Test zwei Devices definiert, die auf das Vorkommen des Wortes "vaillant" im Namen des Devices reagieren sollen, aber nichts tun sollen um nur den Overhead zu sehen.

Code Auswählen Erweitern

defmod vaillant_notify_1 notify .*vaillant.* {}
und das entsprechende in DOIF

Code Auswählen Erweitern

defmod vaillant_DOIF_1 DOIF (["vaillant"]) ()

Während Notify kein NOTIFYDEV gesetzt hat, hat DOIF eins gesetzt.

Die Ergebnisse nach paar Minuten Laufzeit sehen so aus:

Code Auswählen Erweitern

active-timers: 97; max-active timers: 117; max-timer-load: 17  min-tmrHandlingTm: 0.0ms; max-tmrHandlingTm: 357.5ms; totAvgDly: 2.8ms

 name                                     function                               max    count      total  average   maxDly   avgDly TS Max call     param Max call
 vaillant_notify_1                        notify_Exec                              0     4501     251.55     0.06     0.00     0.00 13.01. 16:15:22 HASH(vaillant_notify_1); HASH(vaillant_DOIF_1)
 vaillant_notify_1                        notify_Set                               0        3       0.15     0.05     0.00     0.00 13.01. 16:19:40 HASH(vaillant_notify_1); vaillant_notify_1; ?
 vaillant_DOIF_1                          DOIF_Get                                 0        1       0.00     0.00     0.00     0.00 13.01. 16:20:40 HASH(vaillant_DOIF_1); vaillant_DOIF_1; ?
 vaillant_DOIF_1                          DOIF_Notify                              1      593     132.94     0.22     0.00     0.00 13.01. 16:15:22 HASH(vaillant_DOIF_1); HASH(vaillant)
 vaillant_DOIF_1                          DOIF_Set                                 0        8       0.13     0.02     0.00     0.00 13.01. 16:20:40 HASH(vaillant_DOIF_1); vaillant_DOIF_1; ?

Die Anzahl der Aufrufe und die verbrauchte Zeit in Millisekunden kannst du selbst auswerten. Wäre die Regex beim notify eindeutiger, dann wäre auch notify in der Lage gewesen NOTIFYDEV zu setzen und hätte die gleiche Anzahl von Aufrufen, wie das DOIF und damit eine günstigere Bilanz. Wir reden aber hier von Millisekunden, daher braucht man sich an dieser Stelle keine großen Gedanken machen. Es hängt vor allem davon ab, wie lange die Ausführung eines Befehls dauert, das wurde hier allerdings nicht betrachtet, da beide Devices nichts zu tun hatten.

[betateilchen]

Ich habe mal zum Test zwei Devices definiert, die auf das Vorkommen des Wortes "vaillant" im Namen des Devices reagieren sollen

Code Auswählen Erweitern

defmod vaillant_notify_1 notify .*vaillant.* {}

Falsch.

Das von Dir definierte notify reagiert auf das Vorkommen des Wortes "vaillant" im gesamten event, nicht nur im Namen des devices.

[VolkerGBenner]

Habe "notify loop" im Log gefunden. Ist im zeitlichen Ablauf ja quasi kaum wahrzunehmen, bei allem anderen, was da so passiert. Habe ich das richtig beobachtet, dass mehrere notify loops gleichzeitig abgearbeitet werden oder ist das eine Verzögerung im Log. Habe es mehrfach gesehen, dass ein loop innerhalb eines zuvor begonnenen loops  gestartet und beendet wird.

Auf jeden Fall mache ich mir keine Gedanken mehr darüber, das System mit zuvielen notifies zu überlasten.

Danke für die sehr lehrreichen Ausführungen.

Und wieder einmal hab ich die fhem-community noch etwas lieber. 

[betateilchen]

Habe ich das richtig beobachtet, dass mehrere notify loops gleichzeitig abgearbeitet werden

Das kann durchaus passieren und ist grundsätzlich auch erstmal kein Problem.

Das Einzige, was dabei passieren könnte, wäre eine Endlosschleife, wenn im Ausführungsteil des notify das auslösende device:reading selbst verändert würde und dadurch das notify wieder getriggert wird.

Diese Endlosschleife wird aber von FHEM automatisch unterbunden. Deshalb ist z.B. auch die Verwendung von "setreading" innerhalb eines userReadings verboten und wird mit einer entsprechenden Fehlermeldung abgelehnt:

Code Auswählen Erweitern

Log 1, "'setreading $def' called form userReadings is prohibited";

[Jamo]

Wenn man feststellen will, wie notifydev denkt, kann man folgendes in die Kommandozeile eingeben:

Code Auswählen Erweitern

{ notifyRegexpCheck("myregexp") }Um festzustellen, bei welchem notify/watchdog/sequence das notifydev nicht aktiv ist, folgende Befehle für die Kommandozeile:

Code Auswählen Erweitern

count TYPE=notify
count TYPE=notify:FILTER=NOTIFYDEV~.+
list TYPE=notify:FILTER=NOTIFYDEV!~.+ DEF
list TYPE=watchdog:FILTER=NOTIFYDEV!~.+ DEF
list TYPE=sequence:FILTER=NOTIFYDEV!~.+ DEF

[Damian]

Ich habe mal zum Test zwei Devices definiert, die auf das Vorkommen des Wortes "vaillant" im Namen des Devices reagieren sollen

Code Auswählen Erweitern

defmod vaillant_notify_1 notify .*vaillant.* {}

Falsch.

Das von Dir definierte notify reagiert auf das Vorkommen des Wortes "vaillant" im gesamten event, nicht nur im Namen des devices.

Das ist für meine Betrachtung irrelevant, da es keine Events bei mir gibt, bei denen woanders als im Devicennamen "vaillant" vorkommt. Und eine komplexere Regex beschränkend auf "vaillant" im Devicenamen führt auch nicht zum Setzen von NOTIFYDEV im notify.

[betateilchen]

Das ist für meine Betrachtung irrelevant, da es keine Events bei mir gibt, bei denen woanders als im Devicennamen "vaillant" vorkommt.

Ändert nichts daran, dass Deine getroffene Aussage falsch ist (und bleibt).

[Damian]

Das ist für meine Betrachtung irrelevant, da es keine Events bei mir gibt, bei denen woanders als im Devicennamen "vaillant" vorkommt.

Ändert nichts daran, dass Deine getroffene Aussage falsch ist (und bleibt).

Dann hast du den Sinn meiner Aussage nicht verstanden.

[betateilchen]

Dann hast du den Sinn meiner Aussage nicht verstanden.

Doch, habe ich.

Aber die Aussage, dass sich Deine regex "auf den Namen eines devices" bezieht, stimmt halt für den Fall eines notify nicht. Da kannst Du noch so viel versuchen zu erklären - falsch bleibt falsch.