Neues Modul: Performance Monitor

[herrmannj]

Hallo zusammen,

zur Fehlersuche für mich hilfreich, von daher stelle ich gern zur Verfügung: "99_perfmon.pm".

Dieses Modul überwacht die Reaktionsfähigkeit von fhem indem geprüft wird welche Verzögerung in der Beantwortung von Events entstehen. Wenn Verzögerungen von mehr als 1000msec auftreten wird ein Logeintrag in folgender Form erzeugt:

Code: [Auswählen]

2013.11.10 11:49:48.432 1: Perfmon: possible freeze starting at 11:49:46, delay is 2.431
Liest sich so: um 11:49:46 hat sich der Performance Monitor selbst aufgerufen, der Befehl konnte erst um 11:49:48 (also mit 2.431 msec Verspätung) ausgeführt werden.

Auf diese Weise kann im log verfolgt werden ob und wie oft fhem nicht innerhalb einer Sekunde "responsive" war. Um die Ursachen dann einzugrenzen empfiehlt sich verbose 5 für das log. Mögliche Ursachen sind Bugs bzw Module die sich mehr als 1000msec Zeit für die Ausführung von Aktionen nehmen aber auch ungünstig definierte SVG Plots.

Installation:
Das Modul braucht nur in das Modul Verzeichnis kopiert zu werden (fhem anschließend neu starten). Weitere Schritte sind nicht erforderlich.

viele Grüße
Jörg

[m.zielinski]

Danke für dein tolles Modul.
Ich habe jetzt einige Ansätze gefunden, welche Module/Aufrufe mein System potentiell lange belegen.

Am meisten hatte ich probleme mit Enigma2 und Sonos. Nach Reduzierung auf unbedingt notwenige Geräte kommen deutlich selter die Delay-Warnungen.
Bei den betroffenen Modulen entstanden die Delays meist durch warten auf eine Rückwantwort einer URL - besonders wenn das betreffende gerät nicht erreichbar ist...

Zusammen mit Verbose 5 kann man so echt prima fhem nach Verlangsamungen durchsuchen.

[abc2006]

Hi,

Code: [Auswählen]

2013.11.19 15:34:10 5: Loading ./FHEM/99_perfmon.pm
Subroutine perfmon_Initialize redefined at ./FHEM/99_perfmon.pm line 13, <$fh> line 3.
Subroutine perfmon_ProcessTimer redefined at ./FHEM/99_perfmon.pm line 26, <$fh> line 3.
Subroutine perfmon_Undef redefined at ./FHEM/99_perfmon.pm line 45, <$fh> line 3.
Bareword found where operator expected at ./FHEM/99_perfmon.pm line 58, near "<h3>Performance"
Bareword found where operator expected at ./FHEM/99_perfmon.pm line 60, near "This"
Bareword found where operator expected at ./FHEM/99_perfmon.pm line 60, near ""responsiveness" of"
Bareword found where operator expected at ./FHEM/99_perfmon.pm line 60, near "of fhem"
Bareword found where operator expected at ./FHEM/99_perfmon.pm line 60, near "1000msec"
Bareword found where operator expected at ./FHEM/99_perfmon.pm line 60, near "where fhem"
Bareword found where operator expected at ./FHEM/99_perfmon.pm line 60, near ") a"
Bareword found where operator expected at ./FHEM/99_perfmon.pm line 60, near "a fhem"
Bareword found where operator expected at ./FHEM/99_perfmon.pm line 60, near "tuning fhem"
2013.11.19 15:34:10 1: reload: Error:Modul 99_perfmon deactivated:
 syntax error at ./FHEM/99_perfmon.pm line 54, near "="
sieht nach nem fehler aus, ich weiss nur nicht ob im Modul oder ob ich beim Kopieren was falsch gemacht hab .. ??

lg
stephan

[herrmannj]

Hallo Stephan,

auf welchem OS läuft Dein fhem und wie hast Du das Modul installiert (dahin kopiert) ?

vg
Jörg

[fhainz]

Hallo!

Hab gerade das Modul installiert und in meinem Log gehts schon ziemlich ab. Hast du einen Tipp zur Suche?

