FHEM Forum

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:

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

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.

Hi,


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

Hallo Stephan,

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

vg
Jörg

Hallo!

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

Zitat2013.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

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.:

Zitat013.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

Ok ich denke ich hab den Übeltäter.

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

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

Hallo Stephan,

super, viel Erfolg beim profilen.

vg
Jörg

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

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

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

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

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

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?

noch ein tool zum performance probleme zu finden gibt es hier: http://forum.fhem.de/index.php/topic,16103.msg111482.html#msg111482 (http://forum.fhem.de/index.php/topic,16103.msg111482.html#msg111482)

gruss
  andre

Hallo,

wenn du schon einen RasPi verwendest dann stell doch um auf DBLog.
Diese dann auf eine externe Festplatte auslagern - was auch der SD-Karte zugute kommt - und du hast "Jahrzente"-Logs.

Performaceeinbussen? Wird es sicher geben wenn du 5 Jahre zurück scrollst.
Aber sonst - nicht das ich wüsste.
Ok. Ich weiß fast nichts daher sind meine Meinungen auch mit Vorsicht zu genießen.

Der Performance Monitor läuft bei mir "nebenher" mit.
Ich hab zur Zeit andere Baustellen die mich (oder auch fhem) aufhalten als ein notify.

Hat mit diesem genial Tool aber nichts zu tun.
Die Performance-Werte gehe ich später mal an.

Grüße

Bei mir ruckelt leider alles, seitenaufbau dauert ewig und ich hab seitenlange freezes. Warum auch immer.
Dblog ist eine gute idee. Wird ja sicherlich weitaus performater sein als der filelog oder?

Hallo Jörg,

danke für die Erklärung, mir war nicht bewusst gewesen, dass ein 'richtiges' Device wesentlich mehr Ressourcen verbraten würde. Wenn der aktuelle Mehrbelastung unwesentlich ist, braucht man natürlich keine Erweiterung. AUf meinem Pi hat sich loadavg nicht messbar verändert  :)

LG,

Alexander

Hallo Puschel74,

ich habe mit DBLog mal rumversucht. Dabei wird man die meisten Plot doch verändern müssen. Auch die Systembelastung stieg sehr deutlich an. Da gefallen mir die Logs besser. Oder habe ich etwas übersehen bzw. falsch gemacht?

Grüße,

Alexander

Hallo,

ob DBLog performanter ist kann ich nicht sagen weil - keine Ahnung.

Aber
@fhainz
Wenn bei dir alles ruckelt und der Seitenaufbau ewig dauert hast du sicher ein anderes Problem.
Speck mal deine fhem.cfg auf das absolut nötigste ab und mach dann, wenn die Probleme immer noch bestehen, im RasPi-Unterforum einen neuen thread auf.
Für sowas hab ich immer einen Reserve-Pi aka "Spiel-Pi"  ;)

@hexenmeister
Ich kann an meinem RasPi nicht wirklich eine Verschlechterung der Performance erkennen - aber das sagt ja nichts. Siehe oben - keine Ahnung.
Mein Main_RasPi macht nur FHEM und sammelt die Daten von 2 anderen RasPi um sie mir
a) in DBLog zu loggen und
b) daraus zu plotten.
DBLog hat eben den Vorteil das man Plots aus allen möglichen Einträgen ohne viel Aufwand erstellen kann.

z.B. siehe Screenshot.
Vorlauf und Rücklauftemperatur meiner Heizung sind an meinem I2C_RasPi 2 I2C-Sensoren die per FHEM2FHEM in die Datenbank geloggt werden.
Die Wasserpumpe ist ein FS20-Aktor.
Alle drei "Devices" müssten für einen Plot aus Filelog in ein Logfile schreiben.
Das erspar ich mir da ich DBLog verwende.

Grüße

zum db log kann habe ich keine praktischen Erfahrungen. Beim filelog habe ich festgestellt das der Einfluss der Gesamtgröße des logs (also täglich, monatlich wöchentlich ...) im Verhältnis zur Dichte und zum Aufbau der Daten gering ist.

Mit anderen Worten:

tägliches log mit hoher Datendichte (zB 1min) -> plot in der Tagesübersicht -> verhältnismäßig langsam.
monatliches log mit mäßiger Datendichte (zB 10min) -> plot in der Tagesübersicht -> im Verhältnis viel schneller (obwohl das monatslog insgesamt deutlich größer ist).

Irgendwann wir das log natürlich trotzdem so groß das die Anzeige scheinbar alleine Aufgrund der totalen Datenmenge etwas bremst.

Gute Erfahrungen bzgl des plot/log tunings habe ich mit folgenden Punkten erzielt:

*  regex so aufbauen das keine doppelten Einträge entstehen  (bsp Temp, im state und nachmal als measured-temp etc.)
*  min-interval und Konsorten nutzen damit eben nur alle 10min (oder was auch immer) ein Eintrag erzeugt wird.
*  Abkürzungen im log (also anstelle von "measured-temp:20" nur "t:20")

Damit wird das filelog wirklich erstaunlich performant.

vg
Jörg

Alles klar, danke.
Ich werd das erstmal mit dem FileLog Tunig versuchen. Wenn das nichts bringt versucht in den DBLog.

Hallo!

@Puschel74
Verschlechterung ist zu viel gesagt, ich habe nur gemerkt, dass loadavg von ca. 0,05-0,1 auf 0,8-1,2 gestiegen ist. Damit war die CPU noch nicht völlig überlastet, aber schon sehr nah an der Grenze.
Sonst läuft bei mir auf dem Pi auch nicht viel.

Gruß,

Alexander

Hallo,

ich hab ja keine Ahnung davon aber ... (ich hatte vorerst FileLog verwendet da default in fhem und hab aber vor knapp 7 Monaten auf DBLog umgestellt).
Grund für mich war:
FileLog loggt in eine eigene Datei pro Device - ist erstmal ok aber ...

du kommst nach 3 Monaten drauf das Device a und Device b in einem Plot besser passen würden.
Das geht mit Filolog definitiv - für den Moment ab dem beide Geräte in ein Logfile schreiben.
Für die Vergangenheit? njet - keine Chance es sei den du kopierst die Daten händisch zusammen.

Bei DBLog - kein Problem.
Alle Geräte schreiben in ein "logfile".
Du willst in 2 Jahren die Daten von der Aussentemperatur und der Innentemperatur im Wohnzimmer in einem Plot haben?
Kein Problem.
Ein Gplot-File zusammen bauen das beide Temperaturen abfrägt und anzeigt.
Und das zurück bis zu dem Zeitpunkt als du DBLog passend definiert hast.

FileLog ist ok und hat durchaus seine Daseinsberechtigung.
Aber es schreibt per se (um kompatibel zu sein) nach ./log und das ist am RasPi die SD-Karte.
Diese Karten sind aber nicht "über"lebensfähig.
Schreib-Lesezugriffe machen denen ganz schön zu schaffen.

Also zumindest ein USB-Stick wäre anzuraten um darauf die Logfiles zu speichern (auch das fhem-LogFile da fhem mitunter recht "gesprächig" sein kann).
Ich werf alles! per DBLog in eine Datenbank auf einer USB-HDD am RasPi.
Wenn ich in 2 Jahren auf die Idee komme den Verlauf der Kellertemperatur gegen die Aussentemperatur und der Ventilstellung am Wohnzimmerheizkörper in einem Plot darstellen zu wollen kann ich das machen - und noch 2! Jahre in die Vergangenheit scrollen.
Klar kann man drüber streiten ob das sinvoll ist aber mit Logfile geht das nicht (es sei den ich erstell heute eine Logfile in das ich alles loggen lasse).
Dann kann ich aber auch die Logfiles in der fhem.cfg löschen und DBLog definieren.

Grüße

Danke für die ausführliche Erklärung, die Vorteile sind mir schon klar.
Die Logs müsste man auch auf einen Stick oder HDD verlegen können (per symlink).
Ich bin nicht auf Anhieb mit dem Plots mit DBLog klar gekommen, es würde zumindest viel Aufwand bedeuten, alle meine Plots umzustellen. Vielleicht widme ich mich dem nochmal später.

VG

Alexander

Hallo,

es würde zumindest viel Aufwand bedeuten

Nö.
Der "Aufwand" bestünde darin einen USB-Stick oder eine USB-HDD am RasPi einzubinden und DBLog zu definieren das fortan alles in die Datenbank schreibt.
Einen Umstieg von FileLog-Plot auf DBLog-Plot kann man ja später peu a peu machen.
Die Daten sind ja schon vorhanden  8)

Grüße

Hallo,

die DBLog Definition habe ich schon hinbekommen. Es lief sogar mehrere Wochen parallel mit. Wie gesagt, Systemauslastung hat mir nicht zugesagt. MySQL hat recht viel für sich beansprucht.

Grüße,

Alexander

Hallo,

ZitatMySQL hat recht viel für sich beansprucht.

Dazu kann ich nichts sagen da ich sqlite3 verwende.
Die Installation dafür auf einem RasPi findest du im Wiki unter Charting_Frontend.
Den Teil für den RasPi hab ausnahmsweise mal ich beigesteuert.

Grüße

Hi!

Danke, vielleicht ist das genau die Idee, ich werde mal SQLite ausprobieren. Möglicherweise ist MySQL einfach zu schwerfällig für Rasp. Interessant wäre spezielle DB für Zeitdaten (time-series database) wie 'Timestore' auszuprobieren. Werde ich mal im Netzt suchen, ob das geht.

Mysql ist nicht zu schwerfällig für den pi. Vielleicht im zusammenhang mit fhem aber mysql an sich läuft auf einem pi problemlos.

Grüße

Jo, die DB läuft schon. Bei mir erzeugte sie aber eine hohe CPU-Last (zugegeben, in meinem FHEM wird schon einiges geloggt  :) ).

Hallo,

Zitatzugegeben, in meinem FHEM wird schon einiges geloggt

Wieviel ist einiges?

Mein RasPi sammelt noch Daten von 2 anderen ein und wirft alles in eine DB.
Wenn ich mich nicht verschaut habe hat die DB mittlerweile 1,68 GB.
Seit heute morgen kommt noch sysmon dazu.

Grüße

Moin!

Hmm, so viel wie DU habe ich doch wohl nicht ;)
Ich komme nur auf 466 MB (gesammelt in 1 Jahr).

Ich werde mal SQLite ausprobieren, scheint ja Deine Installation ganz gut zu tragen.
Sag mal, wie hoch ist bei ie die Durchschnittsbelastung von CPU. Jetzt kannst ja bequem aus den SYSMON-Logs ablesen ;-)

Grüße,

Alexander

Hallo,

SYSMON läuft erst seit heut morgen - und ich schaff es erstmal nur die 1-Minuten-Werte zu plotten.

Grüße

P.S.: Ich hoffe man kann was erkennen
Edith: Mal eben das "verwischen" weggemacht

Hi,

man erkennt genug ;) Das System hat nicht viel zu tun. Gefällt mir :)

Grüße,

Alexander

Hi, ist das ein Ersatz für das SYSSTAT Modul?

ich hoffe doch mal das man das SYSTAT modul nicht ersetzen muss :)

wenn du das modul vom anfang dieses threads meins (performancemonitor) dann ist es etwas komplett anderes. das misst ob deine fhem installation hänger hat.

das SYSMON ist etwas ähnliches wie SYSTAT aber scheinbar auf den lokalen rechner und auf linux beschränkt. SYSSTAT kann auch remote überwachen. auch z.b. windows und noch ein paar andere und kann auf unterschiedliche arten überwachen.

gruss
  andre

Hallo,

SYSMON ist kein Ersatz für SYSSTAT. Es ist entstanden, weil SYSSTAT damals nicht alles bieten konnte, was ich alles sehen wollte (und weil ich keine weiteren Perl-Module installieren wollte). Dazu noch diente es als eine Fingerübung zum Kennenlernen von Perl und FHEM-Architektur.
Es sollte keine Konkurenz sein. ;)

Grüße,

Alexander

@herrmannj

Hallo Jörg,

je länger ich überlege, desto besser gefällt mir Dein PerfMon-Modull. Allerdings finde ich es etwas mühsam, die FHEM-Logdatei durchzusehen. Eine Visualisierung wäre hilfreich. Dann könnte man auf einen Schlag sehen, ob sich die Suche lohnt. Eine Art Balkendiagram, wo die Höhe die Freeze-Zeit angibt. Geht so schön mit Plot wahrscheinlich nicht, aber auch eine Graphik mit Punkten (dots) würde es auch tun.
Lange Rede, gar kein Sinn... Hast Du etwas dagegen, wenn ich Deine Idee in mein SYSMON-Modull einbringe, logge und ein entsprechendes Plot dazu erstelle?

Grüße,

Alexander

Hallo Alexander,

na klar kannst Du den code verwenden. Vielleicht lässt sich das aber auch anders lösen.

Eine Duplizierung des codes hätte den Nachteil das ein Benutzer der sysmon nicht verwendet perfom installiert und wenn er dann sysmon einsetzen möchte dann müsste er perfom deinstallieren sonst wäre das doppelt. Aus Benutzersicht fände ich das nicht optimal.

Spontan fallen mir folgende Möglichkeiten ein:
* da wo ich jetzt den Eintrag im log erzeuge könnte ich stattdessen ein event auslösen. Das event kann der user dann in der def eines Filelogs verwenden oder ein notify draufsetzen weches, wie gehabt, einen log 1 Eintrag erzeugt. Das würde zwar mehr cpu verbrauchen als jetzt, aber *nur* wenn sowieso ein freeze da ist. Im Normalbetrieb müsste das neutral sein. Das filelog kann man dann auch prima plotten.

Dieses event könntest Du im auch im sysmon catchen und hättest es dann direkt im modul zur Verfügung.

Alle Werte die unterhalb der 1000ms Schwelle liegen könnte perfmon auch zur Verfügung stellen, entweder als ein als fifo organisiertes array (exportierte var) oder kumuliert alle x sec/min oder so. Dort bin ich aber der Meinung das macht keinen Sinn weil diese Werte ja keinen Rückschluss auf irgendwas zulassen. Man kann zwar sehen wie zeitlich exakt der Aufruf erfolgt. Die die Reihenfolge der Abarbeitung einzelner Tasks nicht definiert ist könnte es sein das perfmon mit 10ms Versatz aufgerufen wird, danach jedoch ein anderer Task der sich 980ms nimmt. Dafür sind Dein Ansatz über die sys-stats, das Modul von justme oder des profiling aus dem Wiki eigentlich viel besser geeignet.

vg
jörg

Hallo Jörg,

danke für die schnelle Antwort!

ZitatEine Duplizierung des codes hätte den Nachteil das ein Benutzer der sysmon nicht verwendet perfom installiert und wenn er dann sysmon einsetzen möchte dann müsste er perfom deinstallieren sonst wäre das doppelt. Aus Benutzersicht fände ich das nicht optimal.

Daran habe ich auch schon gedacht. Aber auf Deinen (eigentlich offensichtlichen) Vorschlag mit dem Event aus PerfMon bin ich irgendwie nicht gekommen. Das finde ich wesentlich besser. Wäre toll, wenn Du das soweit erweitern könntest. Ich würde dann gern ein Plot dazu erstellen.

