Debian memory fragment

[ice00]

hi,

I'm using Debian with kernel tree 101 (not 65) and have the 2GB board.

The server is used with pools coin mining software (already used onto Raspberry Pi2 without problem with Raspian).

I get kernel messages of out of memory due to fragmentation (some python script of the pool use lot of contiguos memory).

Code:

May 25 20:16:27 localhost kernel: [187398.049922] python2.7: page allocation failure: order:1, mode:0x200020 May 25 20:16:27 localhost kernel: [187398.057186] CPU: 1 PID: 5604 Comm: python2.7 Tainted: G           O 3.10.101-0-pine64-l ongsleep #39 May 25 20:16:27 localhost kernel: [187398.069955] [<ffffffc000088388>] dump_backtrace+0x0/0x118 May 25 20:16:27 localhost kernel: [187398.075965] [<ffffffc0000884c4>] show_stack+0x24/0x30 May 25 20:16:27 localhost kernel: [187398.081592] [<ffffffc0006be948>] dump_stack+0x20/0x28 May 25 20:16:27 localhost kernel: [187398.087213] [<ffffffc00015fb58>] warn_alloc_failed+0x118/0x130 May 25 20:16:27 localhost kernel: [187398.093682] [<ffffffc000162d38>] __alloc_pages_nodemask+0x6b8/0x834 May 25 20:16:27 localhost kernel: [187398.100629] [<ffffffc00019deb4>] cache_alloc_refill+0x370/0x6ac May 25 20:16:27 localhost kernel: [187398.107193] [<ffffffc00019e4a0>] kmem_cache_alloc+0x9c/0x200 May 25 20:16:27 localhost kernel: [187398.113472] [<ffffffc0005bc584>] sk_prot_alloc+0x3c/0x10c May 25 20:16:27 localhost kernel: [187398.119465] [<ffffffc0005be94c>] sk_clone_lock+0x34/0x290 May 25 20:16:27 localhost kernel: [187398.125460] [<ffffffc000607e58>] inet_csk_clone_lock+0x30/0xb0 May 25 20:16:27 localhost kernel: [187398.131930] [<ffffffc00061e588>] tcp_create_openreq_child+0x38/0x34c May 25 20:16:27 localhost kernel: [187398.138970] [<ffffffc00061b64c>] tcp_v4_syn_recv_sock+0x4c/0x234 May 25 20:16:27 localhost kernel: [187398.145628] [<ffffffc00061eca8>] tcp_check_req+0x304/0x4c0 May 25 20:16:27 localhost kernel: [187398.151717] [<ffffffc00061b9ac>] tcp_v4_do_rcv+0x178/0x330 May 25 20:16:27 localhost kernel: [187398.157803] [<ffffffc00061de18>] tcp_v4_rcv+0x4c0/0x6ec : Message from syslogd@localhost at May 25 20:26:04 ... kernel:[187965.808278] Call trace: May 25 20:16:27 localhost kernel: [187398.163607] [<ffffffc0005fcbb8>] ip_local_deliver_finish+0x13c/0x240 May 25 20:16:27 localhost kernel: [187398.170642] [<ffffffc0005fd140>] ip_local_deliver+0x88/0x9c May 25 20:16:27 localhost kernel: [187398.176826] [<ffffffc0005fcfa0>] ip_rcv_finish+0x2e4/0x2f4 May 25 20:16:27 localhost kernel: [187398.182914] [<ffffffc0005fd3ec>] ip_rcv+0x298/0x2dc May 25 20:16:27 localhost kernel: [187398.188338] [<ffffffc0005cf82c>] __netif_receive_skb_core+0x650/0x6d0 May 25 20:16:27 localhost kernel: [187398.195472] [<ffffffc0005cf8d4>] __netif_receive_skb+0x28/0x84 May 25 20:16:27 localhost kernel: [187398.201942] [<ffffffc0005d089c>] process_backlog+0xbc/0x194 May 25 20:16:27 localhost kernel: [187398.208124] [<ffffffc0005d06c4>] net_rx_action+0xe0/0x1fc May 25 20:16:27 localhost kernel: [187398.214122] [<ffffffc0000b5ff8>] __do_softirq+0x160/0x2d8 May 25 20:16:27 localhost kernel: [187398.220118] [<ffffffc0000b625c>] do_softirq+0x54/0x64 May 25 20:16:27 localhost kernel: [187398.225733] [<ffffffc0000b62fc>] local_bh_enable_ip+0x90/0xbc May 25 20:16:27 localhost kernel: [187398.232105] [<ffffffc0006c3890>] _raw_spin_unlock_bh+0x44/0x50 May 25 20:16:27 localhost kernel: [187398.238579] [<ffffffc0005bdc78>] release_sock+0x104/0x130 May 25 20:16:27 localhost kernel: [187398.244576] [<ffffffc00062e478>] inet_stream_connect+0x54/0x68 May 25 20:16:27 localhost kernel: [187398.251043] [<ffffffc0005bab78>] SyS_connect+0x8c/0xb4 May 25 20:16:27 localhost kernel: [187398.256748] Mem-Info: May 25 20:16:27 localhost kernel: [187398.259321] DMA per-cpu: May 25 20:16:27 localhost kernel: [187398.262178] CPU    0: hi:  186, btch:  31 usd:  28 May 25 20:16:27 localhost kernel: [187398.267506] CPU    1: hi:  186, btch:  31 usd:   0 May 25 20:16:27 localhost kernel: [187398.272835] CPU    2: hi:  186, btch:  31 usd:   0 May 25 20:16:27 localhost kernel: [187398.278161] CPU    3: hi:  186, btch:  31 usd:  62 May 25 20:16:27 localhost kernel: [187398.283495] active_anon:202579 inactive_anon:112366 isolated_anon:23 May 25 20:16:27 localhost kernel: [187398.283495]  active_file:76997 inactive_file:88954 isolated_file:0 May 25 20:16:27 localhost kernel: [187398.283495]  unevictable:27 dirty:265 writeback:0 unstable:0 May 25 20:16:27 localhost kernel: [187398.283495]  free:6228 slab_reclaimable:5357 slab_unreclaimable:4630 May 25 20:16:27 localhost kernel: [187398.283495]  mapped:12866 shmem:19578 pagetables:1549 bounce:0 May 25 20:16:27 localhost kernel: [187398.283495]  free_cma:721 May 25 20:16:27 localhost kernel: [187398.320086] DMA free:23920kB min:5612kB low:7012kB high:8416kB active_anon:810316kB inactive_anon:449464kB active_file:307988kB inactive_file:356808kB unevictable:108kB isolated(anon):92kB isolated(file):0kB present:2080768kB managed:1969892kB mlocked:108kB dirty:1060kB writeback:0kB mapped:51464kB shmem:78312kB slab_reclaimable:21428kB slab_unreclaimable:18520kB kernel_stack:3472kB pagetables:6196kB unstable:0kB bounce:0kB free_cma:2884kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no May 25 20:16:27 localhost kernel: [187398.368043] lowmem_reserve[]: 0 0 0 May 25 20:16:27 localhost kernel: [187398.371956] DMA: 4021*4kB (UEMC) 395*8kB (UEMC) 52*16kB (UMRC) 28*32kB (MR) 10*64kB (MR) 3*128kB (M) 1*256kB (M) 1*512kB (R) 1*1024kB (R) 0*2048kB 0*4096kB = 23788kB May 25 20:16:27 localhost kernel: [187398.388272] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB May 25 20:16:27 localhost kernel: [187398.397584] 196748 total pagecache pages May 25 20:16:27 localhost kernel: [187398.401963] 10852 pages in swap cache May 25 20:16:27 localhost kernel: [187398.406055] Swap cache stats: add 302607, delete 291755, find 506797/524929 May 25 20:16:27 localhost kernel: [187398.413750] Free swap  = 328416kB May 25 20:16:27 localhost kernel: [187398.417459] Total swap = 524284kB May 25 20:16:27 localhost kernel: [187398.421172] SLAB: Unable to allocate memory on node 0 (gfp=0x20) May 25 20:16:27 localhost kernel: [187398.427825]   cache: TCP, object size: 1728, order: 1 May 25 20:16:27 localhost kernel: [187398.433438]   node 0: slabs: 11/11, objs: 44/44, free: 0