2013.11.19 20:43:23 0: Server started with 208 defined entities (version $Id: fhem.pl 4208 2013-11-12 17:43:33Z rudolfkoenig $, os linux, user fhem, pid 18098)
2013.11.19 20:43:23 1: Perfmon: possible freeze starting at 20:43:05, delay is 18.311
2013.11.19 20:43:26 3: Device szFensterkontakt added to ActionDetector with 028:00 time
2013.11.19 20:43:26 3: PID set szHeizung desired 12
2013.11.19 20:43:26 3: FHT8V set szStellventil valve 0
2013.11.19 20:43:26 1: HMLAN_Parse: HMLAN new condition ok
2013.11.19 20:43:27 1: Perfmon: possible freeze starting at 20:43:24, delay is 3.412
2013.11.19 20:43:29 1: Perfmon: possible freeze starting at 20:43:28, delay is 1.756
2013.11.19 20:43:31 1: Perfmon: possible freeze starting at 20:43:30, delay is 1.974
2013.11.19 20:43:33 1: Perfmon: possible freeze starting at 20:43:32, delay is 1.335
2013.11.19 20:43:37 1: Perfmon: possible freeze starting at 20:43:34, delay is 3.496
2013.11.19 20:43:42 1: Perfmon: possible freeze starting at 20:43:41, delay is 1.203
2013.11.19 20:43:49 1: Perfmon: possible freeze starting at 20:43:45, delay is 4.559
2013.11.19 20:44:13 1: Perfmon: possible freeze starting at 20:44:12, delay is 1.928
2013.11.19 20:44:21 3: FHT8V set szStellventil valve 0
2013.11.19 20:44:24 1: Perfmon: possible freeze starting at 20:44:23, delay is 1.097
2013.11.19 20:44:45 1: Perfmon: possible freeze starting at 20:44:44, delay is 1.936
2013.11.19 20:44:54 1: Perfmon: possible freeze starting at 20:44:50, delay is 4.239
2013.11.19 20:44:55 1: 10.0.0.55:1000 disconnected, waiting to reappear
2013.11.19 20:44:55 1: HMLAN_Parse: HMLAN new condition disconnected
2013.11.19 20:44:56 1: 10.0.0.55:1000 reappeared (HMLAN)
2013.11.19 20:44:56 1: HMLAN_Parse: HMLAN new condition init
2013.11.19 20:44:56 1: Perfmon: possible freeze starting at 20:44:55, delay is 1.768
2013.11.19 20:44:56 1: HMLAN_Parse: HMLAN new condition ok
2013.11.19 20:45:18 1: Perfmon: possible freeze starting at 20:45:17, delay is 1.666
2013.11.19 20:45:20 1: Perfmon: possible freeze starting at 20:45:19, delay is 1.3
2013.11.19 20:45:45 1: Perfmon: possible freeze starting at 20:45:41, delay is 4.51
2013.11.19 20:45:48 1: Perfmon: possible freeze starting at 20:45:47, delay is 1.957
2013.11.19 20:45:59 1: Perfmon: possible freeze starting at 20:45:58, delay is 1.319
2013.11.19 20:46:19 1: Perfmon: possible freeze starting at 20:46:17, delay is 2.158
2013.11.19 20:46:37 1: Perfmon: possible freeze starting at 20:46:32, delay is 5.12
2013.11.19 20:46:51 1: Perfmon: possible freeze starting at 20:46:50, delay is 1.267
2013.11.19 20:47:01 1: Perfmon: possible freeze starting at 20:47:00, delay is 1.537
2013.11.19 20:47:18 3: FHT8V set szStellventil valve 0
2013.11.19 20:47:22 1: Perfmon: possible freeze starting at 20:47:21, delay is 1.679
2013.11.19 20:47:24 1: Perfmon: possible freeze starting at 20:47:23, delay is 1.023
2013.11.19 20:47:54 1: Perfmon: possible freeze starting at 20:47:53, delay is 1.491
2013.11.19 20:47:56 1: Perfmon: possible freeze starting at 20:47:55, delay is 1.802
2013.11.19 20:48:12 1: Perfmon: possible freeze starting at 20:48:08, delay is 4.955
2013.11.19 20:48:13 3: PID set szHeizung desired 12
2013.11.19 20:48:13 3: FHT8V set szStellventil valve 0
2013.11.19 20:48:26 1: Perfmon: possible freeze starting at 20:48:24, delay is 2.128
2013.11.19 20:48:35 1: Perfmon: possible freeze starting at 20:48:34, delay is 1.192
2013.11.19 20:48:58 1: Perfmon: possible freeze starting at 20:48:56, delay is 2.03
2013.11.19 20:49:28 1: Perfmon: possible freeze starting at 20:49:27, delay is 1.915
2013.11.19 20:49:31 1: Perfmon: possible freeze starting at 20:49:29, delay is 2.981
2013.11.19 20:49:59 1: Perfmon: possible freeze starting at 20:49:58, delay is 1.693
2013.11.19 20:50:01 1: Perfmon: possible freeze starting at 20:50:00, delay is 1.283
2013.11.19 20:50:09 1: Perfmon: possible freeze starting at 20:50:08, delay is 1.206
2013.11.19 20:50:15 3: FHT8V set szStellventil valve 0
2013.11.19 20:50:32 1: Perfmon: possible freeze starting at 20:50:30, delay is 2.659
2013.11.19 20:50:39 1: Perfmon: possible freeze starting at 20:50:38, delay is 1.288