Die Werte unter 1 Sekunde finde ich jetzt auch nicht so spannend. Wenn man diese auch noch den Modulen zuordnen könnte und damit die Zeitverteilung füe jedes einzelne Modull erstellen könnte, das wäre natürlich schön, aber so einfach wird es ja nicht gehen :(

Grüße,

Alexander

Hi Alexander,

mach ich fertig. Bei der Gelegenheit versuche ich mal ob ich das im sourceforge ins contrib legen darf. Muss ich mich aber erst einlesen, vermutlich brauche ich da erstmal ein ok von Rudi oder sowas ..

vg
Jörg

Tolles Modul! Hat mir sehr geholfen... Sehr übersichtlich auch ohne grafische Darstellung!
Einchecken wäre wünschenswert.

Grüße

MySQL läuft schlecht, wenn man wenn man Current und History loggt,
weil dann 3 Datenbankaktionen pro Logeintrag(Insert History, Insert or Update Current) gemacht werden müssen.

Es läuft viel performanter, wenn man eben nur in die History-Tabelle loggt.
Ich habe damit recht brauchbare Ergebnisse erziehlt, und mir was MySQL bedeutend lieber, da ich dort keine Timeouts bekommen habe beim bereinigen von alten, nicht mehr benötigten Loggings.
SQLite war zum reinen loggen schneller, jedoch zum Aufräumen unschön.

Frage: Kann ich perfmon auch deaktivieren wenn ich es nicht mehr benötige oder muss ich deinstallieren?

deinstallieren (löschen). Oder laufen lassen, frisst kaum Brot

vg
Jörg

Ok Danke!

Hallo,

ich würde gerne die Meldungen von "perfmon" in DBLog schreiben. Ich habe den Thread gelesen, aber nichts gefunden, was mir weiterhilft. Oder ist es so einfach, daß ich vor lauter Bäumen den Wald nicht sehe?

Gruß
Blueberry63

Wenn es readings gibt werden diese automatisch weg geschrieben in die dB. Ansonsten kannst du per notify o.a. die interne  dblog_push Methode benutzen.

Gesendet von meinem ALCATEL ONE TOUCH 997D mit Tapatalk

Hallo
habe das Modul jetzt auch mal kurzer Hand getestet.


5 16:05:35 2: NONE
2014.04.15 16:05:35 0: Server started with 306 defined entities (version $Id: fhem.pl 5340 2014-03-27 16:19:53Z rudolfkoenig $, os linux, user fhem, pid 1918)
2014.04.15 16:05:35 1: Perfmon: possible freeze starting at 16:05:23, delay is 12.863
2014.04.15 16:05:40 3: Device DEV_SW_Briefkasten added to ActionDetector with 028:00 time
2014.04.15 16:05:40 3: Device DEV_bd_Heizung added to ActionDetector with 000:10 time
2014.04.15 16:05:40 3: Device DEV_ke_Heizung added to ActionDetector with 000:10 time
2014.04.15 16:05:40 3: Device DEV_wc_Heizung added to ActionDetector with 000:10 time
2014.04.15 16:05:40 3: Device DEV_wz_Heizung added to ActionDetector with 000:10 time
2014.04.15 16:05:40 3: Device DEV_wz_Heizung_TC added to ActionDetector with 000:10 time
2014.04.15 16:05:40 3: Device TH_Aus added to ActionDetector with 000:10 time
2014.04.15 16:05:40 3: Device TH_Inn added to ActionDetector with 000:10 time
2014.04.15 16:05:40 3: Device bd_sw_Fenster added to ActionDetector with 028:00 time
2014.04.15 16:05:40 3: Device eg_sw_Tuer added to ActionDetector with 028:00 time
2014.04.15 16:05:40 3: Device ke_Wassermelder added to ActionDetector with 028:00 time
2014.04.15 16:05:40 3: Device le_Rauchmelder added to ActionDetector with 028:00 time
2014.04.15 16:05:41 3: Device lu_Rauchmelder added to ActionDetector with 028:00 time
2014.04.15 16:05:41 3: Device po_smoke_2 added to ActionDetector with 028:00 time
2014.04.15 16:05:41 3: Device po_sw_Fenster added to ActionDetector with 028:00 time
2014.04.15 16:05:41 3: Device wc_sw_Fenster added to ActionDetector with 028:00 time
2014.04.15 16:05:41 3: Device wz_sw_tresen added to ActionDetector with 028:00 time
2014.04.15 16:05:41 1: Perfmon: possible freeze starting at 16:05:36, delay is 5.721
2014.04.15 16:05:53 1: OWCOUNT: model attribute of ow_Counter set to DS2423eold because no memory found
2014.04.15 16:05:55 1: HMLAN_Parse: HMLAN1 new condition ok
2014.04.15 16:05:55 1: Perfmon: possible freeze starting at 16:05:42, delay is 13.097
2014.04.15 16:05:55 3: CUL_HM set DEV_az_Powerbox statusRequest
2014.04.15 16:05:59 1: OWX: 1-Wire devices found on bus OWio1 (ow_2,ow_1,ow_3,ow_m,ow_Counter)
2014.04.15 16:05:59 1: Perfmon: possible freeze starting at 16:05:56, delay is 3.979
2014.04.15 16:06:00 3: CUL_HM set DEV_ku_Schrank statusRequest
2014.04.15 16:06:01 3: CUL_HM set DEV_wz_Licht_CT statusRequest
2014.04.15 16:06:02 3: CUL_HM set DEV_wz_Licht_Tresen statusRequest
2014.04.15 16:06:03 3: CUL_HM set DEV_wz_Steckdose_Terasse statusRequest
2014.04.15 16:06:04 3: CUL_HM set eg_Km_Tuer statusRequest
2014.04.15 16:06:05 3: CUL_HM set ke_Licht_Treppenhaus statusRequest
2014.04.15 16:06:06 3: CUL_HM set ku_Licht_Decke statusRequest
2014.04.15 16:06:07 3: CUL_HM set le_Rauchmelder statusRequest
2014.04.15 16:06:08 3: CUL_HM set lu_Rauchmelder statusRequest
2014.04.15 16:06:09 3: CUL_HM set po_1k_0237444 statusRequest
2014.04.15 16:06:10 3: CUL_HM set po_SW2_KEQ0254147 statusRequest
2014.04.15 16:06:11 3: CUL_HM set po_smoke_2 statusRequest
2014.04.15 16:06:12 3: CUL_HM set po_sw_KEQ0237448 statusRequest
2014.04.15 16:06:13 3: CUL_HM set wz_Licht_Eingang statusRequest
2014.04.15 16:06:14 3: CUL_HM set wz_Licht_Vitrine statusRequest
2014.04.15 16:10:43 1: Perfmon: possible freeze starting at 16:10:42, delay is 1.04
2014.04.15 16:10:46 1: Perfmon: possible freeze starting at 16:10:44, delay is 2.584


Das System ist beim starten schon ganz schön am kämpfen.

Gruß Hannes

Gesendet von Unterwegs mit Tapatalk 4

Das System hat nicht zu kämpfen, nur OWX macht bei jedem Neustart eine komplette Suche auf dem Bus, die physikalisch diese Zeit benötigt, da es eine serielle Kommunikation ist, und OWX das System erst wieder freigibt, wenn die Suche beendet ist.

Gruß Joachim

Mahlzeit...

dank des Moduls konnte ich ein einziges Freeze ausmachen und zwar beim abschicken einer Mail über sendEmail. Eingerichtet ist die ganze Sache über die 99_myUtils, wie in der Wiki beschrieben. Kann ich hier noch Hand anlegen oder besteht deswegen keine Optimierungsbedarf.

2014.05.12 12:47:30 1: sendEmail returned: May 12 12:47:30 cubietruck sendEmail[17781]: Email was sent successfully!
2014.05.12 12:47:30 1: Perfmon: possible freeze starting at 12:47:29, delay is 1.285

Hi Dittel,

die "pause" ist so gering (und vermutlich auch selten). Da wäre ich jetzt völlig unbesorgt.

vg
Jörg

was ist eigentlich der Unterschied zu 99_wdUtils.pm und 99_perfmon.pm?

Wie ist der Königsweg um den Freezes mit einem relativ vollen FHEM-Produktivsystem auf die Spur zu kommen? Ein globales verbose=5?

Hi Tobias,

perfmon ist die Weiterentwicklung, ist aktuell.

ZitatWie ist der Königsweg um den Freezes mit einem relativ vollen FHEM-Produktivsystem auf die Spur zu kommen? Ein globales verbose=5?

am Ende: ja -> shit Arbeit.

Erstmal ist es (denk ich) wichtig vom "gefühlten es klemmt" zu belastbaren Angaben über Hänger zu kommen. Primär dafür ist perfmon da.

Mit Chance schaffst Du es mithilfe von perfmon und geringerem verbose Ursache und Wirkung in Zusammenhang zu bringen. Also zB: Modul A schreibt ins log das es Daten von einem device/Dienst holt, gleichzeitig / kurz danach auftretender freeze: Modul liest blockend. Die dicken Dinger bekommt man so.

Teilweise treten kleine freeze aber bei mir auch in der normalen event loop auf, teilweise halt auch fhem Design.

Wenn Du tiefer rein musst ist apptime gut, danach hilft nur noch perl profiling ...

viel Glück  ;)
Jörg

vielen dank. Habe jetzt 99_wdutils gelöscht und stattdessen 99_perfmon eingebaut.
Ein global verbose 5 erzeugt schon arg viel Logs...Jetzt muss ich noch den kleinen und großen Freezes auf die Spur kommen...

Edit: ist das zb eine Auswirkung von blockierendem 1wire?
2014.06.15 07:17:59.907 5: TRX_Read END
2014.06.15 07:18:01.244 5: Triggering 1wire_Hub_1 (71969 changes)
2014.06.15 07:18:01.244 5: A: 0.344 V B: 4.472 V C: 0.495 V D: 4.501 V
2014.06.15 07:18:01.245 1: Perfmon: possible freeze starting at 07:18:00, delay is 1.245

schönes Ding  :) & schwer zu sagen

Ich glaube aber eher nicht, ich denke das liegt vor dem 1wire. TRX wäre möglich: erzeugt bei mir auch manchmal delays, fast "out-of-the-blue".

fhem und die module loggen ja "leider" auch nicht alles. Irgendwann nach 07:17:00 ist mindestens TRX aktiv gewesen. Zwischen "TRX_Read_END" und "Triggering 1wire..." war fhem auch mit "irgendwas" beschäftigt, womit sieht man nicht im log aber es hat den perfmon Aufruf verhindert. 1one (danach) sieht mir mit 1ms sogar extrem fix aus.

Ich hab einige von diesen "mini freeze" untersucht und dabei festgestellt das es oft keine single source gibt sondern halt einfach modul a xxx ms braucht das event zu processen, dann die eigenen notifys kommen, dann filellog kommt usw. Wenn dann gleichzeitig noch ein zweites oder drittes event reinkommt dann ist es eben so.

Als Ergebnis hab ich dann überall wo möglich/sinnvoll event-on-xxx draufgesetzt, das loggen minimiert, in eigenen notifys alle regex überarbeitet, diesen fhem "eventsammler" (weiß grad nicht wie der heist) abgeschaltet usw. Außerdem alle Module aussortiert die blockend lesen (die bekommt man mit perfmon schön zu fassen)

Das bringt einiges, die freeze sind schon selten, der Rest ist imho eben "by-design".

edith: vor allem die blockenden Module die lange freeze erzeugen. Diese 1200ms Dinger sind gerade noch so tolerierbar (PIR-> licht oder Schalter auf Licht oder so ist aber eben die Grenze...)

vg
jörg

Hallo zusammen. :)

Ich habe das Modul heute auch mal ausprobiert, weil ich häufiger das Problem habe, dass Befehle von FHEM nicht ausgeführt werden. Und es sieht grausam aus. Wenn ich alles richtig deutet, hängt mein FHEM mindestens einmal pro Minute. Nachfolgend ein Auszug aus meinem Log:

