Cannot fork: Cannot allocate memory | BlockingInformParent

[DS_Starter]

Bezüglich DbLog bzw. Mem Leaks in Database Interface habe ich noch etwas im Internet gesucht. Gefunden habe ich ein paar bereits etwas ältere Hinweise auf solche Fälle. So wie ich es gelesen und verstanden habe, müsste in diesen Fällen ein permanenter Anstieg der Database Handles zu verzeichnen sein.

Ich habe eine neue Version von DbLog erstellt (4.7.0), mit der man einen solchen Anstieg erkennen kann wenn man betroffen sein sollte. Dazu gibt es ein Attribut "traceHandles" um das Monitoring einzuschalten.
Verwendung:

attr <DbLog> traceHandles <Sekunden>

Dann werden alle <Sekunden> die vohandenen Handles Systemweit ! im Logfile (verbose 1) ausgegeben.
Im Normalfall gibt es pro verwendeten Datanbanktyp ein Driverhandle und für jede DbLog-Instanz ein DatabaseHandle.
Das kann mal kurzzeitig schwanken, darf aber nicht permanent steigen !

Bei meinem Testsystem sieht es zum Beispiel so aus:

Code Auswählen Erweitern


2019.09.04 23:45:46.152 1: DbLog - traceHandles (system wide) - Driver: Pg, DriverHandle   : DBI::dr=HASH(0x55b3be3b8ae8)
2019.09.04 23:45:46.153 1: DbLog - traceHandles (system wide) - Driver: Pg, DatabaseHandle : DBI::db=HASH(0x55b3c2253f38)
2019.09.04 23:45:46.154 1: DbLog - traceHandles (system wide) - Driver: mysql, DriverHandle   : DBI::dr=HASH(0x55b3b9ac5740)
2019.09.04 23:45:46.154 1: DbLog - traceHandles (system wide) - Driver: mysql, DatabaseHandle : DBI::db=HASH(0x55b3c69eaef8)
2019.09.04 23:45:46.155 1: DbLog - traceHandles (system wide) - Driver: mysql, DatabaseHandle : DBI::db=HASH(0x55b3c69d2d40)
2019.09.04 23:45:46.156 1: DbLog - traceHandles (system wide) - Driver: SQLite, DriverHandle   : DBI::dr=HASH(0x55b3c6a14b88)
2019.09.04 23:45:46.156 1: DbLog - traceHandles (system wide) - Driver: SQLite, DatabaseHandle : DBI::db=HASH(0x55b3c6a16ee8)
2019.09.04 23:45:46.157 1: DbLog - traceHandles (system wide) - Driver: SQLite, DatabaseHandle : DBI::db=HASH(0x55b3c65d8d08)


Ich habe sowohl zwei Datenbanken vom Typ "SQLite", zwei Datenbanken vom Typ "MySQL" sowie eine Datenbank vom Typ "PostgreSQL" auf diesem System laufen. Alle im asynchronen Mode.
Wer mag, kann sich diese Version zunächst aus meinem contrib laden und das Verhalten auf seinem System checken. (Reload bzw. Restart nicht vergessen)

Sollte es einen stetigen Anstieg der Anzahl von DatabaseHandles geben, wäre etwas nicht ok.

Grüße,
Heiko

[rudolfkoenig]

@Hardlife: Da sind meines Geschmacks nach immer noch zuviele Daten von SVG und/oder FHEMWEB drin, ich habe aber nach eine Weile Code-Anstarren keine Idee, woran es liegen koennte. Wie ist plotfork/plotEmbed gesetzt fuer FHEMWEB?

[Hardlife]

Hi!

plotembedded habe ich nicht gesetzt - müsste also auf default=0 sein
plotfork steht auf "1"

LG,
Hardlife

[rudolfkoenig]

Kannst Du bitte pruefen, ob mit plotfork 0 dein Speicherproblem besteht?

[towag]

