Cannot fork: Cannot allocate memory

[rudolfkoenig]

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.

[frank]

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.

Code Auswählen Erweitern

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.

Code Auswählen Erweitern

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:

Code Auswählen Erweitern

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.


[rudolfkoenig]

2015.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.

2015.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.

Aug 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.

[frank]

Diese Meldung brauche ich mit einem aktuellen fhem.pl, da die Zeilennummer nicht passt.

das war das aktuellste, was es gestern morgen zu holen gab.

Code Auswählen Erweitern

# $Id: fhem.pl 9067 2015-08-13 19:02:29Z rudolfkoenig $

jetzt noch mal neu:

Code Auswählen Erweitern

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. 

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.

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

Code Auswählen Erweitern

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

[rudolfkoenig]

Habe fhem.pl geaendert, damit die "undefined" Warnungen nicht mehr kommen. Das ist nur eine kosmetische Verbesserung und hilft beim urspruenglichen Problem garantiert nicht.

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.

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

[frank]

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

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.

Habe 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

[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

[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:

sobald 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

[HeikoE]

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.

Code Auswählen Erweitern


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

[frank]

Passiert so etwa alle zwei Wochen, meist während ich in FHEM rumschaue.

nutzt du plotfork?

[HeikoE]

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.

[frank]

Da 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.