FHEM Log Cannot fork: Cannot allocate memory

michael.winkler · 04 Juli 2017, 08:52:03

Zitat von: rudolfkoenig am 04 Juli 2017, 08:45:38
sec* ist, wie ich das weiter oben erklaert habe, bewusst von den DbLog Jungs eingebaut. Keine Ahnung, wozu.

Wer lesen kann ist klar im vorteil, sorry.

Zitat von: rudolfkoenig am 04 Juli 2017, 08:45:38
Ich glaube wir haben mit diesen Bugfixes Speicherloecher in Groessenordnung 1-10MB gestopft, damit waere dein urspruengliches Problem noch nicht geloest.

Hmm ok, ich dachte damit wäre es gelöst. OK dann beobachte ich mal meine Speicherwerte weiter und melde mich wieder.

Beim Ausführen des Befehls "ps -elf | sort -rnk 10 | head" ist mir aufgefallen dass FHEM zwei mal aufgeführt wird, ist das normal?

Code Auswählen


root@HNMWFHEM01:~# ps -elf | sort -rnk 10 | head
4 S root      2412  2321  0  80   0 - 191941 -     Jul03 ?        00:00:16 homebridge
0 S root      3714     1  0  80   0 - 170827 -     Jul03 ?        00:00:19 alexa
4 S mysql     2780  2440  0  80   0 - 91021 -      Jul03 ?        00:00:40 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
1 R fhem     23241     1  1  80   0 - 59578 -      07:00 ?        00:02:03 /usr/bin/perl fhem.pl fhem.cfg
1 S fhem     23285 23241  0  80   0 - 56985 -      07:01 ?        00:00:00 /usr/bin/perl fhem.pl fhem.cfg
5 S www-data  5119  2139  0  80   0 - 55818 -      Jul03 ?        00:00:00 /usr/sbin/apache2 -k start
5 S www-data  2161  2139  0  80   0 - 55818 -      Jul03 ?        00:00:00 /usr/sbin/apache2 -k start
5 S www-data  2160  2139  0  80   0 - 55818 -      Jul03 ?        00:00:00 /usr/sbin/apache2 -k start
5 S www-data  2159  2139  0  80   0 - 55818 -      Jul03 ?        00:00:00 /usr/sbin/apache2 -k start
5 S www-data  2156  2139  0  80   0 - 55818 -      Jul03 ?        00:00:00 /usr/sbin/apache2 -k start

rudolfkoenig · 04 Juli 2017, 08:58:21

ZitatBeim Ausführen des Befehls "ps -elf | sort -rnk 10 | head" ist mir aufgefallen dass FHEM zwei mal aufgeführt wird, ist das normal?

Ja, wenn einer deiner Module BlockingCall verwendet. Da der Entwickler etwas machen will, was laenger blockiert, forkt BlockingCall einen zweiten Prozess, wo das passiert, und so kann der urspruengliche FHEM Prozess weiterlaufen.

michael.winkler · 04 Juli 2017, 18:40:49

Wenn ich das richtig verstanden habe sollte, wenn alles sauber funktioniert nur ein einziger perl Prozess zu sehen sein.

Bei mir tauchen aber immer noch mehrere auf, und so wie es aussieht bleiben die auch sehr lange stehen. Die Auswertung ist von 18:39.

Gibt es eine Möglichkeit zu sehen welches Modul diese Prozesse anstartet?

Code Auswählen


root@HNMWFHEM01:~# ps -elf | sort -rnk 10 | head
1 S fhem     30287  1966  0  80   0 - 62321 -      18:21 ?        00:00:00 perl fhem.pl fhem.cfg
1 S fhem     30162  1966  0  80   0 - 62321 -      18:19 ?        00:00:00 perl fhem.pl fhem.cfg
1 S fhem      1966     1  1  80   0 - 62321 -      09:00 ?        00:10:17 perl fhem.pl fhem.cfg

Wzut · 05 Juli 2017, 07:16:57

Einer davon stammt schonmal vom MPD Modul , denn das seht im Fork Prozess im Dauerkontakt mit dem MPD Server (Telnet Verbindung) um auf dessen Nachrichten sofort reagieren zu können.

rudolfkoenig · 05 Juli 2017, 09:23:21

ZitatGibt es eine Möglichkeit zu sehen welches Modul diese Prozesse anstartet?

In der bisherigen Version wohl nicht. Ich habe jetzt eine Neue eingecheckt, die nach dem ersten BlockingCall ein blockinginfo Befehl zur Verfuegung stellt, mit folgenden Output:

Code Auswählen

fhem> blockinginfo
Pid:9388 Fn:DoSleep Arg:HASH Timeout:555

Deine Ausgabe wuerde mich interessieren, und auch, ob es dabei Warnungen im FHEM-Log gibt.

michael.winkler · 05 Juli 2017, 10:34:19

Anbei noch die Speicherinformationen vor dem Austausch der Blocking.pm und shutdown restart.

Code Auswählen


  root@HNMWFHEM01:~# ps -elf | sort -rnk 10 | head
