Cannot fork: Cannot allocate memory

[P.A.Trick]

Versuche es mal mit awk in der Shell!

[frank]

Versuche es mal mit awk in der Shell!

das ist zu "hoch" für mich.

[hexenmeister]

Versuche es mal mit awk in der Shell!

Hat Fritte ja nicht.

[Wernieman]

Also ohne Variable ... wird schwer.

Für den ersten FHEM-Prozess könntest DU machen:

Code Auswählen Erweitern

grep -e Vm -e PPid /proc/`ps | grep -m1 [f]hem | cut -f2 -d " "`/status

Kann es jetzt nur nicht testen .. und optimal ist es auch nicht (

[frank]

gute idee. aber über telnet funktioniert es genau einmal. beim 2. mal kommt:

Code Auswählen Erweitern

# grep -e Vm -e PPid /proc/`ps | grep -m2 [f]hem | cut -f2 -d " "`/status
grep: 1832/status: No such file or directory
da wird der erste teil des pfads "vergessen". komisch.

[Wernieman]

... sorry, aber da ich momentan keine "Fritte" zum Testen habe, meine Unix-Server es brav machen .....

Warum willst Du aber FHEM durch FHEM überwachen? Gerade bei solchen "Problemen" wäre eine Externe Überwachung optimaler ..

[frank]

Warum willst Du aber FHEM durch FHEM überwachen? Gerade bei solchen "Problemen" wäre eine Externe Überwachung optimaler

recht hast du.
das war erst einmal als "schneller, einfacher" überblick geplant, um das verhalten der für mich neuen daten kennen zu lernen. sollte mir auch vorläufig das weitere vertiefen in linux ersparen, was aber nicht danach aussieht. 

[Wernieman]

Besser währe es:

Per externen Cron-Script-Sammeln und ablegen
Wenn Du willst (wegen Grafen) vom Script per nc (telnet) in fhem dummys pusten

[rudolfkoenig]

Zu der VmPeak-Ueberwach-Thematik (wieso sucht man nach grep/cut/awk, wenn man perl hat?):

Code Auswählen Erweitern

define d dummy
define a at +*00:05 { my $a=`cat /proc/$$/status`;; $a=~s/.*VmPeak:\s*(\d+).*/$1/s;; fhem "tigger d $a" }

(FritzBox-getestet)

Beim gesetzten "global stacktrace" wird bei einem fork() Fehler ab sofort ein Stacktrace generiert.

[Wernieman]

Viele Wege führen nach Rom ;o)

Sollte noch für die anderen Vm-Werte angepasst werden ...

[frank]

perl, das land meiner träume. danke. 

[frank]

erste erkenntnisse.

mit dem kleinen "at" von rudi, dass ich natürlich kräftig erweitert habe, konnte ich schon mal ein paar module entfernen, was den "empfindlichen" speicher der fritzbox schon sehr entlastet hat. sysmon, so meine vermutung, hat fhem sogar jede nacht, kurz nach dem täglichen reconnect der fritzbox, zum absturz gebracht. die box ist aber schön weitergelaufen. das sollte man sicherlich noch genauer untersuchen, jetzt aber ersteinmal nicht.

ich habe jetzt einen sehr hilfreichen "marker" entdeckt (oom_score = "badness"), mit dem man sehr schön den "verbrauch" des freien speichers fhem anlasten kann, oder eben auch nicht. es gibt wohl dazu passend einen oom_killer, der bei extremer systemspeichernot processe mit den höchsten oom_score werten killt. daher vermute ich, dass ein systemeindringling, wie fhem, immer ganz oben auf der liste steht. also den oom_score immer niedrig halten. oom_score und free_ram sind auf meiner 7390 auszulesen mit:

Code Auswählen Erweitern

cat /proc/<pid_fhem>/oom_score
cat | free

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

mit diesen 2 werten, kann ich eigentlich jetzt schon ziehmlich gut die belastung meiner fritzbox durch fhem beurteilen. anhand des plots ist sehr schön zu erkennen, dass bei den ersten verlusten des freien speichers der oom_score von fhem gleichzeitig ansteigt. hier habe ich jeweils im browser eine raum-übersicht (devices + 2 plots) von fhem reloaded. zu erwähnen ist dazu noch, dass in diesen fällen der freie speicher gross genug war, sodass der genutzte speicher quasi sofort wieder freigegeben wurde, was der kernel mit einer umgehenden reduzierung des oom_scores auf den vorherigen basiswert honoriert. 