here  te actual memory state (I have even 512MB swap area)

Code:

top - 20:30:14 up 2 days,  5:07,  1 user,  load average: 2.14, 2.36, 2.47 Tasks: 143 total,   1 running, 142 sleeping,   0 stopped,   0 zombie %Cpu(s): 12.2 us,  5.6 sy, 30.0 ni, 31.6 id, 20.6 wa,  0.0 hi,  0.0 si,  0.0 st KiB Mem:   2036960 total,  2013580 used,    23380 free,     2652 buffers KiB Swap:   524284 total,   195868 used,   328416 free.   727200 cached Mem

here the fragmentation:

Code:

root@pine64pro:# cat /proc/buddyinfo Node 0, zone      DMA   1420    162     62     11      5      1      0      1      1      0      0

Any Idea about something to do to prevent those errors?

Thanks

[longsleep]

Mhm i do not see why this error would be specific to the Pine64. It might be related to aarch64 though. Could you try to pretty print the output of /proc/buddyinfo (eg. with a script like the one in http://andorian.blogspot.de/2014/03/maki...yinfo.html). Especially compare the output directly after boot and when your software is running and how much it tries to allocate.

[ice00]

Hi,

thanks, I will test after I can make a reboot (at least in the weekend).

I did not know if it is related to aarch64, but in Raspberry Pi2 with 32bit and 1GB or RAM (with a swap of 256Mb if I rememeber good) I never get such message in 6 months of 24/24 server running.

The unique difference in swap memory  is that Raspian installation probably had create a  swap dedicated partition, while in Pine64 I have a 512MB file used as swap area created by me.

[ice00]

1 minute after the boot:

Code:

root@pine64pro:/home/debian# python /root/fragment.py 2016-05-28 14:27:55,939 - main - INFO - Starting.... 2016-05-28 14:27:55,939 - main - INFO - Parsed options: {'size': None} <logging.Logger object at 0x7fa7a844d0> 2016-05-28 14:27:55,940 - main - DEBUG - Parsing line: Node 0, zone      DMA     52     13      9      6      3      1      2      5      5      3    101 2016-05-28 14:27:55,943 - main - DEBUG - Parsed line: {'numa_node': '0', 'zone': 'DMA', 'nr_free': '52     13      9      6      3      1      2      5      5      3    101'} 2016-05-28 14:27:55,944 - main - INFO - defaultdict(<type 'list'>, {0: [{'usage': [212992, 106496, 147456, 196608, 196608, 131072, 524288, 2621440, 5242880, 6291456, 423624704], 'nr_free': [52, 13, 9, 6, 3, 1, 2, 5, 5, 3, 101], 'zone': 'DMA', 'sz_fragment': [4096, 8192, 16384, 32768, 65536, 131072, 262144, 524288, 1048576, 2097152, 4194304]}]}) Node: 0 Zone: DMA Free KiB in zone: 429000.00        Fragment size        Free fragments       Total available KiB        4096                 52                   208.0                      8192                 13                   104.0                      16384                9                    144.0                      32768                6                    192.0                      65536                3                    192.0                      131072               1                    128.0                      262144               2                    512.0                      524288               5                    2560.0                      1048576              5                    5120.0                      2097152              3                    6144.0                      4194304              101                  413696.0

and now some hours later after I activate zram compression and port swapness from standard 60 to 1.

Code:

oot@pine64pro:/home/debian# python /root/fragment.py 2016-05-28 16:55:37,433 - main - INFO - Starting.... 2016-05-28 16:55:37,433 - main - INFO - Parsed options: {'size': None} <logging.Logger object at 0x7fb41324d0> 2016-05-28 16:55:37,436 - main - DEBUG - Parsing line: Node 0, zone      DMA    888   1094    404    169     57     22     13      3      0      1      1 2016-05-28 16:55:37,439 - main - DEBUG - Parsed line: {'numa_node': '0', 'zone': 'DMA', 'nr_free': '888   1094    404    169     57     22     13      3      0      1      1'} 2016-05-28 16:55:37,440 - main - INFO - defaultdict(<type 'list'>, {0: [{'usage': [3637248, 8962048, 6619136, 5537792, 3735552, 2883584, 3407872, 1572864, 0, 2097152, 4194304], 'nr_free': [888, 1094, 404, 169, 57, 22, 13, 3, 0, 1, 1], 'zone': 'DMA', 'sz_fragment': [4096, 8192, 16384, 32768, 65536, 131072, 262144, 524288, 1048576, 2097152, 4194304]}]}) Node: 0 Zone: DMA Free KiB in zone: 41648.00        Fragment size        Free fragments       Total available KiB        4096                 888                  3552.0                      8192                 1094                 8752.0                      16384                404                  6464.0                      32768                169                  5408.0                      65536                57                   3648.0                      131072               22                   2816.0                      262144               13                   3328.0                      524288               3                    1536.0                      1048576              0                    0.0                        2097152              1                    2048.0                      4194304              1                    4096.0

never get a problem until now.

Thanks