FHEM Log Cannot fork: Cannot allocate memory

[Wernieman]

Was mich etwas stört:

Code Auswählen Erweitern

/usr/lib/arm-linux-gnueabihf/libc.so: invalid ELF header at /usr/local/lib/arm-linux-gnueabihf/perl/5.22.1/XSLoader.pm line 96.
Invalid ELF header hört sich eigentlich nicht gut an ....

1. Bitte installiere mal NICHT per CPAN
2. Hast Du in der Vergangenheit per CPAN und dann mal das System per apt-get aktuallisiert?
3. Wie aktuell ist das System (apt-get update / -s upgrade )

[Shadow3561]

Moin,
Ja, ich habe in der Vergangenheit einige Sachen mit cpan (einige sachen für fhem)  installiert.
Apt-get update && upgrade wird einmal wöchentlich gefahren.
System ist Ubuntu 16.04 lts

[Wernieman]

Damit hast Du leider ein System mit verschiedenen versionen von perl-Libarys. Die vom System installierten und per apt-get upgrade installlierten und die per CPAN, welche eben definitiv NICHT per apt-get upgegradet werden.

Sorry aber könntest Du alle per CPAN installierten Libarys reinstallieren?

[Shadow3561]

ich denke nicht, dass ich das kann.
einige, für fhem verwendeten module liessen sich nur über cpan installieren.

ich wage mal einen versuch mit perlbrew.

mfg

[Wernieman]

Wenn es ums update von cpan geht...
https://stackoverflow.com/questions/3727795/how-do-i-update-all-my-cpan-modules-to-their-latest-versions

War gleich der erste Treffer bei der google-Suche
https://www.google.com/search?client=ubuntu&channel=fs&q=CPAN+aktuallisieren&ie=utf-8&oe=utf-8

[choetzu]

Guten Morgen,
das ist ein hochinteressanter Thread. Ich habe ihn sehr aufmerksam durchgelesen. Ob ich alles kapiert habe,ist was anderes. Eine Frage: Ich habe seit dem Update gestern viele Cannot Fork (hmm, "kann nicht Gabel? ", komisch).  Was ich nicht ganz kapiere - als Laie - sind folgende Punkte:

fhemdebug usage:

Code Auswählen Erweitern


   1. defs                            2799987
   2. modules                          941357
   3. modules::eventTypes              671428
   4. modules::eventTypes::ldata       670366
   5. attr                             327462
   6. defs::DB920                       64915
   7. defs::Sonos_Wohnzimmer            55415
   8. defs::Sonos_Bad__Schlafz          55043
   9. defs::Sonos_Wohnzimmer::READINGS    53777
  10. defs::Sonos_Mobil                 53447
  11. defs::Sonos_Bad__Schlafz::READINGS    53401
  12. defs::Sonos_Buero                 53313
  13. defs::Sonos_Mobil::READINGS       51827
  14. defs::Sonos_Buero::READINGS       51693
  15. defs::Raspi_Werte                 47769
  16. POSIX::                           37247
  17. defs::DB920::READINGS             36201
  18. defs::DB7080                      35872


Sehe ich das richtig, dass die ersten 5 Positionen Zusammenfassungen sind? Und Sonos scheint ganz schön Memory zu benützen. War aber bislang (1 Jahr) nie ein Problem.

{ int(keys %intAt) } ergibt 180
{ int(keys %defs).":".int(keys %attr) } ergibt 349:350
{ join(",", grep { !$defs{$_} } sort keys %attr) } ergibt secLogging
{ join("\n", map { "$intAt{$_}{TRIGGERTIME} / $intAt{$_}{FN}" } (sort {$intAt{$a}{TRIGGERTIME}<=>$intAt{$b}{TRIGGERTIME}} keys %intAt)[0..49]) } ergibt..

Code Auswählen Erweitern


