Cannot fork: Cannot allocate memory

[frank]

hallo,

seit längerem habe ich in unregelmässigen abständen folgende fehlermeldungen im log. fhem läuft auf fritzbox 7390.

Code Auswählen Erweitern

2015.08.10 12:00:21.498 1: Cannot fork: Cannot allocate memory
2015.08.10 12:00:21.501 1: Cannot fork: Cannot allocate memory
2015.08.10 12:00:21.505 1: PERL WARNING: Use of uninitialized value $i in hash element at ./FHEM/98_apptime.pm line 36.
2015.08.10 12:00:21.507 1: PERL WARNING: Use of uninitialized value $i in hash element at ./FHEM/98_apptime.pm line 37.
2015.08.10 12:00:21.509 1: PERL WARNING: Use of uninitialized value $i in delete at ./FHEM/98_apptime.pm line 39.


die fork meldung kommt meistens im doppelpack und wird von den apptime warnungen begleitet. könnte da ein zusammenhang mit apptime bestehen? apptime starte ich mit fhem, um bei einem disconnect vom hmlan infos zu generieren. seit einiger zeit sind die ausgaben von apptime bei einem disconnect auch ziehmlich lang geworden. vor allem mit folgenden einträgen, die ich vor der fork-problematik nicht in erinnerung habe. zumindestens nicht in der fülle (stark gekürzt):

Code Auswählen Erweitern

                    tmr-BlockingKill      HASH(0x2311bc8)      0      1        0     0.00      6
                    tmr-BlockingKill      HASH(0x2311c58)      0      1        0     0.00      6
                    tmr-BlockingKill      HASH(0x2311cd8)      0      1        0     0.00      6
                    tmr-BlockingKill      HASH(0x2312378)      0      1        0     0.00      6
                    tmr-BlockingKill      HASH(0x2336288)      0      1        0     0.00      6
                    tmr-BlockingKill      HASH(0x23365e8)      0      1        0     0.00      7
                    tmr-BlockingKill      HASH(0x2392398)      0      1        0     0.00      6


da fällt mir gerade ein, dass apptime beim start auch 2 warnungen generiert:

Code Auswählen Erweitern

2015.08.10 13:41:08.550 1: PERL WARNING: Subroutine HandleTimeout redefined at ./FHEM/98_apptime.pm line 24.
2015.08.10 13:41:08.557 1: PERL WARNING: Subroutine CallFn redefined at ./FHEM/98_apptime.pm line 58.


die 2. variante der fork meldungen sieht so aus:

Code Auswählen Erweitern

2015.08.09 14:32:07.997 1: Cannot fork: Cannot allocate memory
2015.08.09 14:32:26.452 1: PERL WARNING: Use of uninitialized value $p in hash element at fhem.pl line 632.


um das problem mal zu verorten, hatte ich gehofft, dass eventuell ein globales fehlerevent existiert, um die forkmeldungen zu loggen. aus der fork-sub in fhem.pl entnehme ich, dass es solch ein event nicht gibt. spricht etwas dagegen, solch ein event in fhem zu integrieren? am besten wäre natürlich mit anzeige des aufrufenden moduls.

wie kann ich weiter vorgehen?

gruss frank

[rudolfkoenig]

globales fehlerevent existiert, um die forkmeldungen zu loggen

Ich verstehe nicht, was damit gemeint ist.

Es schaut fuer mich so aus, dass irgendein Modul, was Blocking.pm verwendet, amok laeuft.
apptime staendig laufen zu lassen verursacht etwas mehr Last. Ob das hier relevant ist, weiss ich nicht.
Die "redefined" Warnings bei apptime Start sind normal, da apptime eine eigene Version dieser Funktionen mitbringt.

[Elektrolurch]

Hallo,

