hallo,
seit längerem habe ich in unregelmässigen abständen folgende fehlermeldungen im log. fhem läuft auf fritzbox 7390.
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):
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:
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:
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
Zitatglobales 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.
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
ZitatIch 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.
Zitat von: Elektrolurch am 11 August 2015, 07:43:01
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.
Zitat von: rudolfkoenig am 11 August 2015, 06:56:22
Zitatglobales fehlerevent existiert, um die forkmeldungen zu loggen
Ich verstehe nicht, was damit gemeint ist.
rince hat das schon sehr gut erkannt:
Zitat von: Rince am 11 August 2015, 08:23:17
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...).
ZitatDie 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
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.
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.
ZitatWenn FHEM 50mb RAM belegt und dann geforked wird, werden 50mb RAM zusätzlich benötigt.
das passt glaube ich nicht zu dem plott.
ZitatAuf 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
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.
ich habe mir hier (http://forum.fhem.de/index.php/topic,17201.msg321598.html#msg321598) ein wenig hilfe zum plotten gesucht und schiebe das kurz nach, damit es hier weitergehen kann.
Zitatum 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.
ZitatHi 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 :(
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:
ps | grep "fhem.pl fhem.cfg" | grep -v grep
und gefundenen PID einsetzen:
cat /proc/<PID>/status | grep VmSize
K.A. wie man das auf der Box automatisieren kann...,
Zitat
Kleine optimierung:
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:
# 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
Kleine Frage:
Gibt es unter der Fritte ein pgrep?
Dann könnte man vereinfacht die Stati auslesen mit:
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":
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)
# 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
# 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?
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 ....
for i in `ps | grep [f]hem | cut -f2 -d " "`; do echo "PID $i"; cat /proc/$i/status; donedanke, funktioniert. die 2.PID ist übrigens der hmland, also kein fork.
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: 125498sehe 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?
ZitatDas kannst Du dann z.B. per cron wegschreiben lassen
;D ;D ;D da muss der windows user erst einmal forschen gehen.
Also die wichtigen ...
um das logfile etwas "kleiner" zu machen:
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 ...
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.
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
Versuche es mal mit awk in der Shell!
Zitat von: P.A.Trick am 12 August 2015, 22:07:59
Versuche es mal mit awk in der Shell!
das ist zu "hoch" für mich.
Zitat von: P.A.Trick am 12 August 2015, 22:07:59
Versuche es mal mit awk in der Shell!
Hat Fritte ja nicht.
Also ohne Variable ... wird schwer.
Für den ersten FHEM-Prozess könntest DU machen:
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 :o(
gute idee. aber über telnet funktioniert es genau einmal. beim 2. mal kommt:
# 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.
... 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 ..
ZitatWarum 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. :)
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
Zu der VmPeak-Ueberwach-Thematik (wieso sucht man nach grep/cut/awk, wenn man perl hat?):
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.
Viele Wege führen nach Rom ;o)
Sollte noch für die anderen Vm-Werte angepasst werden ...
perl, das land meiner träume. danke. 8)
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:
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.
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
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.
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.
Zitat- 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.
Zitattotal 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
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.
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
Ich vermute, dass ein Modul im Problemfall unbegrenzt Prozesse forkt. Um das zu lokalisieren koennte man:
- aktuelles fhem.pl verwenden, und attr global stacktrace aktivieren: damit wird angezeigt, welches Modul das schiefgegangene fork bestellt hat.
- `ps|grep perl|wc -l` Plotten, um festzustellen, wieviele geforkte perl-Prozesse gleichzeitig rumhaengen.
- falls ungewuehnlich viele offen sind, mit ps | grep perl die pids feststellen.
- attr global loglevel auf mind. 4 stellen, und im Log nach "BlockingCall created child ($pid)" suchen, damit kriegt man mit, wann die Prozesse gestartet wurden. Evtl. diese Meldung in Blocking.pm erweitern, so dass $blockingFn/$arg ausgegeben wird.
die fritzbox mit einem reboot "zu bett" gebracht, lief dann, ohne weitere störungen über das fhem webif, bis zum morgen reibungslos.
(http://forum.fhem.de/index.php?action=dlattach;topic=39887.0;attach=36097;image)
die anzahl der prozesse zeigt leider keine auffälligkeiten. über telnet konnte ich auch keine hängenden prozesse entdecken. dazu habe ich noch die swap nutzung geplottet. hierbei fällt auf, dass der swapspeicher nur genutzt wird, wenn fhem im zombie modus ist, aber auch nicht immer.
(http://forum.fhem.de/index.php?action=dlattach;topic=39887.0;attach=36099;image)
die logausgabe bei no_fork vom webif ergibt einen kleinen unterschied zu allen anderen no_fork meldungen. nach der stacktraceliste erscheint bei allen anderen no_fork "clienten" immer eine 2. no_fork meldung, aber ohne stacktraceausgabe. ist das handling hier unterschiedlich?
die reaktion auf ein abgewiesenen fork scheint auch unterschiedlich bei den modulen zu sein. presence ist hier äusserst sensibel. sobald ein fork abgelehnt wird, bleibt es stumm. keine weiteren versuche mehr. beim fritzboxmodul sieht das anders aus. das ausbleiben der presence meldungen habe ich jetzt ersteinmal zur ansteuerung eines watchdogs genutzt, um die fritzbox zu rebooten.
2015.08.16 18:13:39.254 1: Cannot fork: Cannot allocate memory
2015.08.16 18:13:39.256 1: stacktrace:
2015.08.16 18:13:39.258 1: main::fhemFork called by ./FHEM/01_FHEMWEB.pm (412)
2015.08.16 18:13:39.259 1: main::FW_Read called by fhem.pl (3045)
2015.08.16 18:13:39.261 1: main::CallFn called by fhem.pl (648)
2015.08.16 18:13:41.040 1: PERL WARNING: Use of uninitialized value $p in hash element at fhem.pl line 637.
2015.08.16 18:13:41.235 1: Perfmon: possible freeze starting at 18:13:31, delay is 10.234
2015.08.16 18:13:41.537 1: Cannot fork: Cannot allocate memory
2015.08.16 18:13:41.539 1: stacktrace:
2015.08.16 18:13:41.540 1: main::fhemFork called by FHEM/Blocking.pm (70)
2015.08.16 18:13:41.542 1: main::BlockingCall called by ./FHEM/72_FRITZBOX.pm (628)
2015.08.16 18:13:41.543 1: main::FRITZBOX_Readout_Start called by fhem.pl (2670)
2015.08.16 18:13:41.545 1: main::HandleTimeout called by fhem.pl (581)
2015.08.16 18:13:41.920 1: Cannot fork: Cannot allocate memory
2015.08.16 18:13:43.469 1: PERL WARNING: Use of uninitialized value $i in hash element at fhem.pl line 2663.
2015.08.16 18:13:44.110 1: PERL WARNING: Use of uninitialized value $i in hash element at fhem.pl line 2664.
2015.08.16 18:13:44.112 1: PERL WARNING: Use of uninitialized value $i in delete at fhem.pl line 2666.
2015.08.16 18:13:44.152 1: Cannot fork: Cannot allocate memory
2015.08.16 18:13:44.154 1: stacktrace:
2015.08.16 18:13:44.155 1: main::fhemFork called by ./FHEM/01_FHEMWEB.pm (412)
2015.08.16 18:13:44.157 1: main::FW_Read called by fhem.pl (3045)
2015.08.16 18:13:44.158 1: main::CallFn called by fhem.pl (648)
2015.08.16 18:13:46.947 1: PERL WARNING: Use of uninitialized value $p in hash element at fhem.pl line 637.
2015.08.16 18:13:47.705 1: Perfmon: possible freeze starting at 18:13:42, delay is 5.705
2015.08.16 18:13:48.268 1: Cannot fork: Cannot allocate memory
2015.08.16 18:13:48.270 1: stacktrace:
2015.08.16 18:13:48.271 1: main::fhemFork called by ./FHEM/01_FHEMWEB.pm (412)
2015.08.16 18:13:48.273 1: main::FW_Read called by fhem.pl (3045)
2015.08.16 18:13:48.275 1: main::CallFn called by fhem.pl (648)
2015.08.16 18:13:49.419 1: PERL WARNING: Use of uninitialized value $p in hash element at fhem.pl line 637.
zum abschluss noch ein log auf der telnetconsole als die ganze fritzbox abgestürzt ist. sieht für mich aber nicht sehr hilfreich aus.
Aug 16 14:34:47 ddnsd[948]: Signal Segmentation fault while doing crashdump (2)
Aug 16 14:34:47 ddnsd[948]: /var/flash/crash.log opened
Aug 16 14:34:47 ddnsd[948]: 2015-08-16 14:34:47(2) [Segmentation fault] ddnsd(948) CRASHED at strcmp (/lib/libc.so.0 at 00037550) accessing 0+0x6c6f742a (/lib/libavmcipher.so.0 at 4191442a)
Aug 16 14:34:47 ddnsd[948]: SIGNO 11 ERRNO 0 CODE 1
Aug 16 14:34:47 ddnsd[948]: ze: 00000000 at: 7ff3eff4 v0: ffffffdd v1: 00000020
Aug 16 14:34:47 ddnsd[948]: a0: 6c6f742b a1: 2ad988cc a2: 0000001f a3: 00000000
Aug 16 14:34:47 ddnsd[948]: t0: 00000064 t1: 00000000 t2: 00000000 t3: 00000000
Aug 16 14:34:47 ddnsd[948]: t4: 000002da t5: 00000001 t6: 2abf53cc t7: 2abf9a3c
Aug 16 14:34:47 ddnsd[948]: s0: 7ff3dac8 s1: 00000000 s2: 2ad988bc s3: 2ad76000
Aug 16 14:34:47 ddnsd[948]: s4: 7ff3daf4 s5: 2ad7b550 s6: 2ad988cc s7: 6c6f7427
Aug 16 14:34:47 ddnsd[948]: t8: 000000c0 t9: 2ad1d550 k0: 00000001 k1: 00000000
Aug 16 14:34:47 ddnsd[948]: gp: 2ad98460 sp: 7ff3d478 fp: 6c6f742b ra: 2ad0b34c
Aug 16 14:34:47 ddnsd[948]: FA 6c6f742a 0+0x6c6f742a (/lib/libavmcipher.so.0 at 4191442a)
Aug 16 14:34:47 ddnsd[948]: PC 2ad1d550 strcmp (/lib/libc.so.0 at 00037550)
Aug 16 14:34:48 ddnsd[948]: RA 2ad0b34c 0+0x2ad0b34c (/lib/libc.so.0 at 0002534c)
Aug 16 14:34:48 ddnsd[948]: Code: 03e00008 00000000 00000000 <90830000> 90a20000 24840001 14600003 24a50001 03e00008
Aug 16 14:34:48 ddnsd[948]: [bt] 2ad0b344 [2ad0b270] <0+0x2ad0b270>+0xd4 (/lib/libc.so.0 at 00025270)
Aug 16 14:34:48 ddnsd[948]: [bt] 2ad0972c localtime_r+0x7c (/lib/libc.so.0 at 000236b0)
Aug 16 14:34:48 ddnsd[948]: [bt] 2ac42bc8 [2ac42a74] <0+0x2ac42a74>+0x154 (/lib/libavmcsock.so.2 at 0004fa74)
Aug 16 14:34:48 ddnsd[948]: [bt] !7ff3db60 rtsignal trampoline on stack
Aug 16 14:34:48 ddnsd[948]: [bt] 2ac03f34 slab_object_info+0x60 (/lib/libavmcsock.so.2 at 00010ed4)
Aug 16 14:34:48 ddnsd[948]: [bt] 2ab9fa54 [2ab9d728] <0+0x2ab9d728>+0x232c (/lib/libewnwlinux.so.2 at 0000f728)
Aug 16 14:34:48 ddnsd[948]: [bt] 2ac24dd4 [2ac24d6c] <0+0x2ac24d6c>+0x68 (/lib/libavmcsock.so.2 at 00031d6c)
Aug 16 14:34:48 ddnsd[948]: [bt] 2ac26a50 csock_select_with_timeval+0x42c (/lib/libavmcsock.so.2 at 00033624)
Aug 16 14:34:48 ddnsd[948]: [bt] 004029c4 main+0x774 (ddnsd at 00002250)
Aug 16 14:34:52 ctlmgr[933]: /var/flash/crash.log opened
Aug 16 14:34:52 ctlmgr[933]: 2015-08-16 14:34:52(1) [Bus error] ctlmgr(933) CRASHED at 0+0x2acf3fac (/lib/libavmcsock.so.2 at 0000efac) accessing 0+0x8443001c (/lib/libhtmltemplate.so.0 at 57c9f01c)
Aug 16 14:34:52 ctlmgr[933]: SIGNO 10 ERRNO 0 CODE 2
Aug 16 14:34:52 ctlmgr[933]: Version: 06.04
Aug 16 14:34:52 ctlmgr[933]: Watchdog triggered 49 seconds ago
Aug 16 14:34:52 ctlmgr[933]: No bugmsg
Aug 16 14:34:52 ctlmgr[933]: ze: 00000000 at: 2ad5b83a v0: 2ad65000 v1: 00000001
Aug 16 14:34:52 ctlmgr[933]: a0: 7f9eb160 a1: 84430000 a2: 0000001b a3: 2ab3131c
Aug 16 14:34:52 ctlmgr[933]: t0: 2c57a050 t1: 00000000 t2: 372e3134 t3: 362e3235
Aug 16 14:34:52 ctlmgr[933]: t4: 302e3130 t5: 343a3830 t6: 38392f31 t7: 31386432
Aug 16 14:34:52 ctlmgr[933]: s0: 2ad65000 s1: 2c57a050 s2: 2ab38000 s3: 00000002
Aug 16 14:34:52 ctlmgr[933]: s4: 2c5d3000 s5: 2c5e0a60 s6: 2c5f54e4 s7: 2ad25000
Aug 16 14:34:52 ctlmgr[933]: t8: 00000000 t9: 2acf5000 k0: 00000000 k1: 00000000
Aug 16 14:34:52 ctlmgr[933]: gp: 2ad65090 sp: 7f9eb140 fp: 2ad15000 ra: 2acf5dd0
Aug 16 14:34:52 ctlmgr[933]: FA 8443001c 0+0x8443001c (/lib/libhtmltemplate.so.0 at 57c9f01c)
Aug 16 14:34:52 ctlmgr[933]: PC 2acf3fac 0+0x2acf3fac (/lib/libavmcsock.so.2 at 0000efac)
Aug 16 14:34:52 ctlmgr[933]: RA 2acf5dd0 slab_free_wheredebug+0x58 (/lib/libavmcsock.so.2 at 00010dd0)
Aug 16 14:34:52 ctlmgr[933]: Code: 27a40020 10a00008 00000000 <8ca3001c> 0103182b 1060000c 00000000 8ca5000c 14a0fffa
Aug 16 14:34:52 ctlmgr[933]: [bt] 2acf5dc8 slab_free_wheredebug+0x50 (/lib/libavmcsock.so.2 at 00010d78)
Aug 16 14:34:53 ctlmgr[933]: Signal Segmentation fault while doing crashdump (2)
Aug 16 14:34:53 ctlmgr[933]: /var/flash/crash.log opened
Aug 16 14:34:53 ctlmgr[933]: 2015-08-16 14:34:53(2) [Segmentation fault] ctlmgr(933) CRASHED at 0+0x2c69fbcc (/lib/libmsgwrap.so.1 at 00000bcc) accessing 0+0x659ffaca (/lib/libmsgwrap.so.1 at 39360aca)
Aug 16 14:34:53 ctlmgr[933]: SIGNO 11 ERRNO 0 CODE 1
Aug 16 14:34:53 ctlmgr[933]: ze: 00000000 at: 00000001 v0: 00002410 v1: 00000000
Aug 16 14:34:53 ctlmgr[933]: a0: 2c577600 a1: 00000001 a2: 2ad5dba8 a3: 00000001
Aug 16 14:34:53 ctlmgr[933]: t0: 2c577400 t1: 00000000 t2: 00000000 t3: 00000240
Aug 16 14:34:53 ctlmgr[933]: t4: 03e9a79f t5: 80447aa0 t6: 00000248 t7: 00000001
Aug 16 14:34:53 ctlmgr[933]: s0: 2c577600 s1: 2c65e580 s2: ffffffff s3: 00000000
Aug 16 14:34:53 ctlmgr[933]: s4: ffffffff s5: 00000000 s6: 2c57723c s7: 00000004
Aug 16 14:34:53 ctlmgr[933]: t8: 0000021c t9: 659edfce k0: 00000001 k1: 00000000
Aug 16 14:34:53 ctlmgr[933]: gp: 65a07aae sp: 7f9ea6c8 fp: 00000000 ra: 2c6a1454
Aug 16 14:34:53 ctlmgr[933]: FA 659ffaca 0+0x659ffaca (/lib/libmsgwrap.so.1 at 39360aca)
Aug 16 14:34:53 ctlmgr[933]: PC 2c69fbcc 0+0x2c69fbcc (/lib/libmsgwrap.so.1 at 00000bcc)
Aug 16 14:34:53 ctlmgr[933]: RA 2c6a1454 0+0x2c6a1454 (/lib/libmsgwrap.so.1 at 00002454)
Aug 16 14:34:53 ctlmgr[933]: Code: 3c1c0002 279c9ae0 0399e021 <8f82801c> 27bdffd0 afbc0010 90432750 afbf002c afb30028
Aug 16 14:34:53 ctlmgr[933]: [bt] 2c6a144c _fini+0x3c (/lib/libmsgwrap.so.1 at 00002410)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2add8e44 [2add8ca0] <0+0x2add8ca0>+0x1a4 (/lib/libdl.so.0 at 00000ca0)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2add8aa4 [2add8a80] <dl_cleanup+0x10>+0x24 (/lib/libdl.so.0 at 00000a80)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2aaa8f18 _ftext+0x88 (/lib/ld-uClibc.so.0 at 00000e90)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2ae82dc4 [2ae82d58] <exit+0x18>+0x6c (/lib/libc.so.0 at 00059d58)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2ad35514 [2ad34a74] <0+0x2ad34a74>+0xaa0 (/lib/libavmcsock.so.2 at 0004fa74)
Aug 16 14:34:53 ctlmgr[933]: [bt] !7f9eae20 rtsignal trampoline on stack
Aug 16 14:34:53 ctlmgr[933]: [bt] 2acf3fa4 [2acf3f64] <0+0x2acf3f64>+0x40 (/lib/libavmcsock.so.2 at 0000ef64)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2acf5dc8 slab_free_wheredebug+0x50 (/lib/libavmcsock.so.2 at 00010d78)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2ab2e7e0 _cm_set_text_not_null+0x40 (/lib/libcm.so.0 at 000067a0)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2c5b822c get_ProvisioningCode+0x38 (/usr/share/ctlmgr/libtr069.so at 000351f4)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2c597e78 [2c597e10] <0+0x2c597e10>+0x68 (/usr/share/ctlmgr/libtr069.so at 00014e10)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2c596da0 _ZN14ModuleRegistry31GetParameterValueOfRelativePathEP22TR069_Parameter_ModulePcPS2_P9eDataType+0x70 (/usr/share/ctlmgr/libtr06
Aug 16 14:34:53 ctlmgr[933]: [bt] 2c5ce638 [2c5ce5e0] <0+0x2c5ce5e0>+0x58 (/usr/share/ctlmgr/libtr069.so at 0004b5e0)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2c5ceba0 [2c5ceb20] <0+0x2c5ceb20>+0x80 (/usr/share/ctlmgr/libtr069.so at 0004bb20)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2ad2b220 timercb_docallouts+0x1d0 (/lib/libavmcsock.so.2 at 00046050)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2ad18b40 csock_select_with_timeval+0x51c (/lib/libavmcsock.so.2 at 00033624)
Aug 16 14:34:53 ctlmgr[933]: [bt] 00414364 main+0x1e64 (ctlmgr at 00012500)
Aug 16 14:34:53 ctlmgr[933]: [bt] 2ae87158 __uClibc_main+0x2c4 (/lib/libc.so.0 at 0005de94)
Aug 16 14:34:54 configd[414]: /var/flash/crash.log opened
Aug 16 14:34:54 configd[414]: 2015-08-16 14:34:53(1) [Segmentation fault] /bin/configd(414) CRASHED at 0+0x2aaf65a0 (/lib/libavmcsock.so.2 at 000105a0) accessing 0+0x653aea40 (/lib/libwebsrv.so.2 at 3a6d7a40)
Aug 16 14:34:54 configd[414]: SIGNO 11 ERRNO 0 CODE 1
Aug 16 14:34:54 configd[414]: Version: 06.04
Aug 16 14:34:54 configd[414]: No bugmsg
Aug 16 14:34:54 configd[414]: ze: 00000000 at: 00000000 v0: 653aea40 v1: 00000001
Aug 16 14:34:54 configd[414]: a0: f0200409 a1: 2ab46098 a2: 0000044e a3: 0000044e
Aug 16 14:34:54 configd[414]: t0: 00000000 t1: 8017839c t2: 80089f64 t3: fffffff8
Aug 16 14:34:54 configd[414]: t4: 804f0000 t5: 00000000 t6: 2aac23cc t7: 2aac6a3c
Aug 16 14:34:54 configd[414]: s0: 2aab2a2c s1: 2aab2a00 s2: 2ad21ed8 s3: 2ab46098
Aug 16 14:34:54 configd[414]: s4: 2ad28380 s5: 2ab26000 s6: 00000000 s7: 2aab2a00
Aug 16 14:34:54 configd[414]: t8: 0000018e t9: 2aaf6000 k0: 00000000 k1: 00000000
Aug 16 14:34:54 configd[414]: gp: 2ab66090 sp: 7fd3dc98 fp: 0000044e ra: 2aaf68b4
Aug 16 14:34:54 configd[414]: FA 653aea40 0+0x653aea40 (/lib/libwebsrv.so.2 at 3a6d7a40)
Aug 16 14:34:54 configd[414]: PC 2aaf65a0 0+0x2aaf65a0 (/lib/libavmcsock.so.2 at 000105a0)
Aug 16 14:34:54 configd[414]: RA 2aaf68b4 slab_cache_alloc_wheredebug+0x60 (/lib/libavmcsock.so.2 at 000108b4)
Aug 16 14:34:54 configd[414]: Code: 10400043 00000000 8e440000 <ac440000> 8e420000 1040003b 00000000 8e440004 ac440004
Aug 16 14:34:54 configd[414]: [bt] 2aaf68ac slab_cache_alloc_wheredebug+0x58 (/lib/libavmcsock.so.2 at 00010854)
Aug 16 14:34:54 configd[414]: [bt] 2ab25ff8 ipaddrlist_append+0x34 (/lib/libavmcsock.so.2 at 0003ffc4)
Aug 16 14:34:54 feedd[1203]: Signal Segmentation fault while doing crashdump (3)
Aug 16 14:34:54 feedd[1203]: /var/flash/crash.log opened
Aug 16 14:34:54 audiod[1261]: Signal Segmentation fault while doing crashdump (178)
Aug 16 14:34:54 audiod[1261]: /var/flash/crash.log opened
Aug 16 14:34:54 audiod[1261]: 2015-08-16 14:34:54(178) [Segmentation fault] audiod(1261) CRASHED at __dl_runtime_resolve+0x2c (/lib/ld-uClibc.so.0 at 00002e04) accessing 0001429c (?)
Aug 16 14:34:54 feedd[1203]: 2015-08-16 14:34:54(3) [Segmentation fault] feedd(1203) CRASHED at _dl_find_hash+0x84 (/lib/ld-uClibc.so.0 at 00001a48) accessing 0000004c (?)
Aug 16 14:34:54 audiod[1261]: SIGNO 11 ERRNO 0 CODE 1
Aug 16 14:34:54 audiod[1261]: ze: 00000000 at: 00000000 v0: 2ab673cc v1: 00002280
Aug 16 14:34:54 audiod[1261]: a0: 00000228 a1: 2abe5090 a2: 2aaaf6c8 a3: 7fde3e4c
Aug 16 14:34:54 audiod[1261]: t0: 00000000 t1: 0000fc00 t2: 00000000 t3: 86a88000
Aug 16 14:34:54 feedd[1203]: SIGNO 11 ERRNO 0 CODE 1
Aug 16 14:34:54 audiod[1261]: t4: 804f0000 t5: 00000000 t6: ffffffff t7: 2abb4ae0
Aug 16 14:34:54 feedd[1203]: ze: 00000000 at: 00000000 v0: 2aab1460 v1: 2aab1460
Aug 16 14:34:54 audiod[1261]: s0: 0000000b s1: 2abdd0a0 s2: 7fd75a80 s3: 2ab6ba3c
Aug 16 14:34:54 feedd[1203]: a0: 2aba7b73 a1: 2aaaf064 a2: 2aaaf81c a3: 00000001
Aug 16 14:34:54 audiod[1261]: s4: 7fd75b00 s5: 2abc2338 s6: 7fde3e4c s7: 2abc0f70
Aug 16 14:34:54 feedd[1203]: t0: 00000001 t1: 00000000 t2: ffffffff t3: 2aaa8000
Aug 16 14:34:54 feedd[1203]: t4: f0000000 t5: 00000001 t6: 00000000 t7: 2abecae0
Aug 16 14:34:54 feedd[1203]: s0: 00000000 s1: ffffffff s2: 2aaaf064 s3: 00000000
Aug 16 14:34:54 audiod[1261]: t8: 00000228 t9: 00000000 k0: 00000000 k1: 00000000
Aug 16 14:34:54 audiod[1261]: gp: 0001c238 sp: 7fd753b0 fp: 2ab95000 ra: 2aaae318
Aug 16 14:34:54 feedd[1203]: s4: 00000000 s5: 2aaaf81c s6: 2abc6eec s7: 2aba7b73
Aug 16 14:34:54 feedd[1203]: t8: 00000228 t9: 2aaa99c4 k0: 00000000 k1: 00000000
Aug 16 14:34:54 feedd[1203]: gp: 2aac7010 sp: 7ffd2a10 fp: 7ffd2a10 ra: 2aaaae5c
Aug 16 14:34:54 audiod[1261]: FA 0001429c 0001429c (?)
Aug 16 14:34:54 feedd[1203]: FA 0000004c 0000004c (?)
Aug 16 14:34:54 feedd[1203]: PC 2aaa9a48 _dl_find_hash+0x84 (/lib/ld-uClibc.so.0 at 00001a48)
Aug 16 14:34:54 feedd[1203]: RA 2aaaae5c __dl_runtime_resolve+0x84 (/lib/ld-uClibc.so.0 at 00002e5c)
Aug 16 14:34:54 audiod[1261]: PC 2aaaae04 __dl_runtime_resolve+0x2c (/lib/ld-uClibc.so.0 at 00002e04)
Aug 16 14:34:54 feedd[1203]: Code: 00141080 00621021 8c500000 <8e02004c> 30420004 1440000e 00000000 12a0000c 00000000
Aug 16 14:34:54 audiod[1261]: RA 2aaae318 _dl_runtime_resolve+0x48 (/lib/ld-uClibc.so.0 at 00006318)
Aug 16 14:34:54 feedd[1203]: [bt] 2aaaae54 __dl_runtime_resolve+0x7c (/lib/ld-uClibc.so.0 at 00002dd8)
Aug 16 14:34:54 audiod[1261]: Code: afb3002c 8cc20080 8cd3007c <8f998064> 00621021 8c420000 afbe0038 afb50034 02629821
already running
Aug 16 14:35:02 audiod[13018]: audiod 0.6.1 l0 [ DECT UPNP ] (2 streams) started
audiod running as pid 13018
Aug 16 14:35:02 audiod[13018]: new client (0x2aabc200, dect)
Aug 16 14:35:02 audiod[13018]: new client (0x2aabc300, dect)
already running
gruss frank
edit: die watchdogüberwachung des state events vom presencemodul hat gerade nicht funktioniert, da der watchdog events zu empfangen scheint. im eventmonitor sind aber keine zu sehen und auch das presence device im webif zeigt keine änderungen an. in fhem log gibt es auch keine hinweise auf das modul, da ein fork bereits vor längerem abgewiesen war. seit gut 2 stunden wird der timer vom watchdog regelmässig zurückgesetzt. langsam wird es unheimlich. ;) die letzen "echten" lebenszeichen vom presencemodul:
2015.08.16 18:41:08.117 1: BlockingCall created child (4124), uses telnetForBlockingFn to connect back, Fn:PRESENCE_DoLocalPingScan arg:laptop|192.168.1.21|0|4
2015.08.16 18:42:21.374 1: Cannot fork: Cannot allocate memory
2015.08.16 18:42:21.376 1: stacktrace:
2015.08.16 18:42:21.378 1: main::fhemFork called by FHEM/Blocking.pm (70)
2015.08.16 18:42:21.379 1: main::BlockingCall called by ./FHEM/73_PRESENCE.pm (535)
2015.08.16 18:42:21.381 1: main::PRESENCE_StartLocalScan called by fhem.pl (2670)
2015.08.16 18:42:21.383 1: main::HandleTimeout called by fhem.pl (581)
2015.08.16 18:42:21.990 1: Cannot fork: Cannot allocate memory
2015.08.16 18:42:22.112 1: PERL WARNING: Use of uninitialized value $i in hash element at fhem.pl line 2663.
2015.08.16 18:42:22.114 1: PERL WARNING: Use of uninitialized value $i in hash element at fhem.pl line 2664.
2015.08.16 18:42:22.115 1: PERL WARNING: Use of uninitialized value $i in delete at fhem.pl line 2666.
Zitat2015.08.16 18:13:39.258 1: main::fhemFork called by ./FHEM/01_FHEMWEB.pm (412)
Du hast plotfork auf dem Fritzbox aktiviert... Das ist nach meinen Messungen nicht mal auf der FB7490 mit seinen zwei Prozessoren sinnvoll, geschweige denn auf der 7390 mit einem Prozessor und wenig Speicher. Bei plotfork werden die vom Browser bestellten SVGs parallel berechnet, das sind normalerweise 6 zusaetzliche Prozesse. Bedenke: selbst das alte RPi hat 4-mal mehr Speicher, und normalerweise viel weniger aktivierte Dienste.
Zitat2015.08.16 18:13:41.040 1: PERL WARNING: Use of uninitialized value $p in hash element at fhem.pl line 637.
Diese Meldung brauche ich mit einem aktuellen fhem.pl, da die Zeilennummer nicht passt.
ZitatAug 16 14:34:47 ddnsd[948]: Signal Segmentation fault while doing crashdump (2)
Das ist ein Klassiker: Absturz waehrend der Absturzbehandlung. Kernel-Hacker sind auch nicht mehr das, was sie frueher waren.
Die anderen Meldungen sind vmtl. auch nur folgen des Speichermangels, bzw. der schlechten Programmierung.
ZitatDiese Meldung brauche ich mit einem aktuellen fhem.pl, da die Zeilennummer nicht passt.
das war das aktuellste, was es gestern morgen zu holen gab.
# $Id: fhem.pl 9067 2015-08-13 19:02:29Z rudolfkoenig $ jetzt noch mal neu:
2015.08.17 17:27:15.626 1: Cannot fork: Cannot allocate memory
2015.08.17 17:27:15.628 1: stacktrace:
2015.08.17 17:27:15.630 1: main::fhemFork called by FHEM/Blocking.pm (70)
2015.08.17 17:27:15.632 1: main::BlockingCall called by ./FHEM/73_PRESENCE.pm (535)
2015.08.17 17:27:15.633 1: main::PRESENCE_StartLocalScan called by fhem.pl (2671)
2015.08.17 17:27:15.635 1: main::HandleTimeout called by fhem.pl (582)
2015.08.17 17:27:16.356 1: Cannot fork: Cannot allocate memory
2015.08.17 17:27:16.386 1: PERL WARNING: Use of uninitialized value $i in hash element at fhem.pl line 2664.
2015.08.17 17:27:16.388 1: PERL WARNING: Use of uninitialized value $i in hash element at fhem.pl line 2665.
2015.08.17 17:27:16.390 1: PERL WARNING: Use of uninitialized value $i in delete at fhem.pl line 2667.
2015.08.17 17:27:53.804 1: Perfmon: possible freeze starting at 17:27:52, delay is 1.803
2015.08.17 17:27:59.210 1: Perfmon: possible freeze starting at 17:27:57, delay is 2.209
2015.08.17 17:30:26.303 1: Perfmon: possible freeze starting at 17:30:25, delay is 1.302
2015.08.17 17:33:58.462 1: Perfmon: possible freeze starting at 17:33:57, delay is 1.462
2015.08.17 17:34:33.140 1: BlockingCall created child (5722), uses telnetForBlockingFn to connect back, Fn:WriteStatefile arg:
2015.08.17 17:34:48.944 1: Cannot fork: Cannot allocate memory
2015.08.17 17:34:48.947 1: stacktrace:
2015.08.17 17:34:48.948 1: main::fhemFork called by ./FHEM/01_FHEMWEB.pm (412)
2015.08.17 17:34:48.950 1: main::FW_Read called by fhem.pl (3046)
2015.08.17 17:34:48.951 1: main::CallFn called by fhem.pl (649)
2015.08.17 17:34:50.185 1: PERL WARNING: Use of uninitialized value $p in hash element at fhem.pl line 638.
ohne presence- und fritzboxmodul habe ich gerade keine no_fork durch fhemweb hinbekommen. auch mit definiertem presencemodul wollte zuerst keine no_fork meldung erscheinen. dann, als zuerst presence einen no_fork ausgelöst hat und fhem wieder im "zombie" zustand war, erfolgte auch durch fhemweb die no_fork meldung. und es machte den eindruck, dass die forkanforderung von presence genau dann abgelehnt wurde, als 3 childs zum berechnen der plots aktiv waren. bei cpu auslastung von ca 100% und bereits 5 (4x fhem + 1x hmland, der aber eigenständig ist) prozessen auch verständlich. :)
ZitatDu hast plotfork auf dem Fritzbox aktiviert... Das ist nach meinen Messungen nicht mal auf der FB7490 mit seinen zwei Prozessoren sinnvoll, geschweige denn auf der 7390 mit einem Prozessor und wenig Speicher. Bei plotfork werden die vom Browser bestellten SVGs parallel berechnet, das sind normalerweise 6 zusaetzliche Prozesse. Bedenke: selbst das alte RPi hat 4-mal mehr Speicher, und normalerweise viel weniger aktivierte Dienste.
plotfork nutze ich hauptsächlich in der hoffnung, ein blocken des hauptprozesses zu vermeiden/verkürzen, da mir ansonsten die von fhem gesteuerten homematic stellventile "einschlafen", wenn sie nicht rechtzeitig "gestreichelt" werden. ich hatte das heute mal mit top über telnet beobachtet. bei der darstellung einer ansicht mit drei aufwendigen plots konnte ich 3 zusätzliche childs von fhem erkennen, die über 90% der cpu load beanspruchten. nach jedem fertigen plot verschwand dann ein child.
edit: warnung + stacktrace
2015.08.17 19:31:21.853 1: PERL WARNING: Use of uninitialized value $p in hash element at fhem.pl line 638.
2015.08.17 19:31:21.859 1: stacktrace:
2015.08.17 19:31:21.861 1: main::__ANON__ called by fhem.pl (638)edit2: ich habe jetzt mal eine anfrage bezüglich dem presencemodul gestellt, da ich glaube, dass das modul eine forkablehnung nicht verarbeitet. http://forum.fhem.de/index.php/topic,40119.0.html (http://forum.fhem.de/index.php/topic,40119.0.html)
Habe fhem.pl geaendert, damit die "undefined" Warnungen nicht mehr kommen. Das ist nur eine kosmetische Verbesserung und hilft beim urspruenglichen Problem garantiert nicht.
Zitatplotfork nutze ich hauptsächlich in der hoffnung, ein blocken des hauptprozesses zu vermeiden/verkürzen, da mir ansonsten die von fhem gesteuerten homematic stellventile "einschlafen", wenn sie nicht rechtzeitig "gestreichelt" werden.
Mag alles sein, zeigt aber, dass die FB fuer deine Installation keine gute Loesung ist, jedenfalls nicht mit FHEM. Ich empfehle Hardware zu tauschen. Entweder die FB oder HomeMatic :)
ZitatMag alles sein, zeigt aber, dass die FB fuer deine Installation keine gute Loesung ist, jedenfalls nicht mit FHEM. Ich empfehle Hardware zu tauschen. Entweder die FB oder HomeMatic :)
sicherlich grenzwertig. aber noch machbar, wenn alles so funktioniert, wie es sollte. manche fehler fallen auf leistungsstärkeren systemen scheinbar erst gar nicht auf. demnach wäre "tested & running on fritzbox" ein echtes qualitätssiegel. ;)
wünschenswert wäre aus meiner sicht für leistungsschwächere systeme eine steuerungsmöglichkeit der anzahl der gleichzeitigen forks. mit zb "attr global forkNbr 1" könnte ich den hauptprozess nonblocking halten während es dann auf der "umleitung" vielleich manchmal eng wird, aber deutlich besser als im hauptprozess. luxus wäre natürlich noch eine zusätzliche begrenzung pro modul einzuführen. dann würde mit "global forkNbr=2" und "fhemweb forkNbr=1" ein weiterer fork-kanal während dem plotten für andere module nutzbar bleiben.
ZitatHabe fhem.pl geaendert, damit die "undefined" Warnungen nicht mehr kommen. Das ist nur eine kosmetische Verbesserung und hilft beim urspruenglichen Problem garantiert nicht.
werde ich auf alle fälle testen.
gruss frank
die fehlermeldung ist mit der aktuellen fhem.pl natürlich weg. aber wie erwartet, gab es keine verbesserung im verhalten von fhem.
im code vom presence modul habe ich dann die ursache gefunden. wie schon vermutet, wird hier nicht auf einen abgelehnten fork gecheckt. mit einer kleinen änderung kann nun die "geplagte" fritzbox anscheinend stabil mit den abgelehnten forks umgehen.
(http://forum.fhem.de/index.php?action=dlattach;topic=39887.0;attach=36216;image)
in blocking.pm habe ich am anfang einen kleinen "blocking test" gesehen. vielleicht wäre es sinnvoll, hier eine simulation mit abgelehntem fork zu integrieren. mit leistungsstarker hardware denkt vielleicht auch nicht jeder an diese möglichkeit.
mal schauen, wie die anderen module mit blockingCall umgehen und wie die langzeitstabilität aussieht.
gruss frank
leider war das noch nicht alles.
das hauptproblem ist der äusserst knappe speicher, zumindestens bei meiner fritzbox 7390. laut datenblatt 128 MB RAM, wobei free (total) nur ca 108 MB angibt. erschwerend ist die tatsache, dass bei linux freier speicher quasi gar nicht "wirklich" frei ist, sondern eventuell bereits vielfach "versprochen" wurde. es gibt eine systeminfo commit_AS, die eine art worst-case grösse an versprochenem speicher darstellen soll. wenn also jedes programm bei mir auf der fritzbox den "vorbestellten" speicher komplett selber nutzen sollte, wären das unglaubliche 265 MB. da sind jetzt noch keine forks enthalten. jeder parallele fork vergrössert diesen wert um weitere gute 30MB. mit plotfork (3 forks) also ca 350 MB.
eigentlich schon ein wunder, dass es überhaupt (mehr oder weniger) läuft. der crash lauert sozusagen hinter jeder ecke. :)
ausgangs punkt war:
Zitatsobald die ersten fork meldungen auftauchen, ist der "hänger/absturz" nicht mehr weit.
nach derzeitigem beobachtungsstand kann ich mir das nur folgendermassen vorstellen.
wenn ein prozess (fhem) "freien" speicher zusätzlich ordert (fork) und diesen speicher sogar benutzt, scheint der nach dem fork wieder vermehrte freie speicher aber weniger "frei" zu sein, als ohnehin schon. ???
denn wenn ich nach einem erfolgreichen plotfork (maximalbelastung mit 3 forks) das webif der fritzbox aufgerufen habe, ist fhem meistens gestorben. und fast umgehend, wenn beim plotfork swapspeicher benutzt wurde. anscheinend wird das dem hauptprozess angelastet, obwohl die systembelastung nach meinem verständnis wie vor dem fork sein sollte.
swapspeicher scheint die allerletzte notreserve zu sein. obwohl der plotfork beendet war, wurde aber der dabei benutzte swap nicht wieder freigegeben. auch nach mehreren stunden nicht, falls es nicht schon vorher crashte. solange der swapspeicher nicht angerührt wird, schein die welt in ordnung, zumindestens handhabbar.
so schwer es mir fällt, werde ich ohne plotfork weiterleben müssen, denn so sind 24h ohne absturz bisher kein problem. dabei wurde bisher auch kein swap benutzt. zusätzlich werde ich den swapUse beobachten und mir eine mail schicken, um einen reboot der fritzbox zu initieren. eventuell auch automatisch. somit ist die fhemmeldung "cannot fork" eine erste warnung, ein swapUse die allerletzte gelegenheit noch einzugreifen.
gruss frank
Ich kann nicht mit so detaillierten Infos aus dem Innenleben der FB7390 dienen, aber ich hab auch gelegentlich das Problem.
Bei mir bleibt JSONMETER hängen.
2015.09.01 20:07:35 1: Cannot fork: Cannot allocate memory
2015.09.01 20:07:35 3: stacktrace:
2015.09.01 20:07:35 3: main::fhemFork called by FHEM/Blocking.pm (70)
2015.09.01 20:07:35 3: main::BlockingCall called by ./FHEM/70_JSONMETER.pm (374)
2015.09.01 20:07:35 3: main::JSONMETER_GetUpdate called by fhem.pl (2681)
2015.09.01 20:07:35 3: main::HandleTimeout called by fhem.pl (583)
2015.09.01 20:07:35 1: Cannot fork: Cannot allocate memory
Danach hilft nur noch ein Neustart der Box.
Passiert so etwa alle zwei Wochen, meist während ich in FHEM rumschaue.
Gruß Heiko
ZitatPassiert so etwa alle zwei Wochen, meist während ich in FHEM rumschaue.
nutzt du plotfork?
Zitat von: frank am 01 September 2015, 20:53:42
nutzt du plotfork?
Da mir die Funktion nichts sagt, ist die Antwort "Nein".
Ich habe ein YouLess auf dem Stromzähler, den ich mit JSONMETER abfrage.
ZitatDa mir die Funktion nichts sagt, ist die Antwort "Nein".
im device vom webif (FHEMWEB) gibt es das attribut plotfork. mit plotfork=1 ist es aktiviert.