4 S root      2422  2331  0  80   0 - 176015 -     Jul04 ?        00:00:24 homebridge
0 S root      2066     1  0  80   0 - 170448 -     Jul04 ?        00:00:19 alexa
4 S mysql     2790  2450  0  80   0 - 91021 -      Jul04 ?        00:00:48 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
1 S fhem      1966     1  1  80   0 - 65483 -      Jul04 ?        00:27:21 perl fhem.pl fhem.cfg
1 S fhem     30287  1966  0  80   0 - 62321 -      Jul04 ?        00:00:00 perl fhem.pl fhem.cfg
5 S www-data  3628  2152  0  80   0 - 55818 -      Jul04 ?        00:00:00 /usr/sbin/apache2 -k start
5 S www-data  2174  2152  0  80   0 - 55818 -      Jul04 ?        00:00:00 /usr/sbin/apache2 -k start
5 S www-data  2171  2152  0  80   0 - 55818 -      Jul04 ?        00:00:00 /usr/sbin/apache2 -k start
5 S www-data  2169  2152  0  80   0 - 55818 -      Jul04 ?        00:00:00 /usr/sbin/apache2 -k start
5 S www-data  2165  2152  0  80   0 - 55818 -      Jul04 ?        00:00:00 /usr/sbin/apache2 -k start

Code Auswählen


   1. intAt                           8929506 
   2. icloud.kalender                 6671557 
   3. selectlist                      1081174 
   4. CUL_HM                           721113 
   5. HMConfig::culHmRegDefine         647302 
   6. Abfall                           608621 
   7. teleBot                          581800 
   8. Niklas.Fernseher.UPnP            490747 
   9. Wohnzimmer.Fernseher.UPNP        487595 
  10. Wohnzimmer.Kodi.UPnP             485517 
  11. DLNASocket-FHEM.UPnP-41          477353 
  12. DLNASocket-FHEM.UPnP-42          477353 
  13. DLNASocket-FHEM.UPnP-40          477267 
  14. FHEM.UPnP                        476066 
  15. Service.Spritpreise              365243 
  16. utf8::loose_to_file_of           359363 
  17. SIG                              277555 
  18. BEGIN                            252344 
  19. Role::Tiny::INFO                 249514 
  20. Exporter::Cache                  206201 
  21. attr                             205328 
  22. HMConfig::culHmModel             172179

Folgende Zeit die blockinginfo bei mir

Code Auswählen


Pid:11992 Fn:VIERA_GetDoIt Arg:HASH Timeout:10 
Pid:11941 Fn:MPD_IdleStart Arg:Garten.MPD Timeout:N/A 
Pid:11993 Fn:VIERA_GetDoIt Arg:HASH Timeout:10

Die beiden VIERA verschwinden und tauchen später wieder auf. Im FHEM Log sind keine Meldungen zu sehen.

rudolfkoenig · 05 Juli 2017, 11:14:24

Zu intAt/selectlist: die angezeigte Zahl beinhaltet auch die Groessen der verlinkten Datenstrukturen, und diese beiden Variablen enthalten noralerweise die $defs Eintraege der einzelnen Geraete, will sagen, die 9MB/1MB ist nicht unbedingt Grund zur Sorge. Zu den anderen Zahlen kann ich nichts sagen, z.Bsp. ob ein Kalendar mit 6MB normal oder kaputt ist.

Mir gehen langsam auch die Ideen aus, wie man nach der Ursache suchen kann. Apropos: besteht das Problem noch?

michael.winkler · 05 Juli 2017, 11:44:26

Zitat von: rudolfkoenig am 05 Juli 2017, 11:14:24
Zu intAt/selectlist: die angezeigte Zahl beinhaltet auch die Groessen der verlinkten Datenstrukturen, und diese beiden Variablen enthalten noralerweise die $defs Eintraege der einzelnen Geraete, will sagen, die 9MB/1MB ist nicht unbedingt Grund zur Sorge. Zu den anderen Zahlen kann ich nichts sagen, z.Bsp. ob ein Kalendar mit 6MB normal oder kaputt ist.

Mir gehen langsam auch die Ideen aus, wie man nach der Ursache suchen kann. Apropos: besteht das Problem noch?

Dadurch das ich dem FHEM Server mehr Speicher gegeben habe dauert es natürlich länger bis der Fehler wieder auftaucht. Gerade durch die Änderungen der Dateien musste ich den Server immer wieder neu starten. Ich würde vorschlagen das ich den Speicher wieder auf 512 MB begrenze und mich dann wieder melde wenn der Fehler wieder auftaucht.

Ich denke das durch Deine Änderungen der Fehler verschwunden ist.

Groby · 07 Juli 2017, 17:09:26

@Rudi,

ich beobachte diesen Thread auch schon eine Weile und meine FB7390 läuft wieder stabil ohne "Cannot allocate memory" Error nach den updates.

Kann es sein, dass dieser "Fehler" auch bei FHEM2FHEM im LOG Modus auftritt wenn die Devices nicht angelegt sind?

Code Auswählen

{ int(keys %defs).":".int(keys %attr) }