Zitat2014.07.09 09:18:00 1: Perfmon: possible freeze starting at 09:17:57, delay is 3.012
2014.07.09 09:19:03 1: Perfmon: possible freeze starting at 09:19:00, delay is 3.048
2014.07.09 09:20:06 1: Perfmon: possible freeze starting at 09:20:03, delay is 3.008
2014.07.09 09:21:09 1: Perfmon: possible freeze starting at 09:21:06, delay is 3.017
2014.07.09 09:21:37 1: Perfmon: possible freeze starting at 09:21:36, delay is 1.128
2014.07.09 09:22:12 1: Perfmon: possible freeze starting at 09:22:09, delay is 3.002
2014.07.09 09:23:14 1: Perfmon: possible freeze starting at 09:23:11, delay is 3.012
2014.07.09 09:24:17 1: Perfmon: possible freeze starting at 09:24:14, delay is 3.017
2014.07.09 09:25:20 1: Perfmon: possible freeze starting at 09:25:17, delay is 3.017
2014.07.09 09:26:23 1: Perfmon: possible freeze starting at 09:26:20, delay is 3.028
2014.07.09 09:26:37 1: Perfmon: possible freeze starting at 09:26:36, delay is 1.128
2014.07.09 09:26:43 1: Perfmon: possible freeze starting at 09:26:42, delay is 1.125
2014.07.09 09:27:26 1: Perfmon: possible freeze starting at 09:27:23, delay is 3.028
2014.07.09 09:28:29 1: Perfmon: possible freeze starting at 09:28:26, delay is 3.012
2014.07.09 09:29:32 1: Perfmon: possible freeze starting at 09:29:29, delay is 3.018
2014.07.09 09:30:00 1: Perfmon: possible freeze starting at 09:29:58, delay is 2.104
2014.07.09 09:30:35 1: Perfmon: possible freeze starting at 09:30:32, delay is 3.017
2014.07.09 09:31:38 1: Perfmon: possible freeze starting at 09:31:35, delay is 3.002
2014.07.09 09:32:41 1: Perfmon: possible freeze starting at 09:32:38, delay is 3.017
2014.07.09 09:33:44 1: Perfmon: possible freeze starting at 09:33:41, delay is 3.017
2014.07.09 09:34:47 1: Perfmon: possible freeze starting at 09:34:44, delay is 3.017
2014.07.09 09:35:02 1: Perfmon: possible freeze starting at 09:35:01, delay is 1.257
2014.07.09 09:35:50 1: Perfmon: possible freeze starting at 09:35:47, delay is 3.017
2014.07.09 09:36:39 1: Perfmon: possible freeze starting at 09:36:38, delay is 1.13
2014.07.09 09:36:43 1: Perfmon: possible freeze starting at 09:36:42, delay is 1.126
2014.07.09 09:36:46 1: Perfmon: possible freeze starting at 09:36:45, delay is 1.129
2014.07.09 09:36:53 1: Perfmon: possible freeze starting at 09:36:50, delay is 3.012
2014.07.09 09:37:56 1: Perfmon: possible freeze starting at 09:37:53, delay is 3.008
2014.07.09 09:38:59 1: Perfmon: possible freeze starting at 09:38:56, delay is 3.017
2014.07.09 09:40:02 1: Perfmon: possible freeze starting at 09:39:59, delay is 3.012
2014.07.09 09:40:04 1: Perfmon: possible freeze starting at 09:40:03, delay is 1.819
2014.07.09 09:41:05 1: Perfmon: possible freeze starting at 09:41:02, delay is 3.362
2014.07.09 09:41:43 1: Perfmon: possible freeze starting at 09:41:42, delay is 1.127
2014.07.09 09:41:46 1: Perfmon: possible freeze starting at 09:41:45, delay is 1.128
2014.07.09 09:42:08 1: Perfmon: possible freeze starting at 09:42:05, delay is 3.012
2014.07.09 09:43:11 1: Perfmon: possible freeze starting at 09:43:08, delay is 3.017
2014.07.09 09:44:14 1: Perfmon: possible freeze starting at 09:44:11, delay is 3.017
2014.07.09 09:45:06 1: Perfmon: possible freeze starting at 09:45:05, delay is 1.877
2014.07.09 09:45:17 1: Perfmon: possible freeze starting at 09:45:14, delay is 3.012
2014.07.09 09:46:20 1: Perfmon: possible freeze starting at 09:46:17, delay is 3.017
2014.07.09 09:46:39 1: Perfmon: possible freeze starting at 09:46:38, delay is 1.129
2014.07.09 09:46:46 1: Perfmon: possible freeze starting at 09:46:45, delay is 1.127
2014.07.09 09:47:23 1: Perfmon: possible freeze starting at 09:47:20, delay is 3.032
2014.07.09 09:48:26 1: Perfmon: possible freeze starting at 09:48:23, delay is 3.012
2014.07.09 09:49:29 1: Perfmon: possible freeze starting at 09:49:26, delay is 3.018
2014.07.09 09:50:08 1: Perfmon: possible freeze starting at 09:50:07, delay is 1.979
2014.07.09 09:50:32 1: Perfmon: possible freeze starting at 09:50:29, delay is 3.007
2014.07.09 09:51:35 1: Perfmon: possible freeze starting at 09:51:32, delay is 3.002
2014.07.09 09:51:39 1: Perfmon: possible freeze starting at 09:51:38, delay is 1.128
2014.07.09 09:52:38 1: Perfmon: possible freeze starting at 09:52:35, delay is 3.017
2014.07.09 09:53:41 1: Perfmon: possible freeze starting at 09:53:38, delay is 3.012
2014.07.09 09:54:44 1: Perfmon: possible freeze starting at 09:54:41, delay is 3.012
2014.07.09 09:55:10 1: Perfmon: possible freeze starting at 09:55:09, delay is 1.987
2014.07.09 09:55:47 1: Perfmon: possible freeze starting at 09:55:44, delay is 3.012
2014.07.09 09:56:39 1: Perfmon: possible freeze starting at 09:56:38, delay is 1.129
2014.07.09 09:56:43 1: Perfmon: possible freeze starting at 09:56:42, delay is 1.126
2014.07.09 09:56:46 1: Perfmon: possible freeze starting at 09:56:45, delay is 1.131
2014.07.09 09:56:50 1: Perfmon: possible freeze starting at 09:56:47, delay is 3.012
2014.07.09 09:57:53 1: Perfmon: possible freeze starting at 09:57:50, delay is 3.017
2014.07.09 09:58:56 1: Perfmon: possible freeze starting at 09:58:53, delay is 3.012
2014.07.09 09:59:59 1: Perfmon: possible freeze starting at 09:59:56, delay is 3.012
2014.07.09 10:00:13 1: Perfmon: possible freeze starting at 10:00:11, delay is 2.042
2014.07.09 10:01:02 1: Perfmon: possible freeze starting at 10:00:59, delay is 3.012
2014.07.09 10:02:05 1: Perfmon: possible freeze starting at 10:02:02, delay is 3.237
2014.07.09 10:03:08 1: Perfmon: possible freeze starting at 10:03:05, delay is 3.017
2014.07.09 10:04:11 1: Perfmon: possible freeze starting at 10:04:08, delay is 3.012
2014.07.09 10:05:14 1: Perfmon: possible freeze starting at 10:05:11, delay is 3.007
2014.07.09 10:05:16 1: Perfmon: possible freeze starting at 10:05:15, delay is 1.406
2014.07.09 10:06:17 1: Perfmon: possible freeze starting at 10:06:14, delay is 3.012
2014.07.09 10:07:20 1: Perfmon: possible freeze starting at 10:07:17, delay is 3.017
2014.07.09 10:08:23 1: Perfmon: possible freeze starting at 10:08:20, delay is 3.011
2014.07.09 10:09:26 1: Perfmon: possible freeze starting at 10:09:23, delay is 3.017
2014.07.09 10:10:18 1: Perfmon: possible freeze starting at 10:10:17, delay is 1.459
2014.07.09 10:10:29 1: Perfmon: possible freeze starting at 10:10:26, delay is 3.017
2014.07.09 10:11:32 1: Perfmon: possible freeze starting at 10:11:29, delay is 3.012
2014.07.09 10:11:39 1: Perfmon: possible freeze starting at 10:11:38, delay is 1.13
2014.07.09 10:11:46 1: Perfmon: possible freeze starting at 10:11:45, delay is 1.131
2014.07.09 10:12:35 1: Perfmon: possible freeze starting at 10:12:32, delay is 3.017
2014.07.09 10:13:38 1: Perfmon: possible freeze starting at 10:13:35, delay is 3.012
2014.07.09 10:14:41 1: Perfmon: possible freeze starting at 10:14:38, delay is 3.018
2014.07.09 10:15:20 1: Perfmon: possible freeze starting at 10:15:19, delay is 1.612
2014.07.09 10:15:44 1: Perfmon: possible freeze starting at 10:15:41, delay is 3.017
2014.07.09 10:16:47 1: Perfmon: possible freeze starting at 10:16:44, delay is 3.002
2014.07.09 10:17:50 1: Perfmon: possible freeze starting at 10:17:47, delay is 3.012
2014.07.09 10:18:53 1: Perfmon: possible freeze starting at 10:18:50, delay is 3.017

Woran kann das liegen und wie finde ich den/die Übeltäter?

Hi,

richtig. Die 3 Sekunden Dinger kommen exakt jede Minute (plus 3 Sekunden).

Schritt 1: kurz überdenken welches Deiner Module "jede Minute irgendwas pollen" könnte. Wird eher ein "Exot" (sorry) sein.
sonst
Schritt 2: (global) verbose hochsetzen und schauen ob das betreffende Modul anhand von Einträgen im log identifiziert werden kann.
sonst
Schritt 3: Modul für Modul disablen (oder entfernen) bis die Meldungen verschwinden.

vg
Jörg

Hallo Jörg.

Ich habe das Verbose auf 5 hoch gesetzt. Leider finde ich nicht so recht woran es liegen könnte. Findest du was?

2014.07.09 13:22:39 1: Perfmon: possible freeze starting at 13:22:36, delay is 3.012
2014.07.09 13:22:39 5: Triggering rr_Miro (2 changes)
2014.07.09 13:22:39 5: Notify loop for rr_Miro durTimerPresence_cr: 9686
2014.07.09 13:22:39 4: eventTypes: ROOMMATE rr_Miro durTimerPresence_cr: 9686 -> durTimerPresence_cr: .*
2014.07.09 13:22:39 4: eventTypes: ROOMMATE rr_Miro durTimerPresence: 161:25:57 -> durTimerPresence: .*:.*:.*
2014.07.09 13:22:39 5: Triggering rr_Angie (2 changes)
2014.07.09 13:22:39 5: Notify loop for rr_Angie durTimerAbsence_cr: 34236
2014.07.09 13:22:39 4: eventTypes: ROOMMATE rr_Angie durTimerAbsence_cr: 34236 -> durTimerAbsence_cr: .*
2014.07.09 13:22:39 4: eventTypes: ROOMMATE rr_Angie durTimerAbsence: 570:35:46 -> durTimerAbsence: .*:.*:.*
2014.07.09 13:22:39 5: SYSMON Update
2014.07.09 13:22:39 5: SYSMON SYSMON_getNetworkInfo get eth0:eth0:Ethernet
2014.07.09 13:22:39 5: SYSMON SYSMON_getNetworkInfo get wlan0:wlan0:WiFi
2014.07.09 13:22:39 5: Triggering sysmon (6 changes)
2014.07.09 13:22:39 5: Notify loop for sysmon cpu_freq: 700
2014.07.09 13:22:39 4: eventTypes: SYSMON sysmon cpu_freq: 700 -> cpu_freq: .*
2014.07.09 13:22:39 4: eventTypes: SYSMON sysmon eth0_diff: RX: 0.01 MB, TX: 0.05 MB, Total: 0.06 MB -> eth0_diff: RX: .* MB, TX: .* MB, Total: .* MB
2014.07.09 13:22:39 4: eventTypes: SYSMON sysmon cpu_temp_avg: 48.3 -> cpu_temp_avg: .*
2014.07.09 13:22:39 4: eventTypes: SYSMON sysmon cpu_temp: 48.15 -> cpu_temp: .*
2014.07.09 13:22:39 4: eventTypes: SYSMON sysmon loadavg: 0.06 0.11 0.13 -> loadavg: .* .* .*
2014.07.09 13:22:39 4: eventTypes: SYSMON sysmon ram: Total: 485.24 MB, Used: 88.16 MB, 18.17 %, Free: 397.08 MB -> ram: Total: .* MB, Used: .* MB, .* %, Free: .* MB
2014.07.09 13:22:43 5: FHEMduino/RAW: /K3
2014.07.09 13:22:43 5: FHEMduino/RAW: K3/5000+1
2014.07.09 13:22:43 5: FHEMduino/RAW: K35000+1/3789
2014.07.09 13:22:43 5: FHEMduino/RAW: K35000+13789
/

2014.07.09 13:22:43 5: FHEMduino: K35000+13789
2014.07.09 13:22:43 5: FHEMduino dispatch K35000+13789
2014.07.09 13:22:43 5: FingerprintFn Message: Name: FHEMduino  und Message: K35000+13789
2014.07.09 13:22:43 4: FHEMduino_KW9010 FHEMduino_KW9010_35: T 13.7 H 89
2014.07.09 13:22:44 5: FHEMduino/RAW: /K
2014.07.09 13:22:44 5: FHEMduino/RAW: K/35000+1378
2014.07.09 13:22:44 5: FHEMduino/RAW: K35000+1378/9

2014.07.09 13:22:44 5: FHEMduino: K35000+13789
2014.07.09 13:22:44 5: FHEMduino dispatch K35000+13789
2014.07.09 13:22:44 5: FingerprintFn Message: Name: FHEMduino  und Message: K35000+13789
2014.07.09 13:22:44 4: FHEMduino_KW9010 FHEMduino_KW9010_35: T 13.7 H 89
2014.07.09 13:22:44 5: FHEMduino/RAW: /K3
2014.07.09 13:22:44 5: FHEMduino/RAW: K3/5000+1
2014.07.09 13:22:44 5: FHEMduino/RAW: K35000+1/3789
2014.07.09 13:22:44 5: FHEMduino/RAW: K35000+13789/

2014.07.09 13:22:44 5: FHEMduino: K35000+13789
2014.07.09 13:22:44 5: FHEMduino dispatch K35000+13789
2014.07.09 13:22:44 5: FingerprintFn Message: Name: FHEMduino  und Message: K35000+13789
2014.07.09 13:22:44 4: FHEMduino_KW9010 FHEMduino_KW9010_35: T 13.7 H 89
2014.07.09 13:23:00 5: exec at command tickHeartbeat
2014.07.09 13:23:00 5: Cmd: >{tickHeartbeat('Server_Heartbeat');}<
2014.07.09 13:23:00 5: Cmd: >set Server_Heartbeat 5<
2014.07.09 13:23:00 4: dummy set Server_Heartbeat 5
2014.07.09 13:23:00 5: Triggering Server_Heartbeat (2 changes)
2014.07.09 13:23:00 5: Notify loop for Server_Heartbeat 5
2014.07.09 13:23:00 4: eventTypes: dummy Server_Heartbeat 5 -> .*
2014.07.09 13:23:00 4: eventTypes: dummy Server_Heartbeat lastChange: 13:23:00 -> lastChange: .*:.*:.*
2014.07.09 13:23:00 4: eventTypes: dummy Server_Heartbeat state: 5 -> state: .*
2014.07.09 13:23:00 5: redefine at command tickHeartbeat as +*00:01:00 {tickHeartbeat('Server_Heartbeat');}
2014.07.09 13:23:01 4: Connection accepted from FHEMWEB:127.0.0.1:40464
2014.07.09 13:23:02 4: Connection accepted from FHEMWEB:127.0.0.1:40465
2014.07.09 13:23:02 4: Connection closed for FHEMWEB:127.0.0.1:40464
2014.07.09 13:23:02 4: HTTP FHEMWEB:127.0.0.1:40465 GET /fhem/rss/FrameRSS.jpg
2014.07.09 13:23:02 4: /fhem/rss/FrameRSS.jpg / RL:10127 / image/jpeg; charset=utf-8 /  /
2014.07.09 13:23:02 4: Connection accepted from FHEMWEB:127.0.0.1:40466
2014.07.09 13:23:02 4: Connection closed for FHEMWEB:127.0.0.1:40465
2014.07.09 13:23:02 4: HTTP FHEMWEB:127.0.0.1:40466 GET /fhem/rss/FrameRSS.jpg
2014.07.09 13:23:02 4: /fhem/rss/FrameRSS.jpg / RL:10127 / image/jpeg; charset=utf-8 /  /
2014.07.09 13:23:02 4: Connection closed for FHEMWEB:127.0.0.1:40466
2014.07.09 13:23:15 5: FHEMduino/RAW: /K3
2014.07.09 13:23:15 5: FHEMduino/RAW: K3/5000+1
2014.07.09 13:23:15 5: FHEMduino/RAW: K35000+1/3789
2014.07.09 13:23:15 5: FHEMduino/RAW: K35000+13789/

2014.07.09 13:23:15 5: FHEMduino: K35000+13789
2014.07.09 13:23:15 5: FHEMduino dispatch K35000+13789
2014.07.09 13:23:15 5: FingerprintFn Message: Name: FHEMduino  und Message: K35000+13789
2014.07.09 13:23:15 4: FHEMduino_KW9010 FHEMduino_KW9010_35: T 13.7 H 89
2014.07.09 13:23:16 5: FHEMduino/RAW: /K
2014.07.09 13:23:16 5: FHEMduino/RAW: K/35000+
2014.07.09 13:23:16 5: FHEMduino/RAW: K35000+/1378
2014.07.09 13:23:16 5: FHEMduino/RAW: K35000+1378/9

2014.07.09 13:23:16 5: FHEMduino: K35000+13789
2014.07.09 13:23:16 5: FHEMduino dispatch K35000+13789
2014.07.09 13:23:16 5: FingerprintFn Message: Name: FHEMduino  und Message: K35000+13789
2014.07.09 13:23:16 4: FHEMduino_KW9010 FHEMduino_KW9010_35: T 13.7 H 89
2014.07.09 13:23:16 5: FHEMduino/RAW: /K3
2014.07.09 13:23:16 5: FHEMduino/RAW: K3/5000+1
2014.07.09 13:23:16 5: FHEMduino/RAW: K35000+1/378
2014.07.09 13:23:16 5: FHEMduino/RAW: K35000+1378/9

2014.07.09 13:23:16 5: FHEMduino: K35000+13789
2014.07.09 13:23:16 5: FHEMduino dispatch K35000+13789
2014.07.09 13:23:16 5: FingerprintFn Message: Name: FHEMduino  und Message: K35000+13789
2014.07.09 13:23:16 4: FHEMduino_KW9010 FHEMduino_KW9010_35: T 13.7 H 89
2014.07.09 13:23:22 5: Cmd: >{fhem("set Druckauftrag ".`/opt/fhem/cups.sh`)}<
2014.07.09 13:23:22 5: Cmd: >set Druckauftrag abgeschlossen
<
2014.07.09 13:23:22 5: Triggering Druckauftrag (1 changes)
2014.07.09 13:23:22 5: Notify loop for Druckauftrag abgeschlossen

2014.07.09 13:23:22 4: eventTypes: dummy Druckauftrag abgeschlossen
-> abgeschlossen

2014.07.09 13:23:22 4: eventTypes: dummy Druckauftrag state: abgeschlossen
-> state: abgeschlossen

2014.07.09 13:23:27 5: FHEMduino/RAW: /K
2014.07.09 13:23:27 5: FHEMduino/RAW: K/fc100+
2014.07.09 13:23:27 5: FHEMduino/RAW: Kfc100+/2551
2014.07.09 13:23:27 5: FHEMduino/RAW: Kfc100+2551/27

