[gelöst] Optimierung Dauer von "save config"

[FhemPiUser]

Ich habe inzwischen so viele devices (>1000) und eine so große fhem.cfg (wc -l sagt >7300 Zeilen; dazu kommen noch 2300 Zeilen myUtils), dass ein "save config" auf meinem Raspberry Pi 3B inzwischen ca. 1,5 min dauert und in der Zeit fhem blockiert, was sehr unschön ist.

Kann jemand erläutern, was genau beim "save config" so lange dauert bzw. was ist der Bottleneck und welche Möglichkeiten gibt es dies zu beschleunigen?

Ist der Bottleneck das Schreiben auf SD-Karte, sodass eine schnellere SD-Karte (aktuell: Sandisk Ultra 32GB Klasse 10 U1; Aufrüsten auf Sandisk Extreme oder Extreme Pro wäre möglich) oder ein Buffern im RAM beim Schreiben auf SD-Karte hilft?

Oder ist es eher das Verarbeiten der Daten, sodass ein schnellerer RPI (RPI4) oder mehr RAM hilft?

Oder bringt eine Umstellung auf configdb einen Geschwindigkeitssprung? Ist man vielleicht ab einer bestimmten Größe der fhem.cgf einfach gezwungen auf configdb umstellen? Ich habe mich vor configdb bisher gescheut und würde gerne bei der fhem.cfg bleiben, wenn möglich...

[MadMax-FHEM]

Wie bearbeitest du die fhem.cfg vor dem Speichern?

Manuell?
Dann ist save config inkl. rereadconfig (soweit ich weiß)...

Hast du Module, die ein rereadconfig verzögern (können, so ich richtig liege), z.B. alexa-fhem?

myUtils hat mit save config (mWn) nichts zu tun...

Ich habe 6491 Zeilen (extra "für dich" gezählt) und 686 "Entitäten" und 5007 Zeilen myUtils und bei mir geht es "ratzfatz" und das auf einem PI3...

Allerdings bearbeite ich nur über die Oberfläche, also Eingabezeile oder Device-Detail, max. noch per Raw-Definition... Auch per Edit-Files ist manuelles Bearbeiten...

Woher weißt du, dass es so lange dauert!?

Gruß, Joachim

[FhemPiUser]

Es dauert schon so lange, wenn ich in der Fhem GUI einfach ein attr ändere und danach auf "save config" klicke. Dann blockiert fhem und die GUI ist für 1,5min nicht mehr erreichbar. Mein Dienst zur Überwachung von fhem schlägt auch Alarm, dass fhem nicht mehr erreichbar ist.

Ich sehe die 1,5min auch in der log-Datei

Im Log kommt:

Code Auswählen Erweitern

2020.10.16 18:44:39.018 1: RMDIR: ./restoreDir/save/2020-08-17
2020.10.16 18:46:12.890 1: 192.168.1.127:3493 disconnected, waiting to reappear (nut)
2020.10.16 18:46:14.043 1: 192.168.1.127:3493 reappeared (nut)

(Was macht er eigentlich bei "RMDIR"? Kann das so lange dauern?)

Woher weiß ich denn, welche Module ein "rereadconfig" verzögern? alexa-fhem habe ich nicht (grep "alexa" fhem.cfg liefert keine Ergebnisse).

[rudolfkoenig]

Save an sich macht kaum was, und sollte selbst auf einem langsamen Rechner in <1s durchgefuehrt werden. Es generiert ein SAVE Event, notify/DOIF/etc Konstrukte, die darauf triggern, koennen eine Bremse sein.

rereadcfg greift dann, wenn man fhem.cfg im Browser editiert, das ist de-facto ein FHEM Neustart.
Je nach Anzahl und Art der Geraete kann ein Neustart schon dauern, auf meinem Produktivsystem im Bereich von 100 Definitionen/500 fhem.cfg Zeilen pro Sekunde.

[Otto123]

(Was macht er eigentlich bei "RMDIR"? Kann das so lange dauern?)

Hi,

er löscht den ältesten ./restoreDir/save Pfad. (weil "er" ja einen neuen schreibt und per nrarchive eine bestimmte Anzahl Pfade vorhält) Siehe auch Doku von save https://fhem.de/commandref_DE.html#save

Ist Dein Pfad irgendwo auf dem Weg "HomeDir restoreDir save" in den "Honigtopf" gemappt?
Hast Du irgendwas, was auf das Löschen Pfades oder das save Kommando anspringt und 1,5 min was tut?

Gruß Otto

[FhemPiUser]

