Cannot fork: Cannot allocate memory | BlockingInformParent

[towag]

Output von MemUsage

2019.09.09 18:41:00 4: WEB_192.168.1.242_54097 POST /fhem&fw_id=1670&cmd=fhemdebug+memusage; BUFLEN:0
2019.09.09 18:41:00 5: Cmd: >fhemdebug memusage<
2019.09.09 18:41:00 4: SyslogMgmt - Payload sequence 248 created:
<47>1 2019-09-09T18:41:00 myhost.mydomain.at SyslogMgmt_fhem 248 FHEM [version@Log2Syslog version="5.8.2"] 5: Cmd: >fhemdebug memus ...
2019.09.09 18:41:00 4: Log2Syslog SyslogMgmt - Payload sequence 248 sent

2019.09.09 18:41:00 5: Loading ./FHEM/98_fhemdebug.pm
2019.09.09 18:41:00 4: SyslogMgmt - Payload sequence 249 created:
<47>1 2019-09-09T18:41:00 myhost.mydomain.at SyslogMgmt_fhem 249 FHEM [version@Log2Syslog version="5.8.2"] 5: Loading ./FHEM/98_fhe ...
2019.09.09 18:41:00 4: Log2Syslog SyslogMgmt - Payload sequence 249 sent

2019.09.09 18:41:00 5: Memusage checking selectTimestamp
2019.09.09 18:41:00 4: SyslogMgmt - Payload sequence 250 created:
<47>1 2019-09-09T18:41:00 myhost.mydomain.at SyslogMgmt_fhem 250 FHEM [version@Log2Syslog version="5.8.2"] 5: Memusage checking sel ...
2019.09.09 18:41:00 4: Log2Syslog SyslogMgmt - Payload sequence 250 sent

2019.09.09 18:41:00 5: Memusage checking DbRep_vNotesExtern
2019.09.09 18:41:00 4: SyslogMgmt - Payload sequence 251 created:
<47>1 2019-09-09T18:41:00 myhost.mydomain.at SyslogMgmt_fhem 251 FHEM [version@Log2Syslog version="5.8.2"] 5: Memusage checking DbR ...
2019.09.09 18:41:00 4: Log2Syslog SyslogMgmt - Payload sequence 251 sent

2019.09.09 18:41:00 5: Memusage checking DATEI
2019.09.09 18:41:00 4: SyslogMgmt - Payload sequence 252 created:
<47>1 2019-09-09T18:41:00 myhost.mydomain.at SyslogMgmt_fhem 252 FHEM [version@Log2Syslog version="5.8.2"] 5: Memusage checking DAT ...
2019.09.09 18:41:00 4: Log2Syslog SyslogMgmt - Payload sequence 252 sent

2019.09.09 18:41:00 5: Memusage checking LOG
2019.09.09 18:41:00 4: SyslogMgmt - Payload sequence 253 created:
<47>1 2019-09-09T18:41:00 myhost.mydomain.at SyslogMgmt_fhem 253 FHEM [version@Log2Syslog version="5.8.2"] 5: Memusage checking LOG ...
2019.09.09 18:41:00 4: Log2Syslog SyslogMgmt - Payload sequence 253 sent

2019.09.09 18:41:00 5: Memusage checking oldvalue
2019.09.09 18:41:00 4: SyslogMgmt - Payload sequence 254 created:
<47>1 2019-09-09T18:41:00 myhost.mydomain.at SyslogMgmt_fhem 254 FHEM [version@Log2Syslog version="5.8.2"] 5: Memusage checking old ...
2019.09.09 18:41:00 4: Log2Syslog SyslogMgmt - Payload sequence 254 sent

2019.09.09 18:41:00 5: Memusage checking lastWarningMsg
2019.09.09 18:41:00 4: SyslogMgmt - Payload sequence 255 created:
<44>1 2019-09-09T18:41:00 myhost.mydomain.at SyslogMgmt_fhem 255 FHEM [version@Log2Syslog version="5.8.2"] 5: Memusage checking las ...
2019.09.09 18:41:00 4: Log2Syslog SyslogMgmt - Payload sequence 255 sent

2019.09.09 18:41:00 5: Memusage checking DoInitDev
2019.09.09 18:41:00 4: SyslogMgmt - Payload sequence 256 created:
<47>1 2019-09-09T18:41:00 myhost.mydomain.at SyslogMgmt_fhem 256 FHEM [version@Log2Syslog version="5.8.2"] 5: Memusage checking DoI ...
2019.09.09 18:41:00 4: Log2Syslog SyslogMgmt - Payload sequence 256 sent

