Posts by tempestnano

tempestnano · LE10 rpi4-4gb oom errors tempestnano April 2, 2021 at 2:41 PM

Quote from SupermanLeRetour

For what it's worth, I mitigated the issue by moving the external HDD to a USB 2.0 port and limiting my download speed to 10 MB/s. It seems the best way to prevent the issue it to not do a lot of I/O, so not ideal at all but at least I can use the system again. I'm still having trouble unrar-ing a large 30 GB files though.

I am not even sure it is limited to USB usage. I setup a second rpi4 as an nfs, and ran a docker torrent client on Libreelec accessing its share over samba, and I still got the error. This is backed up by this comment on github where a user is able to reliably trigger the error with a script that employs a using a virtual filesystem. Oh, I see that you are already participating in that issue thread.

My rpi4 running raspbian with the 64-bit kernel handles these docker containers without breaking a sweat. I would very much like to address this somehow, but at this point, I am not sure where to start. It seems that this is unlikely to be fixed in the 32-bit kernel upstream when arm_64bit=1 works in most use cases.

tempestnano · LE10 rpi4-4gb oom errors tempestnano March 19, 2021 at 2:33 AM

Edit: Disregard this, this only delayed the problems for an extra hour or so before the oom-killer kicked in.

I have tried tons of things to fix this, and I believe I have finally cracked it. I am fairly certain that adding these two lines to my autostart.sh has stopped the condition that summons the oom-killer. Naturally, there is still some underlying problem that is merely sidestepped here.

Code: /storage/.config/autostart.sh

sysctl vm.dirty_background_ratio=5
sysctl vm.dirty_ratio=8

Details:

I found that before the oom killer was invoked, the kernel process kswapd0 was using %100 cpu. I found that if the caches were flushed via echo 4 > /proc/sys/vm/drop_caches, it resolved the problem temporarily. This led me to mess with the cache ratios to force the system to keep the caches as empty as possible.

tempestnano · LE10 rpi4-4gb oom errors tempestnano March 18, 2021 at 4:06 PM

Setup

RPi4 4GB
12TB USB 3.0 Drive
LE 10 beta
Docker

I am encountering constant oom events when there is plenty of available ram. The oom-killer can fire as often as every 30 seconds, and it loves to kill kodi. I know I can tell it to avoid killing kodi, but the underlying problem would persist. I've encountered this before on 9.2.6, but not nearly as often as on the new build.

I do a fresh install of LE10, attach my external USB3 drive, add my media libraries and add any docker image that generates lots of disk io (transmission, rsync, medusa, etc), and after a few minutes the oom-killer will begin decimating my processes every few minutes. My rpi4 memory usage never really goes over 1 GB or so (out of 4GB). I have seen the oom events occur even before docker and Kodi loads. I don't believe that memory fragmentation is a problem, as I always have plenty of 4096kB blocks of DMA and HiMem. I have been beating my head against this, and I believe it is possibly related to USB3 disk writes trigger OOM reaper on Pi 4. Any suggestions on how best to try to debug this?

I really love the design philosophy of LE and I would rather not shift to a normal distro, but other users report a 64 bit kernel alleviates may oom errors. Would it even be possible for me to compile a 64 bit version of LE for the rpi4 knowing that this would force software x264 decoding and loss of widevine?

Things I have tried:

Enabling cgroups and limiting the docker images to only 256MB (limiting works, but oom persists)
"sysctl vm.overcommit_memory=2" This causes the system to crash during boot
cron job of "echo 4 > /proc/sys/vm/drop_caches" every minute. This reduces the frequency of oom events, but it doesn't stop them.
mucking about with "vm.extfrag_threshold, vm.vfs_cache_pressure, swappiness": no real change
Adding a massive swap file: It never gets used.
Fresh LE10 install on both a large SD card and a usb 3.0 attached ssd.
Even without docker, I believe I have seen one or two oom events, but they are rare.

Thanks!

Code: Dmesg output of a typical oom event