Seitdem ich die UNIFI-Komponenten deaktiviert habe ist der Speicherverbrauch moderat.
Ich helfe gerne im Detail zu suchen, wenn mir jemand einen Hinweis gibt was ich weiter tun könnte.

Der Spitzenreiter in den Memory-Dumps ist nach 3 Tagen Laufzeit der String "Assuming NOT a POSIX class"
Im Detail
"Assuming NOT a POSIX class since a semi-colon was found instead of a colon in regex; marked by <-- HERE in m/ group[ : <-- HERE ;]/"
"Assuming NOT a POSIX class since a semi-colon was found instead of a colon in regex; marked by <-- HERE in m/ group[ :; <-- HERE ]/"
Diese Strings kommen in Summe 280.000 Mal in den Heap-Segmenten vor.
Ich vermute, dass dies hiermit zu tun hat: https://rt.perl.org/Public/Bug/Display.html?id=130254

[Hardlife]

Kannst Du bitte pruefen, ob mit plotfork 0 dein Speicherproblem besteht?

gesagt - getan
Leider keine erkennbare Veränderung.

Anbei ein neuer Dump mit "plotfork 0"

--> Darin erkennbar:
       einige meiner SVG-Plots, die ich mir anzeigen lasse
       UND
       ziemlich viele Dummy und Geräte, bei denen ich SVG-Grafiken als Icon oder sonstwas verwende

Vielleicht besteht hier ein Zusammenhang?

LG,
Hardlife

[rudolfkoenig]

@towag:
- ich gehe davon aus, dass "Assuming.." auch ohne UNIFI Probleme verursacht.
- verwendest Du perl 5.24, wie im Link beschrieben? Kannst Du es mit einem anderen Perl Version testen?
- sieht man diesen String im FHEM-Log mit "attr global stacktrace 1" ?
- kannst du bitte "fhemdebug memusage" nach einem update (s.u.) ausfuehren?

@Hardlife:
- genau das habe ich in dem letzten dump auch gesehen
- SVG-Icons werden anderes behandelt, damit man diese einfaerben kann. Allerdings sehe ich in FW_makeImage kein Speicherloch.
- Wie oft am Tag holst du eine Seite von FHEMWEB ab?

Da zu meinem erstaunen "fhemdebug memusage" nichtmal die globale Variable $data angezeigt hat, habe ich es komplett umgebaut.
Es zeigt weiterhin nur global sichtbare Variablen an, aber hoffentlich diesmal vollstaendig.
Man kann "weiterbohren", indem man das Angezeigte als Argument angibt.

[towag]

1) ja genau: das war die Auswertung nach 3 Tagen ohne UNIFI und Restart nach Config-Änderung

2) perl -v
This is perl 5, version 24, subversion 1 (v5.24.1) built for arm-linux-gnueabihf-thread-multi-64int
(with 85 registered patches, see perl -V for more detail)
Ich habe mir bisher nicht angeschaut wie ich auf dem Standard Stretch eine andere Perl-Version zum Laufen bekomme

3) Ich hatte das Attribut bereits gesetzt gehabt - diese Strings sind nicht im Log-File

4) ich habe heute Abend ein Update von FHEM gemacht.
Vor dem Update hat "fhemdebug memusage" noch einen Output geliefert, jetzt steht im syslog nur mehr
"Sep 07 20:30:18 coruscant systemd[1]: fhem.service: Main process exited, code=killed, status=11/SEGV"
und meine systemd-Überwachung startet eine neue Instanz

[Hardlife]

- Wie oft am Tag holst du eine Seite von FHEMWEB ab?

Hmm, leider eine schwierige Frage....
Sicher unzählige Male, da wie beschrieben 6 Tablets ständig mit FHEM verbunden sind und deren Browser (WebViewControl) die Seiten im Intervall X aktualisieren.
Auch greifen ich und meine Freundin mit unseren Handys insgesamt ca 10 - 20 mal auf FHEM zu.

LG,
Hardlife

[rudolfkoenig]