Und es geht so weiter...

Grüße

[herrmannj]

Hallo fhainz,

oh, ha .. :-). Damit lässt sich kein Schalter oder piri vernünftig steuern. Bis da das Licht angeht liegst Du ja schon geduscht im Bett ;-)

Schalte mal bitte den verbose auf 5 (das ist ein Attribut vom global device) sowie das attr mseclog auf 1.

Danach wirst Du im log viel detaillierter sehen was die einzelnen Module für Aktionen machen, dh Dein log wird viel aussagekräftiger. Die Suche läuft dann so:

Du suchst Dir einen freeze raus, z.B.:

013.11.19 20:43:27 1: Perfmon: possible freeze starting at 20:43:24, delay is 3.412

Um 20:43:24 Sekunden sollte ein Prüfpunkt aufgerufen werden, der konnte jedoch erst 3 1/2 Sekunden später ausgeführt werden. Ergo hat um 20:43:24 Sekunden ein anderer Prozess das System lahmgelegt. Welcher Prozess, das sollte im log stehen. Die letzte oder eine der letzten Aktionen direkt vor 20:43:24.

Da scheint wirklich irgendwo eine grobe Bremse zu liegen. "Schön" zu sehen ist auch 20:44:55, da haut es Dir gleich mal eben den HMLan raus was ja vermutlich auch nur eine Folge der Hänger ist.

vg
Jörg
 

[fhainz]

Ok ich denke ich hab den Übeltäter.

Code: [Auswählen]

2013.11.19 22:09:35.017 5: Triggering wzMultimediaRG (1 changes)
2013.11.19 22:09:35.028 5: Notify loop for wzMultimediaRG wzMultimedia.power: 268.60 W
2013.11.19 22:09:35.188 5: Triggering wzMultimediaRG (1 changes)
2013.11.19 22:09:35.199 5: Notify loop for wzMultimediaRG wzMultimedia.consumption: 3.69 kWh
2013.11.19 22:09:35.362 5: Triggering wzMultimediaRG (1 changes)
2013.11.19 22:09:35.373 5: Notify loop for wzMultimediaRG wzMultimedia.consumptionTotal: 27.02 kWh
2013.11.19 22:09:35.534 5: Triggering wzMultimediaRGKurz (1 changes)
2013.11.19 22:09:35.544 5: Notify loop for wzMultimediaRGKurz wzMultimedia.power: 268.6 W
2013.11.19 22:09:35.696 5: Triggering wzMultimediaRGKurz (1 changes)
2013.11.19 22:09:35.707 5: Notify loop for wzMultimediaRGKurz wzMultimedia.consumption: 3.69 kWh
2013.11.19 22:09:35.861 5: Triggering wzMultimediaRGKurz (1 changes)
2013.11.19 22:09:35.891 5: Notify loop for wzMultimediaRGKurz wzMultimedia.consumptionTotal: 27.02 kWh
2013.11.19 22:09:36.157 1: Perfmon: possible freeze starting at 22:09:35, delay is 1.156
Nachdem ich die readingsGroup entfernt hatte wars besser aber noch nicht gut. Ich denke der jeelink holt sich zu oft Daten. Das Problem wurde auch schon in einem anderen Thread besprochen. Ich werde ihn morgen mal updaten dann sag ich bescheid wie's aussieht.