2014.07.09 13:23:27 5: FHEMduino: Kfc100+255127
2014.07.09 13:23:27 5: FHEMduino dispatch Kfc100+255127
2014.07.09 13:23:27 5: FingerprintFn Message: Name: FHEMduino  und Message: Kfc100+255127
2014.07.09 13:23:27 5: Triggering FHEMduino (1 changes)
2014.07.09 13:23:27 5: Notify loop for FHEMduino UNKNOWNCODE Kfc100+255127
2014.07.09 13:23:27 4: eventTypes: FHEMduino FHEMduino UNKNOWNCODE Kfc100+255127 -> UNKNOWNCODE Kfc100+.*
2014.07.09 13:23:27 3: FHEMduino: Unknown code Kfc100+255127, help me!
2014.07.09 13:23:27 5: FHEMduino/RAW: /K
2014.07.09 13:23:27 5: FHEMduino/RAW: K/fc100+
2014.07.09 13:23:27 5: FHEMduino/RAW: Kfc100+/2551
2014.07.09 13:23:27 5: FHEMduino/RAW: Kfc100+2551/27

2014.07.09 13:23:27 5: FHEMduino: Kfc100+255127
2014.07.09 13:23:27 5: FHEMduino dispatch Kfc100+255127
2014.07.09 13:23:27 5: FingerprintFn Message: Name: FHEMduino  und Message: Kfc100+255127
2014.07.09 13:23:27 5: Triggering FHEMduino (1 changes)
2014.07.09 13:23:27 5: Notify loop for FHEMduino UNKNOWNCODE Kfc100+255127
2014.07.09 13:23:27 4: eventTypes: FHEMduino FHEMduino UNKNOWNCODE Kfc100+255127 -> UNKNOWNCODE Kfc100+.*
2014.07.09 13:23:27 3: FHEMduino: Unknown code Kfc100+255127, help me!
2014.07.09 13:23:27 5: FHEMduino/RAW: /K
2014.07.09 13:23:27 5: FHEMduino/RAW: K/fc100+255
2014.07.09 13:23:27 5: FHEMduino/RAW: Kfc100+255/127

2014.07.09 13:23:27 5: FHEMduino: Kfc100+255127
2014.07.09 13:23:27 5: FHEMduino dispatch Kfc100+255127
2014.07.09 13:23:27 5: FingerprintFn Message: Name: FHEMduino  und Message: Kfc100+255127
2014.07.09 13:23:27 5: Triggering FHEMduino (1 changes)
2014.07.09 13:23:27 5: Notify loop for FHEMduino UNKNOWNCODE Kfc100+255127
2014.07.09 13:23:27 4: eventTypes: FHEMduino FHEMduino UNKNOWNCODE Kfc100+255127 -> UNKNOWNCODE Kfc100+.*
2014.07.09 13:23:27 3: FHEMduino: Unknown code Kfc100+255127, help me!
2014.07.09 13:23:42 1: Perfmon: possible freeze starting at 13:23:39, delay is 3.012

Hi,

ne - leider nicht. Im fraglichen Zeitraum ist im log nichts zu sehen:
2014.07.09 13:23:27 3: FHEMduino: Unknown code Kfc100+255127, help me!
2014.07.09 13:23:42 1: Perfmon: possible freeze starting at 13:23:39, delay is 3.012
Grundsätzlich erscheint aber eben auch nur das im log was die dazugehörigen Module reinschreiben.

Also #3; Module deaktivieren ....

vg
Jörg

Ich habe nun nach und nach alle Module bzw die Definition dazu aus meiner fhem.cfg gelöscht, anschließend das Log kontrolliert und wieder eingefügt. Leider komme ich nicht weiter. Die Freezes tauchen immer noch auf. Würde Dir meine hem.cfg Datei helfen das Problem zu finden?

Ein weiterer Auszug:

2014.07.09 17:27:03 4: HTTP FHEMWEB:192.168.178.21:62476 GET /fhem/pgm2/svg.js
2014.07.09 17:27:03 4: HTTP FHEMWEB:192.168.178.21:62482 GET /fhem/pgm2/fhemweb_noArg.js
2014.07.09 17:27:03 4: HTTP FHEMWEB:192.168.178.21:62400 GET /fhem/pgm2/fhemweb_readingsHistory.js
2014.07.09 17:27:03 4: HTTP FHEMWEB:192.168.178.21:62458 GET /fhem/pgm2/fhemweb_slider.js
2014.07.09 17:27:03 4: HTTP FHEMWEB:192.168.178.21:62439 GET /fhem/pgm2/fhemweb_svg.js
2014.07.09 17:27:03 4: HTTP FHEMWEB:192.168.178.21:62476 GET /fhem/pgm2/fhemweb_textField.js
2014.07.09 17:27:03 4: HTTP FHEMWEB:192.168.178.21:62482 GET /fhem/pgm2/fhemweb_time.js
2014.07.09 17:27:03 4: HTTP FHEMWEB:192.168.178.21:62400 GET /fhem/images/default/icoEverything.png
2014.07.09 17:27:03 4: Connection accepted from FHEMWEB:127.0.0.1:41511
2014.07.09 17:27:03 4: Connection closed for FHEMWEB:127.0.0.1:41510
2014.07.09 17:27:03 4: HTTP FHEMWEB:127.0.0.1:41511 GET /fhem/rss/FrameRSS.jpg
2014.07.09 17:27:03 4: /fhem/rss/FrameRSS.jpg / RL:9753 / image/jpeg; charset=utf-8 /  /
2014.07.09 17:27:03 4: Connection closed for FHEMWEB:127.0.0.1:41511
2014.07.09 17:27:03 4: Connection accepted from FHEMWEB:127.0.0.1:41512
2014.07.09 17:27:03 4: HTTP FHEMWEB:127.0.0.1:41512 GET /fhem/rss/FrameRSS.jpg
2014.07.09 17:27:04 4: /fhem/rss/FrameRSS.jpg / RL:9753 / image/jpeg; charset=utf-8 /  /
2014.07.09 17:27:04 4: Connection closed for FHEMWEB:127.0.0.1:41512
2014.07.09 17:27:04 4: HTTP FHEMWEB:192.168.178.21:62400 GET /fhem/FileLog_logWrapper?XHR=1&inform=type=status;filter=×tamp=1404919624489
2014.07.09 17:27:04 4: HTTP FHEMWEB:192.168.178.21:62482 GET /fhem/icons/favicon
2014.07.09 17:27:08 5: [Tageslichtsteuerung] Original weather readings
2014.07.09 17:27:08 5: Triggering Tageslichtsteuerung (5 changes)
2014.07.09 17:27:08 5: Notify loop for Tageslichtsteuerung azimuth: 258.83
2014.07.09 17:27:08 4: eventTypes: Twilight Tageslichtsteuerung azimuth: 258.83 -> azimuth: .*
2014.07.09 17:27:08 4: eventTypes: Twilight Tageslichtsteuerung elevation: 37.19 -> elevation: .*
2014.07.09 17:27:08 4: eventTypes: Twilight Tageslichtsteuerung twilight: 100 -> twilight: .*
2014.07.09 17:27:08 4: eventTypes: Twilight Tageslichtsteuerung twilight_weather: 100 -> twilight_weather: .*
2014.07.09 17:27:08 4: eventTypes: Twilight Tageslichtsteuerung compasspoint: west-southwest -> compasspoint: west-southwest
2014.07.09 17:27:08 5: [Tageslichtsteuerung] removing Timer: Tageslichtsteuerung_sunpos
2014.07.09 17:27:08 5: [Tageslichtsteuerung] setting  Timer: Tageslichtsteuerung_sunpos 09.07.2014  17:32:08
2014.07.09 17:27:09 5: SYSMON Update
2014.07.09 17:27:09 5: SYSMON SYSMON_getNetworkInfo get eth0:eth0:Ethernet
2014.07.09 17:27:09 5: SYSMON SYSMON_getNetworkInfo get wlan0:wlan0:WiFi
2014.07.09 17:27:09 5: Triggering sysmon (6 changes)
2014.07.09 17:27:09 5: Notify loop for sysmon cpu_freq: 700
2014.07.09 17:27:09 4: eventTypes: SYSMON sysmon cpu_freq: 700 -> cpu_freq: .*
2014.07.09 17:27:09 4: eventTypes: SYSMON sysmon eth0_diff: RX: 0.04 MB, TX: 0.85 MB, Total: 0.89 MB -> eth0_diff: RX: .* MB, TX: .* MB, Total: .* MB
2014.07.09 17:27:09 4: eventTypes: SYSMON sysmon cpu_temp_avg: 48.5 -> cpu_temp_avg: .*
2014.07.09 17:27:09 4: eventTypes: SYSMON sysmon cpu_temp: 48.69 -> cpu_temp: .*
2014.07.09 17:27:09 4: eventTypes: SYSMON sysmon loadavg: 0.21 0.26 0.32 -> loadavg: .* .* .*
2014.07.09 17:27:09 4: eventTypes: SYSMON sysmon ram: Total: 485.24 MB, Used: 87.21 MB, 17.97 %, Free: 398.03 MB -> ram: Total: .* MB, Used: .* MB, .* %, Free: .* MB
2014.07.09 17:27:09 5: Cmd: >{fhem("set Druckauftrag ".`/opt/fhem/cups.sh`)}<
2014.07.09 17:27:09 5: Cmd: >set Druckauftrag abgeschlossen
<
2014.07.09 17:27:09 5: Triggering Druckauftrag (1 changes)
2014.07.09 17:27:09 5: Notify loop for Druckauftrag abgeschlossen

2014.07.09 17:27:09 4: eventTypes: dummy Druckauftrag abgeschlossen
-> abgeschlossen

2014.07.09 17:27:09 4: eventTypes: dummy Druckauftrag state: abgeschlossen
-> state: abgeschlossen

2014.07.09 17:27:12 5: SW: ORb
2014.07.09 17:27:12 5: CUL/RAW (ReadAnswer): OK:1

2014.07.09 17:27:16 5: I2C_TSL2561_Enable: start
2014.07.09 17:27:16 5: I2C_TSL2561_ReadByte: start
2014.07.09 17:27:16 5: I2C_TSL2561_ReadByte: 3
2014.07.09 17:27:16 5: I2C_TSL2561_Enable: is enabled
2014.07.09 17:27:16 5: I2C_TSL2561_Enable: end
2014.07.09 17:27:16 5: I2C_TSL2561_Disable: start
2014.07.09 17:27:16 5: I2C_TSL2561_Disable: end
2014.07.09 17:27:16 5: Triggering Luminosity (3 changes)
2014.07.09 17:27:16 5: Notify loop for Luminosity luminosity: 14
2014.07.09 17:27:16 4: eventTypes: I2C_TSL2561 Luminosity luminosity: 14 -> luminosity: .*
2014.07.09 17:27:16 4: eventTypes: I2C_TSL2561 Luminosity broadband: 1 -> broadband: .*
2014.07.09 17:27:16 4: eventTypes: I2C_TSL2561 Luminosity ir: 0 -> ir: .*
2014.07.09 17:27:16 5: Pressure empfangen: 125 240
2014.07.09 17:27:16 5: Pressure empfangen: 153 39 64
2014.07.09 17:27:16 5: Triggering Pressure (4 changes)
2014.07.09 17:27:16 5: Notify loop for Pressure T: 37.2 P: 993 P-NN: 1003
2014.07.09 17:27:16 4: eventTypes: I2C_BMP180 Pressure T: 37.2 P: 993 P-NN: 1003 -> T: .* P: .* P-NN: .*
2014.07.09 17:27:16 4: eventTypes: I2C_BMP180 Pressure temperature: 37.2 -> temperature: .*
2014.07.09 17:27:16 4: eventTypes: I2C_BMP180 Pressure pressure: 993 -> pressure: .*
2014.07.09 17:27:16 4: eventTypes: I2C_BMP180 Pressure pressure-nn: 1003 -> pressure-nn: .*
2014.07.09 17:27:16 4: eventTypes: I2C_BMP180 Pressure state: T: 37.2 P: 993 P-NN: 1003 -> state: T: .* P: .* P-NN: .*
2014.07.09 17:27:16 5: Triggering Server (1 changes)
2014.07.09 17:27:16 5: Notify loop for Server isRunning: true
2014.07.09 17:27:16 4: eventTypes: WOL Server isRunning: true -> isRunning: true
2014.07.09 17:27:19 5: SW: ORb
2014.07.09 17:27:19 5: CUL/RAW (ReadAnswer): OK:1

2014.07.09 17:27:19 5: SW: OmD000000558C41328
2014.07.09 17:27:19 5: CUL/RAW (ReadAnswer): m:D00000
2014.07.09 17:27:19 5: CUL/RAW (ReadAnswer): 0558C413
2014.07.09 17:27:19 5: CUL/RAW (ReadAnswer): 28

2014.07.09 17:27:19 5: SW: OwB44
2014.07.09 17:27:19 5: SW: ORb
2014.07.09 17:27:19 5: CUL/RAW (ReadAnswer): OK:1

2014.07.09 17:27:19 5: SW: OmD000000558C41328
2014.07.09 17:27:19 5: CUL/RAW (ReadAnswer): m:D00000
2014.07.09 17:27:19 5: CUL/RAW (ReadAnswer): 0558C413
2014.07.09 17:27:19 5: CUL/RAW (ReadAnswer): 28

2014.07.09 17:27:19 5: SW: OwBbe
2014.07.09 17:27:19 5: SW: OrB
2014.07.09 17:27:19 5: CUL/RAW (ReadAnswer): 6C

2014.07.09 17:27:19 5: SW: OrB
2014.07.09 17:27:19 5: CUL/RAW (ReadAnswer): 01

2014.07.09 17:27:19 5: SW: OrB
2014.07.09 17:27:19 5: CUL/RAW (ReadAnswer): 4B

2014.07.09 17:27:19 5: SW: OrB
2014.07.09 17:27:20 5: CUL/RAW (ReadAnswer): 46

2014.07.09 17:27:20 5: SW: OrB
2014.07.09 17:27:20 5: CUL/RAW (ReadAnswer): 7F

2014.07.09 17:27:20 5: SW: OrB
2014.07.09 17:27:20 5: CUL/RAW (ReadAnswer): FF

2014.07.09 17:27:20 5: SW: OrB
2014.07.09 17:27:20 5: CUL/RAW (ReadAnswer): 04

2014.07.09 17:27:20 5: SW: OrB
2014.07.09 17:27:20 5: CUL/RAW (ReadAnswer): 10

2014.07.09 17:27:20 5: SW: OrB
2014.07.09 17:27:20 5: CUL/RAW (ReadAnswer): 5D

2014.07.09 17:27:20 5: Triggering OWX_28_13C458050000 (2 changes)
2014.07.09 17:27:20 5: Notify loop for OWX_28_13C458050000 temperature: 22.75
2014.07.09 17:27:20 4: eventTypes: OWTHERM OWX_28_13C458050000 temperature: 22.75 -> temperature: .*
2014.07.09 17:27:20 4: eventTypes: OWTHERM OWX_28_13C458050000 T: 22.75 °C ▾ -> T: .* °C ▾
2014.07.09 17:27:20 4: eventTypes: OWTHERM OWX_28_13C458050000 state: T: 22.75 °C ▾ -> state: T: .* °C ▾
2014.07.09 17:27:20 5: T: 22.75 °C ▾
2014.07.09 17:27:20 5: SW: ORb
2014.07.09 17:27:20 5: CUL/RAW (ReadAnswer): OK:1

2014.07.09 17:27:20 5: SW: OmF6000005589C5828
2014.07.09 17:27:20 5: CUL/RAW (ReadAnswer): m:F60000
2014.07.09 17:27:20 5: CUL/RAW (ReadAnswer): 05589C58
2014.07.09 17:27:20 5: CUL/RAW (ReadAnswer): 28