hmm, ich habe notifies auf "global:INITIALIZED", aber das wird nicht bei "save config" ausgelöst, oder?

Auf ein "save" event habe ich kein notify/DOIF o.ä.  Ein grep "save" fhem.cfg liefert da auch nichts dergleichen.

Wird ein "rereadcfg" ausgeführt beim Klicken auf "Save config" in der GUI nach Editieren eines attr in der GUI (nicht im Texteditor der GUI)?

[Otto123]

Wird ein "rereadcfg" ausgeführt beim Klicken auf "Save config" in der GUI nach Editieren eines attr in der GUI (nicht im Texteditor der GUI)?

Nein, rereadcfg oder neustart würdest Du ja auch sehen im Log.

[FhemPiUser]

Ich habe mal in global verbose auf 5 gestellt und dann "save config" geklickt. Folgendest erscheint im Log:

Code Auswählen Erweitern

2020.10.17 18:51:36.603 5: Cmd: >save<
2020.10.17 18:51:36.606 5: Starting notify loop for global, 1 event(s), first is SAVE
2020.10.17 18:51:36.606 5: statistics AussentemperaturStatistik: Notify.280 Notification of 'global' received. Device not monitored.
2020.10.17 18:51:36.607 5: statistics AussentemperaturStatistik_tendency: Notify.280 Notification of 'global' received. Device not monitored.
2020.10.17 18:51:36.608 5: statistics CO20_Statistics: Notify.280 Notification of 'global' received. Device not monitored.
2020.10.17 18:51:36.608 5: statistics Drainage_Statistics: Notify.280 Notification of 'global' received. Device not monitored.
2020.10.17 18:51:36.609 5: statistics Drainage_backup_Statistics: Notify.280 Notification of 'global' received. Device not monitored.
2020.10.17 18:51:36.609 5: statistics stat_Windsensor: Notify.280 Notification of 'global' received. Device not monitored.
2020.10.17 18:51:36.616 5: AptToDate (SysAptInfo) - Notify: $VAR1 = [
          'SAVE'
        ];

2020.10.17 18:51:36.645 5: r_wochenprogramme: not on any display, ignoring notify
2020.10.17 18:51:36.645 5: rg_battery: not on any display, ignoring notify
2020.10.17 18:51:36.646 5: rg_battery_ftui: not on any display, ignoring notify
2020.10.17 18:51:36.646 5: rg_boe: not on any display, ignoring notify
2020.10.17 18:51:36.647 5: rg_dead: not on any display, ignoring notify
2020.10.17 18:51:36.647 5: rg_httpmod_sensitivity: not on any display, ignoring notify
2020.10.17 18:51:36.647 5: rg_missingAck: not on any display, ignoring notify
2020.10.17 18:51:36.648 5: rg_motionIndicator: not on any display, ignoring notify
2020.10.17 18:51:36.648 5: rg_seqnodiffs: not on any display, ignoring notify
2020.10.17 18:51:36.665 5: End notify loop for global
2020.10.17 18:53:05.797 4: WEB: /fhem?cmd=save&XHR=1&fwcsrf=xxx&fw_id=xxx/ RL:52 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/ Cache-Control: no-cache, no-store, must-revalidate


Eine durch notify/DOIF etc. getriggerte Aktion scheint es nicht zu sein, denn der lange Delay kommt nach "end notify loop". Allerdings logt er dann auch nichts in den 1,5min nach dem "end notify loop" und vor dem WEB-Kommando.

Jemand eine Idee, was er da machen könnte oder wie ich herausfinden kann, was er in den 1,5min macht?

[FhemPiUser]

...kann es sein, dass mein fhem RPI3B mit 1GB zu wenig RAM hat und er beim "Save config" auf SD Karte swapped und das die Ursache für die Verzögerung ist?

free liefert:

Code Auswählen Erweitern


              total        used        free      shared  buff/cache   available
Mem:         948304      320720      250628       36536      376956      528836
Swap:        102396       90920       11476


Mich wundert, dass bei swap "used" >0 steht

[amenomade]

Nutzt Du configDB oder fhem.cfg?

[FhemPiUser]

fhem.cfg und wollte eigentlich auch dabei bleiben, wie oben gechrieben.

oder geht es ab einer bestimmten größe nur noch mit configdb?

[MadMax-FHEM]

Hat mit der Größe nichts zu tun.
Meine ist ja ähnlich groß und kein Problem...

Auch nicht mit swap...
Und ist (auch) nur ein PI mit 1GB...

Was läuft denn sonst noch?

