Cannot fork: Cannot allocate memory | BlockingInformParent

[binford6000]

Das Reading des Ram Speicher gibt im Fehlerfall n/a aus und nicht Null!

Hallo Chris,
das kann ich bestätigen. Bei mir kommen die Cannot fork... Meldungen so ab 550 MByte used_ram:

Code Auswählen Erweitern

defmod sysmon_notify_1 notify sysmon:ram_used:.* {
  my $ram_used = ReadingsVal("sysmon","ram_used","0");
  if ($ram_used > 550) {
    fhem "setreading sysmon ram_used 100; msg push FHEM-Neustart wegen Speichermangel!; sleep 5; shutdown restart";
  }
}

Das setreading musste ich einfügen um mehrmalige Neustarts direkt nacheinander zu vermeiden...
VG Sebastian

[Brice]

Falls ihr euch auf meinen Workaround (ram_used) bezieht, ist euer Notify nicht korrekt. Hier hatte ich einen Auszug aus dem Logfile gepostet, das bedeutet bei mir, dass ich den Schwellwert bei > 500 gesetzt habe. Notify bei mir (getestet mit Wert > 180):

Code Auswählen Erweitern

sysmon:ram_used:.* {
if (ReadingsVal("sysmon","ram_used", " ") > 500)
{fhem ("shutdown restart")}
}

Mein Produktivsystem läuft ohne Restart seit dem 20.03.2018 problemlos. Warum? Keine Ahnung...

[Burny4600]

@binford6000
Das ist bei meinen beiden Systemen ebenfalls das es ab ca. 550 Mbyte vorbei ist mit dem System.

[binford6000]

Hallo Brice,

Falls ihr euch auf meinen Workaround (ram_used) bezieht, ist euer Notify nicht korrekt.

Ja, ich verwende Dein userReading ram_used. Nein, das notify funktioniert. Es muss halt ein event-on-update-reading
auf ram_used eingerichtet werden.
Man könnte auch mit

Code Auswählen Erweitern

grep -a "Cannot fork: Cannot allocate memory" /opt/fhem/log/fhem-$(date +%Y-%m-%d).log | tail -1
via cron in einem Shellskript das Logfile überwachen und selbiges jeweils bei global:INITIALIZE mit einem cmdalias löschen:

Code Auswählen Erweitern

defmod c_dellog cmdalias dellog AS {qx(truncate $currlogfile --size 0);;Log 1, "Logfile gelöscht";;}

Viel besser wäre allerdings, wenn ich die ganze Restart-Sch.... wieder löschen könnte 
VG Sebastian

[CoolTux]

Viel besser wäre allerdings, wenn ich die ganze Restart-Sch.... wieder löschen könnte 
VG Sebastian

Das kannst Du! Kommentiere nach und nach alle Devices aus und schaue ab welchem Punkt das Problem nicht mehr auf tritt.
Aussitzen und warten bis andere das Problem für einen lösen ist eher Kontraproduktiv.

[binford6000]

Aussitzen und warten bis andere das Problem für einen lösen ist eher Kontraproduktiv.

Vorsicht mit solchen Behauptungen!
Mein Kommentar im letzten Post war meine persönliche Stimmungslage 

Ich habe bereits einige Module versuchsweise deaktiviert - leider ohne Erfolg. Ich tippe daher auf ein Problem mit debian und/oder perl...
VG Sebastian

[rudolfkoenig]

Ich tippe daher auf ein Problem mit debian und/oder perl...

Ich auch, aber wahrscheinlich nur im Zusammenspiel mit irgendeiner Funktion, was in FHEM nur an bestimmten Stellen verwendet wird, sonst haetten wir hier keine Faelle ohne Probleme. Wenn wir diese Stellen kennen wuerden, dann koennten wir einen Workaround schreiben, oder gezielter nach Loesung suchen.

