Hallo zusammen,
ihc möchte mal vorsichtig iin die Runde fragen ob das unten beschriebene Verhalten von auch von anderen Usern beobachtet wird.
Der Hardwarerahmen, FB7390, HM Lan, Cul868, RFXTRX. Was ich bereits in der Vergangenheit beobachtet habe ist folgendes: in seltenen Fällen hängt bei miir fhem auf der FB, durchaus mal viele Minuten. In den meisten Fällen blieb mir das wohl auch unbemerkt, in den Logs tauchen (bis auf HMLAN disconnect) keine besonderen Hinweise auf und fhem läuft anschließend normal weiter.
Aufgefallen ist mir das durchaus früher schon (irgendeine Aktion, zB Schalter drücken, Licht geht deutlich verzögert an. zB 90 sek später). Wie gesagt, das war nie so richtig festzumachen.
Jetzt habe ich mit den learnings der vergangenen Monate fhem komplett neu aufgesetzt und die Programmierung ist noch überschaubar. In dem Zuge habe ich unter anderem einen Timer eingerichtet der Events für Tageslogs jeweils exakt im 10min Abstand "feuert". Da ich zusätzlich gerade debug Einträge für einen Windsensor (14 Sekunden Events) ins Log schreibe kann man hier recht gut sehen DAS etwas schiefgeht, dummerweise nicht was ....
Der 13:10:00 Eintrag in log stammt aus meinem Timer, im Timer wird der nächste Zeitüunkt (nächste volle 10min dynamisch berechnet).
Von 13:10:12 bis 13:19:26 meldet sich der Windsensor mit aktuell gemessener Windrichtung und dem berechneten gleitendem Durchschnitt.
Danach ist bis 13:32:29 - also mehr als 10 min nichts im Log, der Timer hätte um exakt 13:20 und dazu etwa alle 14 Sekunden eine Windmeldung auftauchen müssen.
Um 13:32:29 "lebt" das System wieder, scheinbar zwischengepufferte Windmeldungen werden am Stück bearbeitet, der HMLAN wird als als vermisst gemeldet. Der überfällige 13:20:00 Timer wird um 13:32:29 abgearbeitet (und schaltet sich selber für 13:40:00 erneut scharf).
Deutlich sichtbar ist das die in der Zwischenzeit aufgelaufenen Windmeldungen jetzt am Stück direkt abgearbeitet werden (normal alle 14 Sekunden, manchmal fehlen natürlich auch welche). Um 13:32:39 ist der Spuk vorbei, das nächste Event ist mit > 10 Sekunden der Windmesser.
Leider habe ich keine zusätzlichen Informationen wo es geklemmt hat im Log, dieses auch früher schon gelegentlich beobachtete Verhalten ist hier nur durch Zufall genau zeitlich dokumentiert.
Irgendwelche Exoten Module (sorry, you know ... ) habe ich nicht im Einsatz, erst recht nicht da ich das System gerade neu aufbaue.
Irgenwelche Gedanken / eigene Beobachtungen anderer User dazu ?
Grüße
Jörg
2013.11.01 13:10:00 2: myUtils 10 min timer called
2013.11.01 13:10:12 1: wind 225 212.378880367041
2013.11.01 13:10:26 1: wind 202 212.448997698335
2013.11.01 13:10:40 1: wind 225 212.390947711122
2013.11.01 13:10:54 1: wind 225 212.460998001616
2013.11.01 13:11:08 1: wind 270 212.530659123829
2013.11.01 13:11:22 1: wind 225 212.849933239808
2013.11.01 13:11:36 1: wind 247 212.917433610698
2013.11.01 13:11:50 1: wind 247 213.10678120175
2013.11.01 13:12:04 1: wind 180 213.29507686174
2013.11.01 13:12:18 1: wind 225 213.110104212508
2013.11.01 13:12:32 1: wind 225 213.176159189105
2013.11.01 13:12:46 1: wind 225 213.24184719361
2013.11.01 13:13:00 1: wind 225 213.307170264757
2013.11.01 13:13:14 1: wind 225 213.372130429953
2013.11.01 13:13:28 1: wind 225 213.436729705342
2013.11.01 13:13:42 1: wind 180 213.500970095868
2013.11.01 13:13:56 1: wind 225 213.314853595335
2013.11.01 13:14:10 1: wind 247 213.379771075361
2013.11.01 13:14:24 1: wind 225 213.566550124942
2013.11.01 13:14:38 1: wind 180 213.630069290915
2013.11.01 13:14:52 1: wind 202 213.443235572632
2013.11.01 13:15:06 1: wind 225 213.379662041673
2013.11.01 13:15:20 1: wind 180 213.444219474775
2013.11.01 13:15:34 1: wind 225 213.25841825547
2013.11.01 13:15:48 1: wind 225 213.323649265162
2013.11.01 13:16:02 1: wind 225 213.388517880356
2013.11.01 13:16:16 1: wind 225 213.453026114354
2013.11.01 13:16:30 1: wind 202 213.517175969274
2013.11.01 13:16:44 1: wind 225 213.453191658334
2013.11.01 13:16:58 1: wind 225 213.517340593565
2013.11.01 13:17:12 1: wind 225 213.581133145823
2013.11.01 13:17:26 1: wind 225 213.644571295013
2013.11.01 13:17:40 1: wind 225 213.707657010041
2013.11.01 13:17:54 1: wind 225 213.770392248874
2013.11.01 13:18:08 1: wind 202 213.832778958602
2013.11.01 13:18:22 1: wind 225 213.767041297721
2013.11.01 13:18:36 1: wind 225 213.829446623845
2013.11.01 13:18:50 1: wind 157 213.891505253713
2013.11.01 13:19:04 1: wind 202 213.575441335636
2013.11.01 13:19:18 1: wind 180 213.511133328216
2013.11.01 13:19:32 1: wind 157 213.324960365282
2013.11.01 13:19:46 1: wind 247 213.012043918808
2013.11.01 13:32:27 1: wind 202 213.200865897037
2013.11.01 13:32:27 1: wind 225 209.840606127926
2013.11.01 13:32:27 1: wind 225 209.92482498277
2013.11.01 13:32:27 1: wind 225 210.008575955088
2013.11.01 13:32:28 1: wind 225 210.091861644227
2013.11.01 13:32:28 1: wind 225 210.174684635092
2013.11.01 13:32:28 1: wind 202 210.257047498231
2013.11.01 13:32:28 1: wind 225 210.211175012129
2013.11.01 13:32:28 1: wind 225 210.293335150951
2013.11.01 13:32:28 1: wind 247 210.375038844557
2013.11.01 13:32:29 1: wind 225 210.578510850976
2013.11.01 13:32:29 1: 192.168.178.20:1000 disconnected, waiting to reappear
2013.11.01 13:32:29 2: HMLAN_Parse: HMLAN1 new condition disconnected
2013.11.01 13:32:29 1: 192.168.178.20:1000 reappeared (HMLAN1)
2013.11.01 13:32:29 2: HMLAN_Parse: HMLAN1 new condition init
2013.11.01 13:32:29 2: myUtils 10 min timer called
2013.11.01 13:32:29 1: wind 225 210.658630235137
2013.11.01 13:32:29 1: wind 157 210.738304511609
2013.11.01 13:32:29 1: wind 202 210.439758375433
2013.11.01 13:32:30 1: wind 225 210.392870828903
2013.11.01 13:32:30 1: wind 225 210.47402154652
2013.11.01 13:32:30 1: wind 247 210.554721426817
2013.11.01 13:32:30 1: wind 202 210.757195196668
2013.11.01 13:32:30 1: wind 225 210.708544112242
2013.11.01 13:32:30 1: wind 225 210.787941089396
2013.11.01 13:32:31 1: wind 202 210.866896972233
2013.11.01 13:32:31 1: wind 247 210.817636433498
2013.11.01 13:32:31 1: wind 247 211.018649564423
2013.11.01 13:32:31 1: wind 225 211.218545955732
2013.11.01 13:32:32 1: wind 225 211.295109589311
2013.11.01 13:32:32 1: wind 202 211.371247869371
2013.11.01 13:32:32 1: wind 202 211.319185381208
2013.11.01 13:32:32 1: wind 225 211.26741212909
2013.11.01 13:32:32 1: wind 225 211.343704283928
2013.11.01 13:32:32 1: wind 202 211.419572593462
2013.11.01 13:32:33 1: wind 180 211.367241634609
2013.11.01 13:32:33 1: wind 225 211.192979181084
2013.11.01 13:32:33 1: wind 225 211.2696848523
2013.11.01 13:32:34 1: wind 225 211.345964380898
2013.11.01 13:32:34 1: wind 225 211.421820134338
2013.11.01 13:32:34 1: wind 225 211.497254466925
2013.11.01 13:32:34 1: wind 225 211.572269719886
2013.11.01 13:32:34 1: wind 225 211.646868221442
2013.11.01 13:32:34 1: wind 202 211.721052286879
2013.11.01 13:32:35 1: wind 157 211.667046440841
2013.11.01 13:32:35 1: wind 202 211.36334062728
2013.11.01 13:32:35 1: wind 225 211.31132206824
2013.11.01 13:32:35 1: wind 225 211.387370278972
2013.11.01 13:32:36 1: wind 225 211.462995999644
2013.11.01 13:32:36 1: wind 225 211.538201577424
2013.11.01 13:32:36 1: wind 202 211.612989346438
2013.11.01 13:32:36 1: wind 202 211.559583850069
2013.11.01 13:32:36 1: wind 225 211.506475050902
2013.11.01 13:32:36 1: wind 225 211.581439078397
2013.11.01 13:32:37 1: wind 225 211.655986639073
2013.11.01 13:32:37 1: wind 247 211.730120046634
2013.11.01 13:32:37 1: wind 180 211.926063824152
2013.11.01 13:32:37 1: wind 225 211.748696802907
2013.11.01 13:32:38 1: wind 225 211.822315154002
2013.11.01 13:32:39 1: wind 225 211.895524514257
2013.11.01 13:32:39 2: HMLAN_Parse: HMLAN1 new condition ok
2013.11.01 13:32:50 1: wind 225 211.968327155845
Hallo,
könnte auch wieder das hier sein: http://forum.fhem.de/index.php/topic,14893.msg102778.html#msg102778
hab's noch nicht lösen können.
Gruß,
-Christian
Guter Hinweis,
hatte zwar die Suche bemüht, den fred aber nicht gefunden.
Ich war zu der Zeit als der Hänger war nicht im Haus, bin etwa 20min vorher gegangen - hatte fhem aber vorher im browser offen.
Wäre also möglich ...
Also longpoll deaktivieren ?
Bei mir tritt das jetzt keinesfalls so häufig auf, ich beobachte das höchstens alle Tage mal. Ich könnte einen zweiten Timer aktivieren der alle 30 Sekunden feuert und selbst seine Aufrufzeit überwacht und dann bei Überschreitung einen Logeintrag generiert. Dann wäre zumindest genauer überprüfbar wie oft das tatsächlich Auftritt. Das ich das so genau sehen konnte war ja eher ein Zufall, in den meisten Fällen dürfte der Hänger unbemerkt bleiben.
Grüße
Jörg
Moin herrmannj,
Du bist nicht allein.
Ich habe (hatte) das Problem auch, allerdings mit OWServer, HM-LAn und MAX.
Ich bin noch dabei, das Problem einzugrenzen, dazu habe ich ein seperates physikalisch getrenntes Subnetz geschaffen, in dem 2 FHEM installationen laufen. Diese laufen jetzt seit 2 Wochen ohne sporadische Ausfälle. Beide FHEM Installationen haben gemeinsam, dass sie auf das Netzwerk zugreifen. Entweder localhost für OWServer oder HMLan und MAX-Cube. Sowie diese beiden FHEM-Instanzen wieder in meinem normalen Netzwerk spielen gibt es wieder Aussetzer. Eine dritte FHEM-Installation läuft ganz normal im Hauptnetzwerk, und ohne Aussetzer, allerdings laufen hier auch nur Module, die nicht auf das Netzwerk zugreifen (RS232).
Bau mal folgende Zeilen in deine fhem.cfg ein
#######################################################################################################################
## Alive
#######################################################################################################################
define alive dummy
attr alive room Alive
attr alive setList 0 1
define at_alive at +*00:01:00 {if ("$value{alive}" == 0) {fhem("set alive 1")} else {fhem("set alive 0")}}
attr at_alive room Alive
define FileLog_alive FileLog ./log/alive-%Y-%m-%d.log alive.*
attr FileLog_alive room Alive
define SVG_FileLog_alive_1 SVG FileLog_alive:SVG_FileLog_alive_1:CURRENT
attr SVG_FileLog_alive_1 plotsize 1200,350
attr SVG_FileLog_alive_1 room Alive
dann findest du Aussetzer schneller.
Gruß Joachim
Moin Joachim,
na denn weiß ich jetzt wenigstens das ich kein Einzelfall bin ;-)
Sporadische nicht eindeutig auftretende Fehler sind natürlich die schönsten ...
Jaydee und Rudi hatten ja in dem von daduke verlinkten fred die Theorie aufgestellt das es am longpoll liegt. Den habe ich erst einmal deaktiviert und seitdem sehe ich auch keine Indizien für die Aufhänger mehr im log. Allerdings ist das auch nur wenige Stunden her und daduke war ja auch im fred und er schreibt das er es für sich noch nicht gelöst hat. Da ich mal unterstelle das er longpoll ebenfalls deaktiviert hat spricht das gegen den longpoll als (alleinige???) Ursache. Hast Du longpoll auf off ?
Wenn ich mir Dein Setup anschaue sind hast Du wahrscheinlich auch nicht ausschließlich Fritzboxen am Start ? Jaydee hat in seiner Sig auch einen Raspi angegeben. Wenn das so stimmt kann man die Fb als Verursacher wohl ebenfalls ausschließen.
viele Grüße
Jörg
Edith:
in diesem fred http://forum.fhem.de/index.php/topic,14719.0.html hat Andyclimb den freeze auch auf ca 10min eingegrenzt. Nach dem deaktivieren des longpolls scheints zu gehen.
Moin Jörg,
longpoll ist bei mir an, und mit meinem Testaufbau trotzdem keine Aussetzer, solange FHEM mit Devices, die Netzwerk brauchen in einem seperaten Subnetz hängen.
Und richtig, 2x Fritzbox (7570,7390) und eimal raspberry.
Gruß Joachim
hier: http://forum.fhem.de/index.php/topic,14719.msg95070.html#msg95070 schreibt andyclimb das er mit ausgeschaltetem longpoll "nur" noch 2min freeze sieht. (manchmal...)
Nun ist es natürlich möglich das longpoll nicht die Ursache ist sondern die Symptome einfach verschlimmert. Vielleicht aufgrund der größeren Anzahl von Verbindungen zu fhem ? Wie das jetzt mit dem setup bei Dir wo longpoll ja in einem isolierten Netz funktioniert zusammenpasst verstehe ich noch nicht.
Wie hast Du das Netz den isoliert ? Einfach den gateway weg ? Läuft dhcp oder sind die ip's statisch ?
Bei mir ist longpoll jetzt ja aus und nachdem ich weiß worauf ich achten muss schaue ich mal ob noch Aussetzer auftreten.
Ansonsten würde ich mir Deine Idee ausleihen und sie in ein kurzes Modul mit höherer Zeitauflösung klöppeln, damit könnten freeze direkt ins log geschrieben werden. Vielleicht erkennt dann ein Modulautor den Timeout wieder, muss ja irgendwas in Richtung I/O sein.
vg
Jörg
Moin Jörg,
ZitatWie hast Du das Netz den isoliert ? Einfach den gateway weg ? Läuft dhcp oder sind die ip's statisch ?
2. Fritzbox zwischengeklemmt siehe Anhang, und damit ein neues Subnetz aufgebaut, alles dahinter denkt, das WWW fängt in meinem Hauptnetz an.
Zum finden der freezes einfach den oben vorgeschlagenen alive Dummy nehmen, man erkennt im Plot sofort Unregelmäßgkeiten, und kann dann gezielt im Log suchen.
Meine Probleme kannst du in folgenden Tread nachlesen
http://forum.fhem.de/index.php/topic,14397.0.html
Nach allem, was ich bisher gefunden und gelesen habe, tendiere ich dazu, dass der Fehler irgendwo in der DevIO.pm liegen muss, aber um da anzusetzen, muss ich den Fehler ersteinmal reproduzieren und vorallem provozieren können.
Gruß Joachim
OK, damit der Fehler besser qualifiziert werden kann:
im Anhang ist ein kleines Watchdog Modul, einfach ins Modulverzeichnis kopieren und "shutdown restart". Das Modul startet und überwacht einen Timer. Wird der Timer mit mehr als 1 Sekunde Verspätung ausgeführt taucht im fhem log ein Eintrag in der Form auf:
2013.11.01 23:59:10 1: possible freeze: timer should 22:59:09, delay is 1.70749402046204
Die Stunde Versatz ist die Zeitzone, der delay ist sec,msec ..
Mit einer Sekunde ist er bewusst "scharf" eingestellt, wird also unter Umständen auch von einem plot ausgelöst.
Damit werden eventuelle freeze mit Zeitpunkt und Dauer im log festgehalten und unter Umständen lassen sich daraus Rückschlüsse ziehen. Irgendwo muss man ja ansetzen.
vg
Jörg
kurzer Zwischenstand:
mit abgeschaltetem longpoll keine Probleme über die Nacht.
Ich denke der Fehler lässt sich recht sicher reproduzieren: im Webinterface den Event Monitor wählen, kurz warten bis die ersten Events eintreffen und NB Deckel zu :)
09:25 Event Monitor an, Notebook aus:
2013.11.02 09:41:03 1: 192.168.178.20:1000 disconnected, waiting to reappear
2013.11.02 09:41:03 2: HMLAN_Parse: HMLAN1 new condition disconnected
2013.11.02 09:41:03 1: 192.168.178.20:1000 reappeared (HMLAN1)
2013.11.02 09:41:03 2: HMLAN_Parse: HMLAN1 new condition init
2013.11.02 09:41:03 1: possible freeze: timer should 08:30:35, delay is 627.290109872818
09:53 Event Monitor an, Notebook aus:
2013.11.02 10:09:45 1: 192.168.178.20:1000 disconnected, waiting to reappear
2013.11.02 10:09:45 2: HMLAN_Parse: HMLAN1 new condition disconnected
2013.11.02 10:09:45 1: 192.168.178.20:1000 reappeared (HMLAN1)
2013.11.02 10:09:45 2: HMLAN_Parse: HMLAN1 new condition init
2013.11.02 10:09:45 1: possible freeze: timer should 09:00:54, delay is 530.607181787491
Wenn der Event Monitor keine Daten mehr an den Browser los wird dauert es etwa 5 - 10 min, dann steht fhem sicher rund reproduzierbar für etwa 10 Minuten.
Ich habe mal in die fhemweb, httputils und httpserv reingeschaut - ich muss gestehen ich verstehe es nicht.
Vielleicht nimmt sich ja jemand der Sache an der die logik in den Modulen versteht. Bzw, wenn mir jemand ein kurzes Intro gibt wo ich suchen muss bin ich dabei.
Zweite Frage wäre dann ob evtl auch andere Module anfällig für dafür sind, soweit ich das verstehe geht es ja darum das ein Puffer vollgeschriebn wird für den ein Client keine Daten mehr abnimmt und wenn der Puffer voll ist dann steht fhem.
vg
Jörg
Meine Erfahrung hatte ich leider nicht so systematisch wie Ihr hinterfragt: Die These, dass das "Nicht-Loswerden" von ins Web-Interface zu schreibenden Events das Problem jedenfalls befördert, habe ich auch. Und ich kann den Verdacht hinzufügen, dass nicht nur der Eventmonitor, sondern auch Module wie readingsgroups dazu beitragen, dass FHEM sekunden oder Minutenlang hängt.
Und noch eine weitere bisher nicht wirklich hinterfragte Beobachtung: Im Room Everything finde ich nach längerem Betrieb mit zahlreichen Aufrufen von FHEMWEB von Tablet (legt sich natürlich oft schlafen) und Rechner(n) eine durchaus mal 5 und mehr Positionen lange Liste á la:
FHEMWEB:XXX.XXX.XXX.XX7:53789 Connected
Die hier geXte IP-Adresse ist dann identisch, die Ports sind unterschiedlich. Nach einem Neustart gibt es mit der ersten Abfrage genau eine Zeile und die Reaktion von FHEMWeb ist "zackig".
Herzliche Grüße
Christian
dir FHEMWEB zeilen gibt es für jedes browser fenster das eine verbindung zu fhem offen hat. also z.b. auch für jeden offenen tab.
readingsGroup benutz den longpoll mechanismus um sich ändernde readings zu aktualisieren. wenn longpoll in bestimmten konstellationen probleme macht wird readingsGroup diese genau so zeigen wie z.b. eine device detail ansicht oder der der event monitor. eventuell trigger readinsGroup das problem früher als eine detail anscht einfach weil mehr readings gleichzeitig sichtbar sind aber auch nicht häufiger als der event monitor. dort ist ja alles zu sehen. readingsGroup sendet nur updates an den browser wenn wirklich ein event aufgetreten ist das zu einem reading passt das auch wierklich angezeigt wird.
man kann für readingsGroup mit 'disable 1' den update mechanismus deaktivieren. dann wird nur noch ein mal beim seitenaufbau die html ansicht erzeugt und es gibt keine updates mehr per longpoll. aktualisierte werte gibt es dann nur noch durch neu laden.
gruss
andre
Hallo Christian,
installiere Dir doch einfach das Modul 4 Posts weiter oben. Das ist auch wirklich ganz einfach, ich habe bewusst den 99_xxUtils Mechanismus genommen damit das bequem über das Webinterface geht.
Lade den Anhang runter und öffne ihn in einem Texteditor. Geh dann in fhem einfach auf "Edit files", öffne die "99_Utils.pm", kopiere den Inhalt des Moduls rein und speichere unter "99_wdUtils.pm". (Hier bitte aufpassen damit Du die "99_Utils.pm" nicht überschreibst !).
Danach findest Du jeden Hänger im fhem log mit dem Vorteil das man nicht über "gefühlte" Hänger sprechen muss sondern klare Daten dazu hat. Immer wenn fhem länger als eine Sekunde nicht reagiert wird ein Eintrag erzeugt.
Mit den gewonnen Erkenntnissen (longpoll + svg+longpoll deaktivieren, Eventmonitor sauber beenden) auf meiner Seite jetzt seid 48h keine Hänger. Letztendlich sehe ich jetzt auch genau ob und wie lange Plots das System aufhalten. Für die Umweltdaten (Wind, Temp, Sonne, Regen etc) hatte ich sowieso radikal auf loggen nur alle 10min umgestellt, damit werden auch 48h Plots in 1-2 Sekunden von der FB geliefert.
Interessant finde ich dabei das ich früher eigentlich viele dieser 10min Freeze gehabt haben muss - die in den meisten Fällen unbemerkt geblieben sind. Du kannst Deine Vermutungen auf alle Fälle prima damit überprüfen.
Die Aussage von Andre bzgl Readingsgroup finde ich konsistent und auch Rudi scheint ja eine sehr klare Vorstellung davon zu haben woran es liegt. In einem anderen threat hat bereits gesagt das er die Sache auf der to-do Liste hat. Vermutlich werden ihm die so gewonnen Daten helfen das umzusetzen.
vg
Jörg
Zitat von: justme1968 am 03 November 2013, 10:21:02
... FHEMWEB zeilen gibt es für jedes browser fenster das eine verbindung zu fhem offen hat. also z.b. auch für jeden offenen tab.
readingsGroup benutz den longpoll mechanismus um sich ändernde readings zu aktualisieren. wenn longpoll in bestimmten konstellationen probleme macht wird readingsGroup diese genau so zeigen wie z.b. eine device detail ansicht oder der der event monitor. eventuell trigger readinsGroup das problem früher als eine detail anscht einfach weil mehr readings gleichzeitig sichtbar sind aber auch nicht häufiger als der event monitor. dort ist ja alles zu sehen. readingsGroup sendet nur updates an den browser wenn wirklich ein event aufgetreten ist das zu einem reading passt das auch wierklich angezeigt wird.
man kann für readingsGroup mit 'disable 1' den update mechanismus deaktivieren. dann wird nur noch ein mal beim seitenaufbau die html ansicht erzeugt und es gibt keine updates mehr per longpoll. aktualisierte werte gibt es dann nur noch durch neu laden.
Vielen Dank, Andre, für die Informationen - tatsächlich habe ich in jüngerer Zeit eigentlich immer nur noch ein TAB in einem Browser zur Zeit offen - mein Hinweis auf readingsGroup war auch nicht als Kritik am von mir sehr geschätzten Modul gemeint, sondern als ein Gedanke, der vielleicht hilft, das Thema weiter einzukreisen.
Christian
Zitat von: herrmannj am 03 November 2013, 10:51:10
installiere Dir doch einfach das Modul 4 Posts weiter oben. Das ist auch wirklich ganz einfach, ich habe bewusst den 99_xxUtils Mechanismus genommen damit das bequem über das Webinterface geht.
Lade den Anhang runter und öffne ihn in einem Texteditor. Geh dann in fhem einfach auf "Edit files", öffne die "99_Utils.pm", kopiere den Inhalt des Moduls rein und speichere unter "99_wdUtils.pm". (Hier bitte aufpassen damit Du die "99_Utils.pm" nicht überschreibst !).
Das habe ich auch gleich beim Erscheinen des Posts gemacht und auch bei mir eine ganze reihe von (selbst verursachten) Gründen gefunden. Da ich soviele "Verzögerungen" hatte, scanne ich aktuell erst einmal auf alle Ereignisse, die länger als 10 Sec dauern. Und da sind tauchen die hier schon beschriebenen Anlässe auf.
Ich muss jetzt erst einmal rauskriegen, wie man ein FHEMWeb-Browserfenster so beendet, dass es nicht als Connected stehen bleibt (die längste Liste war bei mir schon mal 6 oder 8 Zeilen lang) und wie man wie von Dir beschrieben Logs ausdünnt - denn richtig: In vielen Fällen müssen die Datenpunkte gar nicht in dieser Dichte aufgezeichnet werden.
Christian
Koennt ihr bitte das Problem mit dem neuen Patch (siehe mein Kommentar hier (http://forum.fhem.de/index.php/topic,14893.msg106077.html#msg106077)) testen?
Hallo Rudi,
yes !
herzlichen Dank an Dich!
Jörg
Hallo Rudi,
gleiche Symptome, fhem friert für 18min ein.
Verwendete fhem version:
# $Id: fhem.pl 4189 2013-11-09 13:46:31Z rudolfkoenig $
# $Id: 00_CUL.pm 3853 2013-09-04 06:54:57Z rudolfkoenig $
# $Id: 10_CUL_HM.pm 4193 2013-11-09 17:15:13Z martinp876 $
# $Id: 01_FHEMWEB.pm 4092 2013-10-21 20:58:57Z rudolfkoenig $
# $Id: 10_FS20.pm 3764 2013-08-22 07:09:38Z rudolfkoenig $
# $Id: 92_FileLog.pm 3759 2013-08-21 08:13:08Z rudolfkoenig $
# $Id: 00_HMLAN.pm 4184 2013-11-08 16:36:13Z martinp876 $
# $Id: 98_HMinfo.pm 4101 2013-10-23 14:25:19Z martinp876 $
# $Id: 99_SUNRISE_EL.pm 3738 2013-08-18 14:13:59Z rudolfkoenig $
# $Id: 98_SVG.pm 4187 2013-11-09 09:55:16Z rudolfkoenig $
# $Id: 45_TRX.pm 3784 2013-08-24 19:04:30Z wherzig $
# $Id: 46_TRX_ELSE.pm 3774 2013-08-23 21:36:21Z wherzig $
# $Id: 46_TRX_LIGHT.pm 3996 2013-10-03 16:24:44Z wherzig $
# $Id: 46_TRX_SECURITY.pm 3918 2013-09-16 20:14:27Z wherzig $
# $Id: 46_TRX_WEATHER.pm 3874 2013-09-08 04:26:07Z wherzig $
# $Id: 99_Utils.pm 3595 2013-08-05 05:38:48Z tobiasfaust $
# $Id: 90_at.pm 4011 2013-10-06 08:15:26Z rudolfkoenig $
# $Id: 98_autocreate.pm 4114 2013-10-26 09:44:34Z rudolfkoenig $
# $Id: 98_dummy.pm 3738 2013-08-18 14:13:59Z rudolfkoenig $
# $Id: 91_eventTypes.pm 2982 2013-03-24 17:47:28Z rudolfkoenig $
# $Id: 99_Utils.pm 3595 2013-08-05 05:38:48Z tobiasfaust $
# $Id: 91_notify.pm 3738 2013-08-18 14:13:59Z rudolfkoenig $
# $Id: 98_telnet.pm 3738 2013-08-18 14:13:59Z rudolfkoenig $
fhem auf fb 7390, browser ff 25 auf linux.
Steps to replicate:
- longpoll aktiviert
- eventmonitor im browser aufgerufen
- telnet session auf fhem geöffnet, inform timer aktiviert
- abwarten, dann notebookdeckel schliessen
Zum Überwachen habe ich ein 99_perfmon.pm geschrieben das im Falle von freeze logeinträge erzeugt, ich werde das in "Ankündigungen" gleich mit Beschreibung zur Verfügung stellen. (btw, dabei ist mir aufgefallen das im Fall von CommandReload kein undef aufgerufen wird, führt dazu das Timer nicht entfernt werden können)
Edit:
Da ich in "Ankündigungen" nichts erstellen darf unter "Sonstiges" : http://forum.fhem.de/index.php/topic,16347.0.html (http://forum.fhem.de/index.php/topic,16347.0.html)
Logeintrag:
2013.11.10 11:49:45.586 1: Perfmon: possible freeze starting at 11:31:21, delay is 1104.585
Ich werde die Tests jetzt wiederholen (jeweils mit eventmonitor, longpoll auf device und telnet einzeln) um zu sehen ob alle drei betroffen sind. SVG longpoll verwende ich aktuell nicht.
vg
Jörg
Sowohl der Eventmonitor als auch Telnet sind zeigen weiterhin die freeze.
Eventmonitor:
* NB Deckel zu um 12:55:00, freeze von 12:58 bis 13:11:24
2013.11.10 13:11:24.804 1: Perfmon: possible freeze starting at 12:58:37, delay is 767.803
Telnet:
* NB Deckel zu im 13:15:00, freeze von 13:18:13 bis 13:30:55
2013.11.10 13:30:55.776 1: Perfmon: possible freeze starting at 13:18:13, delay is 762.775
Longpoll schenk ich mir jetzt ...
D&G
Jörg
Da meine Tests funktionieren, schlage ich vor zusaetzliche Debug-Ausgaben vor und nach dem Schreiben in fhem.pl (syswrite, Aktuell Zeile 521) einzubauen, um zu sehen ob es daran liegt.
sieht jetzt so aus:
Log 2, "start syswrite";
my $ret = syswrite($hash->{CD}, $wb);
Log 2, "finish syswrite: $ret";
Im log sehe ich nur Einträge wenn ich über telnet auf das fhem gehe. Wenn ich im browser fhem aufrufe werden keine Einträge dazu erzeugt. Ist das korrekt ?
Grüße
Jörg
Test mit telnet / inform timer:
NB geschlossen um 21:55:00
Log:
... (syswrites start / finish)
2013.11.10 21:57:50.532 2: start syswrite
2013.11.10 21:57:50.534 2: finish syswrite: 247
2013.11.10 21:57:50.881 2: start syswrite
2013.11.10 21:57:50.883 2: finish syswrite: 424
2013.11.10 22:10:55.471 1: Perfmon: possible freeze starting at 21:57:51, delay is 784.47
2013.11.10 22:10:57.776 1: 192.168.178.20:1000 disconnected, waiting to reappear
2013.11.10 22:10:57.823 2: HMLAN_Parse: HMLAN1 new condition disconnected
2013.11.10 22:10:57.846 2: start syswrite
2013.11.10 22:10:57.849 2: finish syswrite: 13865
2013.11.10 22:10:57.864 1: 192.168.178.20:1000 reappeared (HMLAN1)
2013.11.10 22:10:57.874 2: HMLAN_Parse: HMLAN1 new condition init
2013.11.10 22:10:57.991 1: Perfmon: possible freeze starting at 22:10:56, delay is 1.99
2013.11.10 22:11:00.967 1: Perfmon: possible freeze starting at 22:10:58, delay is 2.966
2013.11.10 22:11:04.004 1: Perfmon: possible freeze starting at 22:11:01, delay is 3.003
2013.11.10 22:11:06.993 1: Perfmon: possible freeze starting at 22:11:05, delay is 1.992
2013.11.10 22:11:08.074 1: Perfmon: possible freeze starting at 22:11:07, delay is 1.073
2013.11.10 22:11:59.602 1: Perfmon: possible freeze starting at 22:11:09, delay is 50.6
2013.11.10 22:12:00.355 2: HMLAN_Parse: HMLAN1 new condition ok
2013.11.10 22:12:00.776 2: start syswrite
2013.11.10 22:12:00.779 2: finish syswrite:
2013.11.10 22:12:00.790 1: 192.168.178.20:1000 disconnected, waiting to reappear
2013.11.10 22:12:00.828 2: HMLAN_Parse: HMLAN1 new condition disconnected
2013.11.10 22:12:00.861 1: 192.168.178.20:1000 reappeared (HMLAN1)
so wie ich das sehe hing er nie _im_ syswrite.
Der Effekt ist trotzdem sicher durch das "kappen" der bestehen (hier telnet) Verbindung zu provozieren ...
Ich geh jetzt noochmal auf verbose 5 ...
vg
joerg
Der Hänger ist gut getarnt ;-)
Setup wie oben, NB Deckel zu um 22:33. Bis 22:37:30 alles ok, TRX_Read meldet Ende, danach Stillstand bis 22:54:35. (Gewerkschaftlich zugesicherte Pause ??? ;-)
2013.11.10 22:37:30.927 5: TRX_Read END
2013.11.10 22:54:35.913 5: TRX/RAW: /
Das komplette log hängt dran. Soll ich weitere Breakpoints einbauen ? Wenn ja, wo ?
vg
Jörg
> Wenn ich im browser fhem aufrufe werden keine Einträge dazu erzeugt. Ist das korrekt ?
Nein. Habs gerade entdeckt, dass ich FHEMWEB nicht eingecheckt habe, obwohl ich haette darauf schwoeren koennen.
Habs jetzt eingecheckt, und fuer update bereitgestellt. Kannst Du es bitte erneut testen?
Vielen Dank, funktioniert: Eventmonitor und Telnet.
XHR mit inform und longpoll beobachte ich.
Das Du einen (den richtigen) Verdacht hattest war Gold wert, ich habe gefühlte 20.000 Breakpoints gesetzt ohne die Stelle exakt festmachen zu können. Wenn ich das richtig interpretiere ist die fb auch nach einem write durchaus noch einige wenige ms weitergelaufen bevor sie stand.
Danke und Grüße
Jörg
> Wenn ich das richtig interpretiere ist die fb auch nach einem write durchaus noch einige wenige ms weitergelaufen bevor sie stand.
Nee, der Stand ziemlich sicher in 01_FHEMWEB.pm, FW_FlushInform(), print $c $hash->{INFORMBUF}
Dies wurde inzwischen durch addToWritebuffer ersetzt, ist also im Code nicht mehr vorhanden.
Feedback:
mit den von Rudi gemachten Änderungen seid 5 Tagen kein Einfrieren mehr. Gelegentliche 1-3 sec. Aussetzer lassen sich jeweils einzelnen Modulen zuordnen, die langen Aussetzer sind komplett verschwunden.
Markiert als "gelöst", Danke nochmal
vg
Jörg
Moin,,
richtig, auch bei mir haben sich diese Hänger verflüchtigt. Danke dafür an den Mentor von FHEM, Rudolf König.
Allerdings finde ich seit der neuen 01_FHEMWEB kurz nach dem Neustart von FHEM über Telnet diese Meldung
syswrite() on closed filehandle GEN320 at fhem.pl line 522.
Herzliche Grüße
Christian
> syswrite() on closed filehandle GEN320 at fhem.pl line 522.
Ich kann diese Meldung nicht reproduzieren, ich habe shutdown und shutdown restart per telnet und per FHEMWEB eingegeben. Kannst Du bitte den Vorgang sehr genau beschreiben?
dir meldungen hab ich bei mir auch gesehen. aber nur im nachhinein und noch nich gefunden wie ich sie reproduzieren kann.
gruss
andre
Moin,moin,
leider werde ich aktuell ein paar Tage FHEM nicht anrühren können - aber ich kann hier das dreimalige Beobachten so beschreiben:
Ich mache shutdown per FHEMWEB.
Nach einige Minuten verbinde ich mich über Putty mit der Fritzbox, gehe in das Verzeichnis von FHEM und starte dann per ./startfhem.
Nachdem FHEM vollständig gestartet ist, kommen aktuell Fehlermeldungen von HCS (das n/a-Problem, wenn in einem TC keine disired-temp ausgelesen wird und von openweathermap, die ich noch nicht eingegrenzt habe). Dann kommt, wenn ich nun ein neues Browserfenster aufmache und FHEMWeb starte diese Nachricht früher oder später, einmal. (sorry, das kann ich aus der Erinnerung nicht genauer definieren).
Herzliche Grüße
Christian
Hallo. Ich weiss das der thread alt ist habe aber selbe fehlermeldung. Hast du zwischenzeitlich eine lösung? Oder friert fhem wegen anderm fehler?
Gesendet von meinem GT-I9300
Hatte dieses Thema nach Umstieg auf 1-Wire verstärkt (wobei im Nachhinein muss ich sagen: Durch 1-Wire hatte sich die Zahl meiner Device auch drastisch erhöht). Inzwischen ist aber OWX-ASYNC so gereift, dass ich "Hänger" im FHEM nur noch beobachte, wenn ich Plots aus großen Datenmengen schreiben lasse.
Noch ein Hinweis: Ich habe in meinem FHEM überflüssige Devices, AT, Notifys und vor allem automatisch angelegte FIlelogs ausgemistet und bin damit wieder knapp unter 200 Enitiäten gekommen. Mit dem Unix-Befehl FREE stelle ich dann stabilen Betrieb fest, wenn ich nach dem Neustart so an die 22 MB freien Hauptspeicher auf der Box habe. Im sinkt das dann auch mal vorübergehend auf 10 MB. Wenn ich in FHEM noch weitere Programme oder Funktionen nutze, also mehr Hauptspeicher verbraucht wird, habe ich früher oder später durchaus auch einen Absturz.
Christian
Hi Satprofi,
wenn Du ein halbwegs aktuelles fhem hast dann ist dieser Fehler beseitigt. (Schon lange)
Wenn fhem hängt kann das auch andere Symptome haben. (Bitte beschreiben).
Wenn das webif nicht mehr reagiert dann versuche folgendes: einloggen per telnet und "delete FHEMWEB.*" eingeben. Wenn es danach wieder geht bitte kurze Info, sonst am besten neuen thread aufmachen. Dieser hier ist schon historisch ;)
vg
jörg