Fhem startet sehr langsam (3/4h)

Begonnen von mig2, 12 Mai 2022, 17:31:30

Vorheriges Thema - Nächstes Thema

mig2

Guten Abend zusammen,
ich setzte FHEM schon seit ein paar Jahren ein. Leider habe ich seit ein paar Monaten das Problem das ein Neustart von Fhem (Reboot aus WebGui, Reboot aus Shell, Reboot Raspberry) sehr lange dauert. Bei der heutigen Bestandesaufnahme dauerte es 46Min, bis Fhem ansprechbar war.
Fhem läuft auf einem Raspberry 4 mit 4GB Speicher. Der Raspberry ist auf dem aktuellen Stand (bullseye / laufend Update durchgeführt)
Die Konfiguration und Log werden in einer MariaDB auf einer Synology NAS verwaltet. NAS ist auf dem aktuellen Stand. MariaDB ist Version 10.3.32-1041 installiert.
Es ist noch eine CCU3 angehängt. Die wurde heute auch noch auf den neusten Stand updatet (Version 3.63.9).
Für die Aufzeichung heute, wurde folgendes vorgenommen.
NAS wurde am morgen Neugestartet.
CCU wurde am morgen Neugestartet.
FHEM, Verbose habe ich auf 5 gesetzt
Raspberry: Fhem wurde auf der Shell gestoppt
                 Shutdown vom Raspberry
                 Raspberry stromlos gemacht (gleich noch ein Klone von der SD Karte angefertigt.

14:04 wurde der Raspberry an die Stromversorgung angeschlossen
14:04 wurde der Vaterprozess von FHEM gestartet
14:50 wurde noch zusätzliche Prozess hochgezogen und ab diesen Zeitpunkt ist FHEM auch ansprechbar

pi@raspberrypi:~ $ psx fhem
fhem       791     1  4 14:04 ?        00:08:30 /usr/bin/perl fhem.pl configDB
fhem      1528   791  0 14:15 ?        00:00:25 python3 FHEM/bindings/python/bin/fhempy --local
fhem      1633   791  0 14:50 ?        00:00:10 /usr/bin/perl fhem.pl configDB
fhem      1634   791  0 14:50 ?        00:00:12 /usr/bin/perl fhem.pl configDB
pi        2869  2417  0 17:27 pts/2    00:00:00 grep --color=auto fhem

Mit Verbose 5 wurde nun viel in das Log geschrieben. Leider konnte ich nicht wirklich einen Fehler finden. Nur viele Totzeit.
Ich hoffe, jemand kann mir da weiterhelfen.
Im Anhang ist das Logfile, beim Text "Wurde ersetzt", habe ich so Passwörter oder Token entfernt

Vielen Dank
Peter
RPi 3 - CUL 868 (Pigator) - ZWave (RaZberry2)
Homematic:HM-SEC-SC-2 / HM-SEC-SCo / HM-TC-IT-WM-W-EU / HM-ES-PMSw1-Pl-DN-R5
Z-Wave: FGR222 (010f-0302-1000) / FGS223 (010f-0203-1000) / FGD212 (010f-0102-1000) /FGKF601 (010f-1001-1000) / KeyFob / FGS212 (010f-0402-1002)

Wernieman

Gibt es bei den üblichen Verdächtigen Einträge? also kern.log, syslog o.Ä.
- Bitte um Input für Output
- When there is a Shell, there is a Way
- Wann war Dein letztes Backup?

Wie man Fragen stellt: https://tty1.net/smart-questions_de.html

mig2

#2
In den Logs ist nichts spezielles drin

-rw-------   1 root     root              13459 12. Mai 14:04 vncserver-x11.log
-rw-r-----   1 root     adm               10695 12. Mai 14:05 user.log
-rw-r-----   1 root     adm               23841 12. Mai 14:05 debug
-rw-r-----   1 root     adm              154747 12. Mai 14:05 messages
-rw-r-----   1 root     adm              154262 12. Mai 14:05 kern.log
-rw-r--r--   1 root     root              85851 12. Mai 19:04 Xorg.0.log
-rw-r-----   1 root     adm              741381 12. Mai 19:23 syslog
-rw-r-----   1 root     adm              502399 12. Mai 19:23 daemon.log
-rw-r-----   1 root     adm              153037 12. Mai 19:23 auth.log
-rw-rw-r--   1 root     utmp             977664 12. Mai 19:23 wtmp
-rw-rw-r--   1 root     utmp             292292 12. Mai 19:23 lastlog

Ich habe das kern.log und syslog noch angehängt

P.S.: Während dem starten sind auch keine spezielle Auslastung zu Verzeichnen. Im HTOP ist die Prozessorenlast fast bei Null
RPi 3 - CUL 868 (Pigator) - ZWave (RaZberry2)
Homematic:HM-SEC-SC-2 / HM-SEC-SCo / HM-TC-IT-WM-W-EU / HM-ES-PMSw1-Pl-DN-R5
Z-Wave: FGR222 (010f-0302-1000) / FGS223 (010f-0203-1000) / FGD212 (010f-0102-1000) /FGKF601 (010f-1001-1000) / KeyFob / FGS212 (010f-0402-1002)

Beta-User

Das sieht für meine in der Hinsicht ungeübte Augen danach aus, als würde FHEM auf die CCU-Verbindung(en) warten (oder erfolglos versuchen, die zugehörigen Zugangsdaten aus der configDB zu lesen).

Vielleicht hat es was mit dem update auf V5 zu tun?
Server: HP-elitedesk@Debian 12, aktuelles FHEM@ConfigDB | CUL_HM (VCCU) | MQTT2: MiLight@ESP-GW, BT@OpenMQTTGw | MySensors: seriell, v.a. 2.3.1@RS485 | ZWave | ZigBee@deCONZ | SIGNALduino | MapleCUN | RHASSPY
svn: u.a MySensors, Weekday-&RandomTimer, Twilight,  div. attrTemplate-files

mig2

Die CCU habe / hatte ich auch schon im Verdacht. Daher habe ich am Wochenende den rpcserver auf off gestellt. In der Hoffnung, dass es eine Verbesserung geben würde. Aber die Hoffnung ist gestorben.
Der nächste Schritt wäre, wenn hier keine Lösung gibt, dass ich auf der Backup SD mal das Modul HMCCU komplett löschen würde. Davor schrecke ich aber noch ein bissel ab, denn in der CCU habe ich relativ viele Sensoren drin.
Noch eine Frage, was meinst Du mit V5?
RPi 3 - CUL 868 (Pigator) - ZWave (RaZberry2)
Homematic:HM-SEC-SC-2 / HM-SEC-SCo / HM-TC-IT-WM-W-EU / HM-ES-PMSw1-Pl-DN-R5
Z-Wave: FGR222 (010f-0302-1000) / FGS223 (010f-0203-1000) / FGD212 (010f-0102-1000) /FGKF601 (010f-1001-1000) / KeyFob / FGS212 (010f-0402-1002)

betateilchen

Zitat von: mig2 am 12 Mai 2022, 17:31:30
Mit Verbose 5 wurde nun viel in das Log geschrieben.

Zitat von: Beta-User am 12 Mai 2022, 19:54:49
oder erfolglos versuchen, die zugehörigen Zugangsdaten aus der configDB zu lesen

Dann könnte FHEM nicht in verbose 5 laufen, weil dieses Attribut aus der Konfigurationsdatenbank gelesen und gesetzt wird.
-----------------------
Formuliere die Aufgabe möglichst einfach und
setze die Lösung richtig um - dann wird es auch funktionieren.
-----------------------
Lesen gefährdet die Unwissenheit!

Wernieman

#6
Sind so viele Nachfragen von ConfigDB nach der uniqueID normal?

2022.05.12 14:17:24 4: configDB reading file: ./FHEM/FhemUtils/uniqueID
2022.05.12 14:17:48 4: configDB reading file: ./FHEM/FhemUtils/uniqueID
....
....
2022.05.12 14:50:09 4: configDB reading file: ./FHEM/FhemUtils/uniqueID
2022.05.12 14:50:11 4: configDB reading file: ./FHEM/FhemUtils/uniqueID
2022.05.12 14:50:12 4: configDB reading file: ./FHEM/FhemUtils/uniqueID

Davor/danach sind zwar auch diese Einträge zu finden, aber immer unterbrochen von anderen Meldungen. In diesen 33 Minuten nur diese Meldungen .... und davon viele, sehr viele ...
Hast Du geprüft, das Deine DB auf Deiner Synology sauber ist?
- Bitte um Input für Output
- When there is a Shell, there is a Way
- Wann war Dein letztes Backup?

Wie man Fragen stellt: https://tty1.net/smart-questions_de.html

mig2

Hmm,
die uniqueID ist vom 03.05.2020
-rwxrwxrwx 1 fhem dialout   235  3. Mai 2020  uniqueID

Das ist der Inhalt
# This file is auto generated.
# Please do not modify, move or delete it.

uniqueID:xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
TelegramBot_telegram_token:xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
xxx wurde von mir jetzt gesetz, damit die token nicht ersichtlich ist.

Müsste diese File jedesmal neu angelegt werden?
RPi 3 - CUL 868 (Pigator) - ZWave (RaZberry2)
Homematic:HM-SEC-SC-2 / HM-SEC-SCo / HM-TC-IT-WM-W-EU / HM-ES-PMSw1-Pl-DN-R5
Z-Wave: FGR222 (010f-0302-1000) / FGS223 (010f-0203-1000) / FGD212 (010f-0102-1000) /FGKF601 (010f-1001-1000) / KeyFob / FGS212 (010f-0402-1002)

rudolfkoenig

Groessere spruenge im Log sieht man um:
- 2022.05.12 14:04:49 4: configDB reading file: ./FHEM/FhemUtils/uniqueID (20s)
- 2022.05.12 14:05:21 4: configDB reading file: ./log/eventTypes.txt (20s)
- 2022.05.12 14:05:49 4: configDB reading file: ./db.conf (28s)
- 2022.05.12 14:07:25 4: configDB reading file: ./FHEM/FhemUtils/uniqueID (29s)
- 2022.05.12 14:08:24 4: configDB reading file: ./FHEM/FhemUtils/uniqueID (27s)
- 2022.05.12 14:08:52 4: configDB reading file: ./FHEM/FhemUtils/uniqueID (27s)
- 2022.05.12 14:09:19 4: configDB reading file: ./FHEM/FhemUtils/uniqueID (26s)
...
Die Zahlen im Klammern sind meine "Differenz-Rechnungen" zum naechsten Eintrag.

=> Irgendetwas ist in der DB kaputt.

P.S.: Vom Pfadnamen nicht verwirren lassen, das ist in diesem Fall nur der Kenner der Daten in der DB, damit configDB kompatibel bleibt mit der "einfachen Dateisystem" Version.







Wernieman

Hatte ich das nicht auch schon geschrieben?
ZitatHast Du geprüft, das Deine DB auf Deiner Synology sauber ist?
- Bitte um Input für Output
- When there is a Shell, there is a Way
- Wann war Dein letztes Backup?

Wie man Fragen stellt: https://tty1.net/smart-questions_de.html

DS_Starter

Ich vermute eine allgemein sehr schlechte Performance der DB auf der Synology.
Die Syno haben i.A. nicht sehr viel Arbeitsspeicher und könnten bei viel geladenen (sonstigen) Paketen schnell in
den SWAP gehen.
Man kann es sehen im Ressourcen-Monitor-> Arbeitsspeicher -> SWAP wie im angehängten Screenshot.

Möglicherweise sieht man da schon etwas.

Einen gewissen Überblick über die DB Performce bekommst du auch wenn du in DbLog-Device das Attr showproctime = 1
setzt.
Du bekommst dann das Reading sql_processing_time. Das stellt zwar die Dauer eines Schreibzyklus dar, aber gibt schon eine
Ahnung der DB Performance. Im Screenshot siehst du einen Vergleichswert von meiner DB (die liegt allerdings auf einer VMWare Machine mit SSD).






ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

mig2

So wie es aussieht, wird es die DB sein.
Dann werde ich am Wochenende einen DB Dump ziehen.
Anschliessend die notwendigen Tabellen umkopieren, neu Anlegen und dann die Daten wieder reinkopieren.
Zugleich werde ich mal die Trigger (eigene) auf den diversen Tabellen deaktivieren.

Mal vielen Dank für eure Hilfe
RPi 3 - CUL 868 (Pigator) - ZWave (RaZberry2)
Homematic:HM-SEC-SC-2 / HM-SEC-SCo / HM-TC-IT-WM-W-EU / HM-ES-PMSw1-Pl-DN-R5
Z-Wave: FGR222 (010f-0302-1000) / FGS223 (010f-0203-1000) / FGD212 (010f-0102-1000) /FGKF601 (010f-1001-1000) / KeyFob / FGS212 (010f-0402-1002)

mig2

Der Hinweis auf die DB war Goldrichtig. Ich habe heute morgen nun diverse Analyse auf Seite Mariadb durchgeführt.
Das Problem war scheinbar der Zugriff auf Tabelle current. Laut FhemWiki kann die bereinigt werden. Denn diese wird wieder neu aufgebaut.
Ich habe die Tabelle gelöscht und neu erstellt. Jetzt ist der Systemstart <60Sekunden  ;)