Weitere Ideen fuer das Lokalisieren des Problems:
- Unterschiedliche perl Versionen installieren, und testen
- FHEM mit einem debug-malloc library (valgrind oder dmalloc) starten, um die Stelle einzugrenzen.

Btw. mit dem FHEM-Neustart zu warten bis man kein Speicher hat, ist zu spaet: wenn FHEM auf etwa die Haelfte des verfuegbaren Speichers angewachsen ist, wird BlockingCall nicht mehr klappen, weil Linux nicht garantieren kann, dass genug Speicher nach dem fork zur Verfugung steht (stark vereinfacht: fork in BlockingCall dupliziert den alten Prozess).

[Jens_B]

Koennten bitte alle, die dieses Problem haben, die Ausgabe von version hier anhaengen?
Und wenn jemand unter Stretch keine Probleme hat, der sollte das bitte auch tun, aber dazuschreiben, dass es eben keine Probleme gibt.
Evtl. hilft uns danach die Mengenlehre weiter.

Habe hier unter einem PI3 mit Stretch das selbe a Problem.
DBLOG nutze ich nicht.

Code Auswählen Erweitern

Latest Revision: 16492

File                         Rev   Last Change

fhem.pl                      16453 2018-03-20 21:15:44Z rudolfkoenig
57_ABFALL.pm                 11020 2017-09-13 00:40:21Z uniqueck
95_Alarm.pm                  16368 2018-03-10 07:01:51Z phenning
90_at.pm                     15795 2018-01-05 20:46:21Z rudolfkoenig
98_autocreate.pm             15620 2017-12-16 18:10:36Z rudolfkoenig
57_Calendar.pm               15612 2017-12-15 09:26:59Z neubert
57_CALVIEW.pm                16023 2018-01-28 16:28:47Z chris1284
10_CUL_HM.pm                 16258 2018-02-24 22:11:14Z martinp876
98_DOIF.pm                   16481 2018-03-25 09:10:27Z Damian
98_DOIFtools.pm              16245 2018-02-23 13:16:23Z Ellert
98_dummy.pm                  12700 2016-12-02 16:49:42Z rudolfkoenig
91_eventTypes.pm             14888 2017-08-13 12:07:12Z rudolfkoenig
00_FBAHAHTTP.pm              16344 2018-03-06 21:06:34Z rudolfkoenig
10_FBDECT.pm                 16441 2018-03-18 21:39:08Z rudolfkoenig
72_FB_CALLMONITOR.pm         16483 2018-03-25 09:42:35Z markusbloch
01_FHEMWEB.pm                16407 2018-03-14 19:43:35Z rudolfkoenig
92_FileLog.pm                15874 2018-01-13 17:16:33Z rudolfkoenig
98_freezemon.pm              16411 2018-03-14 22:22:14Z KernSani
72_FRITZBOX.pm               16461 2018-03-21 18:26:03Z tupol
98_help.pm                   15223 2017-10-10 10:14:24Z betateilchen
98_HMinfo.pm                 16421 2018-03-17 06:15:49Z martinp876
00_HMLAN.pm                  14073 2017-04-22 13:45:25Z martinp876
95_holiday.pm                16293 2018-02-28 21:33:57Z rudolfkoenig
98_HTTPMOD.pm                16216 2018-02-18 15:26:11Z StefanStrobel
02_HTTPSRV.pm                13976 2017-04-12 13:35:44Z neubert
49_IPCAM.pm                   2626 2013-02-01 19:19:15Z mfr69bs
10_IT.pm                     14852 2017-08-06 08:48:24Z bjoernh
36_JeeLink.pm                14707 2017-07-13 18:08:33Z justme1968
98_JsonList2.pm              16293 2018-02-28 21:33:57Z rudolfkoenig
36_LaCrosse.pm               16168 2018-02-13 21:01:41Z HCS
91_notify.pm                 15937 2018-01-20 13:43:28Z rudolfkoenig
No Id found for 99_on_as_long_as_daylight.pm
No Id found for 99_perfmon.pm
10_pilight_ctrl.pm           16028 2018-01-28 18:34:25Z Risiko
30_pilight_switch.pm         11306 2016-04-24 17:03:16Z risiko79
30_pilight_temp.pm           10506 2016-01-14 20:40:45Z risiko79
59_PROPLANTA.pm              16468 2018-03-22 18:06:34Z tupol
33_readingsGroup.pm          16299 2018-03-01 08:06:55Z justme1968
39_siri.pm                   14044 2017-04-20 07:48:44Z justme1968
98_structure.pm              16293 2018-02-28 21:33:57Z rudolfkoenig
99_SUNRISE_EL.pm             16266 2018-02-25 18:22:51Z rudolfkoenig
98_SVG.pm                    16402 2018-03-13 21:14:22Z rudolfkoenig
42_SYSMON.pm                 15910 2018-01-16 23:07:56Z hexenmeister
98_telnet.pm                 16293 2018-02-28 21:33:57Z rudolfkoenig
59_Twilight.pm               16005 2018-01-27 06:05:51Z igami
98_update.pm                 16426 2018-03-17 16:23:45Z rudolfkoenig
99_Utils.pm                  15713 2017-12-28 11:01:02Z rudolfkoenig
98_version.pm                15140 2017-09-26 09:20:09Z markusbloch
59_Weather.pm                12559 2016-11-13 08:54:54Z borisneubert
98_weblink.pm                16293 2018-02-28 21:33:57Z rudolfkoenig
98_WeekdayTimer.pm           16005 2018-01-27 06:05:51Z igami
10_ZWave.pm                  16266 2018-02-25 18:22:51Z rudolfkoenig
00_ZWDongle.pm               16293 2018-02-28 21:33:57Z rudolfkoenig