liefert bei mir ein Ungleichgewicht, wenn die Devices nicht definiert sind (127:207). Nach identifizieren der "Devices" mit:

Code Auswählen

{ join(",", grep { !$defs{$_} } sort keys %attr) }

und durch das Anlegen eines dummy Devices für jeden gelieferten Eintrag bin ich wieder in Sync: 207:207

MfGroby

rudolfkoenig · 08 Juli 2017, 15:21:07

ZitatKann es sein, dass dieser "Fehler" auch bei FHEM2FHEM im LOG Modus auftritt wenn die Devices nicht angelegt sind?

Ja, aber FHEM2FHEM sollte daran nicht direkt Schuld sein.
Es legt fuer den Dauer des notifies den $defs Eintrag an, und loescht ihn danach. Wenn jemand im notify-Prozess Attribute setzt, dann werden diese nicht entfernt. Ich werde das in FHEM2FHEM fixen, wuesste aber vorher gerne, wer diese Attribute anlegt.

Kannst du bitte rausfinden, welche Attribute so angelegt werden? Falls du unsicher bist wie:
- devices nicht definieren (alos "alter" Zustand)
- mit { join(",", grep { !$defs{$_} } sort keys %attr) } die Liste der Herrenlosen Attribute ausgeben.
- fuer einige dieser Werte mit { join("\n", map { "$_=$attr{XXX}{$_}" } sort keys %{$attr{XXX}}) } die Attribute ausgeben, wobei XXX passend ersetzt werden muss

Groby · 08 Juli 2017, 18:08:17

Code Auswählen

{ join(",", grep { !$defs{$_} } sort keys %attr) }

gibt folgendes aus: Dachluke,Plissee

Code Auswählen


{ join("\n", map { "$_=$attr{Dachluke}{$_}" } sort keys %{$attr{Dachluke}}) }
{ join("\n", map { "$_=$attr{Plissee}{$_}" } sort keys %{$attr{Plissee}}) }

gibt jeweils kein Ergebnis.

Ist das richtig so oder habe ich einen Tippfehler?

Wenn das so richtig ist, begebe ich mich morgen früh auf die genauere Suche und gehe Device für Device durch...

CoolTux · 08 Juli 2017, 18:12:37

Die Devicenamen in ' ' setzen

Groby · 08 Juli 2017, 19:07:15

Code Auswählen


{ join("\n", map { "$_=$attr{'Dachluke'}{$_}" } sort keys %{$attr{'Dachluke'}}) }
{ join("\n", map { "$_=$attr{'Plissee'}{$_}" } sort keys %{$attr{'Plissee'}}) }

Device in '' macht keinen Unterschied. Wieder kein Ergebnis...

Groby · 08 Juli 2017, 19:30:57

ich habe verschiedene Devices über ein "at" abgefragt. Folgendes findet sich dann im LOG:

Code Auswählen


2017.07.08 19:21:45.409 3: CheckDevices: 
{ join("\n", map { "$_=$attr{'SunMeterD'}{$_}" } sort keys %{$attr{'SunMeterD'}}) }
2017.07.08 19:21:45.379 3: eval: { join("\n", map { "$_=$attr{'SunMeter2'}{$_}" } sort keys %{$attr{'SunMeter2'}}) }
2017.07.08 19:21:45.379 1: PERL WARNING: Useless use of join or string in void context at (eval 356) line 1.
{ join("\n", map { "$_=$attr{'SunMeter'}{$_}" } sort keys %{$attr{'SunMeter'}}) }
2017.07.08 19:21:45.372 3: eval: { join("\n", map { "$_=$attr{'SunLight'}{$_}" } sort keys %{$attr{'SunLight'}}) }
2017.07.08 19:21:45.371 1: PERL WARNING: Useless use of join or string in void context at (eval 355) line 1.
{ join("\n", map { "$_=$attr{'LuxMeter'}{$_}" } sort keys %{$attr{'LuxMeter'}}) }
2017.07.08 19:21:45.363 3: eval: { join("\n", map { "$_=$attr{'Lux'}{$_}" } sort keys %{$attr{'Lux'}}) }
2017.07.08 19:21:45.361 1: PERL WARNING: Useless use of join or string in void context at (eval 353) line 1.
{ join("\n", map { "$_=$attr{'SunMeterD'}{$_}" } sort keys %{$attr{'SunMeterD'}}) }}
2017.07.08 19:21:35.088 3: eval: {return undef; { join("\n", map { "$_=$attr{'SunMeter2'}{$_}" } sort keys %{$attr{'SunMeter2'}}) }

Groby · 09 Juli 2017, 07:44:57

@Rudi,

ich habe nochmal eine Standard FHEM Installation probiert und mit "LOG:HK.*" nur die Heizkoerper Events geloggt.

Ergibt dann: 14:20 und: HK_Flur,HK_Kueche,HK_Schlaf,HK_WC,HK_WZ_li,HK_WZ_re

{ join("\n", map { "$_=$attr{XXX}{$_}" } sort keys %{$attr{XXX}}) } bleibt ohne Ergebnis.

Es scheint sich also immer um die "geloggten" Devices zu handeln...