Cubietruck abstürze durch fhem.service bzw. Perl Speicherverbrauch

Tommy82 · 11 November 2020, 04:54:44

Hallo,
ich habe seit ca. Anfang Oktober plötzlich alle paar Tage das sich mein Cubietruck "aufhängt", es hilft nur noch denn Stecker ziehen. Bis dahin lief er sehr lange ohne jegliche Problem.

Nach ein bisschen logs lesen bin ich in denn linux logs des Cubies (armbian) auf diese beiden Meldungen kurz vor dem "hängen" bleiben gestossen

In /usr/log/messages

Code Auswählen

Nov 11 00:33:48 localhost kernel: [454680.731222] [  19841]  1000 19841   453513   438156  1810432        0             0 perl
Nov 11 00:33:48 localhost kernel: [454680.731231] [  19933]  1000 19933    40085     4942   178176        0             0 node /usr/local
Nov 11 00:33:48 localhost kernel: [454680.731240] [  20030]  1000 20030     2722      127    20480        0             0 ssh
Nov 11 00:33:48 localhost kernel: [454680.731255] [  10072]  1000 10072   453404   437922  1810432        0             0 perl
Nov 11 00:33:48 localhost kernel: [454680.731263] [  10095]  1000 10095   453513   438041  1810432        0             0 perl
Nov 11 00:33:48 localhost kernel: [454680.731272] [  10100]  1000 10100   453513   438041  1808384        0             0 perl
Nov 11 00:33:48 localhost kernel: [454680.731277] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/system.slice/fhem.service,task=perl,pid=19841,uid=1000
Nov 11 00:33:49 localhost kernel: [454681.241335] oom_reaper: reaped process 19841 (perl), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Nov 11 04:17:35 localhost rsyslogd: action '*' treated as ':omusrmsg:*' - please use ':omusrmsg:*' syntax instead, '*' will not be supported in the future [v8.1901.0 try https://www.rsyslog.com/e/2184 ]
Nov 11 04:17:35 localhost rsyslogd: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.1901.0]
Nov 11 04:17:35 localhost rsyslogd:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="473" x-info="https://www.rsyslog.com"] start
Nov 11 04:17:35 localhost rsyslogd: action 'action-10-builtin:ompipe' suspended (module 'builtin:ompipe'), retry 0. There should be messages before this one giving the reason for suspension. [v8.1901.0 try https://www.rsyslog.com/e/2007 ]
Nov 11 04:17:35 localhost rsyslogd: action 'action-10-builtin:ompipe' suspended (module 'builtin:ompipe'), next retry is Wed Nov 11 04:18:05 2020, retry nbr 0. There should be messages before this one giving the reason for suspension. [v8.1901.0 try https://www.rsyslog.com/e/2007 ]

und in /user/log/syslog

Code Auswählen

Nov 11 00:33:48 localhost kernel: [454680.731277] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/system.slice/fhem.service,task=perl,pid=19841,uid=1000
Nov 11 00:33:48 localhost kernel: [454680.731359] Out of memory: Killed process 19841 (perl) total-vm:1814052kB, anon-rss:1752172kB, file-rss:452kB, shmem-rss:0kB, UID:1000 pgtables:1768kB oom_score_adj:0
Nov 11 00:33:49 localhost kernel: [454681.241335] oom_reaper: reaped process 19841 (perl), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Nov 11 00:33:49 localhost systemd[1]: fhem.service: Main process exited, code=killed, status=9/KILL
Nov 11 00:33:58 localhost systemd[1]: fhem.service: Failed with result 'signal'.
Nov 11 00:33:59 localhost systemd[1]: fhem.service: Service RestartSec=100ms expired, scheduling restart.
Nov 11 00:33:59 localhost systemd[1]: fhem.service: Scheduled restart job, restart counter is at 9.
Nov 11 00:33:59 localhost systemd[1]: Stopped FHEM Home Automation.
Nov 11 00:33:59 localhost systemd[1]: Starting FHEM Home Automation...
Nov 11 00:34:00 localhost systemd[1]: Started FHEM Home Automation.
Nov 11 00:34:29 localhost hmland[604]: usb-transfer took more than 100ms (134ms), this may lead to timing problems!
Nov 11 00:34:38 localhost hmland[604]: usb-transfer took more than 100ms (131ms), this may lead to timing problems!
Nov 11 00:35:01 localhost CRON[10325]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Nov 11 04:17:35 localhost fake-hwclock[235]: Current system time: 2020-11-11 03:17:28
Nov 11 04:17:35 localhost fake-hwclock[235]: fake-hwclock saved clock information is in the past: 2020-11-01 13:48:10
Nov 11 04:17:35 localhost fake-hwclock[235]: To set system time to this saved clock anyway, use "force"
Nov 11 04:17:35 localhost systemd-remount-fs[245]: mount: /etc/fstab: parse error at line 3 -- ignored

Nach dem fhem.service kommt auf einmal out of mermory.

Was mir erst garnicht aufgefallen ist, ich dann aber im Fhem log auch gesehen habe ist, das fhem plötzlich immer mal wieder Neustartet ohne erkennbaren grund. In diesem Fall um 00:34 und um 00:32 gibt es ein DbLog Problem so wie es aussieht

Code Auswählen

2020.11.11 00:32:59.885 2: DbLog myDbLog -> DbLog_PushAsync Process died prematurely
2020.11.11 00:34:00.608 1: Including fhem.cfg
2020.11.11 00:34:00.717 3: telnetPort: port 7072 opened
2020.11.11 00:34:01.838 3: WEB: port 8083 opened
2020.11.11 00:34:01.893 3: WEBphone: port 8084 opened

Was könnte das Problem verursachen?

Danke

Wernieman · 11 November 2020, 09:27:05

messages
1. 00:33:48: dort ist ein Kern.Dump. Könntest Du uns den Anfang des Dumpes + 2 Zeilen davor geben?
2. 04:17:35 syslog hat ein Problem ...

syslog
1. Siehe gleiche Zeiten wie oben
2. 00:33:49 Zum obengenannten Kern. Dump kommt ein oom-Kill von FHEM. Ob Symptom oder Ursache ... s.o.

Also:
Entweder hast Du ein HardwareProblem, ein Memory-Verbrauch oder .... der Cubi hat doch auch eine SDCard?

Tommy82 · 11 November 2020, 20:23:59

Hallo,
hier der gewünschte
Log Bereich

Code Auswählen

Nov 11 00:32:51 localhost kernel: [454623.580814] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/system.slice/fhem.service,task=perl,pid=9922,uid=1000
Nov 11 00:32:52 localhost kernel: [454624.358596] oom_reaper: reaped process 9922 (perl), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Nov 11 00:33:48 localhost kernel: [454680.730475] perl invoked oom-killer: gfp_mask=0x400dc2(GFP_KERNEL_ACCOUNT|__GFP_HIGHMEM|__GFP_ZERO), order=0, oom_score_adj=0
Nov 11 00:33:48 localhost kernel: [454680.730496] CPU: 1 PID: 10072 Comm: perl Tainted: G         C  E     5.8.16-sunxi #20.08.14
Nov 11 00:33:48 localhost kernel: [454680.730500] Hardware name: Allwinner sun7i (A20) Family
Nov 11 00:33:48 localhost kernel: [454680.730537] [<c010d6cd>] (unwind_backtrace) from [<c0109a7d>] (show_stack+0x11/0x14)
Nov 11 00:33:48 localhost kernel: [454680.730555] [<c0109a7d>] (show_stack) from [<c056e1c9>] (dump_stack+0x75/0x84)
Nov 11 00:33:48 localhost kernel: [454680.730572] [<c056e1c9>] (dump_stack) from [<c020d70b>] (dump_header+0x43/0x16a)
Nov 11 00:33:48 localhost kernel: [454680.730587] [<c020d70b>] (dump_header) from [<c020ce73>] (oom_kill_process+0x123/0x12c)
Nov 11 00:33:48 localhost kernel: [454680.730597] [<c020ce73>] (oom_kill_process) from [<c020d59f>] (out_of_memory+0x19b/0x260)
Nov 11 00:33:48 localhost kernel: [454680.730613] [<c020d59f>] (out_of_memory) from [<c0243c63>] (__alloc_pages_nodemask+0x913/0xc40)
Nov 11 00:33:48 localhost kernel: [454680.730627] [<c0243c63>] (__alloc_pages_nodemask) from [<c0230273>] (__pte_alloc+0x1f/0x118)
Nov 11 00:33:48 localhost kernel: [454680.730639] [<c0230273>] (__pte_alloc) from [<c0230d7d>] (copy_page_range+0x455/0x554)
Nov 11 00:33:48 localhost kernel: [454680.730655] [<c0230d7d>] (copy_page_range) from [<c011949b>] (dup_mm+0x21f/0x340)
Nov 11 00:33:48 localhost kernel: [454680.730667] [<c011949b>] (dup_mm) from [<c011a759>] (copy_process+0xf75/0x1218)
Nov 11 00:33:48 localhost kernel: [454680.730679] [<c011a759>] (copy_process) from [<c011ab5f>] (_do_fork+0x63/0x344)
Nov 11 00:33:48 localhost kernel: [454680.730692] [<c011ab5f>] (_do_fork) from [<c011b07f>] (sys_clone+0x5b/0x74)
Nov 11 00:33:48 localhost kernel: [454680.730704] [<c011b07f>] (sys_clone) from [<c0100061>] (ret_fast_syscall+0x1/0x62)
Nov 11 00:33:48 localhost kernel: [454680.730710] Exception stack(0xed05ffa8 to 0xed05fff0)
Nov 11 00:33:48 localhost kernel: [454680.730720] ffa0:                   b6f69078 b6f694d0 01200011 00000000 00000000 00000000
Nov 11 00:33:48 localhost kernel: [454680.730730] ffc0: b6f69078 b6f694d0 00000000 00000078 00000000 00000000 b6f69010 00000001
Nov 11 00:33:48 localhost kernel: [454680.730737] ffe0: 00000078 bea008d8 b6e15253 b6db7746
Nov 11 00:33:48 localhost kernel: [454680.730742] Mem-Info:
Nov 11 00:33:48 localhost kernel: [454680.730761] active_anon:459843 inactive_anon:5141 isolated_anon:0
Nov 11 00:33:48 localhost kernel: [454680.730761]  active_file:268 inactive_file:308 isolated_file:32
Nov 11 00:33:48 localhost kernel: [454680.730761]  unevictable:4 dirty:0 writeback:0
Nov 11 00:33:48 localhost kernel: [454680.730761]  slab_reclaimable:3671 slab_unreclaimable:7421
Nov 11 00:33:48 localhost kernel: [454680.730761]  mapped:1636 shmem:5228 pagetables:4752 bounce:0
Nov 11 00:33:48 localhost kernel: [454680.730761]  free:21875 free_pcp:0 free_cma:10211
Nov 11 00:33:48 localhost kernel: [454680.730774] Node 0 active_anon:1839372kB inactive_anon:20564kB active_file:1072kB inactive_file:1232kB unevictable:16kB isolated(anon):0kB isolated(file):128kB mapped:6544kB dirty:0kB writeback:0kB shmem:20912kB writeback_tmp:0kB all_unreclaimable? no
Nov 11 00:33:48 localhost kernel: [454680.730793] Normal free:83348kB min:3436kB low:4292kB high:5148kB reserved_highatomic:0KB active_anon:571240kB inactive_anon:5144kB active_file:120kB inactive_file:560kB unevictable:0kB writepending:0kB present:786432kB managed:749504kB mlocked:0kB kernel_stack:1168kB pagetables:5592kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:40844kB
Nov 11 00:33:48 localhost kernel: [454680.730795] lowmem_reserve[]: 0 10216 0
Nov 11 00:33:48 localhost kernel: [454680.730816] HighMem free:4152kB min:5840kB low:7360kB high:8880kB reserved_highatomic:0KB active_anon:1268132kB inactive_anon:15420kB active_file:1000kB inactive_file:1232kB unevictable:16kB writepending:0kB present:1307648kB managed:1307648kB mlocked:16kB kernel_stack:0kB pagetables:13416kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Nov 11 00:33:48 localhost kernel: [454680.730818] lowmem_reserve[]: 0 0 0
Nov 11 00:33:48 localhost kernel: [454680.730825] Normal: 855*4kB (UMEC) 416*8kB (UMEC) 669*16kB (UMEC) 283*32kB (MEC) 145*64kB (UMEC) 46*128kB (UMEC) 20*256kB (UMEC) 11*512kB (UEC) 4*1024kB (UC) 1*2048kB (E) 6*4096kB (C) = 83148kB
Nov 11 00:33:48 localhost kernel: [454680.730864] HighMem: 875*4kB (UM) 123*8kB (UM) 1*16kB (U) 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 4500kB
Nov 11 00:33:48 localhost kernel: [454680.730891] 5810 total pagecache pages
Nov 11 00:33:48 localhost kernel: [454680.730897] 0 pages in swap cache
Nov 11 00:33:48 localhost kernel: [454680.730901] Swap cache stats: add 0, delete 0, find 0/0
Nov 11 00:33:48 localhost kernel: [454680.730904] Free swap  = 0kB
Nov 11 00:33:48 localhost kernel: [454680.730907] Total swap = 0kB
Nov 11 00:33:48 localhost kernel: [454680.730910] 523520 pages RAM
Nov 11 00:33:48 localhost kernel: [454680.730913] 326912 pages HighMem/MovableOnly
Nov 11 00:33:48 localhost kernel: [454680.730916] 9232 pages reserved
Nov 11 00:33:48 localhost kernel: [454680.730919] 24576 pages cma reserved
Nov 11 00:33:48 localhost kernel: [454680.730923] Tasks state (memory values in pages):
Nov 11 00:33:48 localhost kernel: [454680.730926] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
Nov 11 00:33:48 localhost kernel: [454680.730954] [    247]     0   247     8052      869    63488        0             0 systemd-journal
Nov 11 00:33:48 localhost kernel: [454680.730963] [    279]     0   279     4114      155    18432        0         -1000 systemd-udevd
Nov 11 00:33:48 localhost kernel: [454680.730975] [    391]     0   391     1812      767    14336        0             0 haveged
Nov 11 00:33:48 localhost kernel: [454680.730984] [    392]   108   392     1344       80    14336        0             0 rpcbind
Nov 11 00:33:48 localhost kernel: [454680.730993] [    443]     0   443      742       50    12288        0             0 alsactl
Nov 11 00:33:48 localhost kernel: [454680.731003] [    454]   104   454     1386      152    14336        0          -900 dbus-daemon
Nov 11 00:33:48 localhost kernel: [454680.731011] [    463]     0   463     6796       34    18432        0             0 rngd
Nov 11 00:33:48 localhost kernel: [454680.731019] [    468]     0   468     2243      176    16384        0             0 wpa_supplicant
Nov 11 00:33:48 localhost kernel: [454680.731028] [    473]     0   473     2658      166    20480        0             0 systemd-logind
Nov 11 00:33:48 localhost kernel: [454680.731036] [    480]     0   480     6117      230    24576        0             0 rsyslogd
Nov 11 00:33:48 localhost kernel: [454680.731044] [    483]     0   483     5687     1234    28672        0             0 networkd-dispat
Nov 11 00:33:48 localhost kernel: [454680.731052] [    490]     0   490     1914       51    16384        0             0 cron
Nov 11 00:33:48 localhost kernel: [454680.731061] [    491]     0   491    17360      476    47104        0             0 NetworkManager
Nov 11 00:33:48 localhost kernel: [454680.731069] [    596]     0   596     8819     1266    36864        0             0 unattended-upgr
Nov 11 00:33:48 localhost kernel: [454680.731077] [    604]     0   604     2537       68    12288        0             0 hmland
Nov 11 00:33:48 localhost kernel: [454680.731085] [    628]     0   628     2220      137    18432        0         -1000 sshd
Nov 11 00:33:48 localhost kernel: [454680.731094] [    638]   105   638     2753       65    12288        0             0 chronyd
Nov 11 00:33:48 localhost kernel: [454680.731103] [    643]   105   643      806       59    12288        0             0 chronyd
Nov 11 00:33:48 localhost kernel: [454680.731112] [    706]     0   706    49871     1598    55296        0             0 apache2
Nov 11 00:33:48 localhost kernel: [454680.731120] [    757]    33   757    49881     1015    47104        0             0 apache2
Nov 11 00:33:48 localhost kernel: [454680.731129] [    759]    33   759    49881     1015    47104        0             0 apache2
Nov 11 00:33:48 localhost kernel: [454680.731138] [    762]    33   762    49881     1015    47104        0             0 apache2
Nov 11 00:33:48 localhost kernel: [454680.731147] [    763]    33   763    49881     1015    47104        0             0 apache2
Nov 11 00:33:48 localhost kernel: [454680.731155] [    764]    33   764    49877      996    47104        0             0 apache2
Nov 11 00:33:48 localhost kernel: [454680.731163] [    806]     0   806     8986      159    26624        0             0 polkitd
Nov 11 00:33:48 localhost kernel: [454680.731171] [    973]     0   973     1560      212    14336        0             0 dhclient
Nov 11 00:33:48 localhost kernel: [454680.731180] [   1032]     0  1032      959       20    12288        0             0 agetty
Nov 11 00:33:48 localhost kernel: [454680.731189] [   1034]     0  1034     1620       23    14336        0             0 agetty
Nov 11 00:33:48 localhost kernel: [454680.731197] [   1062]     0  1062     1374       64    12288        0             0 oscam.armel
Nov 11 00:33:48 localhost kernel: [454680.731206] [   1064]     0  1064     6627      344    22528        0             0 oscam.armel
Nov 11 00:33:48 localhost kernel: [454680.731214] [   1078]     0  1078      482       59     8192        0             0 osemu.armel

Der Cubie hat eine SD, darauf ist das System installiert

Wernieman · 11 November 2020, 20:50:58

Gucke mal, was der Speicher im laufenden Betrieb so macht, Stichwort "free"

Aber (s.o.) es könnte auch ein Fehler auf der SD Card sein

Tommy82 · 11 November 2020, 21:08:34

Im Moment sagt free

Code Auswählen

 free -h
              total        used        free      shared  buff/cache   available
Mem:          2,0Gi       1,8Gi       130Mi       7,0Mi        86Mi       149Mi
Swap:            0B          0B          0B

htop zeigt dazu

Wernieman · 11 November 2020, 21:20:14

1. Welches System
2. Läuft dort nur FHEM oder auch mehr?

Tommy82 · 11 November 2020, 21:23:49

Armbian
Linux cubietruck 5.8.16-sunxi #20.08.14 SMP Tue Oct 20 22:15:32 CEST 2020 armv7l GNU/Linux

nur das was zu fhem gehört und oscam, das wars

Die "top" Prozesse gehören ja zum User fhem

Wernieman · 12 November 2020, 09:18:00

Welche Perl-Version?

Also das FHEM so viel Speicher braucht ist sehr ungewöhnlich ..

Laut Deinem TOP läuft FHEM seit 3 Minuten und braucht schon 83% Speicher und 33% CPU ... das ist zu viel ...
Das htop zeigt Ähnliches Verhalten, aber da lief fhem seit einer reichlichen Stunde.

Hattest Du das Betriebsystem upgedatet und dabei ein perl-Update? Das würde den Speicherverbrauch erklähren, aber nicht die CPU last ... oder hast Du so viele Geräte/Bedingungen?

Tommy82 · 12 November 2020, 20:24:13

Hallo,
die perl Version

Code Auswählen

 perl -v

This is perl 5, version 28, subversion 1 (v5.28.1) built for arm-linux-gnueabihf-thread-multi-64int

Das System ist aktuell, ob ich kurz bevor die Probleme anfingen ein update gemacht habe kann ich leider nicht mehr sagen.
grade war der Speicherverbrauch insgesamt deutlich nidrieger, allerdings hat Fhem heute nachmittag wieder ohne erkennbaren Grund neugestartet, das restliche System läuft aber ohne Probleme aktuell.....

Wernieman · 12 November 2020, 20:33:42

Naja .. wenn der Speicher gegen Null geht (bzw. die Eingestellte Reserve), schlägt der OOM-Killer des Betriebsystems zu. OOM = OutOfMemory.

Da bei Dir praktisch nur FHEM läuft, betrifft es (meistens) fhem, das zwangsbeendet wird. Systemd ist normalerweise so eingestellt, das er abgestürzte Programme automatisch startet ....

Tommy82 · 13 November 2020, 05:45:10

Zitat von: Wernieman am 12 November 2020, 20:33:42
Naja .. wenn der Speicher gegen Null geht (bzw. die Eingestellte Reserve), schlägt der OOM-Killer des Betriebsystems zu. OOM = OutOfMemory.

Da bei Dir praktisch nur FHEM läuft, betrifft es (meistens) fhem, das zwangsbeendet wird. Systemd ist normalerweise so eingestellt, das er abgestürzte Programme automatisch startet ....

Naja der Neustart klappt ja dann auch bei Fhem, zumindest etwas......

Aber der Grund und vor allem die Lösung wären schon interessant zu finden

Kann man denn Perl Prozess noch weiter eingrenzen, bzw. erkennen was Fhem dann genau macht?

Wernieman · 13 November 2020, 07:36:45

Da müsstest Du bei den "Egschberden" nachfragen .. so tief bin ich beim Debuggen nicht drin.

Tipp: Kannst Du den Betreff des ersten Post Ändern?

Ansonsten .. bezüglich Perl und Speicherverbrauch FHEM gibt es schon mehr als ein Post im Forum ....

Tommy82 · 13 November 2020, 17:16:24

Vielleicht liest ja ein experte mit, eben wieder ein absturz gehabt mit gleichen symthomen....

Kommte eine swap Datei/partition eine verbesserung bringen?

Wernieman · 13 November 2020, 18:28:10

Nein .. das verschiebt das Problem nur "nach hinten" ...

Wobei ich persöhnlich grundsätzlich Unix-Rechner mit Swap-Partitionen einrichte, sofern die Automatik nicht eine Swap-Datei gemacht hat ...

Tommy82 · 13 November 2020, 18:56:16

Hatte ja auch von verbesserung, nicht lösung gesprochen

, lösung wäre mir auch lieber.

Ich hab im LOg plötzlich so eine komische Meldung mit der ich nicht wirklich was anfangen kann, ob das hier im Zusammenhang steht weiss ich allerdings nicht

Code Auswählen

2020.11.13 18:54:24.603 3: Login denied for user >Thomas< via WEB_127.0.0.1_51904
2020.11.13 18:54:25.063 3: Login denied for user >Thomas< via WEB_127.0.0.1_51906
2020.11.13 18:54:25.076 3: Login denied for user >Thomas< via WEB_127.0.0.1_51908