1535437302.52279 / CUL_HM_procQs
1535437307.68473 / SYSMON_Update
1535437307.7803 / ENIGMA2_GetStatus
1535437307.78838 / ENIGMA2_GetStatus
1535437307.85509 / DbLog_execmemcache
1535437309.06315 / HMUARTLGW_SendKeepAlive
1535437314.05931 / HMUARTLGW_CheckCredits
1535437322 / FW_closeInactiveClients
1535437323.50523 / SONOS_IsSubprocessAliveChecker
1535437457.14139 / CUL_HM_ActCheck
1535437459.79839 / myPoolcontroller_GetUpdate
1535437463 / netatmo_poll
1535437472.52632 / HusqvarnaAutomower_DoUpdate
1535437473.98012 / GardenaSmartBridge_getDevices
1535437479 / netatmo_poll
1535437486 / netatmo_poll
1535437800 / DOIF_TimerTrigger
1535437865 / netatmo_poll
1535437876 / netatmo_poll
1535438647.39345 / CUL_HM_complConfigTO
1535438749.61337 / monitoring_modify
1535438749.75914 / monitoring_modify
1535438750.2276 / monitoring_modify
1535438750.48849 / monitoring_modify
1535438960.11449 / monitoring_modify
1535438960.20374 / monitoring_modify
1535438980.2847 / monitoring_modify
1535439034.21547 / monitoring_modify
1535439034.30563 / monitoring_modify
1535439048.27531 / monitoring_modify
1535439060.45029 / monitoring_modify
1535439098.72736 / monitoring_modify
1535439595 / statistics_PeriodChange
1535439600 / DOIF_TimerTrigger
1535439600 / DOIF_TimerTrigger
1535440200 / DOIF_TimerTrigger
1535440200 / DOIF_TimerTrigger
1535440200 / DOIF_TimerTrigger
1535440200 / DOIF_TimerTrigger
1535440450.72071 / at_Exec

{ join("\n", map { "$intAt{$_}{TRIGGERTIME} / $intAt{$_}{FN}" } (sort {$intAt{$b}{TRIGGERTIME}<=>$intAt{$a}{TRIGGERTIME}} keys %intAt)[0..49]) } ergibt..

Code Auswählen Erweitern


1535523767.94828 / BlockingKill
1535522400 / DOIF_TimerTrigger
1535520000 / DOIF_TimerTrigger
1535520000 / DOIF_TimerTrigger
1535519100 / DOIF_TimerTrigger
1535518980 / DOIF_TimerTrigger
1535518980 / DOIF_TimerTrigger
1535518980 / DOIF_TimerTrigger
1535518980 / DOIF_TimerTrigger
1535515839 / DOIF_TimerTrigger
1535515200 / DOIF_TimerTrigger
1535515200 / DOIF_TimerTrigger
1535515200 / DOIF_TimerTrigger
1535515200 / DOIF_TimerTrigger
1535515200 / DOIF_TimerTrigger
1535515200 / DOIF_TimerTrigger
1535515200 / DOIF_TimerTrigger
1535515200 / DOIF_TimerTrigger
1535515200 / DOIF_TimerTrigger
1535515200 / DOIF_TimerTrigger
1535511600 / DOIF_TimerTrigger
1535511600 / DOIF_TimerTrigger
1535511600 / DOIF_TimerTrigger
1535511600 / DOIF_TimerTrigger
1535508847.3897 / CUL_HM_statCntRfresh
1535508000 / DOIF_TimerTrigger
1535506200 / DOIF_TimerTrigger
1535504700 / DOIF_TimerTrigger
1535504400 / DOIF_TimerTrigger
1535504400 / DOIF_TimerTrigger
1535504400 / DOIF_TimerTrigger
1535504400 / DOIF_TimerTrigger
1535504400 / DOIF_TimerTrigger
1535504400 / DOIF_TimerTrigger
1535504400 / DOIF_TimerTrigger
1535504400 / DOIF_TimerTrigger
1535497200 / DOIF_TimerTrigger
1535493603.82898 / DOIFtoolsCounterReset

im raspi shell ergibt ps -elf | sort -rnk 10 ...

Code Auswählen Erweitern