Klasse Modul, sollte unbedingt eincheckt werden!

Grüße

[abc2006]

Hallo Jörg,
sorry, ich habe gleich mal meine Signatur editiert.

Fhem läuft auf Fritzbox 7390, direktinstallation von fhem.de
Ich habe das Modul von einem Ubuntu-PC über Samba-Freigabe dorthin kopiert.

Habe das Problem aber eingrenzen können:
Es waren unnötige Leerzeichen drin, so dass die Syntax der Beschreibung nicht erkannt wurde.
Vermute, beim Kopieren lief irgendwas schief, jetzt passts. Danke!

lg
stephan

[herrmannj]

Hallo Stephan,

super, viel Erfolg beim profilen.

vg
Jörg

[herrmannj]

Hallo fhainz,

super und herzlichen Dank.

btw, das mit dem jeelink kenne ich, meine Frauen haben gesagt "Disco Beleuchtung" (jeelink im transparenten Gehäuse, der blinkt wie wild :-).

Hab ihn auch erst mal raus genommen.

vg
Jörg

[hexenmeister]

Tolle Sache, vielen Dank!

Wie wäre es mit der Idee, ein 'normales' (sihtbare) Device (00_perfmon.pm) daraus zu machen. Dann könnte man dieses immer drinne lassen und nur bei Bedarf zu aktivieren (per Attribute oder so...)?

Grüße,

Alexander

[herrmannj]

Hallo Alexander,

vielen Dank. Wenn Bedarf besteht kann ich gern ein Device daraus machen.

Allerdings ist das Modul ganz gewusst so schlank gehalten um die CPU usage minimal zu halten. Du kannst es praktisch immer mitlaufen lassen ohne das es selbst nennenswert "Brot frisst" .

Ein Device würde jetzt overhead addieren was eigentlich nicht im Sinn der Sache ist.

vg
Jörg

[fhainz]

Mal ne grundsätzliche frage zwischendurch:
Wenn ich hin und wieder einträge im log hab ist das normal? Oder besteht immer ein (lösbares) problem wenn ein eintrag im log vorhanden ist?

Grüße

[herrmannj]

Hallo,

die Einträge im log sind ja erst mal nur ein Zeichen dafür das fhem "von etwas aufgehalten" wurde und helfen den Verursacher zu finden. 

Alles weitere "hängt ab von ... " :-). Je nach Ursache sind ja ab hier entweder der entsprechende Modulautor gefragt oder Du kannst selber aktiv werden.

Selbst Hand anlegen könntest Du zB
* in notifys etc ungünstige regex beseitigen.
* file logs optimieren (weniger Einträge etc) 
* eigene routinen, etx

Wenn ein Modul selbst die Ursache ist (synchrone Abfragen, timeouts etc) brauchts perl-fu um was tun zu können, die Module sind da unterschiedlich optimal aufgebaut.

Bei mir sehe ich aktuell max 1-2 Einträge täglich, so im Bereich 1-2 Sekunden, die ich im rfxtrx verorten konnte, die nehme ich hin.

Alles weitere sind bei mir plots wenn ich auf Sichten größer eine Woche gehe.

vg
Jörg

[fhainz]

Ok filelogs optimieren ist ein gutes stichwort. Da hab ich noch 2 fragen.
Sind mehrer logs (monats logs) sinnvoller als jahreslogs da sie ja kleiner sind?
Sollte ich, wenn ich den filelog optimiert hab die bisherigen einträge irgendwie verkleinern? Oder sind die bisherigen einträge egal?