ich habe ein ähnliches Problem, bekomme auch die "cannot fork" - Meldungen. Bei mir ist es allerdings das 72-fritzbox Modul.
Die Sache schaukelt sich nach einer gewissen Zeit so auf, dass sogar die ganze 7390 FB abstürzt. Ich habe daher wegen der Betriebssicherheit erst einmal das fritzboxd - Modul deaktiviert.
Würde Dir das gleiche für das aptime - Modul empfehlen.
Meine Analyse hat auch auf "blocking - Calls" geführt. Da scheinen irgendwelche child - Prozesse hängenzubleiben und irgendwann hat die Box dann tatsächlich kein memory mehr.

Gruß

Elektrolurch

[Rince]

Ich verstehe nicht, was damit gemeint ist.

Ich denke frank möchte, dass der Name des Moduls, welches nicht erfolgreich geforkt werden konnte, angezeigt/geloggt wird.



Die andere Frage ist, ob das weiter hilft?
Dann wissen wir nur, dass für einen bestimmten geforkten Prozess kein Speicher mehr da war.
Aber der Speicher war ja schon vorher zu voll.
D.h. wir sehen immer noch nicht das Modul, welches Speicher belegt, ohne ihn hinterher wieder frei zu geben.

[frank]

Die Sache schaukelt sich nach einer gewissen Zeit so auf, dass sogar die ganze 7390 FB abstürzt.
...
Meine Analyse hat auch auf "blocking - Calls" geführt. Da scheinen irgendwelche child - Prozesse hängenzubleiben und irgendwann hat die Box dann tatsächlich kein memory mehr.

genau das ist der punkt. sobald die ersten fork meldungen auftauchen, ist der "hänger/absturz" nicht mehr weit.

meine naive vorstellung des forkens ist folgende:
um bei bestimmten aktionen fhem nicht zu blocken, wird für diese aktion ein separater prozess gestartet. wenn genügend speicher zur verfügung steht, wird "geforkt". nach ablauf der aktion wird der prozess wieder beendet und der dafür zuvor bereitgestellte speicher freigegeben. was passiert aber, wenn kein speicher zum forken vorhanden ist? wird die ausführung solch einer aktion dann verschoben, verworfen oder blockend ausgeführt? die handhabung bei ablehnung des forkens, scheint auch problematisch, da nach und nach immer mehr warnungen im log auftauschen, die über nicht initialisierte variablen "schimpfen". wahrscheinlich der anfang des grossen knotens.

aber warum stürzt dann irgendwann die ganze box ab. wenn die box speicher zur verfügung stellt, müsste sie doch auch damit klar kommen. oder "vergisst" sie für sich genügend zu reservieren? irgendwie macht es den eindruck, dass am ende die verteilten häppchen immer kleiner werden, bis der speicher restlos voll ist. um das mal zu visualisieren, habe ich gestern sysmon definiert. eine permanente reduzierung des freien rams konnte ich noch nicht wirklich wahrnehmen. ich weiss natürlich auch nicht, ob dieser speicher entscheidend ist. es macht jetzt eher den eindruck, dass das vorhandensein des moduls zusätzlich das eigentliche problem verstärkt.

die erfahrungen, auch aus anderen threads, lassen vermuten, dass im verfahren des forkens eventuell ein problemchen vorhanden ist. daher hätte ich gerne ein "werkzeug", um das verfahren beobachten/analysieren zu können. perfekterweise wäre das zb eine tabelle (ähnlich wie apptime), aus der hervorgeht, welche aktion läuft gerade als fork (modulname, funktionsname, forkstart, grösse des speichers). ich habe aber im moment überhaupt keinen plan, womit man, zumindestens ansatzweise, dahin kommt.

globales fehlerevent existiert, um die forkmeldungen zu loggen

Ich verstehe nicht, was damit gemeint ist.

rince hat das schon sehr gut erkannt:

Ich denke frank möchte, dass der Name des Moduls, welches nicht erfolgreich geforkt werden konnte, angezeigt/geloggt wird.