4 S mysql      589     1  0  80   0 - 159409 -     08:14 ?        00:00:01 /usr/sbin/mysqld
4 S root       625   420  0  80   0 - 39653 -      08:14 tty7     00:00:00 /usr/lib/xorg/Xorg :0 -seat seat0 -auth /var/run/lightdm/root/:0 -nolisten tcp vt7 -novtswitch
5 S www-data   693   634  0  80   0 - 35271 -      08:14 ?        00:00:00 /usr/sbin/apache2 -k start
5 S www-data   692   634  0  80   0 - 35271 -      08:14 ?        00:00:00 /usr/sbin/apache2 -k start
5 S www-data   691   634  0  80   0 - 35271 -      08:14 ?        00:00:00 /usr/sbin/apache2 -k start
5 S www-data   688   634  0  80   0 - 35271 -      08:14 ?        00:00:00 /usr/sbin/apache2 -k start


und dstat -g -m -s --top-mem im raspi shell ergibt:

Code Auswählen Erweitern


---paging-- ------memory-usage----- ----swap--- --most-expensive-
  in   out | used  buff  cach  free| used  free|  memory process
   0     0 | 356M 38.2M  297M  236M|   0   100M|fhem.pl     98.0M
   0     0 | 356M 38.2M  297M  236M|   0   100M|fhem.pl     98.0M
   0     0 | 356M 38.2M  297M  236M|   0   100M|fhem.pl     98.0M
   0     0 | 356M 38.2M  297M  236M|   0   100M|fhem.pl     98.0M

so, das wärs. Nun habe ich viele Daten, aber ehrlich gesagt, keine Ahnung was ich damit anfangen soll,kann... Wo ist der Uebeltäter? Ich tippe auf mysql, bin aber nicht sicher und kann auch nicht sagen wieso.. Die datanbank mysql (Dblog) klingt schon nach ressourcenverschleiss Und gestern gab es dazu ein Update...

Was meint ihr? danke.

[Wernieman]

Kann den Memoryverbrauch bei Deiner Ausgabe schlecht erkennen .. kannst Du bitte mal:

Code Auswählen Erweitern

ps aux | sort -rnk 4 | head -n5

Hintergrund:
Hast Du mysql Getunt? Laut Speicherverbrauch braucht er bei Dir von allen Programmen am meisten Speicher. Beim Tunen wird einem DB-Programm häufig mehr Speicher zugewiesen.

[choetzu]

so sieht es aus:

Code Auswählen Erweitern


fhem       714 14.3 10.6 109392 100844 ?       S    08:14   5:27 perl fhem.pl fhem.cfg
mysql      589  0.1  8.0 637636 76728 ?        Ssl  08:14   0:03 /usr/sbin/mysqld
fhem      1101  1.3  5.5  93784 53144 ?        Sl   08:14   0:30 /usr/bin/perl ./FHEM/00_SONOS.pm 4711 0 0 startedbyfhem
pi         608  0.2  4.4 138572 42108 ?        Sl   08:14   0:05 homebridge
root       625  0.0  4.2 158612 39968 tty7     Ssl+ 08:14   0:01 /usr/lib/xorg/Xorg :0 -seat seat0 -auth /var/run/lightdm/root/:0 -nolisten tcp vt7 -novtswitch

hmm, getuned habe ich wissentlich nichts. Mit DbRep mache ich Dumps, aber nicht automatisch, sondern manuell. Und für andere Tunings bin ich schlicht zu wenig versiert...

[DS_Starter]

Guten Morgen,

Und gestern gab es dazu ein Update...

nö  , aber es kann sein dass du lange nicht dein FHeM aktualisiert hast und dann siehst du Änderungen reinlaufen die auch schon etwas älter sind (dblog am 05.08.)

In der letzten Zeit hatte Rudi SVG auf Blockingcall umgestellt. Viele Blockingcalls zur gleichen Zeit können einen temporären Speicherengpass verursachen. Dafür gibt es aber die globale Variable blockingCallMax. Die kannst du zb. auf 5 stellen um die Anzahl parallel laufender Blockingcalls zu begrenzen. Etliche Module verwenden Blockingcall um ein blockieren von FHEM bei bestimmten Operationen zu vermeiden.
Probiers mal, vielleicht hilft es dir.

LG,
Heiko

[rudolfkoenig]

