Liebe Gemeinde,
ich hoffe jemand hat ein Idee. Ich bin mit meinen Tests, dem Forum (Suche und Nachstellen) und meinem Latain am Ende.
Anfänglich war es ein geringfügige Verzögerung. Inzwischen reagiert der Dienst zwischen 8-9 min nciht mehr und ich kann schwer sagen ob das System neustartet (watchdog) oder er sich doch wieder fängt.
Auslöser: Immer fhem.save - egal ob Link oder via Script ausgelöst. schön nachvollziehbar im LOG egal welches Level. Es kommen brav die drei SAVE Einträge und dann steh alles. Wenn er sich wieder fängt sieht man schön aller Blocking, wie sich die Deinste HArmony, HMLAn etc. dann wieder nach timeouts reinschubsen.
Habe ne DBConfig - die funktioniert tadelos. DBReps glänzen mit besten Reaktionzeiten. AppTime etc. und Systemanalyse bereits hinter mich gebracht. Jemand ne Idee außer Neuinstallation wo ich noch ansetzen könnte.
2020.04.24 20:46:59 1: in SAVE
2020.04.24 20:46:59 1: in SAVE
2020.04.24 20:46:59 1: in SAVE
2020.04.24 20:46:59 1: in SAVE
2020.04.24 20:57:21 2: HUE: http request failed: read from http://Philips-hue.intranet.lan:80 timed out
2020.04.24 20:57:21 2: HUE: http request failed: connect to http://Philips-hue.intranet.lan:80 timed out
2020.04.24 20:57:21 2: HUE: http request failed: read from http://Philips-hue.intranet.lan:80 timed out
2020.04.24 20:57:22 3: SeppiSurvi - Polling now: 20:57:22 , next Polling: 21:00:52
2020.04.24 20:57:22 3: netatmo_M05_00_00_03_55_c0: poll (MODULE)
2020.04.24 20:57:22 3: netatmo_M05_00_00_03_55_c0: requestDeviceReadings (Rain)
2020.04.24 20:57:23 3: netatmo_D70_ee_50_27_58_54: poll (DEVICE)
2020.04.24 20:57:23 3: netatmo_D70_ee_50_27_58_54: requestDeviceReadings (Temperature,CO2,Humidity,Noise,Pressure)
2020.04.24 20:57:23 3: netatmo_M06_00_00_01_3b_24: poll (MODULE)
2020.04.24 20:57:23 3: netatmo_M06_00_00_01_3b_24: requestDeviceReadings (WindStrength,WindAngle,GustStrength,GustAngle)
2020.04.24 20:57:23 3: netatmo_M02_00_00_27_55_ea: poll (MODULE)
2020.04.24 20:57:23 3: netatmo_M02_00_00_27_55_ea: requestDeviceReadings (Temperature,Humidity)
2020.04.24 20:57:23 3: FHEMCheck - Zeitstempel setzen ausgführt
2020.04.24 20:57:24 3: w_DBConnect: Datenbank 20 mal nicht verbunden.
2020.04.24 20:57:25 3: w_DBConnect: Datenbank 10 mal nicht verbunden.
2020.04.24 20:57:25 3: DBLogging_Reopen: Reopen executed.
2020.04.24 20:57:27 2: luci_harmony: disconnect
Danke Sebastian
Hallo Sebastian,
Den musst Du näher erklären:
ZitatAuslöser: Immer fhem.save - egal ob Link oder via Script ausgelöst. schön nachvollziehbar im LOG egal welches Level. Es kommen brav die drei SAVE Einträge
fhem.save ist für mich eine Datei.
Was hast Du für ein System? HDD, SD Card?
Gruß Otto
Hallo Otto,
mein Fehler.
Raspi4 mit einer Samsung MB-ME64GA (microSDXC).
Ausgelöst kann mein save auf drei Arten werden:
Scripte: fhem("save")
Link: auf dem DashBoard mit den cmd=save UrlAppendix
und autosave ist auch auf 1
Test in dem Zusammenhang:
SD Clone angelegt auf neue SD gleicher Typ und anderer Typ gleiches Problem
ConfDB ne MySQL auf einem SYnoNAS - alle DBRep Devicex funktionieren mit sehr guten Antwort- und Bearbeitungszeiten
Raspi - hat 4GB kein swaping ca. 25 % RAM Auslastung und ne LA <1
Beobachtetet vor ca. 2 Monaten ca. 1 min keine wesentlichen Änderungen außer
Giessanlage mit 12 Xiaomos (BLE) wieder in Betrieb genommen. Problem bestand schon kann aber nicht sagen ob das das Paket noch mal deutlich verschlimmert hat. Die Sensoren hatte ich bereits testweise aus dem Scan genommen ohne positives Ergebnis.
Danke
Ich denke hier:
Zitat2020.04.24 20:46:59 1: in SAVE
2020.04.24 20:46:59 1: in SAVE
2020.04.24 20:46:59 1: in SAVE
2020.04.24 20:46:59 1: in SAVE
hast Du irgendwas mit einer Schleife gebaut. Diese Einträge kommen ja von Dir und nicht vom System?!
Überprüf und deaktiviere doch mal Deine Scripte bez. SAVE
Es scheint als hast Du eine savephobie :)
Könnte man vermuten ;-) Ich weiß nicht wo der Fehlerteufel steckt. Ist mir auch aufgefallen wird aber bei jedem manuellen save sogar dem Kommandozeilen save ausgelöst
Gerade eben in der Webfrontend Kommandozeile.
. 2020.04.24 21:52:12 3: set Mosquitto publish /SmartHome/Schlafzimmer/Temperatur/state 21.68 °C : no pending sleeps
2020.04.24 21:52:12 1: in SAVE
2020.04.24 21:52:12 1: in SAVE
2020.04.24 21:52:12 1: in SAVE
2020.04.24 21:52:12 1: in SAVE
Ich suche aber gern. Wenn mir jemand bitte sagt was genau bei save aufgerufen wird. Also warum Log1 mir das dann scheinbar auch 4mal anzeigt. Habe keine bewusste loop oder rekursion gescriptet.
Das bl... ist selbst mit ver5 kommt zwischen den Save keine Info die Rückschlüsse gibt.
So verkehrt war dein Hinweis aber nicht. Es gibt ein Muster das zwar nicht unmittelbar davor ist aber auffällt. Habe aber noch keine Idee wie ich an die loop oder rekursion rankomme.
2020.04.24 21:30:22 3: n_TempSZWatch wurde ausgelöst und verzögert
2020.04.24 21:30:22 1: in DEFINED
2020.04.24 21:30:22 1: in DEFINED
2020.04.24 21:30:22 1: in DEFINED
2020.04.24 21:30:22 1: in DEFINED
2020.04.24 21:30:22 1: in ATTR
2020.04.24 21:30:22 1: in ATTR
2020.04.24 21:30:22 1: in ATTR
2020.04.24 21:30:22 1: in ATTR
Diesen Eintrag: 020.04.24 21:52:12 1: in SAVE gibt es bei mir nicht, auch nicht bei save. Der kommt also mit ziemlicher Sicherheit von Dir. Also such doch einfach das Script / den Teil wo Du {Log 1,"in SAVE"}stehen hast. ;)
Vielleicht so? (FHEM Kommandozeile)
{qx(grep -r "in SAVE" ./)}
Hatte ich im Systemverzeichnis schon gemacht. Versuche es aber mit deinem Aufruf. Scheint mir aber nach den anderen Log einträgen eher etwas wie Log1 $var zu sein.
aber irgendwo musst Du den String ja mal setzen :)
Also zusammenfassend sagt mir dein grep Kommando, dass dieser Logeintrag bereits 2017 seit der Geburt meines FHEM in den Logs vorkommt. Leider aber in keinem Script.
Was mich selbst wundert schon immer 4mal. Ist also eine Baustelle ich auch mal ansehen muss, scheinbar aber nicht das Problem - direkt - für mein erst junges Issue.
Otto, weißt du ggf. mehr bzw. was / wer exakt save aufruft. Gbt es dafür ne System .pm? Es scheint ja ein Systemroutine zu sein da ATTR, DEFINED bei mir schein auf dem Weg auch immer 4mal auftaucht.
Bzw. sollte ich dem nicht zu sehr nachgehen. Da ich gerade eben einige Frontend Aktionen geteset habe. Die triggern alle 4 mal. Z.B. ein Attr anlegen bzw ändern und speichern.
Dann such mal nur nach SAVE
{qx(grep -r "SAVE" ./)}
save ist eine Systemroutine die wie ich annehme in fhem.pl verankert ist.
gib einfach help save ein, da siehst Du was sie macht.
Das mit dem 4 mal triggern ist auch komisch. Aber Dein Log sagt mir : nach 4 mal in SAVE geht Dein FHEM in die Hofpause.
Du wirst Dir wohl ein Testsystem bauen müssen, wo Du parallel untersuchen kannst.
Bin gerade in der fhem.pl unterwegs. Ich suche mir jetzt exakt raus was da abgesetzt wird und stelle das irgendwie parallel nach. Fakt ist, das der sich erst nach dem Kommandoaufruf inzwischen 10min Zeit nimmt. Das komische ist, er hängt sich nicht auf. Das ich im DB Log sehe das er inserted und Versionen bereinigt.Ohne Zeitverzögerung aber dazwischen hängt irgendwas.
Danke schon mal für die Impulse.
Aber das Problem ist nicht die fhem.pl ::)
Was siehst Du denn im System während der 10 min? Vollast bei fhem?
Zweites Terminalfenster und top ...
Die Meldung 'in save' kommt aus Fronthem/smartvisu. Das freeze nicht ! ;)
Der Chef persönlich. Welche Ehre ;-) guten Abend. Das erklärt die 4 mal .... 4 iOS Devices die alle disconnected sind. Ich werden FTH erstmal deaktivieren, um das auszuschließen.
Ich habe es soweit aufgedröselt das ich S-Routine cfgDB_SaveCfg direkt aufgerufen habe die braucht 10 sek im Frontend. Jetzt werde ich mich wohl durchfriemeln müssen., was danach abläuft für 9:50 min
@Otto das ist ja das komische das System idled. Aber FHEM wird vollständig geblockt. Keine Aktion mehr. Soweit ich die fhem.pl von Jörg verstanden habe kommt sofort der subcall auf dei ConfDB. Der (also die Durchführung) blockiert zwar die 10 sek das würde den rest nicht erklären. Ich muss sehen was noch zwischen den beiden Instanzen hin und her gereicht wird bis das save durch ist.
Zwischenfrage: attr global dnsServer gesetzt?
Ansonsten kann ich glaub ich nicht weiterhelfen.
Gute Nacht
Otto
Also:
1. Herzlichen Dank an euch beide
2. Die Logs sind weg nach dem ich die FTH Devices aufgeräumt habe. Die Savetime liegt jetzt wieder bei ca. 2 min das ist supi. PS: @Jörg für die Programmiererehre. Ich glaube nicht das FTH oder FHEM die Ursache war, aber da ich FTH kaum noch nutze, tat das entfernen der 4 Devices nicht weh.
3. @Otto, mit dnsServer habe ich experimentiert, aber immer wieder Misserfolge gehabt. Teilweise funktionierte die Auflösung nicht. Was wäre diesbezüglich deine Empfehlung gewesen?
vielen Dank aber diese Ehre gebührt mir nicht weil fhem erstens ein Gemeinschaftsprojekt ist und zweitens gerade fhem.pl Rudis Kind ist.
Zum dns: da ist es wichtig eine lokale Adresse zu setzen. Wenn Du da nicht sicher bist welche, dann ist es die IP Deines Routers. Sollte dann die Auflösung bei einigen Namen nicht funktionieren dann bitte einen Bug dafür aufmachen. Nach "maintainer.txt" würde das nach "Automatisierung" gehören, unter "Sonstiges" aber vmtl genauso Beachtung finden.
vg
Joerg
Nachtrag: einen 10min freeze erklärt aber mMn auch DNS nicht. Aber wenn es jetzt läuft passt das ja soweit. Wobei ich 2min fürs save auch viel zu viel empfinde (5 Sekunden schon). Ich würde da eher in der cfgDB Ecke (oder im Dunstkreis von...) noch "was" suchen. Allerdings habe ich da nichts im Hinterkopf und auch keine Idee zum "was"
zu 3. Empfehlung: normal auf die Router Adresse setzen. Siehe Doku
ZitatdnsServer
Enthält die IP Adresse des DNS Servers. Die von bestimmten Modulen (oder eigenen Code) aufgerufene HttpUtils_NonblockingGet wird auch bei der DNS Auflösung nicht mehr blockieren, falls dieses Attribut gesetzt ist, da es in diesem Fall FHEM eigene Routinen aufgerufen werden. Sonst werden die OS-eigenen, blockierenden Routinen inet_aton bzw gethostbyname aufgerufen.
zu 2. 2 min save Time ? Damit hätte ich ein Problem. Ich habe mir da noch nie Gedanken gemacht, save funktioniert einfach. save braucht bei mir ca. 1,5 sec .
Edit habe jetzt länger gebraucht weil ich in perl die Zeit messen wollte - habs nicht hinbekommen. Die Zeit ist gemessen mit einem Aufruf übers System, da ist also noch Ladezeit fürs Script enthalten ;)
Vielleicht mal die configDB aufräumen? Da sind vermutlich zu viele alte Versionen drin...Und um @configDB was in der Konfiguration zu suchen hilft grep wenig, es gibt dafür "search".
Generell scheint es mit fraglich, ob save nicht etwas sparsamer eingesetzt werden sollte...