Neues Modul: 98_FREEZEMON Freezes monitoren und Verursacher identifizieren

Begonnen von KernSani, 05 Februar 2018, 23:27:22

Vorheriges Thema - Nächstes Thema

KernSani

Zitat von: marvin78 am 09 Februar 2018, 09:19:09
Habe ich nicht. Doof hast nur du geschrieben. Was diese seltsamen gplot Dateien sollen, verstehe ich nicht. Sowas kann jeder selbst schnell erstellen.
Ich hatte deinen Kommentar auf die Aussage zum "halbgaren" Modul bezogen.
Wenn du dich auf die gplots beziehst hast du Recht, habe ich ja auch oben schonmal gesagt. 
RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...

DarkT

Zitat von: marvin78 am 09 Februar 2018, 09:19:09
Habe ich nicht. Doof hast nur du geschrieben. Was diese seltsamen gplot Dateien sollen, verstehe ich nicht. Sowas kann jeder selbst schnell erstellen.

Richtig, dass kann bestimmt jeder. Ich hatte ihn darum gebeten mir ein Beispiel zu geben. Liegt also mehr an meiner fehlenden Erfahrung.
Also Puls runter und wieder auf das wesentliche konzentrieren, man braucht keinem einen Vorwurf für eine freiwillig erbrachte Leistung machen. Danke

Zum Them, Kerni... habe ich das richtig verstanden?

Zitat von: DarkT am 09 Februar 2018, 08:15:49
Die folgenden Meldung finde ich im Log (verbose 5)



2018.02.09 08:29:55 3: CALVIEW myCalView - CALENDAR:MyCalendar triggered, updating CALVIEW myCalView ...
2018.02.09 08:30:02 5: CALVIEW myCalView - nextday = 10 , endday = 10 , startday = 09 , btime 00:00:00 , etime 00:00:00



.... scheint, doch dass das Auslesen des Kalenders 7 Sekunden dauert... und das blockierend?

Dazu passt dann auch die Ausgabe von apptime:


maxDly   avgDly TS Max call     param Max call
myCalView                                CALVIEW_Notify                        6769      216    6789.92    31.43



marvin78

Zitat von: DarkT am 09 Februar 2018, 09:27:57
man braucht keinem einen Vorwurf für eine freiwillig erbrachte Leistung machen. Danke


Doch, wenn sie sinnlos mit dem update kommen schon. Mein Puls ist im Übrigen bei 60. Ich lasse mir lediglich nicht gerne Worte in den Mund legen.

KernSani

Zitat von: marvin78 am 09 Februar 2018, 09:31:49
Doch, wenn sie sinnlos mit dem update kommen schon. Mein Puls ist im Übrigen bei 60. Ich lasse mir lediglich nicht gerne Worte in den Mund legen.
Alles gut. Ist ja geklärt. Die gplots einzuchecken war ein Fehler, (aber kriege ich die wieder raus?)

Zitat von: DarkT am 09 Februar 2018, 09:27:57
Zum Them, Kerni... habe ich das richtig verstanden?
Ja, so würde ich das auch interpretieren. Prinzipiell hast du jetzt alle Infos um im entsprechenden Unterforum nachzufragen, woran das liegen... 
RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...

LuckyDay

Könntest du so einen "set <> clear "einbauen um die alten freezes zu löschen?

Danke


binford6000

ZitatKönntest du so einen "set <> clear "einbauen um die alten freezes zu löschen?
siehe hier:
https://forum.fhem.de/index.php/topic,83909.msg762434.html#msg762434
VG Sebastian

DarkT

Zitat von: KernSani am 09 Februar 2018, 09:45:24
Alles gut. Ist ja geklärt. Die gplots einzuchecken war ein Fehler, (aber kriege ich die wieder raus?)
Ja, so würde ich das auch interpretieren. Prinzipiell hast du jetzt alle Infos um im entsprechenden Unterforum nachzufragen, woran das liegen...

Danke, dann habe ich jetzt verstanden wie es funktioniert. Aus diesen Erfahrungen könnte man das Modul wie folgt erweitern, so als Ideen:


  • Erweiterte Analyse aktivieren/deaktivieren
  • Bei erweiterter Analyse -> Log Level auf verbose 5 setzten, bei freeze "apptime" ausführen und sowohl diese Ausgabe als auch Teilabschnitt des Logs zum Freeeze wegspeichern - aber das ist natürlich nur ein Traum ^^

Benni

Zitat von: marvin78 am 09 Februar 2018, 09:19:09
Was diese seltsamen gplot Dateien sollen, verstehe ich nicht. Sowas kann jeder selbst schnell erstellen.