In der letzten Zeit hatte Rudi SVG auf Blockingcall umgestellt.

Klarstellung:
- ich habe die Voreinstellung von plotEmbed von 1 auf 0 gestellt, d.h. die SVGs werden nicht ueber das <embed> Tag geladen, sondern direkt gerendert.
- falls plotFork gesetzt ist, dann wird jetzt auch bei plotEmbed via blockingCall gerendert, das war frueher nicht der Fall.
- falls plotFork gesetzt ist, und plotEmbed auf 1 steht (wie die fruehere Voreinstellung), dann wurde auch frueher geforkt.
- ich habe mit Absicht die plotFork Voreinstellung nicht auf 1 gesetzt, da mir diese Diskussion present ist. Ich habe auf einem "normalen" Rechner seit 10 Jahren damit kein Problem.

Will sagen: meine Aenderung sollte nicht zu mehr Speicherverbrauch fuehren, es sei denn man hat explizit plotFork gesetzt, aber plotEmbed nicht.

@choetzu: mit fhemdebug memusage kann man (im Gluecksfall) Speicherloecher im Perl-Code feststellen, das ist aber nur in den seltensten Faellen das Problem. Vermutlich gibt es mehrere moegliche Speicherlloecher in dieser Diskussion, einer hat ziemlich sicher mit dem Zusammenspiel eines Perl-Moduls und der C-Bibliothek unter ARM/Stretch zu tun.

[choetzu]

Code Auswählen Erweitern

auf 5 stellen um die Anzahl parallel laufender Blockingcalls
super, danke. das hab ich im device "global" so gemacht..

Code Auswählen Erweitern

einer hat ziemlich sicher mit dem Zusammenspiel eines Perl-Moduls und der C-Bibliothek unter ARM/Stretch zu tun.
herzlichen Dank.hmm, und was bedeutet das nun für mich? Wie resp wo kann ich schrauben?

ab wieviel memory usage ist ein modul eigentlich kritisch, bei 1gb? Kann man das so sagen?

[DS_Starter]

Hallo Rudi,

danke für die Ausführung. Es ist doch ein etwas weitergehender Kontext.

Ich arbeite schon eh und je mit plotfork=1 und hatte auch noch nie Probleme damit, obwohl ich viele Devices einsetze die BlockingCall nutzen (auf Prod 112 x DbRep, 3 x DbLog und SMA-Devices etc.). Läuft einwandfrei. Der Speicherverbrauch steigt auch nicht ständig an und lag bisher immer so um die 450/500-550MB.  Wenn umfangreiche Selektionen/Aktivitäten laufen geht er schon mal temporär entsprechend hoch um danach wieder auf den Durchschnittswert zu sinken. Also alles schick so wie es sein soll.

Allerdings hatte ich das Attr "plotEmbed" nie im Blick muss ich gestehen, es war also bisher nicht gesetzt. Nach deiner Ausführung habe ich dieses Attr in allen meinen FHEMWEB-Devices auf "1" gesetzt. Danach liegt der Speicherverbrauch jetzt nur noch bei 390-397MB soweit ich es bisher beobachten konnte, also eine recht deutliche Einsparung.

Das sollte nur mal ein kleiner Erfahrungs/Vergleichsbereicht sein. Da ich genügend Speicher zur Verfügung habe, funktionieren beide Einstellungsvarianten problemlos ... aber wenn man sparen kann 

@choetzu, das Sonos recht viel Speicher braucht kann ich bestätigen, ist bei mir genauso. Der Sonos Subprozess läuft ebenso mit auf dem Produktivrechner. Die MariaDB (MySQL) Datenbanken sind bei mir allerdings remote auf meiner Synology angelegt und nehmen keine Ressourcen auf dem FHEM-Rechner weg.

Hat denn die Einstellung von Blockingcalls etwas gebracht ?

LG,
Heiko

[choetzu]