ABFALL_getEvents.pm          11021 2017-09-13 00:32:22Z uniqueck
ABFALL_setUpdate.pm          11021 2017-09-13 00:32:22Z uniqueck
Blocking.pm                  15412 2017-11-09 14:34:29Z rudolfkoenig
Color.pm                     11159 2016-03-30 16:08:06Z justme1968
DevIo.pm                     16329 2018-03-04 20:18:08Z rudolfkoenig
FritzBoxUtils.pm             16344 2018-03-06 21:06:34Z rudolfkoenig
HMConfig.pm                  16265 2018-02-25 18:22:43Z martinp876
No Id found for HMConfig_SenTHPL.pm
HttpUtils.pm                 16407 2018-03-14 19:43:35Z rudolfkoenig
myUtilsTemplate.pm            7570 2015-01-14 18:31:44Z rudolfkoenig
RTypes.pm                    10476 2016-01-12 21:03:33Z borisneubert
SetExtensions.pm             16211 2018-02-18 11:59:09Z rudolfkoenig
TcpServerUtils.pm            15707 2017-12-27 14:41:21Z rudolfkoenig
YahooWeatherAPI.pm           15742 2018-01-01 07:55:55Z neubert
ZWLib.pm                     15466 2017-11-20 22:22:19Z rudolfkoenig

doif.js                    15546 2017-12-03 09:57:42Z Ellert
fhemweb.js                 16348 2018-03-07 21:02:42Z rudolfkoenig
fhemweb_readingsGroup.js   15189 2017-10-03 17:53:27Z justme1968
svg.js                     15896 2018-01-14 21:35:42Z rudolfkoenig


Ich habe eventuell das Gefühl das es was mit dem Homebridge Modul zusammen hängt?

Ich weiß alles nicht sehr hilfreich

Gruß
Jens

[Jens_B]

Läst sich irgendwie ein automatischer Reboot einrichten bis dieser Fehler gefunden wurde.
Wenn ich alle 24 Stunden einen Autorboot durchführen könnte wäre ich zumindest so weit Sicher das sich das System nicht weghängt.

Das lässt sich über die crontab einfach einrichten.


Z.B.
0 3 * * * sudo reboot