entscheidend aber in diesem plot, ist der grosse "happen" am ende gegen 15:45. hier habe ich mich mit dem browser über das webif auf der fritzbox eingeloged. das braucht schon mal knapp 4MB. aber das seltsamste ist, dass der speicher nicht wieder freigegeben wird! selbst ein ausloggen und dann das löschen des browsertabs hat keine änderung ergeben. ich habe sogar ein wenig gewartet, bis zum nächsten oom_score peak. hier habe ich nun die erwähnte raum-übersicht wieder neu geladen, um fehler zu provozieren. aber im gegenteil, nun hat fhem die fritzbox dazu veranlasst den "blockierten" speicher endlich zu räumen. ich lerne daraus, das webif der fritzbox, wenn möglich, zu meiden. bisher hatte ich beim experimentieren mit fhem häufig gleichzeitig einen tab mit dem webif geöffnet. nun besser nicht mehr.

die bisherigen tests haben gezeigt, dass es wohl auch eine mindestgrösse des freien speichers gibt, die nicht freigegeben wird. die niedrigsten werte des freien speichers lagen bei mir nie unter 10000, immer knapp drüber. einige infos im internet lassen vermuten, dass der linuxkernel "reserve-speicher" blockt. daraufhin habe ich folgenden wert entdeckt, den ich in diesem zusammenhang sehe und der in meiner box auf 8192kB steht. zumindestens würde das zu den beobachteten 10 MB passen. vielleicht weiss ja jemand näheres.

Code Auswählen Erweitern

cat /proc/sys/vm/min_free_kbytes

damit würde sich aber sozusagen der "reale" frei speicher deutlich reduzieren. wenn man dann noch den speicher fürs webif dazunimmt, bleibt für fhem nicht mehr viel, und meldungen wie "cannot allocate memory" werden schwer zu vermeiden sein. ich habe mir jetzt übrigens ein setreading in die fork-sub eingebaut, um die meldungen mit zu plotten. mit hilfe des neuen "qualitäts-indikators" sind jetzt noch keine meldungen aufgetaucht. der oom_score beginnt bei mir übrigens mit knapp 400 beim rebooten der box und sinkt quasi im laufe der zeit, wie die entladekurve eines kondensators. nach knapp 4 std ist er von 391 auf jetzt 44 gesunken.

grobes zwischenfazit: freier speicher um 20MB (wenige module, kein webif von der box), oom_score niedrig halten, nach einem reboot der box fhem ein wenig zeit gönnen (nicht gleich dutzende plots aufrufen).
jeder fritzbox nutzer müsste eigentlich den oom_score und free_ram im fhem-logo angezeigt bekommen. 

gruss frank

[rudolfkoenig]

Das Linux Haupspeichermanagement ist nicht einfach, und aendert sich oefters, so dass mein Wissen von vor 15 Jahren varaltet ist, aber:
- free allein sagt nicht viel aus, eigentlich sollte free gegen 0 tendieren, damit der teuer bezahlte Hauptspeicher auch verwendet wird, z.Bsp. zum cachen von Dateien (== buffers).
- fork braucht nicht sofort die gleiche Speichermenge, weil die Seiten zunaechst "Copy on Write" markiert werden, und erst bei einer Aenderung einer Seite durch einen der beiden Prozesse die Kopie erstellt wird.
- fork wird auch dann erlaubt, wenn weniger Speicher zur Verfuegung steht, als maximal benoetigt, da es unwahrscheinlich ist, dass alle Seiten geaendert werden. Wenn die Seiten wg. Speichermangel nicht mehr kopiert werden koennen, wird der Pechvogel abgeschossen.
- wie gross ein Prozess ist, ist schwer zu sagen, weil viele Seiten von mehreren Prozessen gemeinsam verwendet werden (Stichwort shared library).
- die Fritzbox verwendet ein Teil seines Hauptspeichers (8MB?) als komprimierten Swap

Das hilft erstmal nicht konkret weiter, ich wollte damit nur andeuten, dass bevor man aus irgendwelchen Zahlen in /proc Schluesse zieht, sich ein paar White-Papers zu Gemuete fuehren sollte. Damit es nicht zu einfach wird, veralten White-Papers schneller, als es einem lieb ist, und je nach Prozessor/Architektur gibt es Abweichungen vom White-Paper.

[frank]

danke für die hinweise.

letzenendes möchte ich ja nicht unbedingt in erfahrung bringen welches byte wo und warum gespeichert wird. jeder tip und jede info hilft natürlich im verständnis der zusammenhänge und vor allem in der anschliessenden beurteilung der auswirkungen. im augenblick geht es mir eher darum, ab wann wird die fritzbox unzuverlässig und welche module/aktionen sind kritischer als andere. immerhin hat sie eine ziehmlich lange zeit tapfer einigermassen zuverlässig mitgemacht. igendwann war wohl ein limit erreicht, das ich aber bisher keinem bestimmten ereignis zuordnen konnte. nun möchte ich sozusagen versuchen irgendwo ein limit zu erkennen und das mit möglichst einfachen mitteln.

