swapper/0: page allocation failure: order:0, mode:0x1080020(GFP_ATOMIC), nodemask=(null)

[Asgaroth]

NOTE: I had to snip ALOT of this message due to the 6000 character limit on posts in these forums.

Hi,

After reporting some bursty transfer (upload) speeds on the F5-421 (see here), I thought I'd login via SSH and see if I could see anything odd going on.

The allocation errors I'm seeing are listed in the code block below, these are happening quite frequently:

Code: Select all

[Mon Apr  6 11:33:10 2020] swapper/0: page allocation failure: order:0, mode:0x1080020(GFP_ATOMIC), nodemask=(null)
[Mon Apr  6 11:33:10 2020] swapper/0 cpuset=/ mems_allowed=0-63
[Mon Apr  6 11:33:10 2020] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W  O    4.13.16 #270
[Mon Apr  6 11:33:10 2020] Hardware name: retsamarret 000-F5421-FBA002-0001/Default string, BIOS 5.12 10/19/2018
[Mon Apr  6 11:33:10 2020] Call Trace:
[Mon Apr  6 11:33:10 2020]  <IRQ>
[Mon Apr  6 11:33:10 2020]  dump_stack+0x4d/0x70
[Mon Apr  6 11:33:10 2020]  warn_alloc+0xdb/0x170
[Mon Apr  6 11:33:10 2020]  __alloc_pages_slowpath+0xd1d/0xdd0
[Mon Apr  6 11:33:10 2020]  ? __netif_receive_skb_core+0x386/0xa50
[Mon Apr  6 11:33:10 2020]  __alloc_pages_nodemask+0x1f9/0x210
[Mon Apr  6 11:33:10 2020]  page_frag_alloc+0x114/0x150
[Mon Apr  6 11:33:10 2020]  __napi_alloc_skb+0x8a/0xe0
[Mon Apr  6 11:33:10 2020]  r8152_poll+0x253/0x1020
[Mon Apr  6 11:33:10 2020]  net_rx_action+0x11b/0x350
[Mon Apr  6 11:33:10 2020]  __do_softirq+0xd3/0x2b0
[Mon Apr  6 11:33:10 2020]  irq_exit+0xab/0xb0
[Mon Apr  6 11:33:10 2020]  do_IRQ+0x7b/0xc0
[Mon Apr  6 11:33:10 2020]  common_interrupt+0x86/0x86
[Mon Apr  6 11:33:10 2020] RIP: 0010:cpuidle_enter_state+0x129/0x2b0
[Mon Apr  6 11:33:10 2020] RSP: 0018:ffffffffba803e10 EFLAGS: 00000202 ORIG_RAX: ffffffffffffffad
[Mon Apr  6 11:33:10 2020] RAX: ffff8e283fc1a280 RBX: 000000000000fbdc RCX: 000000000000001f
[Mon Apr  6 11:33:10 2020] RDX: 000098325d057aae RSI: fffffff70a65ebab RDI: 0000000000000000
[Mon Apr  6 11:33:10 2020] RBP: ffffffffba803e50 R08: 00000000ffffffff R09: 0000000000000008
[Mon Apr  6 11:33:10 2020] R10: ffffffffba803df0 R11: 0000000000000045 R12: ffff8e283fc23210
[Mon Apr  6 11:33:10 2020] R13: 0000000000000000 R14: 0000000000000001 R15: ffffffffba8e3e38
[Mon Apr  6 11:33:10 2020]  </IRQ>
[Mon Apr  6 11:33:10 2020]  cpuidle_enter+0x12/0x20
[Mon Apr  6 11:33:10 2020]  call_cpuidle+0x1e/0x30
[Mon Apr  6 11:33:10 2020]  do_idle+0x17f/0x1c0
[Mon Apr  6 11:33:10 2020]  cpu_startup_entry+0x18/0x20
[Mon Apr  6 11:33:10 2020]  rest_init+0xb7/0xc0
[Mon Apr  6 11:33:10 2020]  start_kernel+0x3aa/0x3b7
[Mon Apr  6 11:33:10 2020]  x86_64_start_reservations+0x24/0x26
[Mon Apr  6 11:33:10 2020]  x86_64_start_kernel+0x104/0x10d
[Mon Apr  6 11:33:10 2020]  secondary_startup_64+0x9f/0x9f
[Mon Apr  6 11:33:10 2020]  ? secondary_startup_64+0x9f/0x9f
[Mon Apr  6 11:33:10 2020] Mem-Info:
[Mon Apr  6 11:33:10 2020] active_anon:70679 inactive_anon:72652 isolated_anon:7
[Mon Apr  6 11:33:10 2020] Node 0 active_anon:282716kB inactive_anon:290608kB active_file:2011752kB inactive_file:518520kB unevictable:0kB isolated(anon):28kB isolated(file):0kB mapped:38108kB dirty:58140kB writeback:24164kB shmem:17956kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
[Mon Apr  6 11:33:10 2020] Node 0 DMA free:13272kB min:32kB low:44kB high:56kB active_anon:156kB inactive_anon:80kB active_file:1276kB inactive_file:52kB unevictable:0kB writepending:96kB present:15964kB managed:15880kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[Mon Apr  6 11:33:10 2020] lowmem_reserve[]: 0 1350 3316 3316
[Mon Apr  6 11:33:10 2020] Node 0 DMA32 free:8956kB min:3004kB low:4384kB high:5764kB active_anon:70060kB inactive_anon:71776kB active_file:955276kB inactive_file:196212kB unevictable:0kB writepending:32096kB present:1448612kB managed:1383044kB mlocked:0kB kernel_stack:3712kB pagetables:952kB bounce:0kB free_pcp:652kB local_pcp:480kB free_cma:0kB
[Mon Apr  6 11:33:10 2020] lowmem_reserve[]: 0 0 1965 1965
[Mon Apr  6 11:33:10 2020] Node 0 Normal free:1488kB min:4316kB low:6300kB high:8284kB active_anon:212500kB inactive_anon:218752kB active_file:1055200kB inactive_file:322256kB unevictable:0kB writepending:50112kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11312kB pagetables:17264kB bounce:0kB free_pcp:196kB local_pcp:120kB free_cma:0kB
[Mon Apr  6 11:33:10 2020] lowmem_reserve[]: 0 0 0 0
[Mon Apr  6 11:33:10 2020] Node 0 DMA: 12*4kB (UM) 23*8kB (M) 15*16kB (UM) 10*32kB (UME) 9*64kB (UE) 7*128kB (UME) 7*256kB (UME) 2*512kB (U) 2*1024kB (UM) 3*2048kB (UME) 0*4096kB = 13272kB
[Mon Apr  6 11:33:10 2020] Node 0 DMA32: 11*4kB (M) 306*8kB (UME) 182*16kB (UEH) 53*32kB (UH) 1*64kB (H) 2*128kB (H) 0*256kB 1*512kB (H) 1*1024kB (H) 0*2048kB 0*4096kB = 8956kB
[Mon Apr  6 11:33:10 2020] Node 0 Normal: 340*4kB (MH) 16*8kB (H) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1488kB
[Mon Apr  6 11:33:10 2020] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[Mon Apr  6 11:33:10 2020] 643369 total pagecache pages
[Mon Apr  6 11:33:10 2020] 7317 pages in swap cache
[Mon Apr  6 11:33:10 2020] Swap cache stats: add 210748, delete 203432, find 2020379/2044778
[Mon Apr  6 11:33:10 2020] Free swap  = 808580kB
[Mon Apr  6 11:33:10 2020] Total swap = 999868kB
[Mon Apr  6 11:33:10 2020] 890432 pages RAM
[Mon Apr  6 11:33:10 2020] 0 pages HighMem/MovableOnly
[Mon Apr  6 11:33:10 2020] 37445 pages reserved