da ich die meldungen überhaupt noch nicht zuordnen kann, hatte ich die vorstellung, als "einstieg" das auftauchen der fork-meldungen zu plotten. deswegen der wunsch nach einem event. häufig kann man aus einem plot vermutungen ziehen, da die events eventuell bestimmte muster zeigen (zeiten, abfolgen, abhängigkeiten, häufungen, etc...).

Die andere Frage ist, ob das weiter hilft?
Dann wissen wir nur, dass für einen bestimmten geforkten Prozess kein Speicher mehr da war.
Aber der Speicher war ja schon vorher zu voll.
D.h. wir sehen immer noch nicht das Modul, welches Speicher belegt, ohne ihn hinterher wieder frei zu geben.

wie gesagt, ein erster, primitiver ansatz. zumindestens würde man informiert werden und könnte eingreifen. (zb gezielt runterfahren und rebooten).

apptime habe ich jetzt zwar mal versuchsweise abgestellt, aber letztendlich kann das eigentlich nicht die ursache sein. denn es gab auch zeiten, da lief apptime auch ohne forkmeldungen. das erste auftreten bei mir würde ich grob auf anfang des jahres festlegen. richtig problematisch empfand ich auch das fritzbox modul, das ich daraufhin disabled habe. die ersten anzeichen hatte ich aber bereits davor. es könnte natürlich daran liegen, dass immer mehr module auf nonblocking umgestellt haben.

gruss frank

[TeeVau]

Ich kenne die genauen Details von Blocking.pm nicht, bin aber der Meinung, dass nicht nur der Prozess, der "extern" ausgeführt werden soll, geforked wird, sondern die komplette FHEM Prozess Instanz.
Die FBF scheint pingelich zu sein, was den Speicher angeht. Als mein FHEM auf der FBF lief hatte ich auch öfters das Problem, dass aufgrund von vollem Speicher die FBF neustartet. Mein Gedankengang dazu ist: Wenn FHEM 50mb RAM belegt und dann geforked wird, werden 50mb RAM zusätzlich benötigt.
Hat die FBF aber nur noch 30mb frei, gibt es Probleme. Ist jetzt ziemlich einfach dargestellt, und vielleicht auch falsch.

Auf jeden Fall habe ich, nachdem Umzug von FHEM auf eine perfomante Hardware, keine Probleme mehr mit FHEM auf der FBF. Das Ding läuft nur noch um den CUL per FHEM2FHEM RAW an den "richtigen" FHEM Server anzubinden, braucht also deutlich weniger Speicher. Seitdem keinen einzigen Absturz mehr.

[frank]

so, einen schritt weiter.

das plotten der rambelegung hat doch schon mal etwas ergeben (mit integrierten peaks für forkmeldungen wäre das sehr anschaulich  )