Es ist m.E. schon in Ordnung, die zur Verfügung zu stellen, auch wenn sie simpel sind, allerdings gehören die definitiv nicht mit in die Standardverteilung von FHEM. Ich würde die auch, wenn überhaupt, in contrib sehen (wollen).

Oder einfach hier im Forum als Beispiele anhängen.

Ansonsten finde ich das Modul und die Zusatzmöglichkeiten gegenüber perfmon prima!

Vielen Dank dafür!

gb#

justme1968

eigentlich gehört es zu apptime, aber da hier gerade fleissig getestet wird:

ich hätte zwei vorschlage für apptime:
1. statt nur die funktionsnamen zu loggen könnte man auch den callstack loggen.
wenn man den callstack als key verwendet kann man unterscheiden über welchen weg genau der aufruf einer funktion die zeit verbraucht. und man kann sehen auf welcher ebene die zeit verbraucht wird.

das schaut dann z.b. so aus: name                                     function                               max    count      total  average   maxDly   avgDly TS Max call     param Max call
telnetPort_192.168.161.236_56587         telnet_Read                           2012        2    2012.18  1006.09     0.00     0.00 09.02. 18:55:12 HASH(telnetPort_192.168.161.236_56587)
timer                                    telnet_Read->dummy_Set                2011        2    4016.09  2008.04     0.00     0.00 09.02. 18:55:12 HASH(timer); timer; on
tf                                       telnet_Read->dummy_Set->notify_Exec   2003        2    4006.18  2003.09     0.00     0.00 09.02. 18:55:14 HASH(tf); HASH(timer)
tmr-freezemon_ProcessTimer               HASH(0x7f8acd162b50)                    10        6      14.95     2.49  3479.39   913.01 09.02. 18:55:06 HASH(freezmon)


hier sieht man das die zeit im notify_Exec verbraucht wird das durch ein dummy_Set über eine telnet verbindung eingegeben wurde. wenn man die total zeiten vergleicht sieht man auch das die zeit tatsächlich auf der untersten ebene verbraucht wird und nicht schon vorher. d.h. das notify das am event hängt kostet zeit, nicht das set selber.

wenn man sich die zeiten merkt könnte man in der auswertung auch die 'falsch positiven' ausblenden und nur die 'echten' verursacher zeigen. d.h. im beispiel oben würde telnet und set nicht mehr auftauchen. nur das notify.


2. für notify zusätzlich die events die zum notify geführt haben als key verwenden. so kann man unterscheiden welches ereignis tatsächlich probleme macht: name                                     function                               max    count      total  average   maxDly   avgDly TS Max call     param Max call
telnetPort_192.168.161.236_56878         telnet_Read                           6023        2    6023.49  3011.75     0.00     0.00 09.02. 19:35:57 HASH(telnetPort_192.168.161.236_56878)
timer                                    telnet_Read->dummy_Set                6022        2   12037.19  6018.60     0.00     0.00 09.02. 19:35:57 HASH(timer); timer; on
tf                                       telnet_Read->dummy_Set->notify_Exec(on)   4007        2    8013.88  4006.94     0.00     0.00 09.02. 19:36:03 HASH(tf2); HASH(timer)
tf                                       telnet_Read->dummy_Set->notify_Exec(off)  2006        2    4011.68  2005.84     0.00     0.00 09.02. 19:35:53 HASH(tf); HASH(timer)

eine ähnliche sonderbehandlung könnte man auch für DOIF einbauen.

hier sieht man das die ausführung des notify im fall on doppelt so lange dauert wie im fall off.

die zusatzinfo könnte man konfigurierbar aktivieren.




der patch für alles beides schaut so aus:
Index: 98_apptime.pm
===================================================================
--- 98_apptime.pm (revision 16133)
+++ 98_apptime.pm (working copy)
@@ -170,10 +170,27 @@
   else         {return $ret[0];}
}