2019.09.09 18:41:00 5: Memusage checking SVG_zoomLink
2019.09.09 18:41:00 4: SyslogMgmt - Payload sequence 257 created:
<47>1 2019-09-09T18:41:00 myhost.mydomain.at SyslogMgmt_fhem 257 FHEM [version@Log2Syslog version="5.8.2"] 5: Memusage checking SVG ...
2019.09.09 18:41:00 4: Log2Syslog SyslogMgmt - Payload sequence 257 sent

2019.09.09 18:41:00 5: Memusage checking defs
2019.09.09 18:41:00 4: SyslogMgmt - Payload sequence 258 created:
<47>1 2019-09-09T18:41:00 myhost.mydomain.at SyslogMgmt_fhem 258 FHEM [version@Log2Syslog version="5.8.2"] 5: Memusage checking def ...
2019.09.09 18:41:00 4: Log2Syslog SyslogMgmt - Payload sequence 258 sent

[DS_Starter]

@Rudi, habe das neue "fhemdebug memusage" gerade mal getestet.
FHEM startet nach dem Aufruf zügig neu:

Code Auswählen Erweitern


....
2019.09.09 20:54:11.078 5: Cmd: >fhemdebug memusage<
2019.09.09 20:54:11.082 5: Memusage checking DbRep_vNotesIntern
2019.09.09 20:54:11.083 5: Memusage checking FW_icons
2019.09.09 20:54:11.084 5: Memusage checking HMinfo_templateMark
2019.09.09 20:54:11.084 5: Memusage checking FW_types
2019.09.09 20:54:11.085 5: Memusage checking FH1
2019.09.09 20:54:11.085 5: Memusage checking GetInfoType
2019.09.09 20:54:11.086 5: Memusage checking LOG
2019.09.09 20:54:11.086 5: Memusage checking FW_RETTYPE
2019.09.09 20:54:11.086 5: Memusage checking FW_formmethod
2019.09.09 20:54:11.087 5: Memusage checking currlogfile
2019.09.09 20:54:11.088 5: Memusage checking FW_httpheader
2019.09.09 20:54:11.088 5: Memusage checking lastWarningMsg
2019.09.09 20:54:11.088 5: Memusage checking structChangeHist
2019.09.09 20:54:11.089 5: Memusage checking readytimeout
2019.09.09 20:54:11.089 5: Memusage checking FW_ME
2019.09.09 20:54:11.090 5: Memusage checking DH
2019.09.09 20:54:11.090 5: Memusage checking oldvalue
2019.09.09 20:54:11.091 5: Memusage checking FH3
2019.09.09 20:54:11.091 5: Memusage checking FW_gplotdir
2019.09.09 20:54:11.092 5: Memusage checking DoInitDev
2019.09.09 20:54:11.092 5: Memusage checking _
2019.09.09 20:54:11.093 5: Memusage checking :
2019.09.09 20:54:11.093 5: Memusage checking RESIDENTStk_subTypes
2019.09.09 20:54:11.093 5: Memusage checking SMAInverter_vNotesIntern
2019.09.09 20:54:11.094 5: Memusage checking fhemForked
2019.09.09 20:54:11.094 5: Memusage checking SSCam_vHintsExt_de
2019.09.09 20:54:11.095 5: Memusage checking FILE
2019.09.09 20:54:11.095 5: Memusage checking ISA
2019.09.09 20:54:11.095 5: Memusage checking SIG
2019.09.09 20:54:11.097 1: PERL WARNING: Devel::Size: Unknown variable type: 244 encountered
2019.09.09 20:54:11.358 1: Including fhem.cfg
2019.09.09 20:54:11.369 3: telnetPort: port 7072 opened
2019.09.09 20:54:11.443 3: WEB: port 8083 opened
...


Die Stelle des Neustarts bzw. Nummern nach "Unknown variable type" sind variabel. Es können auch mehrere Warnings oder auch keine Warnings auftreten bevor der Neustart ausgeführt wird.

Grüße,
Heiko

[rudolfkoenig]

Es schaut so aus, dass Devel::Size schwer kaputt ist.
Vermutlich muss man es selbst bauen.
Seufz.

[rudolfkoenig]

Ich habe fhemdebug memusage entfernt, da ich keine Version hingekriege, was nicht abstuerzt und trotzdem was Sinnvolles anzeigt.

[DS_Starter]