(http://forum.fhem.de/index.php?action=dlattach;topic=39887.0;attach=35818;image)

im abstand von 5-6 min werden immer etwa 5MB freier speicher "entfernt". in fhem log tauchen die fork meldungen zb einmal um 22:14:25 auf. zu diesem zeitpunkt wäre etwa wieder der 5MB happen drangewesen. meine vermutung ist nun, dass der kleine happen gegen 22:13:30 das niveau des freien speichers unter eine schwelle gesenkt hat, dass es zur forkmeldung kam. die nächste forkmeldung kommt um 22:32:13. auch hier wäre der 5MB happen wieder dran gewesen. auf diesem tiefen niveau kommen jetzt öfter forkmeldungen bis 22:52:19. hier meldet fhem neustart nach einem reboot der box.

jetzt muss ich mich wohl auf die suche machen, wer hier alle 5-6 min 5MB haben möchte. mal schauen.
edit: interessanter wäre natürlich, warum nach 22:32 kein speicher mehr freigegeben wird. der 5MB happen kann es ja eigentlich nicht sein.

Wenn FHEM 50mb RAM belegt und dann geforked wird, werden 50mb RAM zusätzlich benötigt.

das passt glaube ich nicht zu dem plott.

Auf jeden Fall habe ich, nachdem Umzug von FHEM auf eine perfomante Hardware, keine Probleme mehr mit FHEM auf der FBF.

das ist ja zu einfach. egal wie gross oder klein, trotzdem muss es stabil laufen, meine ich. mit einem mofa kommt man auch bis barcelona, ohne dass sie alle 2km ausgeht. 

gruss frank

[TeeVau]

Das mit dem Mofa klappt aber nur, wenn die Tankstellen keine 800km auseinander sind

Wie gesagt, das mit der speicherbelegung ist nur eine Vermutung. Bestimmt gibt es was kluges im Betriebssystem, was vorhandene Daten im RAM nutzt, ohne sie doppelt anzulegen.
Mein fhem wurde in jedem Fall zu groß für die fbf, warum auch immer.

[frank]

ich habe mir hier ein wenig hilfe zum plotten gesucht und schiebe das kurz nach, damit es hier weitergehen kann.

um das näher zu untersuchen, plotte ich gerade die ram-nutzung. gibt es die möglichkeit, den gerade von fhem genutzen speicher zu ermitteln? dann könnte ich besser erkennen, wer den weniger werdenden freien speicher benutzt. zumindestens ob der an fhem geht, oder nicht.

Hi Frank!

Sysmon kann das nicht. Sollte man auch außerhalb von FHEM machen, um das Ergebnis nicht zu verfälschen. Damit sind wir hier OT.
Ich habe schnell (und schmutzig) ein Befehl zusammengesetzt, habe dann aber begriffen, dass FritzBox kein AWK am Bord hat und ps kennt kein xa

Code Auswählen Erweitern

ps xa | grep "fhem.pl fhem.cfg" | grep -v grep | awk '{system("cat /proc/"$1"/status")}' | grep VmSize | awk '{ SUM += $2} END { print SUM }'

Per Hand geht aber:

Code Auswählen Erweitern

ps | grep "fhem.pl fhem.cfg" | grep -v grep
und gefundenen PID einsetzen:

Code Auswählen Erweitern

cat /proc/<PID>/status | grep VmSize

K.A. wie man das auf der Box automatisieren kann...,

Kleine optimierung:

Code Auswählen Erweitern

ps | grep [f]hem
damit spart man sich den grep Befehl wieder rauszugreppen ...

und um die Probleme mit dem "PID" raussuchen zu automatisieren .. könntest Du mir bitte mal ie Ausgabe von ps der Fritte geben?

hallo wernieman, hier die ps-ausgabe:

Code Auswählen Erweitern

# ps
  PID USER       VSZ STAT COMMAND
    1 root      1280 S    init
    2 root         0 SW<  [kthreadd]
    3 root         0 SW<  [ksoftirqd/0]
    4 root         0 SW<  [watchdog/0]
    5 root         0 SW<  [events/0]
    6 root         0 SW<  [khelper]
    7 root         0 SW<  [async/mgr]
    8 root         0 SW<  [CPMAC workqueue]
    9 root         0 SW<  [kblockd/0]
   10 root         0 SW   [pdflush]
   12 root         0 SW<  [kswapd0]
   13 root         0 SW<  [aio/0]
   14 root         0 SW<  [nfsiod]
   22 root         0 SWN  [avmdebug]
   23 root         0 SW   [pm_info]
   24 root         0 SW<  [mtdblockd]
   27 root         0 SW<  [rpciod/0]
   28 root         0 SW<  [l2tp]
   29 root         0 SW   [tffsd_mtd_0]
   89 root         0 SW   [cleanup_timer_f]
  209 root         0 SW<  [yaffs-bg-1]
  226 root         0 SW<  [capi_pipew/0]
  227 root         0 SW<  [capi_schedw/0]
  228 root         0 SW   [pcmlink_ctrl]
  229 root         0 SW   [capitransp]
  232 root         0 SW<  [avm_dect_thread]
  233 root         0 SW   [ksock tcp worke]
  234 root         0 SW   [ksock tcp serve]
  306 root      1276 S <  /sbin/udevd --daemon
  339 root         0 SW<  [khubd]
  384 root      1276 S <  /sbin/udevd --daemon
  387 root      1276 S <  /sbin/udevd --daemon
  413 root      2676 S    /bin/configd
  729 root     62776 S    /usr/bin/vdsld ats
  745 root     18988 S    /usr/sbin/dsl_monitor -d
  795 root         0 SW   [pdflush]
  913 root         0 SWN  [dectuart_route]
  916 root      2828 S    avmipcd
  919 root      3344 S    l2tpv3d
  926 root     30600 S    ctlmgr
  930 root     23696 S    upnpd
  935 root      4232 S    multid
  941 root      3764 S    ddnsd
  947 root     11212 S    upnpdevd
  964 root      2824 S    wland -B
  969 root      4452 S    dsld -i -n
  981 root     28952 S    pbd
1029 root     14152 S    telefon a127.0.0.1
1030 root      1276 S    telnetd -l /sbin/ar7login
1065 root      5700 S    dect_manager
1073 root      6036 S <  voipd
1092 root      4712 S    /usr/bin/faxd -a
1127 root      1280 S    /usr/sbin/inetd
1205 root         0 SW   [avmcsrpc]
1210 root      4460 S    feedd
1222 root      2348 S    pictured -Dpicserver -Dhandheld -Dsequence -Dpicdb -
1239 root      3384 S    audiod
1273 root     61788 S    /usr/bin/aha
1346 root      1176 S    /bin/run_clock -c /dev/tffs -d
1495 root      9788 S    /var/InternerSpeicher/fhem/lib/hmland -d -p 1234
1505 root      2712 S    /sbin/nmbd
1542 root      3624 S    usermand
1550 root      3480 S    contfiltd
1799 root      1456 S    hostapd -B /etc/wpa2/WSC_ath0.conf
1829 root     35284 S    perl fhem.pl fhem.cfg
1835 root      1284 S    sh -c echo "$0[$$]: ++++fork set_modulemen, sleep 60
1837 root      1280 S    init
1838 root      1268 S    sleep 600
1883 root      1456 S    /sbin/chronyd -n -f /var/tmp/chrony.conf
2276 root      1292 S    -sh
2383 root      1276 R    ps

[Wernieman]

Kleine Frage:
Gibt es unter der Fritte ein pgrep?

Dann könnte man vereinfacht die Stati auslesen mit:

Code Auswählen Erweitern

for i in `pgrep [f]hem`; do echo "PID $i"; cat /proc/$i/status; done

ansonsten müste man mit "cut", kann nur momentan nicht "testen":

Code Auswählen Erweitern

ps | grep [f]hem | cut -f2 -d " "

Edit:
für die Lesbarkeit eventuell die Ausgabe der PID-Stati nur den Bereich "Vm" betrachten.

z.B. bei meinem FHEM, welches aber auf einem größeren System zu Hause ist:
(Eine von den beiden PID ist ein Folk für MPD, zu sehen an der PPid)

Code Auswählen Erweitern


# for i in `pgrep [f]hem`; do echo "PID $i"; grep -e Vm -e PPid /proc/$i/status; done
PID 2667
PPid:   1
VmPeak:   181696 kB
VmSize:   170808 kB
VmLck:         0 kB
VmPin:         0 kB
VmHWM:     97112 kB
VmRSS:     88076 kB
VmData:    85792 kB
VmStk:       136 kB
VmExe:         8 kB
VmLib:      6108 kB
VmPTE:       348 kB
VmSwap:        0 kB
PID 2799
PPid:   2667
VmPeak:   155180 kB
VmSize:   155176 kB
VmLck:         0 kB
VmPin:         0 kB
VmHWM:     63416 kB
VmRSS:     63416 kB
VmData:    70340 kB
VmStk:       136 kB
VmExe:         8 kB
VmLib:      6108 kB
VmPTE:       296 kB
VmSwap:        0 kB


[frank]

Code Auswählen Erweitern

# for i in `pgrep [f]hem`; do echo "PID $i"; cat /proc/$i/status; done
-sh: pgrep: not found
# ps | grep [f]hem | cut -f2 -d " "
1495
1829
die 2. version funktioniert. aber!
das scheint eventuell nicht ganz das richtige verfahren zu sein, da ich für fhem immer die selbe grösse erhalte. falls fhem forked, wäre dann ein weiterer fhem prozess über "ps" zu sehen, oder würde die speichergrösse von fhem sich ändern?

[Wernieman]

Dann einfach mal probieren:
for i in `ps | grep [f]hem | cut -f2 -d " "`; do echo "PID $i"; cat /proc/$i/status; done

Das kannst Du dann z.B. per cron wegschreiben lassen und hast bei einem Fehlerfalle ein Logfile ....

Du hast übrigens schon ein folk! Deshalb 2 PIDs ....

[frank]

Code Auswählen Erweitern

for i in `ps | grep [f]hem | cut -f2 -d " "`; do echo "PID $i"; cat /proc/$i/status; done
danke, funktioniert. die 2.PID ist übrigens der hmland, also kein fork.

Code Auswählen Erweitern

PID 1829
Name:   perl
State:  S (sleeping)
Tgid:   1829
Pid:    1829
PPid:   1
TracerPid:      0
Uid:    0       0       0       0
Gid:    0       0       0       0
NetMark:        0
FDSize: 256
Groups:
VmPeak:    36428 kB
VmSize:    36168 kB
VmLck:         0 kB
VmHWM:     31952 kB
VmRSS:     31420 kB
VmData:    31496 kB
VmStk:        88 kB
VmExe:      1444 kB
VmLib:      2912 kB
VmPTE:        44 kB
Threads:        1
SigQ:   0/475
SigPnd: 00000000000000000000000000000000
ShdPnd: 00000000000000000000000000000000
SigBlk: 00000000000000000000000000000000
SigIgn: 00000000000000000000000000021080
SigCgt: 00000000000000000000000180006003
CapInh: 0000000000000000
CapPrm: fffffffffffffeff
CapEff: fffffffffffffeff
CapBnd: fffffffffffffeff
voluntary_ctxt_switches:        16601
nonvoluntary_ctxt_switches:     125498
sehe ich das richtig, dass unter "VmSize" die aktuelle grösse und unter "VmPeak" die maximale grösse seit fhemstart zu sehen sind? demnach ändert sich der fhem-speicherwert dann wohl doch. welche werte wären denn noch aussagekräftig bezüglich der "forkproblematik" und einem eventuellen nicht wieder freigegebenen speicher?

Das kannst Du dann z.B. per cron wegschreiben lassen

  da muss der windows user erst einmal forschen gehen.

[Wernieman]

Also die wichtigen ...

um das logfile etwas "kleiner" zu machen:

Code Auswählen Erweitern

for i in `ps | grep [f]hem | cut -f2 -d " "`; do echo "PID $i"; grep -e Vm -e PPid /proc/$i/status; done

Auf die Kürze würde ich "nur" die Vm-Daten als Wichtig erachten ...

[frank]

Code Auswählen Erweitern

for i in `ps | grep [f]hem | cut -f2 -d " "`; do echo "PID $i"; grep -e Vm -e PPid /proc/$i/status; done
das funktioniert auch klasse.

ich habe jetzt das modul customreadings gefunden, das mir die daten loggen kann. aber immer nur für einen satz daten. also für eine pid. daraufhin habe ich den einzeiler umgebaut, was auch funktioniert. aber das modul kommt hiermit nicht klar. das nroblem scheint das dolarzeichen der variable zu sein. es muss doch auch eine lösung ohne "for" geben, aber ich komme nicht darauf.

Code Auswählen Erweitern

for i in `ps | grep fhem.pl | cut -f2 -d " "`; do grep -e Vm -e PPid /proc/$i/status; done

vielleicht hat jemand eine idee?

gruss frank