Any ideas as to why the system is logging these errors?

[Asgaroth]

Code: Select all

[Mon Apr  6 11:33:10 2020] Node 0 Normal free:1488kB min:4316kB low:6300kB high:8284kB active_anon:212500kB inactive_anon:218752kB active_file:1055200kB inactive_file:322256kB unevictable:0kB writepending:50112kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11312kB pagetables:17264kB bounce:0kB free_pcp:196kB local_pcp:120kB free_cma:0kB

This line seems to indicate that the amount of available memory (488kB) is below min (4316kB). Only the kernel is allowed to reduce memory below the min value, when this happens all user space applications will freeze until the system has more memory available than the min free value. If the oom killer was active here is would activly go about killing applications until memory resource became available.

I check to see what min_free_kbytes is set to:

Code: Select all

# sysctl vm.min_free_kbytes
vm.min_free_kbytes = 7360

This seems to be pretty low as it seems, I am wondering what is eating up the memory that the system appears to think that it doesnt have available memory

Code: Select all

# free -mt
              total        used        free      shared  buff/cache   available
Mem:           3331         765          42          18        2523        2513
Swap:           976         174         802
Total:         4308         939         845

Buffer/Cache should be free'd if required, so the system doesnt appear to be suffering from memory starvation..

Any thoughts would be appreciated.