- free allein sagt nicht viel aus, eigentlich sollte free gegen 0 tendieren, damit der teuer bezahlte Hauptspeicher auch verwendet wird, z.Bsp. zum cachen von Dateien (== buffers).
- die Fritzbox verwendet ein Teil seines Hauptspeichers (8MB?) als komprimierten Swap

free liefert mir folgendes ergebnis. da nutze ich zur zeit den wert, der angeblich ohne buffer gilt. den swap anteil hatte ich jetzt auch zusätzlich gesehen, wegen der seltsamen grösse bei total, denn used+free=total, und wenn ich da dann swap und buffer addiere, komme ich in die nähe von 128kB. wieder alles spekulation, ich weiss. free ist im augenblick aber ein sehr schöner wert, der sich mit aktionen in fhem korrelieren lässt und der fehler "cannot allocate memory" deutet ja sehr stark nach nicht ausreichend vorhandenem speicher hin. jeder bessere wert ist natürlich herzlich willkommen.

total        used         free       shared      buffers
Mem:        107872     86992       20880          0          2228
-/+ buffers:              84764        23108
Swap:        16376            0        16376

meine bisherigen beobachtungen lassen aber sehr stark vermuten, dass es ein, wie auch immer geartetes, lowlimit für diesen speicherwert gibt. schon im ersten plot am anfang des threads, war ja zu erkennen, das speicheranforderungen, ausgehend von einem hohen verfügbaren level ohne fehler stattfanden und von einem tieferen level mitunter fehler erzeugten. die resultierenden free werte lagen dabei immer über diesem "lowlevel". wenn keine fehler auftraten war der tiefe free wert dann über eine längere zeitspanne gegeben. also in kleinen häppchen dargereicht.
im neuen plot ist mein neuester tiefstwert mit 8276 kB zu erkennen. entstanden durch das laden einer raumübersicht mit vielleicht 7-8 plots, in denen auch noch ziehmlich viele kurven stecken. in letzter zeit kaum zu gebrauchen, da die fritzbox regelmässig abgestürzt ist. heute ohne probleme in rekordzeit dargestellt.

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

im neuen plot habe ich jetzt ein presence device wieder enabled. es erzeugt pings über lan im 60 sek rythmus. ich finde es schon erstaunlich was dieses "kleine" zusätzliche device für auswirkungen auf das speicherverhalten zeigt. die abtastung der plotdaten erfolgt allerdings im 5 sek rythmus, um alle aktivitäten erkennen zu können. eine sicher auch belastende angelegenheit. eine 30 sek abtastung sah aber auch nicht viel anders aus. da kann ich mir gut vorstellen, wie der plotverlauf bei jemandem aussieht der eventuell 4-5 handys anpingt, oder sogar noch weiteres equipment. ansonsten startet fhem bei mir mit 339 entities. trotzdem funktionierte die ansicht der 7-8 plots in rekordzeit und fällt noch nicht einmal besonders auf.

wär schön, wenn ich von anderen fritzbox usern plots zum vergleichen sehen könnte. bei bedarf poste ich gerne meine codes.

gruss frank

[frank]

so schaut es aus, wenn fhem abstürzt. ich habe dafür das fritzboxmodul wieder definiert und gleichzeitig läuft auch das presence device wieder.

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

der obere plot zeigt den free memory der fritzbox mit dem oom_score von fhem. der untere plot zeigt vmSize,vmRSS und vmData von fhem. zusätzlich kann man die no_fork meldungen jeweils am unteren plotrand als rote peaks erkennen.

zu sehen sind 3 reboots (oom_score=400 und blaue init-peaks im unteren plot), die durch ein fhemabsturz nötig wurden. erste anzeichen der abstürze sind bereits vorher zu erkennen. im oberen plot verschwinden jeweils plötzlich die markanten speicherzugriffe (dunkelgrüne vertikale linien) und, wie im anderen post angesprochen, die mit diesen speicherzugriffen korrellierenden peaks bei oom_score. jedesmal direkt mit einer no_fork-meldung beginnend.

im unteren plot fällt auf, dass vmRSS zu diesen zeiten oft plötzlich weit unterhalb von vmData verläuft. im "normalfal" liegt vmRSS sehr nahe bei vmData, meist ein paar kB drüber.