[12007.624637] Mem-Info:
[12007.624649] active_anon:2019 inactive_anon:108517 isolated_anon:0
[12007.624649]  active_file:71240 inactive_file:80161 isolated_file:39
[12007.624649]  unevictable:0 dirty:4 writeback:0
[12007.624649]  slab_reclaimable:10261 slab_unreclaimable:9625
[12007.624649]  mapped:48527 shmem:4136 pagetables:1389 bounce:0
[12007.624649]  free:673253 free_pcp:155 free_cma:116364
[12007.624659] Node 0 active_anon:8076kB inactive_anon:434068kB active_file:284960kB inactive_file:320644kB unevictable:0kB isolated(anon):0kB isolated(file):156kB mapped:194108kB dirty:16kB writeback:0kB shmem:16544kB writeback_tmp:0kB kernel_stack:3288kB all_unreclaimable? yes

[12007.624671] DMA free:485840kB min:16384kB low:20480kB high:24576kB reserved_highatomic:4096KB active_anon:0kB inactive_anon:0kB active_file:1352kB inactive_file:6260kB unevictable:0kB writepending:0kB present:786432kB managed:652332kB mlocked:0kB pagetables:640kB bounce:0kB free_pcp:256kB local_pcp:52kB free_cma:465456kB

[12007.624677] lowmem_reserve[]: 0 0 3187 0

[12007.624714] HighMem free:2207172kB min:512kB low:21000kB high:41488kB reserved_highatomic:0KB active_anon:8076kB inactive_anon:434068kB active_file:283520kB inactive_file:314416kB unevictable:0kB writepending:16kB present:3263488kB managed:3263488kB mlocked:0kB pagetables:4916kB bounce:0kB free_pcp:364kB local_pcp:0kB free_cma:0kB

[12007.624720] lowmem_reserve[]: 0 0 0 0
[12007.624751] DMA: 500*4kB (UE) 452*8kB (UEC) 358*16kB (UEC) 12*32kB (UEC) 41*64kB (UEC) 9*128kB (UEC) 17*256kB (UC) 8*512kB (UC) 3*1024kB (C) 2*2048kB (C) 111*4096kB (C) = 485776kB
[12007.624878] HighMem: 14135*4kB (UM) 11331*8kB (UM) 5085*16kB (UM) 1180*32kB (UM) 376*64kB (UM) 85*128kB (UM) 55*256kB (UM) 13*512kB (UM) 9*1024kB (UM) 2*2048kB (UM) 457*4096kB (M) = 2207172kB
[12007.625005] 150713 total pagecache pages
[12007.625012] 0 pages in swap cache
[12007.625018] Swap cache stats: add 0, delete 0, find 0/0
[12007.625024] Free swap  = 0kB
[12007.625030] Total swap = 0kB
[12007.625036] 1012480 pages RAM
[12007.625042] 815872 pages HighMem/MovableOnly
[12007.625047] 33525 pages reserved
[12007.625053] 131072 pages cma reserved

Display More

tempestnano

Raspberry Pi 4, 9.2.0.

Cec standby and wake works like a charm for the first few minutes after restarting the Kodi service or manually powering on the TV, but it stops working altogether after a few minutes. The TV will stubbornly stay away or asleep despite what Kodi thinks it is telling it to do. However, if I then go to the command line and manually tell the TV to power on via:

Code

LibreELEC:~ # echo 'on 0' | cec-client -s -d 1
opening a connection to the CEC adapter...

The TV responds properly and wakes up. Which makes me think that I can rule out the TV as the source of the problem.

Any help parsing the following debug logs would be appreciated.

Normal wake from standby

2019-12-21 17:37:51.371 T:2560471920 DEBUG: CecLogMessage - GetPhysicalAddress - physical address = 1000

2019-12-21 17:37:51.371 T:2560471920 DEBUG: CecLogMessage - physical address unchanged (1000)

2019-12-21 17:37:51.996 T:2560471920 DEBUG: CecLogMessage - << powering on 'TV' (0)

2019-12-21 17:37:51.997 T:2560471920 DEBUG: CecLogMessage - << 10:04

2019-12-21 17:37:52.057 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): active source (1000)

2019-12-21 17:37:52.057 T:2560471920 DEBUG: CecLogMessage - << 1f:82:10:00