Lite oder mit Desktop?
Hast du die "Speicherverteilung" angepasst?
Ich hab für Grafik 16MB (habe ja keinen Desktop, sondern nur Lite)...
Glaube aber nicht, dass es (nur) daran liegt...

Evtl. eher interessant was noch läuft...

Gruß, Joachim

[amenomade]

fhem.cfg und wollte eigentlich auch dabei bleiben, wie oben gechrieben.

oder geht es ab einer bestimmten größe nur noch mit configdb?

Nein, zum Gegenteil. Mit einer grossen Konfig und sqlite auf einem pi ist es eher langsamer mit configdb.

[FhemPiUser]

Hat mit der Größe nichts zu tun.
Meine ist ja ähnlich groß und kein Problem...

Auch nicht mit swap...
Und ist (auch) nur ein PI mit 1GB...

Was läuft denn sonst noch?

Lite oder mit Desktop?
Hast du die "Speicherverteilung" angepasst?
Ich hab für Grafik 16MB (habe ja keinen Desktop, sondern nur Lite)...
Glaube aber nicht, dass es (nur) daran liegt...

Evtl. eher interessant was noch läuft...

Gruß, Joachim

läuft sonst nur noch mosquito und sendmail. den speicher verbraucht fhem...

wie kann ich denn die speicherverteilung anpassen?

[MadMax-FHEM]

sudo raspi-config

Aber wie geschrieben: das wird nicht wirklich groß helfen...

Raspbian Lite oder mit Desktop?

Gruß, Joachim

[FhemPiUser]

ja, 48mb mehr bringen nicht viel.

mein raspian sollte lite sein...

[betateilchen]

Das Problem ist höchstwahrscheinlich in FHEM zu suchen, nicht im Betriebssystem oder in der Hardware.

Was ich als erstes machen würde: alle devices in FHEM deaktivieren, die exzessiv mit Betriebssystemaufrufen arbeiten.

Beobachte doch mal mit top in einem offenen Fenster auf dem pi, ob dort irgendwelche Auffälligkeiten passieren, wenn Du in FHEM ein save ausführst.

[FhemPiUser]

Ich habe mal "save config" gedrückt und parallel mit htop geschaut:

Der fhem-Hauptprozess geht auf 100% (in der Anzeige oben geht auch nur einer der 4 Prozessoren auf 100%).

Gleichzeitig vermehren sich die fhem-Prozesse auf 6 (Update: Das scheint an den "ping"-devices zu liegen und nicht die Ursache zu sein: Wenn ich alle "ping"-devices deaktiviere werden keine neuen Prozesse gestartet. Die CPU geht aber trotzdem auf 100% und fhem blockiert trotzdem für 1,5min)

Nach 1,5min normalisiert sich die Situation wieder und es gibt nur noch 1 fhem-Prozess, der 23,7% Memory benötigt und kaum CPU.

Es scheint also kein RAM, sondern ein CPU-Problem zu sein.

Gibt es eine Möglichkeit die CPU/RAM-Nutzung der einzelnen fhem-devices auszuwerten?

[FhemPiUser]

Ich habe es: Ich habe mein snips/MQTT devices in fhem gelöscht, ein fhem update all ausgeführt, neu gestartet und jetzt geht das "save config" schnell...

Es scheint also an den snips / mqtt devices gelegen zu haben, bei dem die gegenstelle der mqtt nicht mehr da ist, da ich snips nicht mehr verwende...

[rudolfkoenig]

Kannst Du bitte das Problem mit dem angehaengten fhem.pl nachstellen, und den FHEM-Log-Ausschnitt hier anhaengen?

Welchen Typ hat snipsMQTT ?

[FhemPiUser]