die markanten speicherzugriffe können eigentlich drei modulen zugeordnet werden. proplanta (bis ca 9:00 ausschliesslich) presence und fritzbox. mit starten von fritzbox fangen dann die forkmeldungen an. zusätzlich sind natürlich noch manuelle aktionen über webif dabei. das seltsamste an diesen "zombie" zuständen vor dem absturz ist, dass ich im log trotzdem noch erfolgreiche datenerfassungen bekomme (zb proplanta 17:00). andererseits habe ich während einer dieser phasen im presence modul das attribut verbose auf 5 gestellt, aber im log wurde nichts geschrieben, obwohl das setzen des attributes normal ausgeführt wurde. ebenso save config. nach dem folgenden reboot hat es dann wie gewünscht funktioniert.

für den letzen zomby zustand, hier noch ein log ab der letzen no_fork meldung. presence und fritzbox melden einfach gar nichts mehr, als seien sie verschwunden. fhem über webif ist noch zu bedienen.

Code Auswählen Erweitern

2015.08.15 22:22:38.962 5: PRESENCE (laptop) - stopping timer
2015.08.15 22:22:38.965 5: PRESENCE (laptop) - starting blocking call for mode lan-ping
2015.08.15 22:22:39.052 5: PRESENCE (laptop) - starting ping scan: laptop|192.168.1.21|0|4
2015.08.15 22:22:47.414 1: Perfmon: possible freeze starting at 22:22:46, delay is 1.413
2015.08.15 22:22:52.078 5: PRESENCE (laptop) - ping command returned with output:
PING 192.168.1.21 (192.168.1.21): 56 data bytes

--- 192.168.1.21 ping statistics ---
4 packets transmitted, 0 packets received, 100% packet loss
2015.08.15 22:22:52.114 5: PRESENCE (laptop) - blocking scan result: laptop|0|absent
2015.08.15 22:22:52.331 4: PRESENCE (laptop) - rescheduling next check in 60 seconds
2015.08.15 22:23:02.075 1: Perfmon: possible freeze starting at 22:23:01, delay is 1.074
2015.08.15 22:23:06.383 1: Perfmon: possible freeze starting at 22:23:05, delay is 1.382
2015.08.15 22:23:31.185 1: Perfmon: possible freeze starting at 22:23:30, delay is 1.184
2015.08.15 22:23:52.343 5: PRESENCE (laptop) - stopping timer
2015.08.15 22:23:52.347 5: PRESENCE (laptop) - starting blocking call for mode lan-ping
2015.08.15 22:23:52.359 1: Cannot fork: Cannot allocate memory
2015.08.15 22:23:52.612 1: Cannot fork: Cannot allocate memory
2015.08.15 22:23:52.653 1: PERL WARNING: Use of uninitialized value $i in hash element at fhem.pl line 2624.
2015.08.15 22:23:52.655 1: PERL WARNING: Use of uninitialized value $i in hash element at fhem.pl line 2625.
2015.08.15 22:23:52.657 1: PERL WARNING: Use of uninitialized value $i in delete at fhem.pl line 2627.
2015.08.15 22:24:23.627 1: Perfmon: possible freeze starting at 22:24:22, delay is 1.626
2015.08.15 22:24:34.347 1: Perfmon: possible freeze starting at 22:24:31, delay is 3.346
2015.08.15 22:24:52.936 1: Perfmon: possible freeze starting at 22:24:38, delay is 14.843
2015.08.15 22:24:56.657 1: FRITZBOX fritz: Exec_Local.2362 Error: No STDOUT from shell command.
2015.08.15 22:24:59.258 1: Perfmon: possible freeze starting at 22:24:53, delay is 6.258
2015.08.15 22:25:02.921 1: Perfmon: possible freeze starting at 22:25:00, delay is 2.92
2015.08.15 23:05:02.990 1: Perfmon: possible freeze starting at 23:05:01, delay is 1.99
2015.08.15 23:11:50.002 1: Perfmon: possible freeze starting at 23:11:49, delay is 1.001
2015.08.15 23:11:52.754 1: Perfmon: possible freeze starting at 23:11:51, delay is 1.753
2015.08.15 23:12:14.370 1: Perfmon: possible freeze starting at 23:12:13, delay is 1.37
2015.08.15 23:12:51.116 1: Perfmon: possible freeze starting at 23:12:50, delay is 1.115
2015.08.15 23:13:32.486 1: Perfmon: possible freeze starting at 23:13:31, delay is 1.485
2015.08.15 23:13:34.052 1: Perfmon: possible freeze starting at 23:13:33, delay is 1.052
2015.08.15 23:16:56.775 3: IT01 on->off
2015.08.15 23:16:57.026 1: ----- SYNC-ITR1500 ----- FB_IT01_chn01:off => IT01:off


gibt es dazu erklärungsansätze, oder tipps zur weiteren untersuchung?

gruss frank