2019-12-21 17:37:52.177 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): menu state 'activated'

2019-12-21 17:37:52.177 T:2560471920 DEBUG: CecLogMessage - 'menu status' is marked as unsupported feature for device 'TV'

2019-12-21 17:37:52.711 T:2560471920 DEBUG: CecLogMessage - >> 0f:80:00:00:10:00

2019-12-21 17:37:52.711 T:2560471920 DEBUG: CecLogMessage - Recorder 1 (1) was already marked as active source

2019-12-21 17:37:52.711 T:2560471920 DEBUG: CecLogMessage - >> source activated: Recorder 1 (1)

2019-12-21 17:37:52.712 T:2560471920 DEBUG: CecLogMessage - sending active source message for 'Recorder 1'

2019-12-21 17:37:52.712 T:2560471920 DEBUG: CecLogMessage - << powering on 'TV' (0)

2019-12-21 17:37:52.712 T:2560471920 DEBUG: CecLogMessage - << 10:04

2019-12-21 17:37:52.712 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Broadcast (F): routing change (80)

2019-12-21 17:37:52.802 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): active source (1000)

2019-12-21 17:37:52.802 T:2560471920 DEBUG: CecLogMessage - << 1f:82:10:00

2019-12-21 17:37:52.922 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): menu state 'activated'

2019-12-21 17:37:52.922 T:2560471920 DEBUG: CecLogMessage - 'menu status' is marked as unsupported feature for device 'TV'

2019-12-21 17:37:53.368 T:2560471920 DEBUG: CecLogMessage - >> 01:00:04:00

2019-12-21 17:37:53.368 T:2560471920 DEBUG: CecLogMessage - marking opcode 'image view on' as unsupported feature for device 'TV'

2019-12-21 17:37:53.368 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): feature abort ( 0)

2019-12-21 17:37:53.551 T:2560471920 DEBUG: CecLogMessage - >> 0f:84:00:00:00

2019-12-21 17:37:53.551 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): physical address 1000

2019-12-21 17:37:53.551 T:2560471920 DEBUG: CecLogMessage - << 1f:84:10:00:01

2019-12-21 17:37:53.551 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Broadcast (F): report physical address (84)

2019-12-21 17:37:53.898 T:2560471920 DEBUG: CecLogMessage - >> 0f:87:6d:74:6b

2019-12-21 17:37:53.898 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> Broadcast (F): vendor id Pulse Eight (1582)

2019-12-21 17:37:53.898 T:2560471920 DEBUG: CecLogMessage - << 1f:87:00:15:82

2019-12-21 17:37:53.898 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Broadcast (F): device vendor id (87)

2019-12-21 17:37:55.842 T:2560471920 DEBUG: CecLogMessage - >> 4f:84:20:00:04

2019-12-21 17:37:55.842 T:2560471920 DEBUG: CecLogMessage - >> Playback 1 (4) -> Broadcast (F): report physical address (84)

2019-12-21 17:37:55.909 T:2560471920 DEBUG: CecLogMessage - >> 01:83

2019-12-21 17:37:55.909 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): physical address 1000

2019-12-21 17:37:55.910 T:2560471920 DEBUG: CecLogMessage - << 1f:84:10:00:01

2019-12-21 17:37:55.910 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): give physical address (83)

2019-12-21 17:37:56.615 T:2560471920 DEBUG: CecLogMessage - >> 01:46

2019-12-21 17:37:56.615 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): OSD name 'Kodi'

2019-12-21 17:37:56.616 T:2560471920 DEBUG: CecLogMessage - << 10:47:4b:6f:64:69

2019-12-21 17:37:56.616 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): give osd name (46)

2019-12-21 17:37:56.985 T:2560471920 DEBUG: CecLogMessage - >> 4f:87:08:00:46

2019-12-21 17:37:56.985 T:2560471920 DEBUG: CecLogMessage - >> Playback 1 (4) -> Broadcast (F): device vendor id (87)

2019-12-21 17:37:57.052 T:2560471920 DEBUG: CecLogMessage - >> 01:8c