2014.07.09 17:27:20 5: SW: OwB44
2014.07.09 17:27:21 5: SW: ORb
2014.07.09 17:27:21 5: CUL/RAW (ReadAnswer): OK:1

2014.07.09 17:27:21 5: SW: OmF6000005589C5828
2014.07.09 17:27:21 5: CUL/RAW (ReadAnswer): m:F60000
2014.07.09 17:27:21 5: CUL/RAW (ReadAnswer): 05589C58
2014.07.09 17:27:21 5: CUL/RAW (ReadAnswer): 28

2014.07.09 17:27:21 5: SW: OwBbe
2014.07.09 17:27:21 5: SW: OrB
2014.07.09 17:27:21 5: CUL/RAW (ReadAnswer): 6D

2014.07.09 17:27:21 5: SW: OrB
2014.07.09 17:27:21 5: CUL/RAW (ReadAnswer): 01

2014.07.09 17:27:21 5: SW: OrB
2014.07.09 17:27:21 5: CUL/RAW (ReadAnswer): 4B

2014.07.09 17:27:21 5: SW: OrB
2014.07.09 17:27:21 5: CUL/RAW (ReadAnswer): 46

2014.07.09 17:27:21 5: SW: OrB
2014.07.09 17:27:21 5: CUL/RAW (ReadAnswer): 7F

2014.07.09 17:27:21 5: SW: OrB
2014.07.09 17:27:21 5: CUL/RAW (ReadAnswer): FF

2014.07.09 17:27:21 5: SW: OrB
2014.07.09 17:27:21 5: CUL/RAW (ReadAnswer): 03

2014.07.09 17:27:21 5: SW: OrB
2014.07.09 17:27:21 5: CUL/RAW (ReadAnswer): 10

2014.07.09 17:27:21 5: SW: OrB
2014.07.09 17:27:21 5: CUL/RAW (ReadAnswer): 70

2014.07.09 17:27:21 5: Triggering OWX_28_589C58050000 (2 changes)
2014.07.09 17:27:21 5: Notify loop for OWX_28_589C58050000 temperature: 22.8125
2014.07.09 17:27:21 4: eventTypes: OWTHERM OWX_28_589C58050000 temperature: 22.8125 -> temperature: .*
2014.07.09 17:27:21 4: eventTypes: OWTHERM OWX_28_589C58050000 T: 22.81 °C ▾ -> T: .* °C ▾
2014.07.09 17:27:21 4: eventTypes: OWTHERM OWX_28_589C58050000 state: T: 22.81 °C ▾ -> state: T: .* °C ▾
2014.07.09 17:27:21 5: T: 22.81 °C ▾
2014.07.09 17:27:21 1: Perfmon: possible freeze starting at 17:27:20, delay is 1.348

Danke schonmal für deine Hilfe!

Hi,

ZitatIch habe nun nach und nach alle Module bzw die Definition dazu aus meiner fhem.cfg gelöscht, anschließend das Log kontrolliert und wieder eingefügt. Leider komme ich nicht weiter. Die Freezes tauchen immer noch auf.

Da stimmt dann was nicht.

Wenn Du eine leere cfg hast (bzw die Democonfig) wüsste ich keinen plausiblen Grund warum die freeze auftauchen sollten.

Im "normalen" Betrieb musst Du unterscheiden: kleine (und seltene) freeze (1..2 Sekunden) können vorkommen, liegt in der Art wie fhem aufgebaut ist, je schneller die Hardware desto seltener.

In Deinem Beispiel von heute morgen hast Du regelmäßig, einmal pro Minute, für 3 Sekunden Stillstand. Das wird sich ganz sicher auf ein einzelnes Modul zurückführen lassen welches einmal aller 60 Sekunden einen Task ausführt. 

ZitatWürde Dir meine hem.cfg Datei helfen das Problem zu finden?

Leider nein. Daran sehe ich nur welche Module Du verwendest, nicht jedoch welches blockiert.

Schau Dir mal parallel "apptime" (siehe commandref) an. Perfmon ist gut darin einzelne "Hänger" und deren Zeitpunkt aufzuzeigen. "Apptime" zeigt an welche Module wieviel Rechenzeit insgesamt brauchen. Beides kombiniert macht ein gutes Gesamtbild.

Poste gerne mal den Output von apptime.

vg
Jörg

Ich habe es heute Nachmittag mal mit der FHEM.cfg.demo ausprobiert. Da gabs keine Hänger.

Das gibt mir Apptime aus (als Bild damit die Tabelle erhalten bleibt. :) ):

ZitatIch habe es heute Nachmittag mal mit der FHEM.cfg.demo ausprobiert. Da gabs keine Hänger.

alles andere wäre verrückt  8)

Der screenshot von apptime sieht erstmal recht unspektakulär aus - allerdings weiß ich auch nicht über welchen Zeitraum der erstellt wurde.

Gedankenspiel:
wenn Du jeweils aller 60 Sekunden einen freeze hast müsste doch nach einer apptime-daten-sammelzeit von 10x60 + 10x3 Sekunden = 10m30s die verursachende Funktion genau 10 mal im apptime auftauchen...

vg
Jörg

Gesagt, getan. ^^ Habe Apptime ungefähr 10 min 30 sec laufen lassen. Parallel dazu der Auszug aus dem Log:

2014.07.09 20:13:57 1: Perfmon: possible freeze starting at 20:13:56, delay is 1.559
2014.07.09 20:14:13 1: FHEMduino_KW9010 77 Temperature jump too large
2014.07.09 20:14:27 1: FHEMduino_KW9010 35 Temperature jump too large
2014.07.09 20:14:45 1: KindleDisplay aktualisiert
2014.07.09 20:15:45 1: KindleDisplay aktualisiert
2014.07.09 20:16:35 1: FHEMduino_KW9010 35 Temperature jump too large
2014.07.09 20:16:35 1: FHEMduino_KW9010 35 Temperature jump too large
2014.07.09 20:16:36 1: FHEMduino_KW9010 UNDEFINED sensor detected, code 34
2014.07.09 20:16:45 1: KindleDisplay aktualisiert
2014.07.09 20:17:39 1: FHEMduino_KW9010 35 Temperature jump too large
2014.07.09 20:17:45 1: KindleDisplay aktualisiert
2014.07.09 20:18:11 1: FHEMduino_KW9010 35 Temperature jump too large
2014.07.09 20:18:12 1: FHEMduino_KW9010 35 Temperature jump too large
2014.07.09 20:18:29 1: FHEMduino_KW9010 UNDEFINED sensor detected, code 1b
2014.07.09 20:18:45 1: KindleDisplay aktualisiert
2014.07.09 20:18:56 1: Perfmon: possible freeze starting at 20:18:55, delay is 1.284
2014.07.09 20:19:45 1: KindleDisplay aktualisiert
2014.07.09 20:20:32 1: FHEMduino_KW9010 UNDEFINED sensor detected, code b5
2014.07.09 20:20:45 1: KindleDisplay aktualisiert
2014.07.09 20:21:45 1: KindleDisplay aktualisiert
2014.07.09 20:21:56 1: FHEMduino_KW9010 35 Temperature jump too large
2014.07.09 20:22:13 1: FHEMduino_KW9010 77 Temperature jump too large
2014.07.09 20:22:39 1: FHEMduino_KW9010 UNDEFINED sensor detected, code b5
2014.07.09 20:22:45 1: KindleDisplay aktualisiert
2014.07.09 20:23:45 1: KindleDisplay aktualisiert
2014.07.09 20:23:56 1: Perfmon: possible freeze starting at 20:23:55, delay is 1.285
2014.07.09 20:24:03 1: FHEMduino_KW9010 35 Temperature jump too large
2014.07.09 20:24:36 1: FHEMduino_KW9010 UNDEFINED sensor detected, code 34
2014.07.09 20:24:45 1: KindleDisplay aktualisiert
2014.07.09 20:25:20 1: FHEMduino_KW9010 UNDEFINED sensor detected, code b5
2014.07.09 20:25:49 1: Perfmon: possible freeze starting at 20:25:44, delay is 5.612

Komischerweise sind nur noch vier Freezes vorhanden.  ???

Edit: Ich sehe gerade, dass meine Drucker Automatisierung nicht in der hem.cfg abgespeichert war. Habe diese hier nachgebaut:

http://forum.fhem.de/index.php/topic,22942.15.html

Können die Hänger daraus resultieren?

ZitatKomischerweise sind nur noch vier Freezes vorhanden

ja, die haben auch einen ganz anderen Fingerprint als die von heute morgen. verbose scheint wieder auf 1 zu stehen. Vielleicht (!) hats was mit dem owtherm zu tun - ich meine das es da eine asynchrone Version gibt.

Die 5 Sekunden am Ende tauchen im apptime leider nicht auf - vermutlich sind die 5 Sekunden also die Summe von mehreren Einzel-Aufrufen. (?)

Versuch Module einzeln zu deaktivieren. (save und Neustart!). Sorry - mehr kann ich von hier aus vermutlich nicht beitragen...

vg
Jörg

Ich habe nun alles aus meiner fhem.cfg gelöscht. Verblieben sind nur die Standardeinträge:

attr global altitude 85
attr global autoload_undefined_devices 1
attr global logfile ./log/fhem-%Y-%m.log
attr global modpath .
attr global statefile ./log/fhem.save
attr global updateInBackground 0
attr global userattr devStateIcon devStateStyle fm_type icon lightSceneParamsToSave lightSceneRestoreOnlyIfChanged:1,0 sortby webCmd widgetOverride
attr global verbose 3

#attr global mseclog 1

define WEB FHEMWEB 8083 global
attr WEB basicAuth XXXXXXXXXX
attr WEB menuEntries restart,cmd=shutdown+restart,update,cmd=update,updatecheck,cmd=update+check
attr WEB ploteditor always
attr WEB roomIcons Alarmanlage:building_security Anwesenheit:status_available Flur:control_building_empty Küche:scene_dinner Bad:scene_bath Wohnzimmer:scene_livingroom Schlafzimmer:scene_baby Umwelt:scene_day System:edit_settings RaspberryPi:RPi Logs:edit_copy
attr WEB sortRooms Alarmanlage Anwesenheit Flur Küche Bad Wohnzimmer Schlafzimmer Umwelt System RaspberryPi Logs Everything Unsorted
attr WEB stylesheetPrefix bright

define WEBphone FHEMWEB 8084 global
attr WEBphone basicAuth XXXXXXXXXX
attr WEBphone hiddenroom DashboardRoom
attr WEBphone stylesheetPrefix smallscreen

define WEBtablet FHEMWEB 8085 global
attr WEBtablet basicAuth XXXXXXXXXX
attr WEBtablet hiddenroom DashboardRoom
attr WEBtablet stylesheetPrefix touchpad

define telnetPort telnet 7072
attr telnetPort SSL 1
attr telnetPort password XXXXXXXXXX

# Fake FileLog entry, to access the fhem log from FHEMWEB
define Logfile FileLog ./log/fhem-%Y-%m.log fakelog
attr Logfile room Logs

#define autocreate autocreate
#attr autocreate filelog ./log/%NAME-%Y.log
#attr autocreate room Unsorted

define eventTypes eventTypes ./log/eventTypes.txt

# Disable this to avoid looking for new USB devices on startup
define initialUsbCheck notify global:INITIALIZED usb create

Eigentlich dürften jetzt doch keine Freezes mehr auftreten. Leider ist das aber nicht der Fall... -.-

2014.07.13 15:50:05 0: Server shutdown
2014.07.13 15:50:09 2: Perfmon: ready to watch out for delays greater than one second
2014.07.13 15:50:10 1: Including fhem.cfg
2014.07.13 15:50:11 3: WEB: port 8083 opened
2014.07.13 15:50:11 3: WEBphone: port 8084 opened
2014.07.13 15:50:11 3: WEBtablet: port 8085 opened
2014.07.13 15:50:11 3: telnetPort: port 7072 opened
2014.07.13 15:50:12 2: eventTypes: loaded 1195 events from ./log/eventTypes.txt
2014.07.13 15:50:12 1: Including ./log/fhem.save
2014.07.13 15:50:12 3: initialUsbCheck return value: Unknown command usb, try help.
2014.07.13 15:50:12 0: Server started with 8 defined entities (version $Id: fhem.pl 6080 2014-06-07 16:12:09Z rudolfkoenig $, os linux, user fhem, pid 13741)
2014.07.13 15:50:12 1: Perfmon: possible freeze starting at 15:50:10, delay is 2.344
2014.07.13 15:51:03 1: Perfmon: possible freeze starting at 15:51:02, delay is 1.033
2014.07.13 15:51:17 1: Perfmon: possible freeze starting at 15:51:12, delay is 5.116
2014.07.13 15:57:08 1: Perfmon: possible freeze starting at 15:57:03, delay is 5.213

Hast du noch irgendeine Idee?  :(

ZitatHast du noch irgendeine Idee?

Immer  :)

Wenn das wirklich die komplette cfg ist dann prüfe bitte nochmal die 99_xxx.pm dateien (und nimm sie kurz aus dem Verzeichnis). Für die 99er gibt es einen autoload Mechanismus unabhängig von der cfg.

Wenn es dann immer noch auftritt bleibt nur fhem (mit pgm2) als quelle. pgm2 ist auch definitiv buggy (!!!) - ggf  ssl abschalten und beobachten.

vg
jörg

Ich habe mir grad dazu entschlossen, einfach alles nochmals neu aufzusetzen. Hoffentlich ist danach alles so wie es sein soll.

Vielen Dank für deine Hilfe! :)

Mir ist bei meiner FHEM Installation und einer, die ich betreue aufgefallen, das man oft diese Freezes erhält, wenn man  seine Plots anzeigen lässt. Besonders über die externe Adresse. Kann man das irgendwie optimieren?

Schau dir plotfork an.

gruss
  andre

danke, mach ich.

Edit: Schon besser... ;D

Hallo zusammen,

ich versuche gerade die die Ursachen der Verzögerungen in meinem FHEM mittels des Performace Monitors zu ermitteln. Dabei wäre es für mich hilfreich, wenn ich erst die großen Brocken beseitigte und dann die kleineren. Ich denke, es wäre hilfreich, wenn ich die Schwelle im Modul anpassen könnte.

Kann mir jemand sagen, ob das überhaupt möglich ist und wenn ja, wo ich was im Modul muss. Eigentlich besteht es ja "nur" aus ein paar Zeilen aber leider verstehe ich die Funktionen nicht ganz.

Viele Grüße und schönes Wochenende

Harald

Nachtrag: Ich hab's gefunden: Zeile 31  if ($freeze > 1). Vergrößert man den Wert ( hier 1), wird die Schwelle auch vergrößert.

Hallo herrmannj,

ist es sehr aufwendig, Dein Modul so zu ändern, dass das zusätzlich das verursachende Modul mit ausgegeben wird, auch wenn das etwas mehr Resourcen benötigt?

Setzt man verbose auf hohe Werte (z.B. 5), werden von den entsprechenden Modulen u.U. sehr viele Logausgaben erzeugt. Dann ist es m.E. nicht so einfach, die Ausgabe von perfmon zu finden. Gibt es zu der Meldung von perfmon nur eine zusätzliche Zeile mit dem Namen des verursachenden Moduls, ist das doch deutlich übersichtlicher. Dann kann man das entsprechende Modul weiter untersuchen.

Viele Grüße und schönes Wochenende

Harald

Hallo Harald,

den Verursacher zu finden ist echte Detektivarbeit. Perfmon führt nur Messungen durch ob alles flutscht. Schau Dir mal apptime an, das wird verwendet um die aktiven Module zu untersuchen. perfmon und apptime sollte man immer als Gespann sehen. Perfmon gibt genaue Aussagen ob und wann Probleme auftreten. Wenn welche da sind liefert apptime statistische Informationen welches Modul wieviel Zeit benötigt.