das war ein MQTT-Device und ein SNIPS-Device (http://snips.ai):

Code Auswählen Erweitern

define SnipsMQTT MQTT 192.168.1.xx:xx
setuuid SnipsMQTT xx
attr SnipsMQTT room Snips
define Snips SNIPS SnipsMQTT Wohnzimmer
setuuid Snips xxx
attr Snips IODev SnipsMQTT
attr Snips room Snips

Ich versuche es mal nachzustellen. Noch kann ich nicht zu 100% sagen, ob das die Ursache war oder einfach das fhem Update oder der Neustart. Ich hatte vorher mein fhem >6 Monate nicht neu gestartet....

[FhemPiUser]

Ich habe gerade versucht es nachzustellen, leider ohne Erfolg.

Nachdem ich die Snips devices wieder eingerichtet habe, geht das save config noch immer schnell (wobei ich die setuid Kommandos nicht ausführen konnte und daher weglassen musste)

Es muss also wohl mit dem fhem Update/Neustart zu tun gehabt haben, kann aber jetzt nicht das update rückgängig machen.

Meine Systemversion vorher:
- fhem.pl-Version war 20415 2019-10-27 17:23:55Z
- 01_FHEMWEB.pm 22632 2020-08-19 17:02:35Z

Evtl. ist es auch ein (kleines) Memory-Leak in irgendeinem Device, was erst nach mehreren Monaten fhem runtime bemerkbar ist und bei einem save config zum swap führt. Denn der Memory-Verbrauch ist bei mir jetzt niedriger seit dem update/neustart. Wobei das eigentlich nicht die Ursache sein kann, da ich keinen größeren IO-Traffic zur SD-Karte gesehen hatte in den 1,5min...

Habe jetzt auch nochmal den Raspberry neu gebootet udn der GPU nur 16MB gegeben

free -m sagt jetzt:

Code Auswählen Erweitern

              total        used        free      shared  buff/cache   available
Mem:            975         148         719           6         107         768
Swap:            99           0          99



"used mem" war vorher etwa doppelt so hoch...

Ich richte jetzt ein DOIF auif sysmon swap used mit Benachrichtigung ein, damit ich weiß, wenn der Swap mal wieder verwendet wird...

[betateilchen]

Das Problem ist höchstwahrscheinlich in FHEM zu suchen, nicht im Betriebssystem oder in der Hardware.

Ich habe es: Ich habe mein snips/MQTT devices in fhem gelöscht, ein fhem update all ausgeführt, neu gestartet und jetzt geht das "save config" schnell...

q.e.d.

[FhemPiUser]

Hier der Beweis: Log-Output mit global verbose auf 5:

Code Auswählen Erweitern

2020.10.18 13:09:40.541 5: Cmd: >save<
2020.10.18 13:09:40.542 5: Starting notify loop for global, 1 event(s), first is SAVE
2020.10.18 13:09:40.542 5: createNotifyHash
2020.10.18 13:09:40.630 5: statistics AussentemperaturStatistik: Notify.280 Notification of 'global' received. Device not monitored.
2020.10.18 13:09:40.630 5: statistics AussentemperaturStatistik_tendency: Notify.280 Notification of 'global' received. Device not monitored.
2020.10.18 13:09:40.631 5: statistics CO20_Statistics: Notify.280 Notification of 'global' received. Device not monitored.
2020.10.18 13:09:40.631 5: statistics Drainage_Statistics: Notify.280 Notification of 'global' received. Device not monitored.
2020.10.18 13:09:40.631 5: statistics Drainage_backup_Statistics: Notify.280 Notification of 'global' received. Device not monitored.
2020.10.18 13:09:40.632 5: statistics stat_Windsensor: Notify.280 Notification of 'global' received. Device not monitored.
2020.10.18 13:09:40.636 5: AptToDate (SysAptInfo) - Notify: $VAR1 = [
          'SAVE'
        ];

2020.10.18 13:09:40.658 5: r_wochenprogramme: not on any display, ignoring notify
2020.10.18 13:09:40.659 5: rg_battery: not on any display, ignoring notify
2020.10.18 13:09:40.659 5: rg_battery_ftui: not on any display, ignoring notify
2020.10.18 13:09:40.659 5: rg_boe: not on any display, ignoring notify
2020.10.18 13:09:40.659 5: rg_dead: not on any display, ignoring notify
2020.10.18 13:09:40.660 5: rg_httpmod_sensitivity: not on any display, ignoring notify
2020.10.18 13:09:40.660 5: rg_missingAck: not on any display, ignoring notify
2020.10.18 13:09:40.660 5: rg_motionIndicator: not on any display, ignoring notify
2020.10.18 13:09:40.660 5: rg_seqnodiffs: not on any display, ignoring notify
2020.10.18 13:09:40.670 5: End notify loop for global
2020.10.18 13:09:40.809 4: PROPLANTA proplanta: HtmlAcquire.594 345257 characters captured
2020.10.18 13:09:40.837 4: PROPLANTA proplanta: Run.703 Start HTML parsing of captured page
2020.10.18 13:09:41.011 4: WEB: /fhem?cmd=save&XHR=1&fwcsrf=xxx&fw_id=5771 / RL:52 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/ Cache-Control: no-cache, no-store, must-revalidate


Das config save hat jetzt also ca. 500ms gedauert, war voher 1,5min...