[Asgaroth]

It's actually redonkulous how often these memory allocation errors are reported:

Code: Select all

# dmesg -T | grep 'Node 0 Normal free:'
[Mon Apr  6 13:02:51 2020] Node 0 Normal free:1284kB min:4316kB low:6300kB high:8284kB active_anon:187108kB inactive_anon:205580kB active_file:1059336kB inactive_file:376900kB unevictable:0kB writepending:49652kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11104kB pagetables:17268kB bounce:0kB free_pcp:120kB local_pcp:120kB free_cma:0kB
[Mon Apr  6 13:02:57 2020] Node 0 Normal free:2152kB min:4316kB low:6300kB high:8284kB active_anon:190756kB inactive_anon:204980kB active_file:1071304kB inactive_file:357368kB unevictable:0kB writepending:239476kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11168kB pagetables:16988kB bounce:0kB free_pcp:120kB local_pcp:120kB free_cma:0kB
[Mon Apr  6 13:03:12 2020] Node 0 Normal free:1384kB min:4316kB low:6300kB high:8284kB active_anon:191056kB inactive_anon:204724kB active_file:1041068kB inactive_file:385284kB unevictable:0kB writepending:182904kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11168kB pagetables:17172kB bounce:0kB free_pcp:488kB local_pcp:364kB free_cma:0kB
[Mon Apr  6 13:03:22 2020] Node 0 Normal free:2972kB min:4316kB low:6300kB high:8284kB active_anon:190780kB inactive_anon:204300kB active_file:1061188kB inactive_file:362588kB unevictable:0kB writepending:255256kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11120kB pagetables:16928kB bounce:0kB free_pcp:1640kB local_pcp:80kB free_cma:0kB
[Mon Apr  6 13:03:43 2020] Node 0 Normal free:1404kB min:4316kB low:6300kB high:8284kB active_anon:202052kB inactive_anon:212544kB active_file:1146652kB inactive_file:262060kB unevictable:0kB writepending:215012kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11136kB pagetables:17016kB bounce:0kB free_pcp:992kB local_pcp:120kB free_cma:0kB
[Mon Apr  6 13:03:48 2020] Node 0 Normal free:1548kB min:4316kB low:6300kB high:8284kB active_anon:201660kB inactive_anon:212580kB active_file:1150520kB inactive_file:258304kB unevictable:0kB writepending:225304kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11136kB pagetables:16960kB bounce:0kB free_pcp:2228kB local_pcp:140kB free_cma:0kB
[Mon Apr  6 13:04:20 2020] Node 0 Normal free:1416kB min:4316kB low:6300kB high:8284kB active_anon:207656kB inactive_anon:218764kB active_file:1089072kB inactive_file:309044kB unevictable:0kB writepending:254628kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11152kB pagetables:17056kB bounce:0kB free_pcp:620kB local_pcp:120kB free_cma:0kB
[Mon Apr  6 13:04:49 2020] Node 0 Normal free:1236kB min:4316kB low:6300kB high:8284kB active_anon:208184kB inactive_anon:218528kB active_file:1132780kB inactive_file:262460kB unevictable:0kB writepending:106208kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11184kB pagetables:16860kB bounce:0kB free_pcp:240kB local_pcp:120kB free_cma:0kB
[Mon Apr  6 13:04:52 2020] Node 0 Normal free:2036kB min:4316kB low:6300kB high:8284kB active_anon:208036kB inactive_anon:218612kB active_file:1145388kB inactive_file:252796kB unevictable:0kB writepending:120820kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11136kB pagetables:17056kB bounce:0kB free_pcp:144kB local_pcp:144kB free_cma:0kB
[Mon Apr  6 13:04:54 2020] Node 0 Normal free:1440kB min:4316kB low:6300kB high:8284kB active_anon:208176kB inactive_anon:219668kB active_file:1150860kB inactive_file:247976kB unevictable:0kB writepending:120748kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11168kB pagetables:16864kB bounce:0kB free_pcp:312kB local_pcp:0kB free_cma:0kB
[Mon Apr  6 13:05:00 2020] Node 0 Normal free:1464kB min:4316kB low:6300kB high:8284kB active_anon:207640kB inactive_anon:220432kB active_file:1148012kB inactive_file:251092kB unevictable:0kB writepending:146252kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11168kB pagetables:16860kB bounce:0kB free_pcp:896kB local_pcp:308kB free_cma:0kB
[Mon Apr  6 13:05:17 2020] Node 0 Normal free:4952kB min:4316kB low:6300kB high:8284kB active_anon:199588kB inactive_anon:219560kB active_file:1100776kB inactive_file:297796kB unevictable:0kB writepending:181616kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11168kB pagetables:16820kB bounce:0kB free_pcp:992kB local_pcp:196kB free_cma:0kB
[Mon Apr  6 13:05:46 2020] Node 0 Normal free:1904kB min:4316kB low:6300kB high:8284kB active_anon:205432kB inactive_anon:212684kB active_file:1112136kB inactive_file:295392kB unevictable:0kB writepending:48436kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11168kB pagetables:16892kB bounce:0kB free_pcp:72kB local_pcp:72kB free_cma:0kB
[Mon Apr  6 13:06:04 2020] Node 0 Normal free:1392kB min:4316kB low:6300kB high:8284kB active_anon:205112kB inactive_anon:209864kB active_file:1131644kB inactive_file:270480kB unevictable:0kB writepending:243372kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11168kB pagetables:16892kB bounce:0kB free_pcp:116kB local_pcp:116kB free_cma:0kB
[Mon Apr  6 13:07:17 2020] Node 0 Normal free:1416kB min:4316kB low:6300kB high:8284kB active_anon:220588kB inactive_anon:226244kB active_file:1027248kB inactive_file:339296kB unevictable:0kB writepending:237712kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11184kB pagetables:17008kB bounce:0kB free_pcp:984kB local_pcp:484kB free_cma:0kB
[Mon Apr  6 13:10:32 2020] Node 0 Normal free:1124kB min:4316kB low:6300kB high:8284kB active_anon:221748kB inactive_anon:236736kB active_file:1047528kB inactive_file:308024kB unevictable:0kB writepending:204968kB present:2097152kB managed:2013024kB mlocked:0kB kernel_stack:11168kB pagetables:17064kB bounce:0kB free_pcp:1548kB local_pcp:132kB free_cma:0kB