Mir hat das ganze Thema keine Ruhe gelassen und habe angefangen den Speicherverbrauch meiner Module zu analysieren.
Dabei habe in SSCam einen unnötigen Speicherverbrauch festgestellt.
Es ist zwar kein richtiger Mememory-Leak, aber trotzdem unschön. Er kam zum Tragen wenn man sich Aufnahmen zugeschickt hat.
Die Daten verblieben dann im Speicher.
Darauf gekommen bin ich, weil ich eigene Hashes im lokalen Kontext definiert und darauf referenziert hatte was ich ändern
wollte.

Nach der Umstellung aller dieser Variablen auf das zentrale %data-Hash (hatte ich überhaupt nicht auf meinem Radar) konnte ich die Strukturen besser untersuchen.
Dazu habe ich mir ein kleines Programm in der 99_myUtils erstellt. Es funktioniert ähnlich dem memusage von Rudi.
Wer es nachnutzen möchte, kann es sich im Anhang herunterladen und in seine 99_myUtils kopieren.

Damit kann man nun seine eventuell verdächtigen Devices näher untersuchen oder in den zentralen %data Hash schauen.
Mit diesem Hilfsmittel konnte ich nun den Memorykonsum von SSCam-Devices im Extremfall auf 1/10tel reduzieren. Durch die Verarbeitung von Schnappschüssen und Aufnahmen macht es sich schnell bemerkbar, da es dabei nicht nur um ein paar Byte handelt.

@Rudi, ich habe festgestellt, dass Devices vom TYPE HTTPMOD und TelegramBot zum Absturz von Devel::Size führen. Warum das so ist, habe ich noch nicht herausgefunden. D.h. wenn man versuchen würde diese Devices mit meinem Programm zu untersuchen, kommt es zum gleichen Absturz wie bei deinem memusage. Ist ja auch nur Devel::Size. Deshalb werden diese Typen automatisch vom Check ausgeschlossen.
Alle anderen TYPEn sind bei mir problemlos durchgelaufen mit "analyzeObject("TYPE=.*")"

Man kann das Programm in zwei Kontexten verwenden. Um ein Device bzw. Gruppe von Devices (mit devspec) zu untersuchen,
sieht der Aufruf so aus:

Code Auswählen Erweitern

   Verwendung im Device-Kontext:
   analyzeObject(<Devspec [Subhash1] [Subhash2] ...>,[<Analysetiefe>],[<Text zur Erläuterung>]);

   z.Bsp.:
   analyzeObject("CamHE1")
   analyzeObject("CamHE1 HELPER .SNAPHASH,6,SVS")
   analyzeObject("CamHE1 HELPER .SNAPHASH 2,0,SVS")
   analyzeObject("TYPE=SSCam HELPER .SNAPHASH")
   analyzeObject("TYPE=.*")
   