@choetzu, das Sonos recht viel Speicher braucht kann ich bestätigen, ist bei mir genauso. Der Sonos Subprozess läuft ebenso mit auf dem Produktivrechner. Die MariaDB (MySQL) Datenbanken sind bei mir allerdings remote auf meiner Synology angelegt und nehmen keine Ressourcen auf dem FHEM-Rechner weg.
Har denn die Einstellung von Blockingcalls etwas gebracht ?
LG,
Heiko

Halllo Heiko,
ich denke schon, dass es was gebracht hat. Bin mir aber nicht sicher, denn ich denke, dass mein LGW-Gateway (HMUARTLGW) dazu beigetragen hat. Seit neustem macht der Probleme, öffnet, schliesst, öffnet etc.

Code Auswählen Erweitern

2018.08.28 18:18:29 1: XXXXX:2000 reappeared (LGW_Gateway)
2018.08.28 18:18:30 3: LGW_Gateway:keepAlive device opened
2018.08.28 18:18:30 3: HMUARTLGW LGW_Gateway BidCoS-port opened
2018.08.28 18:18:30 3: HMUARTLGW LGW_Gateway:keepAlive KeepAlive-port opened
2018.08.28 18:31:52 1: XXXXX:2001 disconnected, waiting to reappear (LGW_Gateway:keepAlive)
2018.08.28 18:31:52 1: HMUARTLGW LGW_Gateway:keepAlive KeepAlive sent 90.570s too late, this might cause a disconnect!
2018.08.28 18:31:53 1: XXXXX:2000 disconnected, waiting to reappear (LGW_Gateway)
2018.08.28 18:31:53 3: Opening LGW_Gateway:keepAlive device XXXXX:2001
2018.08.28 18:31:53 1: XXXXX:2000 reappeared (LGW_Gateway)
2018.08.28 18:31:53 3: LGW_Gateway:keepAlive device opened
2018.08.28 18:31:53 3: HMUARTLGW LGW_Gateway BidCoS-port opened
2018.08.28 18:31:53 3: HMUARTLGW LGW_Gateway:keepAlive KeepAlive-port opened
2018.08.28 18:42:03 3: LGW_Gateway device closed

Ich hab ihn mal deaktiviert und es scheint schonmal besser zu laufen. BIn mich grad am durchlesen, was das sein könnte..

Bezüglich Datenbank auf NAS schreiben, ich habe auch eine Synology (DS216play), da werd ich mich mal schlau machen. V.a. auch wie man ihn konfiguriert, dass er nicht ins Standby geht... Das dauert sonst..

danke nochmals für die Hilfe. Ich bleibe dran..

EDIT: Ich habe über Nacht apptime laufen lassen. Sonos scheint mir hier etwas Kummer zu machen. Deshalb habe ich direkt ein Post in Multimedia eröffnet: https://forum.fhem.de/index.php/topic,90656.0.html

Code Auswählen Erweitern

name                                     function                               max    count      total  average   maxDly   avgDly TS Max call     param Max call
tmr-SONOSPLAYER_TriggerCoverTitleLater   HASH(0x3023c00)                      19683       29  536795.79 18510.20 40829.32  9341.50 29.08. 06:21:19 HASH(Sonos_Bad__Schlafz)
Logging                                  DbLog_Log                            19583     8883  589674.92    66.38     0.00     0.00 29.08. 06:21:19 HASH(Logging); HASH(Sonos_Bad__Schlafz)
Sonos                                    SONOS_Read                            4647      494   40709.86    82.41     0.00     0.00 29.08. 06:05:34 HASH(Sonos)

Sonos schreibt übrigens nix ins Log...

[Wernieman]

naja .. wenn die Synologa nur wegen mysql durchlaufen soll .... hättest Du etwas mehr Stromverbrauch,. Nur mal so bedenken.

[choetzu]

naja .. wenn die Synologa nur wegen mysql durchlaufen soll .... hättest Du etwas mehr Stromverbrauch,. Nur mal so bedenken.

danke. etwas mehr oder etwas VIEL mehr?  Ich habe nun das Logging auf Synology DS216play umgesattelt. funktioniert ganz gut. Doch nach wie vor habe ich LGW abgeschaltet, da es in die Quere mit SONOS kommt, sobald ich SONOS am Morgen einschalte. Keine Ahnung wieso..