Ich denke es reicht aber einfach schon fhem mit sudo Service fhem restart

[binford6000]

Btw. mit dem FHEM-Neustart zu warten bis man kein Speicher hat, ist zu spaet: wenn FHEM auf etwa die Haelfte des verfuegbaren Speichers angewachsen ist, wird BlockingCall nicht mehr klappen, weil Linux nicht garantieren kann, dass genug Speicher nach dem fork zur Verfugung steht (stark vereinfacht: fork in BlockingCall dupliziert den alten Prozess).

Genau das kann ich bei mir beobachten. Allerdings verschwinden die duplizierten fhem-Prozesse wieder nach kurzer Zeit.

Ich habe eventuell das Gefühl das es was mit dem Homebridge Modul zusammen hängt?

Homebridge habe ich auch im Einsatz. Werde es mal testweise deaktivieren und schauen.

Ich habe zwischenzeitlich meinen nextcloud Kalender via CALENDAR-Modul deaktiviert. Das Resultat ist leider das gleiche,
lediglich die Zeitspanne verlängert sich um etwa eine Stunde...
VG Sebastian

[mumpitzstuff]

Btw. mit dem FHEM-Neustart zu warten bis man kein Speicher hat, ist zu spaet: wenn FHEM auf etwa die Haelfte des verfuegbaren Speichers angewachsen ist, wird BlockingCall nicht mehr klappen, weil Linux nicht garantieren kann, dass genug Speicher nach dem fork zur Verfugung steht (stark vereinfacht: fork in BlockingCall dupliziert den alten Prozess).

Bedeutet das, wenn FHEM 100MB belegt und irgendwann 5 BlockingCalls von verschiedenen Modulen aufeinandertreffen, dass dann kurzzeitig 600MB RAM benötigt werden? Was passiert wenn es zu diesem Problem kommt? Bleibt es beim Versuch den Fork zu machen ohne das irgndwas im Speicher zurück bleibt oder crasht dann irgendwas so, das dann der restliche Speicher komplett dicht gemacht wird?

Gibts denn keine Möglichkeit sich den RAM Verbrauch der einzelnen Module irgendwie anzuzeigen? Falls doch was genau müssten die betroffenen Personen machen? Ich für meinen Teil wüsste jetzt nicht auf Anhieb was man hierfür machen müsste: "FHEM mit einem debug-malloc library (valgrind oder dmalloc) starten, um die Stelle einzugrenzen".

PS: Das habe ich auf die Schnelle finden können aber nicht getestet:

Code Auswählen Erweitern

sudo apt-get install libtest-valgrind-perl

Code Auswählen Erweitern

valgrind --tool=massif --depht=1 --trace-children=yes perl fhem.pl fhem.cfg

[Jens_B]

Enno Du könntest eventuell Gold wert sein mein Junge.
Ein schneller Blick über alle Threadeinträge mit version ergab das alle das Modul

Code Auswählen Erweitern

96_SIP.pm                15827 2018-01-08 18:36:07Z Wzut
in Verwendung haben die Probleme haben.

Die User welche das so haben sind nun am Zug. Modul deaktivieren oder besser noch erstmal komplett raushauen und testen bitte.

Das Modul wird in meiner fhem Installation nicht genutzt, und trotzdem habe ich das gleiche Problem.

[binford6000]

Gibts denn keine Möglichkeit sich den RAM Verbrauch der einzelnen Module irgendwie anzuzeigen?

Ich denke so:

Code Auswählen Erweitern

fhemdebug memusage
Sieht bei mir aktuell so aus:

Code Auswählen Erweitern