This is perl 5, version 24, subversion 1 (v5.24.1) built for arm-linux-gnueabihf-thread-multi-64int

Das ist laut deinem Link auch die beanstandete Version, ich wuerde versuchen, eine andere/neue Version zu installieren.

"Sep 07 20:30:18 coruscant systemd[1]: fhem.service: Main process exited, code=killed, status=11/SEGV"

Seufz. Da hat man die Wahl zwischen nichtssagenden Output oder eins, was abstuerzt.
Ich habe jetzt weitere Ausgaben bei "attr global verbose 5" in fhemdebug memusage eingebaut (update ab morgen), wenn Du Lust hast beim Lokalisieren des Absturzes zu helfen, dann bitte hier die Ausgabe anhaengen.

[Skusi]

Nur mal eben so zwischendurch:

Ich habe die Änderungen in FehmWeb zum Anlass genommen und testweise mal wieder das echodevice Modul installiert.
Seit dem wieder wie eh und jeh ca 20MB / Tag Speicher Anstieg.

Also hau ich das erstmal wieder raus. Dann ist alles stabil !

[sig10680]

Nur mal eben so zwischendurch:

Ich habe die Änderungen in FehmWeb zum Anlass genommen und testweise mal wieder das echodevice Modul installiert.
Seit dem wieder wie eh und jeh ca 20MB / Tag Speicher Anstieg.

Also hau ich das erstmal wieder raus. Dann ist alles stabil !

Hallo,

ich beobachte das Echodevice Modul seit einiger Zeit. Wenn ich das FHEM mit dem Modul laufen lasse benötige ich nach knapp 5 Tagen einen Neustart. Jetzt mal zum Test FHEM ohne Echodevice Modul läuft es schon seit ca.6 Wochen ohne jegliche Probleme. Ich habe am System Nichts verändert, auch kein FHEM Update!

MFG Sig10680

[Skusi]

Ich bin froh, das bei mir klar ist woran es liegt und ich nur auf das Echo Modul verzichten muß um einen stabilen Speicherverbraucht  zu haben. Ich lese hier schon lange mit, und habe Mitleid mit denen die den Grund noch nicht kennen. Nur schade das keiner rausfindet warum z. B. das Echomeodul diese Probleme verursacht. Ich würde das Modul sehr gerne wieder benutzen können.

[GSK19]

Ich bin froh, das bei mir klar ist woran es liegt und ich nur auf das Echo Modul verzichten muß um einen stabilen Speicherverbraucht  zu haben. Ich lese hier schon lange mit, und habe Mitleid mit denen die den Grund noch nicht kennen. Nur schade das keiner rausfindet warum z. B. das Echomeodul diese Probleme verursacht. Ich würde das Modul sehr gerne wieder benutzen können.

Kann ich bei meinem System nicht ganz bestätigen. Bei uns wird der Echo nur zur Ausgabe genutzt (also set ... tunein und set ...  speak_ssml ), und damit läuft alles seit einiger Zeit stabil. Vorher hatten wir einen Speicheranstieg, der das System nach 18 Stunden gekillt hat, aber das lag an einem deaktivierten Freezemon-Device. Nachdem das gelöscht (und nicht nur deaktiviert) war, ist der Speicherbedarf absolut konstant.

[der-Lolo]

Hm, heute morgen habe ich ein Update gemacht - seitdem "Toi-Toi-Toi" ist der RAM bedarf stabil.

Und ja lieber CoolTux - es war FHEM, ich habe das problem schon länger gehabt - lange Zeit auch versucht zu analysieren, leider erfolglos.

Gestern machte ich auch ein Update, keine ahnung was jetzt zwischen gestern und heute geändert wurde - aber 10.000 Dank dafür...
So kann FHEM wohl endlich wieder etwas mehr unattended laufen

Code Auswählen Erweitern