Mit "{ analyzeObject("CamHE1") }" kann man sich direkt in der FHEMWEB Kommandozeile die Größe des Device-Hash anschauen und mit Zusätzen wie "{analyzeObject("CamHE1 HELPER}" usw. immer weiter hineingehen. Will man sich den Inhalt der Hashes anschauen, setzt man noch eine Analysetiefe, z.B. "{analyzeObject("CamHE1 HELPER,7}".

Ähnlich funktioniert die Ausgabe für das %data Hash. Dazu gibt man am Anfang das Keywort "#DATA#" an.

Code Auswählen Erweitern

   Verwendung im HASH-Kontext (z.Zt. nur $data):
   analyzeObject(<#DATA# [Subhash1] [Subhash2] ...>,[<Analysetiefe>],[<Text zur Erläuterung>]);

   z. Bsp.:
   analyzeObject("#DATA#")
   analyzeObject("#DATA# ESPBridge,10")
   analyzeObject("#DATA# SSCam CamHE1")
   analyzeObject("#DATA# SSCam CamHE1 PARAMS")

Das Hilfsmittel ist nicht perfekt und kann mit Sicherheit weiter ausgebaut und verbessert werden. Aber mir ging es darum
ein Hilfsmittel zu haben um ein bisschen besser in sein System hineinschauen zu können.
Wer es sich zutraut und mit Perl nicht ganz ungeübt ist, kann den sich den Inhalt der angehängten Datei in seine 99_myUtils
kopieren und dann wie angegeben verwenden. Ggf. ist Devel::Peek zu installieren. Geht mit dem Installer von Loredo ganz
einfach.

Hier ein Ausgabebeispiel von "{ analyzeObject("CamHE1") }"

Code Auswählen Erweitern

analyzeObject - check object $defs{CamHE1} type: HASH
analyzeObject - Data::Peek deep: 0 -> analyzed $defs{CamHE1} (type: HASH):
SV = IV(0x555a8662f668) at 0x555a8662f678
  REFCNT = 1
  FLAGS = (ROK)
  RV = 0x555a91d8e488

analyzeObject - Devel::Size -> total size object $defs{CamHE1} (type: HASH): 6943118 Bytes
analyzeObject - checked SMTPCREDENTIALS (type: PV): 42 Bytes
analyzeObject - checked .attrminint (type: ARRAY): 64 Bytes
analyzeObject - checked FVERSION (type: PV): 80 Bytes
analyzeObject - checked SERVERADDR (type: PV): 46 Bytes
analyzeObject - checked OLDREADINGS (type: HASH): 120 Bytes
analyzeObject - checked HELPER (type: HASH): 6896144 Bytes
analyzeObject - checked CREDENTIALS (type: PV): 42 Bytes
analyzeObject - checked COMPATIBILITY (type: PV): 42 Bytes
analyzeObject - checked TYPE (type: PV): 42 Bytes
analyzeObject - checked MODEL (type: PV): 51 Bytes
analyzeObject - checked .setup (type: PV): 5865 Bytes
analyzeObject - checked .FhemMetaInternals (type: PV): 24 Bytes
analyzeObject - checked .attraggr (type: ARRAY): 64 Bytes
analyzeObject - checked SERVERPORT (type: PV): 58 Bytes
analyzeObject - checked CAMNAME (type: PV): 45 Bytes
analyzeObject - checked NR (type: PV): 58 Bytes
analyzeObject - checked .ptzhtml (type: PV): 42 Bytes
analyzeObject - checked STATE (type: PV): 82 Bytes
analyzeObject - checked NAME (type: PV): 42 Bytes
analyzeObject - checked READINGS (type: HASH): 37599 Bytes
analyzeObject - checked FUUID (type: PV): 74 Bytes
analyzeObject - checked OPMODE (type: PV): 47 Bytes
analyzeObject - checked DEF (type: PV): 63 Bytes
analyzeObject - checked PROTOCOL (type: PV): 42 Bytes
analyzeObject - checked CAMID (type: PV): 42 Bytes

Und ein Beispiel von "{ analyzeObject("ActionDetector helper io") }"

Code Auswählen Erweitern

analyzeObject - check object $defs{ActionDetector}{helper}{io} type: HASH
analyzeObject - Data::Peek deep: 0 -> analyzed $defs{ActionDetector}{helper}{io} (type: HASH):
SV = PVNV(0x555a9027ea60) at 0x555a94c0e420
  REFCNT = 1
  FLAGS = (ROK)
  IV = 0
  NV = 0
  RV = 0x555a8ce25ec0
  PV = 0x555a8ce25ec0 ""
  CUR = 0
  LEN = 0

analyzeObject - Devel::Size -> total size object $defs{ActionDetector}{helper}{io} (type: HASH): 368 Bytes
analyzeObject - checked vccu (type: PV): 42 Bytes
analyzeObject - checked prefIO (type: PV): 24 Bytes

Für SSCam-Interressenten ... die Version 8.18.0 befindet sich zum Test in meinem contrib.

Grüße,
Heiko

[Mave]

Gibt es zu diesem scheinbar global auftretenden Problem eigentlich einen zentralen Thread?

Ich bin seit einiger Zeit auch betroffen und da das Absturzintervall immer kürzer wird, muss ich mich jetzt auch mal damit beschäftigen. So macht FHEM keinen Spaß mehr.

Mein Sysmon zeigt nach einem Neustart des Rpi3 einen freien Speicher von ca. 520 MB an. Nach einem Tag sind nur noch ca. 130 MB frei.
Auch ein Neustart von FHEM ändert nichts an den freien 130 MB. Erst ein Neustart des Rpi3 ergibt wieder 520 MB freien Speicher.

Könnte mir das bitte jemand erklären?

Vielen Dank.

[rudolfkoenig]

Gibt es zu diesem scheinbar global auftretenden Problem eigentlich einen zentralen Thread?

Ja, diesen hier.
Diese Meldung ist typisch bei einem Speicherleck, weil fork() / BlockingCall nochmal die bisher allozierte Menge des Speichers reserviert.

Fuer einen Speicherleck gibt es sicher mehrere Ursachen, die mir bekannten:
- FHEMWEB bei bestimmten Kombination von plotfork und plotEmbed (ist mW gefixt)
- EchoDevice (nur in bestimmten, bisher unbekannten Konfigurationen).
- SSCam (Loesung unterwegs, siehe https://forum.fhem.de/index.php/topic,84372.msg974569.html#msg974569)
- DOIF mit perl 5.24 und bestimmten Attributen (Perl-Regexp-Bug, mit Workaround in DOIF geloest?)
Es gibt sicher noch Weitere, auch nicht genau identifizierte.

Generell hat FHEM kein Problem mit Speicheranstieg: ich protokolliere meine Produktion seit 3 Monaten, siehe Anhang.

Mir sind zwei Wege bekannt, um das Problem zu lokalisieren:
- alle Module einzeln abschalten, bis man keinen Speicheranstieg beobachtet. Alternativ: Module nacheinander auf eine zweite FHEM-Instanz umziehen.
- fuer Leute mit etwas UNIX Erfahrung: https://forum.fhem.de/index.php/topic,84372.msg970863.html#msg970863

Auch ein Neustart von FHEM ändert nichts an den freien 130 MB.

Die Angabe "Freier Speicher" sollte mAn in "Unnuetz rumliegender Speicher" umbenannt werden, dann haetten wir beim Support weniger Aufgaben. Betriebsysteme benutzen den Hauptspeicher um Daten von der Festplatte zu cachen, diese Zahl zaehlt nicht zu "free", kann aber bei Bedarf jederzeit von Programmen belegt werden, und wird nur bei einem Betriebsystem-Neustart zurueckgesetzt.
EDIT: Perl version korrigiert.

[Mave]

Moin Rudi,

vielen Dank für Deine Erklärungen.

Welche Speicherwerte muss ich überwachen und mit welchem Tool?
Mit sysmon und dort den aktuellen Speicherbedarf?

Danke.

[rudolfkoenig]

SYSMON kenne ich nicht wirklich, und ist mir wegen BlockingCall suspekt

Die Daten fuer meine SVG erstelle ich per crontab (alle 5 Minuten) mit

Code Auswählen Erweitern

echo `date +"%Y-%m-%d_%H:%M:%S"` size `ps -flC perl | awk '/perl/{print $10}'` >> ..../log/perlsize.logDas funktioniert aber nur, weil ich kein Modul mit BlockingCall verwende, und damit nur eine perl-Instanz auf der Maschine laeuft.

Folgendes sollte selbst bei Verwendung von BlockingCall bzw. mehreren FHEM Instanzen funktionieren:

Code Auswählen Erweitern

define pSizeAt at +*00:05 {`echo \`date +"%Y-%m-%d_%H:%M:%S"\` size \`awk '/VmSize/{print \$2}' /proc/$$/status\` >> /opt/FHEM/log/perlsize.log`}Achtung: ich habe Letzteres nur kurz/oberflaechlich getestet, und wg. /proc laeuft das nur unter Linux.

In beiden Faellen legt man ein FakeLog mit log/perlsize.log an, und damit baut man eine SVG.

[tomcat.x]

Fuer einen Speicherleck gibt es sicher mehrere Ursachen, die mir bekannten:
- FHEMWEB bei bestimmten Kombination von plotfork und plotEmbed (ist mW gefixt)
- EchoDevice (nur in bestimmten, bisher unbekannten Konfigurationen).
- SSCam (Loesung unterwegs, siehe https://forum.fhem.de/index.php/topic,84372.msg974569.html#msg974569)
- DOIF mit perl 5.28 und bestimmten Attributen (Perl-Regexp-Bug, mit Workaround in DOIF geloest?)

Bei mir kam auf jeden Fall  Freezemon (in Verbindung mit apptime) dazu. Das Problem hatte glaube ich auch jemand anders hier im Thread. Seit ich Freezmon deaktiviert (in der fhem.cfg auskommentiert!) habe, lese ich hier nur noch aus Interesse mit.

[Mave]

In der cfg auskommentieren bedeutet, dass die Definition erhalten bleibt und später wieder aktiviert werden kann?
Wohingegen Device löschen bedeutet, dass alles aus der cfg entfernt wird?

[der-Lolo]

Löschen ist hier der bessere Weg - die .cfg editiert man nicht.
Bei Freezemon ist es ja auch kein großes Problem neu zu definieren...

[Mave]

Okay, vielen Dank.

Hab ich gestern gelöscht.
Jetzt heißt es beobachten.

[mumpitzstuff]

Einige meinten, das man freezemon komplett löschen muss, um eine Besserung zu erzielen.

[Mave]

Was meinst Du mit komplett löschen?