I'm trying to upgrade the system using sysupgrade. I've generated my own firmware that is 11MB in size, and the device has only 32MB FLASH memory. I have 13MB free space in /tmp.
When I upload the image to the device, it becomes very slow. The sys load goes to 90+%. My bet is that this is a filesystem issue. There are situations, when the system runs out of memory and logs messages like this:
Jun 16 08:04:02 IPS-231-0000 kernel: [ 1277.967103] udhcpc invoked oom-killer: gfp_mask=0x2420848, order=0, oom_score_adj=0
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1277.975092] CPU: 0 PID: 1459 Comm: udhcpc Not tainted 4.4.61 #0
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1277.981211] Stack : 8033ddb4 00000000 00000001 80380000 819b6fcc 8037ce03 8031f704 000005b3
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1277.981211] #011 803c3434 807f1ac4 00000000 00000031 00001bdd 8004ab64 00000006 80327d90
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1277.981211] #011 00000000 00000000 80323020 807f1964 803c61e2 80048ad0 8037c490 00000000
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1277.981211] #011 00000001 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1277.981211] #011 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1277.981211] #011 ...
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.017812] Call Trace:
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.020492] [<8004ab64>] vprintk_default+0x24/0x30
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.025560] [<80048ad0>] printk+0x2c/0x38
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.029759] [<8007631c>] dump_header.isra.4+0x48/0x130
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.035110] [<80149600>] dump_stack+0x14/0x28
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.039579] [<800147cc>] show_stack+0x50/0x84
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.044115] [<8007631c>] dump_header.isra.4+0x48/0x130
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.049485] [<800817e4>] shrink_slab.part.6.constprop.15+0x2d4/0x308
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.056196] [<800429b0>] put_prev_task_fair+0x2c/0x5c
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.061572] [<80076700>] oom_kill_process+0x98/0x43c
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.066808] [<80076e08>] out_of_memory+0x2e0/0x324
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.071804] [<8007a708>] __alloc_pages_nodemask+0x684/0x6f0
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.077647] [<80073820>] pagecache_get_page+0x154/0x278
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.083150] [<800d52f8>] __find_get_block+0xf0/0x214
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.088386] [<800d55ac>] __getblk_slow+0x190/0x374
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.093627] [<800d57c8>] __getblk_gfp+0x38/0x90
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.098457] [<800fce90>] squashfs_read_data+0x1c8/0x6e8
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.104266] [<80100e54>] squashfs_readpage_block+0x37c/0x5a0
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.110383] [<800fece8>] squashfs_readpage+0x5b0/0x708
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.116033] [<8007de98>] __do_page_cache_readahead+0x1f8/0x264
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.122240] [<8007296c>] find_get_entry+0x24/0x9c
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.127552] [<80075654>] filemap_fault+0x1ac/0x458
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.132552] [<80093594>] do_set_pte+0xfc/0x150
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.137425] [<8009074c>] __do_fault+0x3c/0xa8
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.142049] [<80093594>] do_set_pte+0xfc/0x150
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.146675] [<80093acc>] handle_mm_fault+0x4e4/0xba8
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.151942] [<801f6b7c>] dev_load+0x18/0x8c
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.156489] [<80019668>] __do_page_fault+0x1b8/0x4f4
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.161673] [<800bfaf4>] evict+0x12c/0x154
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.165970] [<800bf98c>] destroy_inode+0x2c/0x68
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.170972] [<800429b0>] put_prev_task_fair+0x2c/0x5c
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.176185] [<801c55c4>] sock_release+0x2c/0xb8
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.181037] [<800432f8>] pick_next_task_fair+0xe8/0x16c
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.186446] [<8003ed3c>] update_rq_clock+0x28/0x84
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.191505] [<8000a7d0>] __schedule+0x15c/0x628
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.196236] [<80004420>] ret_from_exception+0x0/0x10
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.201508] [<800d3b9c>] end_buffer_read_sync+0x0/0x38
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.206901]
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.208432] Mem-Info:
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.210865] active_anon:707 inactive_anon:2729 isolated_anon:0
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.210865] active_file:126 inactive_file:129 isolated_file:0
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.210865] unevictable:0 dirty:0 writeback:0 unstable:0
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.210865] slab_reclaimable:144 slab_unreclaimable:1278
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.210865] mapped:30 shmem:2793 pagetables:64 bounce:0
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.210865] free:310 free_pcp:0 free_cma:0
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.243573] Normal free:1240kB min:1024kB low:1280kB high:1536kB active_anon:2828kB inactive_anon:10916kB active_file:504kB inactive_file:516kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:32768kB managed:28532kB mlocked:0kB dirty:0kB writeback:0kB mapped:120kB shmem:11172kB slab_reclaimable:576kB slab_unreclaimable:5112kB kernel_stack:352kB pagetables:256kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_sc
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.288486] lowmem_reserve[]: 0 0
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.291930] Normal: 50*4kB (UM) 54*8kB (UME) 34*16kB (UME) 2*32kB (U) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1240kB
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.304606] 3048 total pagecache pages
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.308480] 0 pages in swap cache
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.311931] Swap cache stats: add 0, delete 0, find 0/0
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.317272] Free swap = 0kB
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.320213] Total swap = 0kB
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.323208] 8192 pages RAM
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.325979] 0 pages HighMem/MovableOnly
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.329893] 1059 pages reserved
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.333149] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.341953] [ 397] 0 397 295 16 3 0 0 0 ubusd
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.350837] [ 406] 0 406 224 10 3 0 0 0 askfirst
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.359917] [ 787] 0 787 307 35 5 0 0 0 logd
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.368695] [ 788] 0 788 335 23 4 0 0 0 logread
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.377746] [ 797] 0 797 361 22 4 0 0 0 rpcd
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.386506] [ 844] 0 844 427 45 4 0 0 0 netifd
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.395460] [ 865] 0 865 355 30 4 0 0 0 odhcpd
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.404420] [ 905] 0 905 265 11 3 0 0 0 dropbear
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.413582] [ 934] 0 934 385 32 4 0 0 0 uhttpd
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.422544] [ 1073] 0 1073 298 11 3 0 0 0 ntpd
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.431326] [ 1239] 453 1239 263 18 4 0 0 0 dnsmasq
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.440313] [ 1329] 0 1329 282 26 3 0 0 0 dropbear
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.449442] [ 1332] 0 1332 297 9 3 0 0 0 udhcpc
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.458401] [ 1337] 0 1337 298 10 4 0 0 0 ash
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.467071] [ 1459] 0 1459 297 10 4 0 0 0 udhcpc
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.476024] [ 1529] 0 1529 837 355 6 0 0 0 luci
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.484793] Out of memory: Kill process 1529 (luci) score 49 or sacrifice child
Jun 16 08:04:03 IPS-231-0000 kernel: [ 1278.492344] Killed process 1529 (luci) total-vm:3348kB, anon-rss:1352kB, file-rss:68kB
After rebooting, copying the firmware again to the device, I don't experience this issue. I suspect that there must be some process that initializes the flash, and when it is done everything works like a charm.
The question is obviously how to stop this memory issue? I run LEDE v17.01.1. It is okay to run the device in some minimal mode, i.e. stopping services when doing firmware upgrade, but I don't really know where to start. Any help welcome.
Levente