Wachsende timeouts - FHEM save

SeppiDeluxe · 24 April 2020, 21:01:35

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.

Code Auswählen


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

Otto123 · 24 April 2020, 21:20:32

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

SeppiDeluxe · 24 April 2020, 21:34:00

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

Otto123 · 24 April 2020, 21:48:12

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

SeppiDeluxe · 24 April 2020, 21:53:45

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.

.

Code Auswählen

2020.04.24 21:52:12 3: set Mosquitto publish /SmartHome/Schlafzimmer/Temperatur/state 21.68 &deg;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.

Code Auswählen

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

Otto123 · 24 April 2020, 22:06:07

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)

Code Auswählen

{qx(grep -r "in SAVE" ./)}

SeppiDeluxe · 24 April 2020, 22:12:58

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.

Otto123 · 24 April 2020, 22:20:32

aber irgendwo musst Du den String ja mal setzen

SeppiDeluxe · 24 April 2020, 22:30:18

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.

SeppiDeluxe · 24 April 2020, 22:38:50

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.

Otto123 · 24 April 2020, 22:47:13

Dann such mal nur nach SAVE

Code Auswählen

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

SeppiDeluxe · 24 April 2020, 22:50:37

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.

Otto123 · 24 April 2020, 22:56:27

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

herrmannj · 24 April 2020, 22:58:52

Die Meldung 'in save' kommt aus Fronthem/smartvisu. Das freeze nicht !

SeppiDeluxe · 24 April 2020, 23:18:02

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.