vg
jörg

Hi,

was ich diesbezüglich unlängst gelernt habe: Perfmon zeigt auf, wann es zu Problemen kommt. apptime kann dann Anhaltspunkte liefern, welche FHEM Funktionen beteiligt sind. Idealerweise findet man damit heraus, wie sich das ungünstige zeitliche Verhalten provozieren lässt. Wenn man es schafft, das mit einem Fhem Kommando zu reproduzieren, kann man direkt davor verbose auf 5 und direkt danach zurück auf 0 setzen.

Im Notfall kann man auch mit 'attr .+ verbose 5; CMD; deleteattr .+ verbose' für ordentlich Lektüre sorgen :-)

Und selbst dann kann es nötig sein, im Modulcode zusätzliche Log-einträge einzufügen, um der eigentlichen Ursache auf den Grund zu kommen. Spätestens hier kann es sich dann lohnen, den Modulautor mit den nötigen Informationen zur Fehlersuche zu kontaktieren.

Grüße,
Andy.

Vorsicht mit deleteattr .+ verbose

ich meine mich zu erinnern das es probleme gib wenn das verbose attribut von global weg ist.

gruss
  andre

ok, ich habe das zwar die letzten Tage recht häufig genauso gemacht, habe aber die Information unterschlagen, dass nein Script davor alle gesetzen verbose Einstellungen gesichert und nach dem deleteattr wieder hergestellt hat. Zumindest kurzzeitig hat das fehlende global verbose nichts ausgemacht.

Grüße,
Andy.

Vielen Dank für Eure Hinweise. Da werde ich mich mal drangeben und versuchen die Ursachen für die Verzögerungen zu finden.

Besten Dank nochmals und schönes Wochenende

Harald

Hallo,

da meine (Licht-)Schalter immer mal wieder auf sich warten lassen, wollte ich versuchen, mein System mit Perfmon zu analysieren und zu optimieren. Dabei komme ich jetzt nicht weiter und hoffe, es kann mit jemand einen Anhaltspunkt geben, wo ich weiter suchen kann. Da ich im Log sehr viele Einträge der Form

2014.12.01 14:31:34 1: Perfmon: possible freeze starting at 14:31:33, delay is 1.879

habe, dachte ich mir, ich drehe mal das Verbose auf 5 und sehe mir an, in welchem Zusammenhang diese Einträge kommen. Erstaunlicherweise kommen diese aber nicht mehr, sobald das Verbose auf 5 läuft. Also habe ich mal eine Excel-Auswertung meines Logs gemacht: Zwischen 00:00 und 13:00 auf Verbose 2 ca. 580 mal Freeze. Zwischen 13:00 und 14:30 auf Verbose 5 genau 4 mal Freeze. Nach dem Rücksetzten auf Verbose 2 gleich wieder 6 Freeze in 3 Minuten.
Noch eine andere Besonderheit ist mir aufgefallen: von den ca. 600 mal Freeze im Log beträgt der Abstand zwischen zwei aufeinanderfolgenden Freezes ca. 490 mal genau 00:01:03 (1 Minute und 3 Sekunden). Da wird scheinbar etwas alle 1 Minute 3 Sekunden ausgeführt, was zu einem Freeze führt? Der Freeze beträgt meistens ca. 3 Sekunden - vielleicht wird da auch etwas minütlich ausgeführt? Wie bekomme ich heraus, worum es sich dabei handelt, wenn ein Verbose 5 zu keinem Freeze mehr führt?

Vielen Dank
Ronny

Exakt dieses Muster (alle 63 Sekunden 3 Sekunden Freeze) hatte ich einmal als beim In-Rente-Schicken eines alten Rechners vergessen hatte, dass mein FHEM immer noch versuchte, einen dort angeschlossenen HM-USB über hmland anzusprechen. Das HMLAN Modul hat dann mit 3 Sek. timeout alle 60 Sek versucht, die Verbindung aufzubauen. Wenn Du nicht den gleichen Fehler machst, schau trotzdem mal, ob Du im lokalen Netz einen Dienst nutzt, die zugehörige IP-Adresse aber nicht erreichbar ist.

Ist alles ein wenig wie Fischen im Trüben, aber vielleicht hilft das ja weiter...

Grüße,
Andy.

Das scheint ein Anhaltspunkt zu sein: ich nutze den hmland, allerdings läuft der auf der gleichen Rechner und wird vom HMLAN Modul mit 127.0.0.1 angesprochen :-|

Hast du mit apptime versucht?

Ich habe den Übeltäter gefunden: beim STV-Modul das Attribut fork auf enable gesetzt und schon sind die Freezes verschwunden :-)

...ist es Möglich die Zeitschwelle bis der Monitor "anspringt" zu vergrössern und damit nur bei sehr groben Hängern einen Log zu erzeugen?

Nach dem reinkopieren ins Module-Verzeichnis und restart von FHEM kommt folgendes im Log :

2016.02.23 18:08:00 1: PERL WARNING: Subroutine HandleTimeout redefined at ./FHEM/98_apptime.pm line 24.
2016.02.23 18:08:00 1: PERL WARNING: Subroutine CallFn redefined at ./FHEM/98_apptime.pm line 58.

Gruss
Joe

Das hat aber nichts mit perfmon zu tun.

OK stimmt, die Funktionen kommen da drin gar nicht vor.
Habe es halt erst bekommen seit ich Perfmon reinkopiert habe.
Allerdings habe ich auch apptime zum ersten mal verwendet.

