Fhem startet sehr langsam (3/4h)

[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

[Wernieman]

Gibt es bei den üblichen Verdächtigen Einträge? also kern.log, syslog o.Ä.

[mig2]

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

[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?

[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?

[betateilchen]

Mit Verbose 5 wurde nun viel in das Log geschrieben.

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.

[Wernieman]

Sind so viele Nachfragen von ConfigDB nach der uniqueID normal?

Code Auswählen Erweitern


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?

[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?

[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?

Hast Du geprüft, das Deine DB auf Deiner Synology sauber ist?

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

[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

[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

[rudolfkoenig]

Das 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

Code Auswählen Erweitern

define logdb DbLog ./db.conf .*:.*

Code Auswählen Erweitern

define logdb DbLog /opt/fhem/db.conf .*:.*

Code Auswählen Erweitern

define logdb DbLog ./configDB.conf .*:.*

Code Auswählen Erweitern

define logdb DbLog /opt/fhem/configDB.conf .*:.*
Immer kommt die gleiche Meldung

Könnt Ihr mir da weiterhelfen?

[DS_Starter]

Ich bin jetzt kein configDB User, deswegen muß ich mit meiner Aussage nicht unbedingt richtig liegen.
Aber das File "./db.conf" muß zunächst in der configDB lesbar vorliegen. Das kannst du mit  "configdb filelist" checken.
Das File "./db.conf" kannst du mit "configdb fileimport ./db.conf" in die configDB importieren wenn es nicht vorhanden ist.
Wenn du danach

Code Auswählen Erweitern


define logdb DbLog ./db.conf .*:.*


ausführst sollte es m.M. nach klappen.

[Beta-User]

Falls diese etwas diffuse Aussage des TE bedeuten soll, dass configDB und die DBLog-Daten in ein und derselben Datenbank liegen: Wo kommt die Empfehlung her, das so zu organisieren?

(habe nicht in die commandrefs geschaut, aber vielleicht wäre es eine gute Idee, jeweils darauf hinzuweisen, dass man das unbedingt getrennt halten sollte (falls das heute fehlt). Es gibt einige Fälle, die hier bereits aufgeschlagen waren, und das war eine häufige (mit-) Problemursache...).

[betateilchen]

Die db.conf ist identisch die Einstellung in configDB.conf.

Das bedeutet aber nicht, dass Du in beiden Fällen die gleiche Konfigurationsdatei verwenden kannst.

Die Konfigurationsdatei für die configDB wird IMMER aus dem Dateisystem gelesen, sonst kann keine Verbindung zur Datenbank aufgebaut werden, um überhaupt eine Konfiguration einlesen zu können.

Die Konfigurationsdatei für DbLog wird in dem Fall, in dem configDB verwendet wird, zu einem späteren Zeitpunkt während des FHEM Starts aus der Datenbank gelesen. Deshalb muss, wie DS_Starter beschrieben, dafür gesorgt sein, dass sich diese Datei auch tatsächlich in der Datenbank befindet.

(habe nicht in die commandrefs geschaut, aber vielleicht wäre es eine gute Idee, jeweils darauf hinzuweisen, dass man das unbedingt getrennt halten sollte (falls das heute fehlt). Es gibt einige Fälle, die hier bereits aufgeschlagen waren, und das war eine häufige (mit-) Problemursache...).

Im vorliegenden Fall haben wir aber eher ein logisches Problem als ein technisches Problem.
Wenn sich eine Konfigurationsdatei nicht in der Datenbank befindet, dann kann das DbLog device nicht angelegt werden.

Da hilft übrigens auch ein "configdb recover" nicht, weil sich das recover ausschließlich auf die Konfigurationseinträge bezieht und nicht auf gespeicherte Dateien in der configDB.

[betateilchen]

Das Problem war scheinbar der Zugriff auf Tabelle current.

kann man glauben, muss man aber nicht... 

[mig2]

Sorry das ich mich erst wieder jetzt melde, bin leider auf der Arbeit. Ich schaue mal. ob ich das

Das kannst du mit  "configdb filelist" checken.

nachvollziehen kann.
Warum dies verschwunden sein sollte, ist mir soweit nicht klar.
Aktuell sind die Startzeiten immer noch eine Wucht (<60Sek), hat ohne Logfiles in der DB  .

Sonst würde ich wohl um einen Neuaufbau nicht rumherum kommen. Aber mir war nicht klar, dass Configdb und logdb nicht auf der gleichen Db laufen sollten.

Morgen Abend werde ich sicher wieder mehr Inputs haben 

[mig2]

Ich habe nun wieder alles eingerichtet. Die Logdb musste das File wieder eingespielt werden und der TelegramBot war auch nicht mehr lauffähig.
Das ist alles gerichtet und die Startzeit ist jetzt rund bei 60 Sekunden 
Vielen Dank für die vielen Inputs