These repeat several times per minute or two, sometimes more

[TMroy]

Yeah, will forward these info to engineer.

[TMroy]

Would you provide following information?

1. TOS version;
2. Run ps -ef command from SSH, and post us the output;
3. what apps you are running in the device.

[Asgaroth]

[1] TOS Version

Code: Select all

4.1.21-2003031748

[2] Please let me know how I can get the process output to you.
[*] I cannot post it in the message as the character limit of 6000 makes it too big
[*] I cannot attach it as a file as I cannot attach a .txt, .log, .sh file to this message.

[3] I'm currently only running docker, which has 1 syncthing container running. However, these issues were there before I started docker and syncthing.

I am also trying to transfer files across to the nas which has burst speed, it appears that these errors correlate with the drop in transfer speeds.

[TMroy]

please send the output to support(a)terra-master.com, thank you!

[Asgaroth]

Email sent.

I can reproduce this with transferring large files to the NAS without any other applications running.

The nas has a 6 x RAID-6 pool setup with 1 volume running a btrfs file system.
The nas also has it's 4 x 1Gbps interfaces configured in a static lag group.
I connect to the NAS using FTP (plain, not FTP over TLS).
I upload continuously files of sizes between 2 to 3GB in size with 4 concurrent sessions.

It appears that as soon as the buffers are filled, this error occurs, the nas then stalls ("freezes") until it free's memory and then continues on transferring.

Sometimes this stall can result in complete session disconnects on the ftp client's side.

[TMroy]

Thank you! we will study it and come back to you soon.

[Asgaroth]

Okay, thanks.

I just noticed that I mad a typo in the RAID-6 configuration, what I meant to say was:

The NAS has 5 x Seagate Barracuda ST4000LM024 SATA HDD's configured in a RAID-6 pool.