Hallo
kann mir bitte jemand bei diesen Meldungen weiterhelfen?
2016.04.05 09:32:24 4: WEB_192.168.0.1_55757 GET /fhem/pgm2/fhemweb_readingsGroup.js; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55757 => 304 Not Modified
2016.04.05 09:32:24 4: WEB_192.168.0.1_55760 GET /fhem/pgm2/fhemweb_fbcalllist.js; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55760 => 304 Not Modified
2016.04.05 09:32:24 4: WEB_192.168.0.1_55758 GET /fhem/pgm2/fhemweb_weekprofile.js; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55758 => 304 Not Modified
2016.04.05 09:32:24 4: Connection accepted from WEB_192.168.0.1_55761
2016.04.05 09:32:24 4: WEB_192.168.0.1_55761 GET /fhem/pgm2/darkCommon.css; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55761 => 304 Not Modified
2016.04.05 09:32:24 4: Connection accepted from WEB_192.168.0.1_55762
2016.04.05 09:32:24 4: WEB_192.168.0.1_55759 GET /fhem/pgm2/fhemweb_readingsHistory.js; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55759 => 304 Not Modified
2016.04.05 09:32:24 4: WEB_192.168.0.1_55762 GET /fhem/pgm2/svg.js; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55762 => 304 Not Modified
2016.04.05 09:32:24 4: Connection accepted from WEB_192.168.0.1_55763
2016.04.05 09:32:24 4: Connection accepted from WEB_192.168.0.1_55764
2016.04.05 09:32:24 4: Connection accepted from WEB_192.168.0.1_55765
2016.04.05 09:32:24 4: Connection accepted from WEB_192.168.0.1_55766
2016.04.05 09:32:24 4: WEB_192.168.0.1_55764 GET /fhem/pgm2/fhemweb_knob.js; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55764 => 304 Not Modified
2016.04.05 09:32:24 4: Connection accepted from WEB_192.168.0.1_55767
2016.04.05 09:32:24 4: WEB_192.168.0.1_55765 GET /fhem/pgm2/dashboard.js; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55765 => 304 Not Modified
2016.04.05 09:32:24 4: WEB_192.168.0.1_55766 GET /fhem/pgm2/dashboard_darkstyle.css; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55766 => 304 Not Modified
2016.04.05 09:32:24 4: WEB_192.168.0.1_55767 GET /fhem/pgm2/fhemweb_sortable.js; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55767 => 304 Not Modified
2016.04.05 09:32:24 4: Connection accepted from WEB_192.168.0.1_55768
2016.04.05 09:32:24 4: WEB_192.168.0.1_55763 GET /fhem/codemirror/fhem_codemirror.js; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55763 => 304 Not Modified
2016.04.05 09:32:24 4: Connection accepted from WEB_192.168.0.1_55769
2016.04.05 09:32:24 4: WEB_192.168.0.1_55769 GET /fhem/pgm2/fhemweb_uzsu.js; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55769 => 304 Not Modified
2016.04.05 09:32:24 4: WEB_192.168.0.1_55768 GET /fhem/images/default/icoEverything.png; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55768 => 304 Not Modified
2016.04.05 09:32:24 4: Connection accepted from WEB_192.168.0.1_55770
2016.04.05 09:32:24 4: WEB_192.168.0.1_55770 GET /fhem/images/default/fhemicon_dark.png; BUFLEN:0
2016.04.05 09:32:24 4: WEB_192.168.0.1_55770 => 304 Not Modified
2016.04.05 09:32:24 4: Connection accepted from WEB_192.168.0.1_55771
2016.04.05 09:32:24 4: WEB_192.168.0.1_55771 GET /fhem/FileLog_logWrapper?XHR=1&inform=type=status;filter=;since=1459841542;fmt=JSON&fw_id=557×tamp=1459841544699; BUFLEN:0
2016.04.05 09:32:28 1: Perfmon: possible freeze starting at 09:32:27, delay is 1.207
2016.04.05 09:33:11 4: Connection closed for WEB_192.168.0.1_55771: EOF
2016.04.05 09:33:41 1: Perfmon: possible freeze starting at 09:33:40, delay is 1.334
2016.04.05 09:36:43 1: Perfmon: possible freeze starting at 09:36:42, delay is 1.017
2016.04.05 09:38:39 1: Perfmon: possible freeze starting at 09:38:38, delay is 1.262
2016.04.05 09:40:45 1: Perfmon: possible freeze starting at 09:40:44, delay is 1.464
2016.04.05 09:41:40 1: Perfmon: possible freeze starting at 09:41:39, delay is 1.271
2016.04.05 09:42:45 1: Perfmon: possible freeze starting at 09:42:44, delay is 1.235
2016.04.05 09:43:46 1: Perfmon: possible freeze starting at 09:43:45, delay is 1.569
2016.04.05 09:44:41 1: Perfmon: possible freeze starting at 09:44:40, delay is 1.3
2016.04.05 09:45:45 1: Perfmon: possible freeze starting at 09:45:44, delay is 1.518
2016.04.05 09:47:42 1: Perfmon: possible freeze starting at 09:47:41, delay is 1.58
2016.04.05 09:47:45 1: Perfmon: possible freeze starting at 09:47:44, delay is 1.336
2016.04.05 09:48:47 1: Perfmon: possible freeze starting at 09:48:46, delay is 1.53
2016.04.05 09:49:43 1: Perfmon: possible freeze starting at 09:49:42, delay is 1.101
2016.04.05 09:50:46 1: Perfmon: possible freeze starting at 09:50:45, delay is 1.524
2016.04.05 09:52:44 1: Perfmon: possible freeze starting at 09:52:43, delay is 1.26
2016.04.05 09:55:36 1: Perfmon: possible freeze starting at 09:55:35, delay is 1.305
2016.04.05 09:55:48 1: Perfmon: possible freeze starting at 09:55:47, delay is 1.019
2016.04.05 09:56:50 1: Perfmon: possible freeze starting at 09:56:49, delay is 1.242
2016.04.05 09:58:46 1: Perfmon: possible freeze starting at 09:58:45, delay is 1.258
2016.04.05 09:59:50 1: Perfmon: possible freeze starting at 09:59:49, delay is 1.298
2016.04.05 10:02:51 1: Perfmon: possible freeze starting at 10:02:50, delay is 1.487
2016.04.05 10:02:53 1: Perfmon: possible freeze starting at 10:02:52, delay is 1.043
2016.04.05 10:04:48 1: Perfmon: possible freeze starting at 10:04:47, delay is 1.515
2016.04.05 10:04:52 1: Perfmon: possible freeze starting at 10:04:51, delay is 1.009
2016.04.05 10:05:54 1: Perfmon: possible freeze starting at 10:05:53, delay is 1.252
2016.04.05 10:06:40 1: Perfmon: possible freeze starting at 10:06:39, delay is 1.096
2016.04.05 10:07:52 1: Perfmon: possible freeze starting at 10:07:51, delay is 1.569
2016.04.05 10:07:54 1: Perfmon: possible freeze starting at 10:07:53, delay is 1.099
2016.04.05 10:09:41 1: Perfmon: possible freeze starting at 10:09:40, delay is 1.313
2016.04.05 10:09:53 1: Perfmon: possible freeze starting at 10:09:52, delay is 1.021
2016.04.05 10:10:55 1: Perfmon: possible freeze starting at 10:10:54, delay is 1.238
2016.04.05 10:11:56 1: Perfmon: possible freeze starting at 10:11:55, delay is 1.51
2016.04.05 10:12:51 1: Perfmon: possible freeze starting at 10:12:50, delay is 1.267
2016.04.05 10:12:54 1: Perfmon: possible freeze starting at 10:12:53, delay is 1.007
2016.04.05 10:13:57 1: Perfmon: possible freeze starting at 10:13:56, delay is 1.069
2016.04.05 10:15:56 1: Perfmon: possible freeze starting at 10:15:55, delay is 1.023
2016.04.05 10:16:58 1: Perfmon: possible freeze starting at 10:16:57, delay is 1.254
2016.04.05 10:18:56 1: Perfmon: possible freeze starting at 10:18:55, delay is 1.537
2016.04.05 10:18:58 1: Perfmon: possible freeze starting at 10:18:57, delay is 1.073
2016.04.05 10:20:54 1: Perfmon: possible freeze starting at 10:20:53, delay is 1.258
2016.04.05 10:20:57 1: Perfmon: possible freeze starting at 10:20:56, delay is 1.022
2016.04.05 10:21:58 1: Perfmon: possible freeze starting at 10:21:57, delay is 1.529
2016.04.05 10:23:58 1: Perfmon: possible freeze starting at 10:23:57, delay is 1.291
2016.04.05 10:25:47 1: Perfmon: possible freeze starting at 10:25:46, delay is 1.043
2016.04.05 10:26:56 1: Perfmon: possible freeze starting at 10:26:55, delay is 1.733
2016.04.05 10:27:00 1: Perfmon: possible freeze starting at 10:26:59, delay is 1.206
2016.04.05 10:28:48 1: Perfmon: possible freeze starting at 10:28:47, delay is 1.16
2016.04.05 10:28:57 1: Perfmon: possible freeze starting at 10:28:56, delay is 1.082
2016.04.05 10:31:03 1: Perfmon: possible freeze starting at 10:31:02, delay is 1.516
2016.04.05 10:31:49 1: Perfmon: possible freeze starting at 10:31:48, delay is 1.379
2016.04.05 10:31:58 1: Perfmon: possible freeze starting at 10:31:57, delay is 1.324
2016.04.05 10:32:01 1: Perfmon: possible freeze starting at 10:32:00, delay is 1.086
2016.04.05 10:34:59 1: Perfmon: possible freeze starting at 10:34:58, delay is 1.268
2016.04.05 10:36:04 1: Perfmon: possible freeze starting at 10:36:03, delay is 1.293
2016.04.05 10:38:00 1: Perfmon: possible freeze starting at 10:37:59, delay is 1.547
2016.04.05 10:38:03 1: Perfmon: possible freeze starting at 10:38:02, delay is 1.303
2016.04.05 10:39:06 1: Perfmon: possible freeze starting at 10:39:05, delay is 1.218
2016.04.05 10:41:01 1: Perfmon: possible freeze starting at 10:41:00, delay is 1.719
2016.04.05 10:44:05 1: Perfmon: possible freeze starting at 10:44:04, delay is 1.549
2016.04.05 10:46:03 1: Perfmon: possible freeze starting at 10:46:02, delay is 1.302
2016.04.05 10:46:06 1: Perfmon: possible freeze starting at 10:46:05, delay is 1.063
2016.04.05 10:47:08 1: Perfmon: possible freeze starting at 10:47:07, delay is 1.23
2016.04.05 10:48:09 1: Perfmon: possible freeze starting at 10:48:08, delay is 1.494
2016.04.05 10:48:55 1: Perfmon: possible freeze starting at 10:48:54, delay is 1.322
2016.04.05 10:50:08 1: Perfmon: possible freeze starting at 10:50:07, delay is 1.529
2016.04.05 10:52:05 1: Perfmon: possible freeze starting at 10:52:04, delay is 1.537
2016.04.05 10:52:08 1: Perfmon: possible freeze starting at 10:52:07, delay is 1.295
2016.04.05 10:53:57 1: Perfmon: possible freeze starting at 10:53:56, delay is 1.057
2016.04.05 10:55:06 1: Perfmon: possible freeze starting at 10:55:05, delay is 1.711
2016.04.05 10:55:10 1: Perfmon: possible freeze starting at 10:55:09, delay is 1.198
2016.04.05 10:55:18 1: Perfmon: possible freeze starting at 10:55:15, delay is 3.206
2016.04.05 10:57:11 1: Perfmon: possible freeze starting at 10:57:10, delay is 1.265
2016.04.05 10:58:59 1: Perfmon: possible freeze starting at 10:58:58, delay is 1.335
2016.04.05 10:59:11 1: Perfmon: possible freeze starting at 10:59:10, delay is 1.011
2016.04.05 11:00:12 1: Perfmon: possible freeze starting at 11:00:11, delay is 1.529
2016.04.05 11:02:00 1: Perfmon: possible freeze starting at 11:01:59, delay is 1.59
2016.04.05 11:02:09 1: Perfmon: possible freeze starting at 11:02:08, delay is 1.537
2016.04.05 11:02:12 1: Perfmon: possible freeze starting at 11:02:11, delay is 1.291
2016.04.05 11:04:01 1: Perfmon: possible freeze starting at 11:04:00, delay is 1.052
2016.04.05 11:05:10 1: Perfmon: possible freeze starting at 11:05:09, delay is 1.711
2016.04.05 11:05:14 1: Perfmon: possible freeze starting at 11:05:13, delay is 1.204
2016.04.05 11:06:16 1: Perfmon: possible freeze starting at 11:06:15, delay is 1.263
2016.04.05 11:07:02 1: Perfmon: possible freeze starting at 11:07:01, delay is 1.098
2016.04.05 11:08:15 1: Perfmon: possible freeze starting at 11:08:14, delay is 1.324
2016.04.05 11:09:17 1: Perfmon: possible freeze starting at 11:09:16, delay is 1.522
2016.04.05 11:09:44 4: Connection accepted from WEB_192.168.0.1_53981
2016.04.05 11:09:44 4: WEB_192.168.0.1_53981 GET /fhem; BUFLEN:0
2016.04.05 11:09:45 4: name: /fhem / RL:2479 / text/html; charset=UTF-8 / Content-Encoding: gzip
/
2016.04.05 11:09:45 4: WEB_192.168.0.1_53981 GET /fhem/pgm2/jquery-ui.min.css; BUFLEN:0
2016.04.05 11:09:45 4: WEB_192.168.0.1_53981 => 304 Not Modified
2016.04.05 11:09:45 4: Connection accepted from WEB_192.168.0.1_53982
2016.04.05 11:09:45 4: Connection accepted from WEB_192.168.0.1_53983
2016.04.05 11:09:45 4: WEB_192.168.0.1_53981 GET /fhem/pgm2/fhemweb_knob.js; BUFLEN:0
2016.04.05 11:09:45 4: WEB_192.168.0.1_53981 => 304 Not Modified
2016.04.05 11:09:45 4: Connection accepted from WEB_192.168.0.1_53984
2016.04.05 11:09:45 4: WEB_192.168.0.1_53982 GET /fhem/pgm2/jquery.min.js; BUFLEN:0
2016.04.05 11:09:45 4: WEB_192.168.0.1_53982 => 304 Not Modified
2016.04.05 11:09:45 4: WEB_192.168.0.1_53984 GET /fhem/pgm2/fhemweb.js; BUFLEN:0
2016.04.05 11:09:45 4: WEB_192.168.0.1_53984 => 304 Not Modified
2016.04.05 11:09:45 4: Connection accepted from WEB_192.168.0.1_53985
2016.04.05 11:09:45 4: WEB_192.168.0.1_53983 GET /fhem/pgm2/style.css?v=1459837367; BUFLEN:0
2016.04.05 11:09:45 4: WEB_192.168.0.1_53983 => 304 Not Modified
2016.04.05 11:09:45 4: WEB_192.168.0.1_53981 GET /fhem/pgm2/fhemweb_fbcalllist.js; BUFLEN:0
2016.04.05 11:09:45 4: WEB_192.168.0.1_53981 => 304 Not Modified
2016.04.05 11:09:45 4: WEB_192.168.0.1_53982 GET /fhem/pgm2/fhemweb_uzsu.js; BUFLEN:0
2016.04.05 11:09:45 4: WEB_192.168.0.1_53982 => 304 Not Modified
2016.04.05 11:09:45 4: WEB_192.168.0.1_53984 GET /fhem/pgm2/fhemweb_weekprofile.js; BUFLEN:0
2016.04.05 11:09:45 4: WEB_192.168.0.1_53984 => 304 Not Modified
2016.04.05 11:09:45 4: Connection accepted from WEB_192.168.0.1_53986
2016.04.05 11:09:45 4: WEB_192.168.0.1_53985 GET /fhem/pgm2/jquery-ui.min.js; BUFLEN:0
2016.04.05 11:09:45 4: WEB_192.168.0.1_53985 => 304 Not Modified
2016.04.05 11:09:45 4: WEB_192.168.0.1_53981 GET /fhem/pgm2/fhemweb_readingsHistory.js; BUFLEN:0
2016.04.05 11:09:45 4: WEB_192.168.0.1_53981 => 304 Not Modified[/code

Ich werde leider nicht schlau daraus

mein Sysmonitor zeigt folgendes an

Ich dachte zu erst die hohe Frequenz stammt vom EMONITOR hab den in der Früh deaktiviert aber jetzt sind plötzlich wieder diese Ausschläge da????

Gruß
Helmut


Hallo herrmannj,

ich hoffe ich in diesem Thread richtig und Du kannst mir zumindest einen kleinen Hinweis geben.

Also, ich habe einen CUBIETRUCK und immer mal wieder Probleme das fhem offensichtig in ein Freezing geht. Also habe ich
gesucht und bin auf deinen Performance Monitor gestossen ==> und aktiviert. Ich log sehen jetzt folgendes...... (s.u.).
Ich deute das so, dass immer die Module VOR dem "Perfmon: possible freeze starting at......." die Verursacher sind , ODER ?

2016.07.02 12:15:00 3: get Abfall summary 20160225T120128CET7484IScrcbwwwbsrde : Abholung Hausmüll
2016.07.02 12:15:00 3: get Abfall start 20160225T120128CET7484IScrcbwwwbsrde : 26.10.2016 00:00:00
2016.07.02 12:15:02 3: ABFALL myABFALL - CALENDAR:muellkalender triggered, updating ABFALL myABFALL ...
2016.07.02 12:15:02 3: ABFALL_UPDATE
2016.07.02 12:15:14 3: CALVIEW vocalview2 - CALENDAR:K1 triggered, updating CALVIEW vocalview2 ...
2016.07.02 12:15:15 1: Perfmon: possible freeze starting at 12:15:07, delay is 8.786
2016.07.02 12:15:18 1: Perfmon: possible freeze starting at 12:15:16, delay is 2.41
2016.07.02 12:15:21 1: Perfmon: possible freeze starting at 12:15:19, delay is 2.048
2016.07.02 12:15:30 3: CALVIEW vocalview2 - CALENDAR:K2 triggered, updating CALVIEW vocalview2 ...
2016.07.02 12:15:31 1: Perfmon: possible freeze starting at 12:15:22, delay is 9.722
2016.07.02 12:15:34 1: Calendar Familie: retrieval failed with error message read from http://xxx.xxx.xxx.xxx:80 timed out
2016.07.02 12:15:34 1: Calendar Familie: retrieved no or empty data
2016.07.02 12:15:34 3: CALVIEW vocalview2 - CALENDAR:Fam triggered, updating CALVIEW vocalview2 ...
2016.07.02 12:15:37 1: Perfmon: possible freeze starting at 12:15:32, delay is 5.045
2016.07.02 12:15:45 1: Perfmon: possible freeze starting at 12:15:44, delay is 1.254
2016.07.02 12:15:49 1: Perfmon: possible freeze starting at 12:15:48, delay is 1.319
2016.07.02 12:15:51 1: Perfmon: possible freeze starting at 12:15:50, delay is 1.932
2016.07.02 12:15:53 1: Perfmon: possible freeze starting at 12:15:52, delay is 1.31
2016.07.02 12:15:55 1: Perfmon: possible freeze starting at 12:15:54, delay is 1.933
2016.07.02 12:15:57 1: Perfmon: possible freeze starting at 12:15:56, delay is 1.266
2016.07.02 12:15:59 1: Perfmon: possible freeze starting at 12:15:58, delay is 1.894
2016.07.02 12:16:01 1: Perfmon: possible freeze starting at 12:16:00, delay is 1.338
2016.07.02 12:16:03 1: Perfmon: possible freeze starting at 12:16:02, delay is 1.973
2016.07.02 12:16:05 1: Perfmon: possible freeze starting at 12:16:04, delay is 1.341
2016.07.02 12:16:08 1: Perfmon: possible freeze starting at 12:16:06, delay is 2.002
2016.07.02 12:16:10 1: Perfmon: possible freeze starting at 12:16:09, delay is 1.624
2016.07.02 12:16:13 1: Perfmon: possible freeze starting at 12:16:11, delay is 2.244
2016.07.02 12:16:15 1: Perfmon: possible freeze starting at 12:16:14, delay is 1.88
2016.07.02 12:16:18 1: Perfmon: possible freeze starting at 12:16:16, delay is 2.499
2016.07.02 12:16:21 1: Perfmon: possible freeze starting at 12:16:19, delay is 2.251
2016.07.02 12:16:23 1: Perfmon: possible freeze starting at 12:16:22, delay is 1.983
2016.07.02 12:16:26 1: Perfmon: possible freeze starting at 12:16:24, delay is 2.865
2016.07.02 12:16:29 1: Perfmon: possible freeze starting at 12:16:27, delay is 2.436
2016.07.02 12:16:33 1: Perfmon: possible freeze starting at 12:16:30, delay is 3.287
2016.07.02 12:16:37 1: Perfmon: possible freeze starting at 12:16:34, delay is 3.139
2016.07.02 12:16:41 1: Perfmon: possible freeze starting at 12:16:38, delay is 3.007
2016.07.02 12:16:45 1: Perfmon: possible freeze starting at 12:16:42, delay is 3.14
2016.07.02 12:16:49 1: Perfmon: possible freeze starting at 12:16:46, delay is 3.072
2016.07.02 12:16:52 1: Perfmon: possible freeze starting at 12:16:50, delay is 2.969
2016.07.02 12:16:55 1: Perfmon: possible freeze starting at 12:16:53, delay is 2.621
2016.07.02 12:16:58 1: Perfmon: possible freeze starting at 12:16:56, delay is 2.277
2016.07.02 12:17:02 1: Perfmon: possible freeze starting at 12:16:59, delay is 3.197
2016.07.02 12:17:06 1: Perfmon: possible freeze starting at 12:17:03, delay is 3.099
2016.07.02 12:17:10 1: Perfmon: possible freeze starting at 12:17:07, delay is 3.057
2016.07.02 12:17:13 1: Perfmon: possible freeze starting at 12:17:11, delay is 2.97
2016.07.02 12:17:16 1: Perfmon: possible freeze starting at 12:17:14, delay is 2.603
2016.07.02 12:17:19 1: Perfmon: possible freeze starting at 12:17:17, delay is 2.22
2016.07.02 12:17:23 1: Perfmon: possible freeze starting at 12:17:20, delay is 3.155
2016.07.02 12:17:27 1: Perfmon: possible freeze starting at 12:17:24, delay is 3.098
2016.07.02 12:17:31 1: Perfmon: possible freeze starting at 12:17:28, delay is 3.049
2016.07.02 12:17:34 1: Perfmon: possible freeze starting at 12:17:32, delay is 2.93
2016.07.02 12:17:37 1: Perfmon: possible freeze starting at 12:17:35, delay is 2.525
2016.07.02 12:17:39 3: UWZ Unwetterzentrale2: Run.684 Done fetching data
2016.07.02 12:17:39 3: UWZ Unwetterzentrale3: Run.684 Done fetching data
2016.07.02 12:17:40 1: Perfmon: possible freeze starting at 12:17:38, delay is 2.475
2016.07.02 12:17:43 1: Perfmon: possible freeze starting at 12:17:41, delay is 2.335
2016.07.02 12:17:47 1: Perfmon: possible freeze starting at 12:17:44, delay is 3.445

Demnach wäre der CALVIEW vocalview2 bzw. der Zugriff auf die Kalender (K1 / K2 / Fam) das Problem.

Wie würde man hier weiter vorgehen um die wirklich Ursache noch weiter einzugrenzen ???

Danke für die Hilfe
Klaus

2016.07.02 12:16:01 1: Perfmon: possible freeze starting at 12:16:00, delay is 1.338
2016.07.02 12:16:03 1: Perfmon: possible freeze starting at 12:16:02, delay is 1.973
2016.07.02 12:16:05 1: Perfmon: possible freeze starting at 12:16:04, delay is 1.341
2016.07.02 12:16:08 1: Perfmon: possible freeze starting at 12:16:06, delay is 2.002
2016.07.02 12:16:10 1: Perfmon: possible freeze starting at 12:16:09, delay is 1.624
2016.07.02 12:16:13 1: Perfmon: possible freeze starting at 12:16:11, delay is 2.244
2016.07.02 12:16:15 1: Perfmon: possible freeze starting at 12:16:14, delay is 1.88
2016.07.02 12:16:18 1: Perfmon: possible freeze starting at 12:16:16, delay is 2.499
2016.07.02 12:16:21 1: Perfmon: possible freeze starting at 12:16:19, delay is 2.251
2016.07.02 12:16:23 1: Perfmon: possible freeze starting at 12:16:22, delay is 1.983
2016.07.02 12:16:26 1: Perfmon: possible freeze starting at 12:16:24, delay is 2.865
2016.07.02 12:16:29 1: Perfmon: possible freeze starting at 12:16:27, delay is 2.436
2016.07.02 12:16:33 1: Perfmon: possible freeze starting at 12:16:30, delay is 3.287
2016.07.02 12:16:37 1: Perfmon: possible freeze starting at 12:16:34, delay is 3.139
2016.07.02 12:16:41 1: Perfmon: possible freeze starting at 12:16:38, delay is 3.007
2016.07.02 12:16:45 1: Perfmon: possible freeze starting at 12:16:42, delay is 3.14
2016.07.02 12:16:49 1: Perfmon: possible freeze starting at 12:16:46, delay is 3.072
2016.07.02 12:16:52 1: Perfmon: possible freeze starting at 12:16:50, delay is 2.969
2016.07.02 12:16:55 1: Perfmon: possible freeze starting at 12:16:53, delay is 2.621
2016.07.02 12:16:58 1: Perfmon: possible freeze starting at 12:16:56, delay is 2.277
2016.07.02 12:17:02 1: Perfmon: possible freeze starting at 12:16:59, delay is 3.197

wenn man sich die Logeinträge nur von der Uhrzeit 12:16 ansieht, und die Delay zeiten addiert,
ist dein fhem Hauptprozess von 60 Sekunden geschätzt 21x2 sekunden = 42 Sekunden blockiert!

Deine Fhem läuft bestimmt nicht flüssig, du hast ein weit großeres Problem als den Kalender

Edit:
die Verursacher siehst du erst mit verbose 5 , dein Log wird dann rapide anwachsen , das wird dann kein Spass

Hallo Hary,

danke Dir für die schnelle Antwort!

ZitatDeine Fhem läuft bestimmt nicht flüssig, du hast ein weit großeres Problem als den Kalender

Doch, das fhem läuft ziemlich flüssig ...(vielleicht dank Cubietruck) !

gut dann werd ich mal verbose auf 5 stellen !

Hallo Klaus,

Noch ein Tipp, der bei mir ganz gut hilft.
Nach einem Freeze schaue ich mit 'apptime' nach, ob man da einen passenden Eintrag findet.
In der Spalte max sollte dann ein passender Wert zum Freeze zu finden sein. Das funktioniert natürlich bei einzelnen längeren Freezes besser.
Danach 'apptime clear' und wieder abwarten.

Gruß Ulf

Zitat von: vuffiraa am 03 Juli 2016, 20:25:55
Hallo Klaus,

Noch ein Tipp, der bei mir ganz gut hilft.
Nach einem Freeze schaue ich mit 'apptime' nach, ob man da einen passenden Eintrag findet.
In der Spalte max sollte dann ein passender Wert zum Freeze zu finden sein. Das funktioniert natürlich bei einzelnen längeren Freezes besser.
Danach 'apptime clear' und wieder abwarten.

Gruß Ulf

Hallo Ulf,

danke für den Tipp mit dem 'apptime' , grade mal aktiviert  ;)