2019-12-21 17:37:57.052 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): vendor id Pulse Eight (1582)

2019-12-21 17:37:57.052 T:2560471920 DEBUG: CecLogMessage - << 1f:87:00:15:82

2019-12-21 17:37:57.052 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): give device vendor id (8C)

2019-12-21 17:37:57.455 T:2560471920 DEBUG: CecLogMessage - >> 01:8f

2019-12-21 17:37:57.455 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): on

2019-12-21 17:37:57.455 T:2560471920 DEBUG: CecLogMessage - << 10:90:00

2019-12-21 17:37:57.455 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): give device power status (8F)

2019-12-21 17:37:57.610 T:2560471920 DEBUG: CecLogMessage - >> 01:8f

2019-12-21 17:37:57.610 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): on

2019-12-21 17:37:57.610 T:2560471920 DEBUG: CecLogMessage - << 10:90:00

2019-12-21 17:37:57.610 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): give device power status (8F)

2019-12-21 17:37:57.994 T:2560471920 DEBUG: CecLogMessage - >> 01:8f

2019-12-21 17:37:57.994 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): on

2019-12-21 17:37:57.994 T:2560471920 DEBUG: CecLogMessage - << 10:90:00

2019-12-21 17:37:57.994 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): give device power status (8F)

2019-12-21 17:37:58.230 T:2560471920 DEBUG: CecLogMessage - >> 0f:86:10:00

2019-12-21 17:37:58.230 T:2560471920 DEBUG: CecLogMessage - >> TV (0) sets stream path to physical address 1000

2019-12-21 17:37:58.230 T:2560471920 DEBUG: CecLogMessage - Recorder 1 (1) was already marked as active source

2019-12-21 17:37:58.230 T:2560471920 DEBUG: CecLogMessage - >> source activated: Recorder 1 (1)

2019-12-21 17:37:58.230 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): active source (1000)

2019-12-21 17:37:58.231 T:2560471920 DEBUG: CecLogMessage - << 1f:82:10:00

2019-12-21 17:37:58.231 T:2560471920 DEBUG: CecLogMessage - >> TV (0) -> Broadcast (F): set stream path (86)

Failed wake from standby

2019-12-21 17:43:16.846 T:2560471920 DEBUG: CecLogMessage - Recorder 1 (1) was already marked as active source

2019-12-21 17:43:16.846 T:2560471920 DEBUG: CecLogMessage - >> source activated: Recorder 1 (1)

2019-12-21 17:43:16.846 T:2560471920 DEBUG: CecLogMessage - sending active source message for 'Recorder 1'

2019-12-21 17:43:16.847 T:2560471920 DEBUG: CecLogMessage - << powering on 'TV' (0)

2019-12-21 17:43:16.847 T:2560471920 DEBUG: CecLogMessage - 'image view on' is marked as unsupported feature for device 'TV'

2019-12-21 17:43:16.847 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): active source (1000)

2019-12-21 17:43:16.847 T:2560471920 DEBUG: CecLogMessage - << 1f:82:10:00

2019-12-21 17:43:16.876 T:3011833872 DEBUG: ToggleDeviceState - waking up CEC device...

2019-12-21 17:43:16.966 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): menu state 'activated'

2019-12-21 17:43:16.966 T:2560471920 DEBUG: CecLogMessage - 'menu status' is marked as unsupported feature for device 'TV'

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - Recorder 1 (1) was already marked as active source

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - >> source activated: Recorder 1 (1)

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - sending active source message for 'Recorder 1'

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - << powering on 'TV' (0)

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - 'image view on' is marked as unsupported feature for device 'TV'

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> broadcast (F): active source (1000)

2019-12-21 17:43:16.971 T:2560471920 DEBUG: CecLogMessage - << 1f:82:10:00

2019-12-21 17:43:17.091 T:2560471920 DEBUG: CecLogMessage - << Recorder 1 (1) -> TV (0): menu state 'activated'

2019-12-21 17:43:17.091 T:2560471920 DEBUG: CecLogMessage - 'menu status' is marked as unsupported feature for device 'TV'

Failed when using: kodi-send --action=CECActivateSource