+my @callstack;
sub apptime_getTiming($$$@) {
   my ($e,$fnName,$fn,$tim,@arg) = @_;
   my $h;
   my $ts1;
+
+  if( @callstack ) {
+    $fnName = join('->', @callstack)."->$fnName";
+    if( @arg && ref($arg[0]) eq 'HASH' ) {
+      if( my $name = $arg[0]->{NAME} ) {
+        if( $fn eq 'notify_Exec' ) {
+          my $events = deviceEvents($arg[1], AttrVal($arg[0]->{NAME}, "addStateEvent", 0));
+          $fnName .= '(';
+          $fnName .= join( ',', @{$events});
+          $fnName .= ')';
+        }
+      }
+    }
+  }
+
   if ($apptimeStatus){
     if (!$defs{$e}{helper} ||
         !$defs{$e}{helper}{bm} ||
@@ -203,9 +220,11 @@
     }
   }

+  push @callstack, $fn;
   no strict "refs";
   my @ret = &{$fn}(@arg);
   use strict "refs";
+  pop @callstack;

   if ($apptimeStatus){
     $ts1 = gettimeofday()-$ts1;
hue, tradfri, alexa-fhem, homebridge-fhem, LightScene, readingsGroup, ...

https://github.com/sponsors/justme-1968

KernSani

Zitat von: DarkT am 09 Februar 2018, 10:20:18
Danke, dann habe ich jetzt verstanden wie es funktioniert. Aus diesen Erfahrungen könnte man das Modul wie folgt erweitern, so als Ideen:


  • Erweiterte Analyse aktivieren/deaktivieren
  • Bei erweiterter Analyse -> Log Level auf verbose 5 setzten, bei freeze "apptime" ausführen und sowohl diese Ausgabe als auch Teilabschnitt des Logs zum Freeeze wegspeichern - aber das ist natürlich nur ein Traum ^^
Im Grunde macht Freezemon bei der Ermittlung der "bad guys" nichts anderes als apptime, mit dem Unterschied, dass apptime Werte über die Laufzeit aggregiert, während freezemon die Prozesse, die zum Zeitpunkt des freezes aktiv waren sammelt. Während eines freezes irgendwas zu tun geht leider nicht... deshalb ist es ja ein Freeze... Zudem kann man apptime zwar einschalten, aber nicht ohne restart ausschalten.

 
RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...

KernSani

Zitat von: justme1968 am 09 Februar 2018, 19:46:18
eigentlich gehört es zu apptime, aber da hier gerade fleissig getestet wird:
Danke. Das sieht sehr interessant aus... Muss mir das Coding mal in Ruhe ansehen (und verstehen) und schauen, ob man das in Freezemon übernehmen könnte
RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...

KernSani

Und noch was: Nachdem ich ja jetzt genug Haue bekommen habe - wegen der gplot-Files - habe ich nun zwei Möglichkeiten:
1. Ich baue die gplot-files so um, dass sie eine Komplexität aufweisen, die einer Veröffentlichung würdig ist
2. Ich finde raus wie ich die gplots wieder aus der distribution werfe.
Da mir für Punkt 1 sowohl das Wissen, als auch die Ideen fehlen geht die Wahrscheinlichkeit gegen 100%, dass es auf 2. rauslaufen wird. Ich empfehle also jedem, der die gplot-Files nutzt, sie unter eigenem zu sichern - sie werden in absehbarer Zeit verschwinden.   
RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...

willybauss

Da die Plot-Dateien im 1. Beitrag angehängt sind sollte 2. kein Problem sein.
FHEM auf Raspberry Pi B und 2B; THZ (THZ-303SOL), CUL_HM, TCM-EnOcean, SamsungTV, JSONMETER, SYSMON, OBIS, STATISTICS

P.A.Trick

Ich habe auf meinem QNAP das folgende Problem:


2018.02.11 11:22:45 0: Type of arg 1 to keys must be hash (not private array) at ./FHEM/98_freezemon.pm line 203, near "@freezes >"

Type of arg 1 to keys must be hash (not private array) at ./FHEM/98_freezemon.pm line 203, near "@freezes >"
2018.02.11 11:22:45 1: reload: Error:Modul 98_freezemon deactivated:


2018.02.11 11:19:48 0: Server started with 15 defined entities (fhem.pl:16107/2018-02-07 perl:5.010000 os:linux user:fhem pid:1019)
2018.02.11 11:19:48 0: Featurelevel: 5.8


Über eine Lösung würde ich mich freuen.
Cubietruck,RPI,QNAP Ts-419p+, FS20, FRITZ!DECT200, 7 MAX! Thermostate, 3 MAX! Fensterkontakte, Kodi, CUL V3.3, EM1000S, LW12, LD382, HUE, HM-CFG-USB-2, 1x HM-LC-SW1-FM, 2x HM-LC-SW2-FM, 2x HM-LC-Sw1PBU-FM, 3xHM-LC-Bl1PBU-FM,HM-SEC-RHS, 2xHM-SEC-SD,HM-WDS30-T-O, 3x HM-LC-Dim1TPBU-FM, RPI+AddOn

KernSani

Zitat von: P.A.Trick am 11 Februar 2018, 11:26:53
Ich habe auf meinem QNAP das folgende Problem:
Über eine Lösung würde ich mich freuen.

Tritt das Problem erst seit dem heutigen update auf, oder schon länger?
RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...