Mal schauen wer der Übeltäter ist .... vermute aber schon Calendar ... bzw. die Owncloud !

gruß Klaus

Hallo,
wenn ich die Ausgaben von apptime richtig deute, liegen die Probleme bei
Calendar
CALVIEW
HttpUtils

....oder ?

Wie kann ich mit einem notify auf einen freeze reagieren?
Ich möchte die freezes zählen und ggf.  nach einem freeze eine Nachricht verschicken.

Grüße Marcel

Entweder mit einem notify + attr readLog oder du baust in das Modul einen trigger ein.
Ich würde mir das aber sparen und das Einfrieren abstellen ;)

Ich habe nur 1 oder 2 mal die Woche einen freeze von knapp 1,2 Sekunden, da ich aber nicht jeden Tag ins log schaue bzw. am Rechner bin, möchte ich informiert werden wenn ein freeze kommt um dann ggfs. ins log zu schauen.
Bis jetzt konnte ich leider noch nicht feststellen woran es liegt.

Grüße Marcel


Gesendet von iPhone mit Tapatalk

Zitat von: Ma_Bo am 01 September 2016, 21:37:59
Ich habe nur 1 oder 2 mal die Woche einen freeze von knapp 1,2 Sekunden, da ich aber nicht jeden Tag ins log schaue bzw. am Rechner bin, möchte ich informiert werden wenn ein freeze kommt um dann ggfs. ins log zu schauen.
Bis jetzt konnte ich leider noch nicht feststellen woran es liegt.

Grüße Marcel


Gesendet von iPhone mit Tapatalk

Apptime sollte Dich da weiter bringen.

1 oder 2 freeze von 1,2Sekunden scheint mir jedoch kein Grund zur Sorge. Es muss sich ja nicht zwingend um eine einzelne Ursache mit 1200msec Dauer handeln. Wenn Beispielsweise ein einzelnes Ereignis 200ms "erzeugt", und dann zufällig 1 oder 2 mal pro Woche zufällig 6 Stück gleichzeitig auftreten bekommst Du diese Meldung genauso.

vg
joerg

Ok, wusste nicht das sich einzelne Ereignisse auch addieren, dachte immer, dass es sich dann immer um ein Event handelt.

Kann mir jemand ein Beispiel notify nennen wie ich auf den perfmon reagiere, so evtl: define test_notify perfmon:.* set TelegramBot message Perfmon hat zugeschlagen ?

Gruß Marcel

Siehe commandref:

ZitatreadLog
Execute the notify for messages appearing in the FHEM Log. The device in this case is set to the notify itself, e.g. checking for the startup message looks like:

Code Auswählen Erweitern

define n notify n:.*Server.started.* { Log 1, "Really" }
attr n readLog

Hallo zusammen,

ich bin auch gerade dabei, mit Hilfe des Perfmon und apptime zu analysieren, wo meine freezes herkommen. Ich habe pro Tag ca. 100 Freezes von 1 bis ca. 3 Sekunden. Außerdem hatte ich bis vor 2 Tagen auch jeden Tag 2, 3 Freezes von 30 Sekunden und länger, da kam es dann schon ab und an vor, dass just während eines Freezes Fhem etwas machen sollte, was dann natürlich klemmte ("Schatz, das Sch**ß-Licht geht schon wieder nicht an!" ;-) . Es scheint, als wären dafür vor allem Aufrufe aus dem Web verantwortlich, z. B. das Holen der Wetterdaten von Yahoo oder die Abfrage von Wetterstationen über wunderground.com. Habe ich jetzt erstmal rausgenommen.

Nun scheint es so, als ob die etwas längeren Freezes von 3 bis 5, manchmal auch 7 Sekunden vor allem bei Abfragen der Fritzbox (FBAHA/FBDECT) und der HueBridge auftreten, wobei ich hier eigentlich eine saubere Einbindung habe. Ich muss vielleicht dazusagen, dass bei mir ein Großteil der Technik im Wohnzimmer in einem Schrank verbaut ist, der Fhem-Raspi jedoch räumlich in der Wohnungsmitte in einem Abstellraum installiert ist und seinen Connect zum Rest der Hardware über ein Fritz PowerLine 1000E erhält. Im Wohnzimmer gibt es neben dem ganzen Router- Bridge- und und und Geraffel noch einen zweiten Fhem-Raspi, der aber einzig und allein für eine Sprachausgabe und Wandtaster-Quittungston für im Wohnzimmer laufende Aktionen zuständig ist. Dieser Raspi hat eine "echte" Kabelverbindung zum Netzwerk, also auch zur HueBridge etc.

Nun zwei Fragen:

1) Sind 100 kurze Freezes am Tag noch normal oder muss ich das als katastrophal einstufen?

2) Haltet Ihr es in meiner Konstellation für sinnvoll, die scheinbar Freeze-kritischen Fritzbox und HueBridge nicht mit dem Haupt-Fhem im Abstellraum, sondern mit dem kabelverbundenen Fhem-"Client" im Wohnzimmer anzusprechen? A) ist es eben Kabel statt PowerLan, und B) würden eventuelle Freezes ja dann nur auf dem Fhem-Client auftreten und nicht das Haupt-Fhem einbremsen, oder?

Danke vorab für Eure Meinungen!

Sieht man irgendwo, ob Perfmon läuft? Ich hab Hänger, finde aber keine Einträge von Perfmon

Zitat von: Merlin123 am 12 März 2017, 20:00:10
Sieht man irgendwo, ob Perfmon läuft? Ich hab Hänger, finde aber keine Einträge von Perfmon

Ja, perfmon schreibt beim Start von fhem eine Meldung ins log das es ready ist.

btw, perfmon protkolliert *das* etwas hängt. Apptime kann helfen den Verursacher zu finden.

vg
joerg

Danke erstmal. Da steht nix drin.
Muss nochmal schauen, ob das im richtigen Verzeichnis ist...

Merke: Man sollte das Modul an die richtige Stelle kopieren.
Vielleicht könnte man das "in das Modulverzeichnis" etwas näher erklären für Einsteiger wie mich ;)

OK... Läuft und ich komme nicht weiter. Hab die Ausgabe unten, apptime liefert eine leere Tabelle.
Sehe ich das richtig, dass der Kalender ein Hauptproblem ist?
Das war jetzt direkt nach dem Start. Muss mal im Betrieb schauen, da habe ich regelmäßig Hänger :(

Zitat
2017.03.13 11:13:48 2: Perfmon: ready to watch out for delays greater than one second
2017.03.13 11:13:48 1: Including fhem.cfg
2017.03.13 11:13:50 3: WEB: port 8083 opened
2017.03.13 11:13:50 3: WEBphone: port 8084 opened
2017.03.13 11:13:50 3: WEBtablet: port 8085 opened
2017.03.13 11:13:51 2: eventTypes: loaded 715 events from ./log/eventTypes.txt
2017.03.13 11:13:51 3: telnetPort: port 7072 opened
2017.03.13 11:13:51 0: Using EIB is deprecated. Please migrate to KNX soon. Module 10_EIB is not maintained any longer. If you still want to use the module EIB,
   please set the attribute useEIB to 1 within the tul-device. Please keep in mind, that 10_KNX has a changed syntax regarding the definition, arguments and readings. Please refer to the commandref.
   As well 10_EIB and 10_KNX are compatible to daemon eibd and knxd.
2017.03.13 11:13:51 3: TUL opening KNX device eibd:192.168.0.127
2017.03.13 11:13:51 3: TUL device opened
2017.03.13 11:13:51 3: TABLETUI: new ext defined infix:ftui/: dir:./www/tablet/:
2017.03.13 11:13:51 3: Registering HTTPSRV TABLETUI for URL /ftui   and assigned link ftui/ ...
2017.03.13 11:13:52 3: Opening CallMonitor device 192.168.0.1:1012
2017.03.13 11:13:58 3: TelegramBot_Define teleBot: called
2017.03.13 11:13:59 1: Including ./log/fhem.save
2017.03.13 11:14:01 3: FB_CALLMONITOR (CallMonitor) - found 2 phonebooks
2017.03.13 11:14:05 2: FB_CALLMONITOR (CallMonitor) - read 223 contacts from remote phonebook "Gmail"
2017.03.13 11:14:05 1: PERL WARNING: Use of uninitialized value $VALUE in string eq at (eval 50) line 1.
2017.03.13 11:14:05 3: SZ.Harmony: connected
2017.03.13 11:14:05 2: SecurityCheck:  WEB,WEBphone,WEBtablet has no associated allowed device with basicAuth. telnetPort has no associated allowed device with password/globalpassword.  Restart FHEM for a new check if the problem is fixed, or set the global attribute motd to none to supress this message.
2017.03.13 11:14:05 0: Featurelevel: 5.8
2017.03.13 11:14:05 0: Server started with 57 defined entities (fhem.pl:13447/2017-02-19 perl:5.020002 os:linux user:fhem pid:4651)
2017.03.13 11:14:05 1: Perfmon: possible freeze starting at 11:13:49, delay is 16.662
2017.03.13 11:14:05 3: CallMonitor device opened
2017.03.13 11:14:09 1: Perfmon: possible freeze starting at 11:14:08, delay is 1.461
2017.03.13 11:14:09 3: SZ.Harmony: new config
2017.03.13 11:21:38 2: Calendar: keyword BYSETPOS in RRULE FREQ=MONTHLY;COUNT=12;BYDAY=MO,TU,WE,TH,FR;BYSETPOS=-1 is not supported
2017.03.13 11:22:27 3: CALVIEW Oli_Kal - CALENDAR:Kalender_Oliver triggered, updating CALVIEW Oli_Kal ...
2017.03.13 11:23:18 1: Perfmon: possible freeze starting at 11:14:15, delay is 543.338
2017.03.13 11:23:18 2: SZ.Harmony: disconnect
2017.03.13 11:23:18 3: FHEMWEB WEB CSRF error: fhem_71026270709600.6 ne fhem_37175456711916.9. For detals see the csrfToken FHEMWEB attribute
2017.03.13 11:23:18 3: FHEMWEB WEB CSRF error: fhem_71026270709600.6 ne fhem_37175456711916.9. For detals see the csrfToken FHEMWEB attribute
2017.03.13 11:23:18 3: FHEMWEB WEB CSRF error: fhem_71026270709600.6 ne fhem_37175456711916.9. For detals see the csrfToken FHEMWEB attribute
2017.03.13 11:23:18 3: FHEMWEB WEB CSRF error: fhem_71026270709600.6 ne fhem_37175456711916.9. For detals see the csrfToken FHEMWEB attribute
2017.03.13 11:23:20 3: SZ.Harmony: connected
2017.03.13 11:23:21 3: SZ.Harmony: new config
2017.03.13 11:30:07 3: FHEMWEB WEB CSRF error: fhem_71026270709600.6 ne fhem_37175456711916.9. For detals see the csrfToken FHEMWEB attribute
2017.03.13 11:31:25 1: PERL WARNING: Subroutine HandleTimeout redefined at ./FHEM/98_apptime.pm line 24.
2017.03.13 11:31:25 1: PERL WARNING: Subroutine CallFn redefined at ./FHEM/98_apptime.pm line 58.
2017.03.13 11:32:07 3: FHEMWEB WEB CSRF error: fhem_71026270709600.6 ne fhem_37175456711916.9. For detals see the csrfToken FHEMWEB attribute

Zitat von: Merlin123 am 13 März 2017, 12:38:25
Merke: Man sollte das Modul an die richtige Stelle kopieren.
Vielleicht könnte man das "in das Modulverzeichnis" etwas näher erklären für Einsteiger wie mich ;)

Hm, du sagst Du bist Einsteiger, hast aber die Einsteigerdoku noch nicht gelesen (dann weiß man wo Module hingehören) und beschäftigst Dich schon mit der Fhem Performance?! Was bekommen den ggf. Maintainer für Anfragen zu vermeintlichen Freeze, wo doch die Moduldoku oft Hinweise zu Laufzeitverhalten beinhaltet...


Gesendet von iPad mit Tapatalk

Grüße Jörg

Hallo Jörg,

in der Doku werden Module mehrfach erwähnt, aber ich habe jetzt da nicht gesehen, wo die hin müssen. Beim Erstellen eigener Module wird angegeben, wo die bei Sourgeforge eingecheckt werden müssen. Was mir zum Verhängnis wurde: Im Hauptverzeichnis liegt bei mir das Modul configdb.pm, deswegen dachte ich, das sei der richtige Platz. Hab es ja nicht "irgendwohin" kopiert. Hab mir allerdings nicht die komplette Verzeichnisstruktur angeschaut, sonst hätte ich das FHEM Verzeichnis als das richtige erkannt. Man könnte hinter "Modulverzeichnis" einfach ein (meist /opt/app/fhem/FHEM) oder so einfügen. Das war ja auch nur ein Hinweis :(



Bei Calview und Calendar steht im Wiki kein Hinweis bzgl. Laufzeit.

Und auch als Einsteiger kann man sich mit Performance beschäftigen. Mir geht es nicht um das letzte Quentchen Performance, sondern darum, dass FHEM bei mir teilweise sehr lange nicht mehr reagiert.

Mittlerweile gab es auch im laufenden Betrieb Hänger, nun liefert Apptime auch was. Sieht nach Calendar/Calview aus. Jetzt weiß ich zumindest wo ich weitersuchen muss.

Super.

Vielen Dank

Zitat von: herrmannj am 10 November 2013, 12:49:13Installation:
Das Modul braucht nur in das Modul Verzeichnis kopiert zu werden (fhem anschließend neu starten). Weitere Schritte sind nicht erforderlich.

Welche Rechte soll die Datei besitzen?
Derzeit sieht es bei mir so aus:
-rwxr--r--  1 fhem dialout   1422 Mar  5 07:06 99_perfmon.pm

Viele Grüße Gisbert​