1. defs                            2239018
   2. attr                             351253
   3. modules                          323827
   4. defs::AgrarWetter                257655
   5. defs::AgrarWetter::READINGS      255724
   6. FW_cmdret                        170161
   7. defs::WU_Home                    115415
   8. defs::WU_Home::READINGS          111670
   9. defs::Sonos_Kueche                59881
  10. defs::Sonos_Kueche::READINGS      58230
  11. attr::Wohnung                     57409
  12. defs::FritzBox                    56994
  13. modules::Wunderground             53122
  14. modules::Wunderground::readingsDesc    51614
  15. defs::MeinWetter                  48150
  16. defs::sysmon                      47267
  17. defs::MeinWetter::READINGS        46093
  18. POSIX::                           37247
  19. defs::Daemmerung                  35562
  20. defs::Shuttle.PC                  35177
  21. defs::Muell_Kalender              35126
  22. defs::Dreambox                    34619
  23. defs::rgr_AufderDahl              33805
  24. defs::Shuttle.PC::READINGS        33749
  25. defs::Dreambox::READINGS          33588
  26. defs::Wohnung                     33217
  27. defs::rgr_Kinder                  33114
  28. defs::Spielplatz.PC               32642
  29. defs::sysmon::READINGS            31714
  30. defs::Sonos                       31548
  31. defs::Spielplatz.PC::READINGS     31211
  32. defs::rgr_AufderDahl::READINGS    30920
  33. defs::rgr_Kinder::READINGS        30870
  34. defs::Sonos::READINGS             30504
  35. defs::FritzBox::READINGS          30459
  36. defs::Wohnung::READINGS           28874
  37. defs::WEBapi_10.3.3.40_53916      27113
  38. defs::Muell_Kalender::.fhem       26048
  39. defs::WEBapi_10.3.3.40_53916::inform    25537
  40. defs::WEBapi_10.3.3.40_53916::inform::devices    24854
  41. defs::Astrodaten                  23943
  42. defs::FritzBox::fhem              23922
  43. defs::fhemBot                     23444
  44. B::                               23404
  45. defs::Astrodaten::READINGS        23014
  46. INC                               22289
  47. defs::Muell_Kalender::.fhem::iCalendar    21738
  48. defs::rr_Sebastian                21650
  49. defs::Sonos::READINGS::MusicServicesList    21326
  50. defs::Sonos::READINGS::MusicServicesList::VAL    20993
VG Sebastian

[mumpitzstuff]

Na das ist doch schon mal was.

[rudolfkoenig]

Bedeutet das, wenn FHEM 100MB belegt und irgendwann 5 BlockingCalls von verschiedenen Modulen aufeinandertreffen, dass dann kurzzeitig 600MB RAM benötigt werden?

Ja.

Was passiert wenn es zu diesem Problem kommt?

Erstmal nix, 600MB zu Verbrauchen ist per-se kein Problem, nur wenn man nicht so viel hat. Und dann gibt es beim letzten Fork die im Betreff: zu findende Fehlermeldung. Und der letzte BlockingCall geht schief.

Bleibt es beim Versuch den Fork zu machen ohne das irgndwas im Speicher zurück bleibt oder crasht dann irgendwas so, das dann der restliche Speicher komplett dicht gemacht wird?

Wenn die BlockingCall Prozesse terminieren, dann geben diese den Speicher frei. Der urspruengliche Prozess waechst aber munter weiter. Wenn nichts mehr geht, weil kein Speicher da ist, dann schiesst der Linux-Kernel den groessten Prozess ab.

Gibts denn keine Möglichkeit sich den RAM Verbrauch der einzelnen Module irgendwie anzuzeigen?

Es gibt zwar fhemdebug memusage, das ist aber ungenau, weil es nur "richtige" Perl Variablen zaehlt (z.Bsp. keine Funktionsdefinitionen, usw). Weiterhin vermute ich das Problem nicht an dieser Stelle, sondern in einem der Bibliotheken.

valgrind --tool=massif --depht=1 --trace-children=yes perl fhem.pl fhem.cfg

Den Verbrauch der Kinder wuerde ich nicht pruefen (die Ursache sind nicht die, sondern der zuerst gestartete Prozess), aber damit das klappt, muss man "attr global nofork" setzen.