2019.09.09 07:23:56 1: update finished, "shutdown restart" is needed to activate the changes.
2019.09.09 07:23:56 1:
2019.09.09 07:23:15 1: Calling /volume1/@entware/ActivePerl-5.24/bin/perl-static ./contrib/commandref_join.pl -noWarnings, this may take a while
2019.09.09 07:23:15 1: nothing to do...
2019.09.09 07:23:15 1: homeconnect
2019.09.09 07:23:15 1:
2019.09.09 07:23:15 1:
2019.09.09 07:23:15 1: nothing to do...
2019.09.09 07:23:15 1: fhemdeparture
2019.09.09 07:23:15 1:
2019.09.09 07:23:15 1:
2019.09.09 07:23:15 1: ... rest of lines skipped.
2019.09.09 07:23:15 1:               added combineReads
2019.09.09 07:23:15 1:               check if request is already in rqueue
2019.09.09 07:23:15 1:               added timeout message
2019.09.09 07:23:15 1:               added ModbusRTU_CalcNextUpdate
2019.09.09 07:23:15 1:   150314 0008 fixed typo in attribute name pollIntervall
2019.09.09 07:23:15 1: 36_ModbusRTU:
2019.09.09 07:23:15 1:                                                                                                  .   
2019.09.09 07:23:15 1: all changes:
2019.09.09 07:23:15 1:                                                                                                  .   
2019.09.09 07:23:15 1:   180206 0024 added DATE
2019.09.09 07:23:15 1: 37_ModbusRegister:
2019.09.09 07:23:15 1:               fix Wago DO address calculation
2019.09.09 07:23:15 1:               documentation update
2019.09.09 07:23:15 1:               fixed access to Wago PFC area
2019.09.09 07:23:15 1:   170106 0014 added writeMode SetReset
2019.09.09 07:23:15 1: 37_ModbusCoil:
2019.09.09 07:23:15 1:   181107 0022 changed detection of wago plc
2019.09.09 07:23:15 1:   190906 0023 added (empty) fingerprint
2019.09.09 07:23:15 1: 36_ModbusTCPServer:
2019.09.09 07:23:15 1:               added support for coils
2019.09.09 07:23:15 1:               added combineReads
2019.09.09 07:23:15 1:               check if request is already in rqueue
2019.09.09 07:23:15 1:               added timeout message
2019.09.09 07:23:15 1:               added ModbusRTU_CalcNextUpdate
2019.09.09 07:23:15 1:   150314 0008 fixed typo in attribute name pollIntervall
2019.09.09 07:23:15 1: 36_ModbusRTU:
2019.09.09 07:23:15 1: New entries in the CHANGED file:
2019.09.09 07:23:15 1:
2019.09.09 07:23:15 1: saving ./log/fhem.save
2019.09.09 07:23:14 1: UPD FHEM/36_ModbusTCPServer.pm
2019.09.09 07:23:14 1: modbus
2019.09.09 07:23:14 1:
2019.09.09 07:23:14 1:
2019.09.09 07:23:14 1:  - feature:     30_tradfri: blind support
2019.09.09 07:23:14 1: New entries in the CHANGED file:
2019.09.09 07:23:14 1:
2019.09.09 07:23:14 1: saving ./log/fhem.save
2019.09.09 07:23:14 1: UPD www/images/fhemSVG/tradfri_gateway.svg
2019.09.09 07:23:14 1: UPD FHEM/firmware/JeeLink_LaCrosseGateway.bin
2019.09.09 07:23:14 1: UPD FHEM/98_fhemdebug.pm
2019.09.09 07:23:14 1: UPD FHEM/31_HUEDevice.pm
2019.09.09 07:23:14 1: UPD FHEM/30_tradfri.pm
2019.09.09 07:23:14 1: UPD ./configDB.pm
2019.09.09 07:23:13 1: UPD ./CHANGED
2019.09.09 07:23:13 1: RMDIR: ./restoreDir/update/2019-08-31
2019.09.09 07:23:13 1: fhem
2019.09.09 07:23:13 1:

Bei mir also vermutlich einer der Kandidaten die heute morgen ein Update bekommen haben.