Vielen Dank für eure Unterstützung
RPi 3 - CUL 868 (Pigator) - ZWave (RaZberry2)
Homematic:HM-SEC-SC-2 / HM-SEC-SCo / HM-TC-IT-WM-W-EU / HM-ES-PMSw1-Pl-DN-R5
Z-Wave: FGR222 (010f-0302-1000) / FGS223 (010f-0203-1000) / FGD212 (010f-0102-1000) /FGKF601 (010f-1001-1000) / KeyFob / FGS212 (010f-0402-1002)

rudolfkoenig

ZitatDas Problem war scheinbar der Zugriff auf Tabelle current.
Ich lese und staune.

mig2

Das starten ist immer noch sehr schnell. Leider habe ich seit heute morgen zwei Devices verloren.
Davon ist auch die DBLOG betroffen. Ich habe versucht. configdb recover <version> die Version 6, welche noch den LogDB eintrag enthält zu aktiveren. Das hat funktioniert. Aber der Logdb Eintrag ist beim Neustart wieder verschwunden.
Nun habe ich versucht, anhand dem Eintrag aus der Version 6 (jetzt Version 7) diesen mit define zu erstellen
define logdb DbLog ./db.conf .*:.* > dies entspricht genau auch am Wiki Eintrag. Da kommt die Fehlermeldung " Error on reading ./db.conf from database!" Die db.conf ist identisch die Einstellung in configDB.conf.
Ich habe dann folgende define ausprobiert
define logdb DbLog ./db.conf .*:.*
define logdb DbLog /opt/fhem/db.conf .*:.*
define logdb DbLog ./configDB.conf .*:.*
define logdb DbLog /opt/fhem/configDB.conf .*:.*
Immer kommt die gleiche Meldung

Könnt Ihr mir da weiterhelfen?
RPi 3 - CUL 868 (Pigator) - ZWave (RaZberry2)
Homematic:HM-SEC-SC-2 / HM-SEC-SCo / HM-TC-IT-WM-W-EU / HM-ES-PMSw1-Pl-DN-R5
Z-Wave: FGR222 (010f-0302-1000) / FGS223 (010f-0203-1000) / FGD212 (010f-0102-1000) /FGKF601 (010f-1001-1000) / KeyFob / FGS212 (010f-0402-1002)