* rsync: page allocation stalls in kernel 4.9.10 to a VessRAID NAS
@ 2017-02-27 21:36 Robert Kudyba
2017-02-28 14:15 ` Michal Hocko
0 siblings, 1 reply; 11+ messages in thread
From: Robert Kudyba @ 2017-02-27 21:36 UTC (permalink / raw)
To: linux-kernel
This sounds very similar to David Arendt’s problem from December 2016 on 12/13 post numbered 529 in the URL with the title page allocation stall in kernel 4.9 when copying files from one btrfs hdd to another
This happens about 2 hours after our daily rsnapshot/rsync cron job starts pretty much every time. And I set these parameters in /etc/sysctl.conf on a Fedora 25 server:
net.ipv4.tcp_window_scaling=0
net.ipv4.tcp_timestamps=0
net.ipv4.tcp_tw_recycle=0
vm.zone_reclaim_mode=1
vm.min_free_kbytes=131072
# write-cache, foreground/background flushing
vm.dirty_ratio = 3
# vm.dirty_background_ratio = 5 (% of RAM)
vm.dirty_background_ratio = 1
# make it 10 sec
vm.dirty_writeback_centisecs = 1000
Feb 27 04:36:54 curie kernel: rsync: page allocation stalls for 10699ms, order:0, mode:0x2420848(GFP_NOFS|__GFP_NOFAIL|__GFP_HARDWALL|__GFP_MOVABLE)
Feb 27 04:36:54 curie kernel: CPU: 2 PID: 32649 Comm: rsync Tainted: G L 4.9.10-200.fc25.i686+PAE #1
Feb 27 04:36:54 curie kernel: Hardware name: Dell Computer Corporation PowerEdge 1850/0D8266, BIOS A07 04/25/2008
Feb 27 04:36:54 curie kernel: ec725bac cd76bd10 cdd774bc 00000000 ec725bdc cd584b96 cdd7bc69 02420848
Feb 27 04:36:54 curie kernel: ec725be4 ec725bec cdd774bc ec725bc0 a0988a17 cdef9c48 ffffd635 00000000
Feb 27 04:36:54 curie kernel: ec725ca4 cd585686 02420848 cdd774bc 000029cb 00000000 00000010 00000050
Feb 27 04:36:54 curie kernel: Call Trace:
Feb 27 04:36:54 curie kernel: [<cd76bd10>] dump_stack+0x58/0x78
Feb 27 04:36:54 curie kernel: [<cd584b96>] warn_alloc+0xf6/0x110
Feb 27 04:36:54 curie kernel: [<cd585686>] __alloc_pages_nodemask+0xa66/0xd30
Feb 27 04:36:54 curie kernel: [<cd57c212>] ? find_get_entry+0x22/0x160
Feb 27 04:36:54 curie kernel: [<cd57cb92>] pagecache_get_page+0xc2/0x2d0
Feb 27 04:36:54 curie kernel: [<cd61f3a9>] __getblk_gfp+0x109/0x330
Feb 27 04:36:54 curie kernel: [<cd673a73>] ext4_getblk+0xa3/0x1b0
Feb 27 04:36:54 curie kernel: [<cd673ba3>] ext4_bread+0x23/0xb0
Feb 27 04:36:54 curie kernel: [<cd67dc97>] __ext4_read_dirblock+0x27/0x3a0
Feb 27 04:36:54 curie kernel: [<cd5f50f6>] ? lookup_fast+0x46/0x2d0
Feb 27 04:36:54 curie kernel: [<cd67e652>] htree_dirblock_to_tree+0x52/0x260
Feb 27 04:36:54 curie kernel: [<cd60a690>] ? mntput+0x20/0x40
Feb 27 04:36:54 curie kernel: [<cd5f431f>] ? terminate_walk+0x8f/0x100
Feb 27 04:36:54 curie kernel: [<cd67f730>] ext4_htree_fill_tree+0x90/0x2e0
Feb 27 04:36:54 curie kernel: [<cd5f9aa4>] ? putname+0x54/0x60
Feb 27 04:36:54 curie kernel: [<cd66b9d1>] ? ext4_readdir+0x9d1/0xa60
Feb 27 04:36:54 curie kernel: [<cd66b9d1>] ? ext4_readdir+0x9d1/0xa60
Feb 27 04:36:54 curie kernel: [<cd66ab46>] ? free_rb_tree_fname+0x16/0x70
Feb 27 04:36:54 curie kernel: [<cd66b7a4>] ext4_readdir+0x7a4/0xa60
Feb 27 04:36:54 curie kernel: [<cd77a090>] ? _copy_to_user+0x40/0x50
Feb 27 04:36:54 curie kernel: [<cd6ee4bf>] ? security_file_permission+0x9f/0xc0
Feb 27 04:36:54 curie kernel: [<cd5fe259>] iterate_dir+0x179/0x1a0
Feb 27 04:36:54 curie kernel: [<cd5f00d0>] ? SyS_fstat64+0x30/0x50
Feb 27 04:36:54 curie kernel: [<cd5fe83b>] SyS_getdents64+0x7b/0x100
Feb 27 04:36:54 curie kernel: [<cd5fe280>] ? iterate_dir+0x1a0/0x1a0
Feb 27 04:36:54 curie kernel: [<cd40378a>] do_fast_syscall_32+0x8a/0x150
Feb 27 04:36:54 curie kernel: [<cdb723ca>] sysenter_past_esp+0x47/0x75
Feb 27 04:36:54 curie kernel: Mem-Info:
Feb 27 04:36:55 curie kernel: active_anon:2091 inactive_anon:1298 isolated_anon:0#012 active_file:268004 inactive_file:1386276 isolated_file:0#012 unevictable:1986 dirty:0 writeback:0 unstable:0#012 slab_reclaimable:144934 slab_unreclaimable:7392#012 mapped:14331 shmem:170 pagetables:460 bounce:0#012 free:252753 free_pcp:470 free_cma:0
Feb 27 04:36:55 curie kernel: Node 0 active_anon:8364kB inactive_anon:5192kB active_file:1072016kB inactive_file:5545104kB unevictable:7944kB isolated(anon):0kB isolated(file):0kB mapped:57324kB dirty:0kB writeback:0kB shmem:680kB writeback_tmp:0kB unstable:0kB pages_scanned:171672794 all_unreclaimable? yes
Feb 27 04:36:55 curie kernel: DMA free:5584kB min:2580kB low:3224kB high:3868kB active_anon:0kB inactive_anon:0kB active_file:148kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15916kB mlocked:0kB slab_reclaimable:10032kB slab_unreclaimable:120kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Feb 27 04:36:55 curie kernel: lowmem_reserve[]: 0 751 8055 8055
Feb 27 04:36:55 curie kernel: Normal free:128408kB min:128488kB low:160608kB high:192728kB active_anon:0kB inactive_anon:0kB active_file:44340kB inactive_file:4720kB unevictable:0kB writepending:0kB present:892920kB managed:791608kB mlocked:0kB slab_reclaimable:569704kB slab_unreclaimable:29448kB kernel_stack:1168kB pagetables:0kB bounce:0kB free_pcp:1568kB local_pcp:236kB free_cma:0kB
Feb 27 04:36:55 curie kernel: lowmem_reserve[]: 0 0 58430 58430
Feb 27 04:36:55 curie kernel: HighMem free:877020kB min:512kB low:303996kB high:607480kB active_anon:8364kB inactive_anon:5192kB active_file:1027528kB inactive_file:5540384kB unevictable:7944kB writepending:0kB present:7479040kB managed:7479040kB mlocked:7944kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:1840kB bounce:0kB free_pcp:312kB local_pcp:196kB free_cma:0kB
Feb 27 04:36:55 curie kernel: lowmem_reserve[]: 0 0 0 0
Feb 27 04:36:55 curie kernel: DMA: 16*4kB (ME) 26*8kB (UME) 8*16kB (UE) 2*32kB (ME) 2*64kB (UM) 1*128kB (U) 3*256kB (UME) 2*512kB (UM) 3*1024kB (UME) 0*2048kB 0*4096kB = 5584kB
Feb 27 04:36:55 curie kernel: Normal: 556*4kB (UME) 1269*8kB (UEH) 568*16kB (UE) 362*32kB (UME) 116*64kB (UMEH) 23*128kB (UMEH) 66*256kB (MEH) 69*512kB (ME) 22*1024kB (ME) 5*2048kB (M) 0*4096kB = 128408kB
Feb 27 04:36:55 curie kernel: HighMem: 6301*4kB (UM) 3861*8kB (UM) 1616*16kB (UM) 1468*32kB (UM) 247*64kB (UM) 237*128kB (UM) 462*256kB (UM) 476*512kB (UM) 228*1024kB (UM) 6*2048kB (UM) 23*4096kB (UM) = 877020kB
Feb 27 04:36:55 curie kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Feb 27 04:36:55 curie kernel: 1656105 total pagecache pages
Feb 27 04:36:55 curie kernel: 81 pages in swap cache
Feb 27 04:36:55 curie kernel: Swap cache stats: add 6469, delete 6388, find 28828/29500
Feb 27 04:36:55 curie kernel: Free swap = 8352872kB
Feb 27 04:36:55 curie kernel: Total swap = 8355836kB
Feb 27 04:36:55 curie kernel: 2096989 pages RAM
Feb 27 04:36:55 curie kernel: 1869760 pages HighMem/MovableOnly
Feb 27 04:36:55 curie kernel: 25348 pages reserved
Feb 27 04:36:55 curie kernel: 0 pages hwpoisoned
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: rsync: page allocation stalls in kernel 4.9.10 to a VessRAID NAS
2017-02-27 21:36 rsync: page allocation stalls in kernel 4.9.10 to a VessRAID NAS Robert Kudyba
@ 2017-02-28 14:15 ` Michal Hocko
[not found] ` <40F07E96-7468-4355-B8EA-4B42F575ACAB@fordham.edu>
0 siblings, 1 reply; 11+ messages in thread
From: Michal Hocko @ 2017-02-28 14:15 UTC (permalink / raw)
To: Robert Kudyba; +Cc: linux-kernel
On Mon 27-02-17 16:36:43, Robert Kudyba wrote:
> Feb 27 04:36:54 curie kernel: rsync: page allocation stalls for 10699ms, order:0, mode:0x2420848(GFP_NOFS|__GFP_NOFAIL|__GFP_HARDWALL|__GFP_MOVABLE)
> Feb 27 04:36:54 curie kernel: CPU: 2 PID: 32649 Comm: rsync Tainted: G L 4.9.10-200.fc25.i686+PAE #1
[...]
This is a lowmem request (aka only zones DMA and Normal can be used).
> Feb 27 04:36:55 curie kernel: DMA free:5584kB min:2580kB low:3224kB high:3868kB active_anon:0kB inactive_anon:0kB active_file:148kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15916kB mlocked:0kB slab_reclaimable:10032kB slab_unreclaimable:120kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
> Feb 27 04:36:55 curie kernel: lowmem_reserve[]: 0 751 8055 8055
this one is protected by the lowmem_reserve
> Feb 27 04:36:55 curie kernel: Normal free:128408kB min:128488kB low:160608kB high:192728kB active_anon:0kB inactive_anon:0kB active_file:44340kB inactive_file:4720kB unevictable:0kB writepending:0kB present:892920kB managed:791608kB mlocked:0kB slab_reclaimable:569704kB slab_unreclaimable:29448kB kernel_stack:1168kB pagetables:0kB bounce:0kB free_pcp:1568kB local_pcp:236kB free_cma:0kB
and this one is hitting the min watermark while there is not really
much to reclaim. Only the page cache which might be pinned and not
reclaimable from this context because this is GFP_NOFS request. It is
not all that surprising the reclaim context fights to get some memory.
There is a huge amount of the reclaimable slab which probably just makes
a slow progress.
That is not something completely surprsing on 32b system I am afraid.
Btw. is the stall repeating with the increased time or it gets resolved
eventually?
--
Michal Hocko
SUSE Labs
^ permalink raw reply [flat|nested] 11+ messages in thread
* rsync: page allocation stalls in kernel 4.9.10 to a VessRAID NAS
@ 2017-02-28 16:13 Robert Kudyba
0 siblings, 0 replies; 11+ messages in thread
From: Robert Kudyba @ 2017-02-28 16:13 UTC (permalink / raw)
To: linux-fsdevel
This sounds very similar to David Arendt’s problem from December 2016 on 12/13 post numbered 529 in the URL with the title page allocation stall in kernel 4.9 when copying files from one btrfs hdd to another
This happens about 2 hours after our daily rsnapshot/rsync cron job starts pretty much every time. And I set these parameters in /etc/sysctl.conf on a Fedora 25 server:
net.ipv4.tcp_window_scaling=0
net.ipv4.tcp_timestamps=0
net.ipv4.tcp_tw_recycle=0
vm.zone_reclaim_mode=1
vm.min_free_kbytes=131072
# write-cache, foreground/background flushing
vm.dirty_ratio = 3
# vm.dirty_background_ratio = 5 (% of RAM)
vm.dirty_background_ratio = 1
# make it 10 sec
vm.dirty_writeback_centisecs = 1000
Feb 27 04:36:54 curie kernel: rsync: page allocation stalls for 10699ms, order:0, mode:0x2420848(GFP_NOFS|__GFP_NOFAIL|__GFP_HARDWALL|__GFP_MOVABLE)
Feb 27 04:36:54 curie kernel: CPU: 2 PID: 32649 Comm: rsync Tainted: G L 4.9.10-200.fc25.i686+PAE #1
Feb 27 04:36:54 curie kernel: Hardware name: Dell Computer Corporation PowerEdge 1850/0D8266, BIOS A07 04/25/2008
Feb 27 04:36:54 curie kernel: ec725bac cd76bd10 cdd774bc 00000000 ec725bdc cd584b96 cdd7bc69 02420848
Feb 27 04:36:54 curie kernel: ec725be4 ec725bec cdd774bc ec725bc0 a0988a17 cdef9c48 ffffd635 00000000
Feb 27 04:36:54 curie kernel: ec725ca4 cd585686 02420848 cdd774bc 000029cb 00000000 00000010 00000050
Feb 27 04:36:54 curie kernel: Call Trace:
Feb 27 04:36:54 curie kernel: [<cd76bd10>] dump_stack+0x58/0x78
Feb 27 04:36:54 curie kernel: [<cd584b96>] warn_alloc+0xf6/0x110
Feb 27 04:36:54 curie kernel: [<cd585686>] __alloc_pages_nodemask+0xa66/0xd30
Feb 27 04:36:54 curie kernel: [<cd57c212>] ? find_get_entry+0x22/0x160
Feb 27 04:36:54 curie kernel: [<cd57cb92>] pagecache_get_page+0xc2/0x2d0
Feb 27 04:36:54 curie kernel: [<cd61f3a9>] __getblk_gfp+0x109/0x330
Feb 27 04:36:54 curie kernel: [<cd673a73>] ext4_getblk+0xa3/0x1b0
Feb 27 04:36:54 curie kernel: [<cd673ba3>] ext4_bread+0x23/0xb0
Feb 27 04:36:54 curie kernel: [<cd67dc97>] __ext4_read_dirblock+0x27/0x3a0
Feb 27 04:36:54 curie kernel: [<cd5f50f6>] ? lookup_fast+0x46/0x2d0
Feb 27 04:36:54 curie kernel: [<cd67e652>] htree_dirblock_to_tree+0x52/0x260
Feb 27 04:36:54 curie kernel: [<cd60a690>] ? mntput+0x20/0x40
Feb 27 04:36:54 curie kernel: [<cd5f431f>] ? terminate_walk+0x8f/0x100
Feb 27 04:36:54 curie kernel: [<cd67f730>] ext4_htree_fill_tree+0x90/0x2e0
Feb 27 04:36:54 curie kernel: [<cd5f9aa4>] ? putname+0x54/0x60
Feb 27 04:36:54 curie kernel: [<cd66b9d1>] ? ext4_readdir+0x9d1/0xa60
Feb 27 04:36:54 curie kernel: [<cd66b9d1>] ? ext4_readdir+0x9d1/0xa60
Feb 27 04:36:54 curie kernel: [<cd66ab46>] ? free_rb_tree_fname+0x16/0x70
Feb 27 04:36:54 curie kernel: [<cd66b7a4>] ext4_readdir+0x7a4/0xa60
Feb 27 04:36:54 curie kernel: [<cd77a090>] ? _copy_to_user+0x40/0x50
Feb 27 04:36:54 curie kernel: [<cd6ee4bf>] ? security_file_permission+0x9f/0xc0
Feb 27 04:36:54 curie kernel: [<cd5fe259>] iterate_dir+0x179/0x1a0
Feb 27 04:36:54 curie kernel: [<cd5f00d0>] ? SyS_fstat64+0x30/0x50
Feb 27 04:36:54 curie kernel: [<cd5fe83b>] SyS_getdents64+0x7b/0x100
Feb 27 04:36:54 curie kernel: [<cd5fe280>] ? iterate_dir+0x1a0/0x1a0
Feb 27 04:36:54 curie kernel: [<cd40378a>] do_fast_syscall_32+0x8a/0x150
Feb 27 04:36:54 curie kernel: [<cdb723ca>] sysenter_past_esp+0x47/0x75
Feb 27 04:36:54 curie kernel: Mem-Info:
Feb 27 04:36:55 curie kernel: active_anon:2091 inactive_anon:1298 isolated_anon:0#012 active_file:268004 inactive_file:1386276 isolated_file:0#012 unevictable:1986 dirty:0 writeback:0 unstable:0#012 slab_reclaimable:144934 slab_unreclaimable:7392#012 mapped:14331 shmem:170 pagetables:460 bounce:0#012 free:252753 free_pcp:470 free_cma:0
Feb 27 04:36:55 curie kernel: Node 0 active_anon:8364kB inactive_anon:5192kB active_file:1072016kB inactive_file:5545104kB unevictable:7944kB isolated(anon):0kB isolated(file):0kB mapped:57324kB dirty:0kB writeback:0kB shmem:680kB writeback_tmp:0kB unstable:0kB pages_scanned:171672794 all_unreclaimable? yes
Feb 27 04:36:55 curie kernel: DMA free:5584kB min:2580kB low:3224kB high:3868kB active_anon:0kB inactive_anon:0kB active_file:148kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15916kB mlocked:0kB slab_reclaimable:10032kB slab_unreclaimable:120kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Feb 27 04:36:55 curie kernel: lowmem_reserve[]: 0 751 8055 8055
Feb 27 04:36:55 curie kernel: Normal free:128408kB min:128488kB low:160608kB high:192728kB active_anon:0kB inactive_anon:0kB active_file:44340kB inactive_file:4720kB unevictable:0kB writepending:0kB present:892920kB managed:791608kB mlocked:0kB slab_reclaimable:569704kB slab_unreclaimable:29448kB kernel_stack:1168kB pagetables:0kB bounce:0kB free_pcp:1568kB local_pcp:236kB free_cma:0kB
Feb 27 04:36:55 curie kernel: lowmem_reserve[]: 0 0 58430 58430
Feb 27 04:36:55 curie kernel: HighMem free:877020kB min:512kB low:303996kB high:607480kB active_anon:8364kB inactive_anon:5192kB active_file:1027528kB inactive_file:5540384kB unevictable:7944kB writepending:0kB present:7479040kB managed:7479040kB mlocked:7944kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:1840kB bounce:0kB free_pcp:312kB local_pcp:196kB free_cma:0kB
Feb 27 04:36:55 curie kernel: lowmem_reserve[]: 0 0 0 0
Feb 27 04:36:55 curie kernel: DMA: 16*4kB (ME) 26*8kB (UME) 8*16kB (UE) 2*32kB (ME) 2*64kB (UM) 1*128kB (U) 3*256kB (UME) 2*512kB (UM) 3*1024kB (UME) 0*2048kB 0*4096kB = 5584kB
Feb 27 04:36:55 curie kernel: Normal: 556*4kB (UME) 1269*8kB (UEH) 568*16kB (UE) 362*32kB (UME) 116*64kB (UMEH) 23*128kB (UMEH) 66*256kB (MEH) 69*512kB (ME) 22*1024kB (ME) 5*2048kB (M) 0*4096kB = 128408kB
Feb 27 04:36:55 curie kernel: HighMem: 6301*4kB (UM) 3861*8kB (UM) 1616*16kB (UM) 1468*32kB (UM) 247*64kB (UM) 237*128kB (UM) 462*256kB (UM) 476*512kB (UM) 228*1024kB (UM) 6*2048kB (UM) 23*4096kB (UM) = 877020kB
Feb 27 04:36:55 curie kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Feb 27 04:36:55 curie kernel: 1656105 total pagecache pages
Feb 27 04:36:55 curie kernel: 81 pages in swap cache
Feb 27 04:36:55 curie kernel: Swap cache stats: add 6469, delete 6388, find 28828/29500
Feb 27 04:36:55 curie kernel: Free swap = 8352872kB
Feb 27 04:36:55 curie kernel: Total swap = 8355836kB
Feb 27 04:36:55 curie kernel: 2096989 pages RAM
Feb 27 04:36:55 curie kernel: 1869760 pages HighMem/MovableOnly
Feb 27 04:36:55 curie kernel: 25348 pages reserved
Feb 27 04:36:55 curie kernel: 0 pages hwpoisoned
Here is a top showing kswapd0 usage:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
50 root 20 0 0 0 0 R 13.5 0.0 6:46.97 kswapd0
And more than rsync getting the page allocation stalls:
Feb 28 09:16:49 curie kernel: perf: interrupt took too long (6217 > 6197), lowering kernel.perf_event_max_sample_rate to 32000
Feb 28 09:24:21 curie kernel: automount: page allocation stalls for 10344ms, order:1, mode:0x27000c0(GFP_KERNEL_ACCOUNT|__GFP_NOTRACK)
Feb 28 09:24:22 curie kernel: CPU: 1 PID: 1430 Comm: automount Not tainted 4.9.11-200.fc25.i686+PAE #1
Feb 28 09:24:22 curie kernel: Hardware name: Dell Computer Corporation PowerEdge 1850/0D8266, BIOS A07 04/25/2008
Feb 28 09:24:22 curie kernel: eefd3db8 d0b6bd10 d11774e8 00000000 eefd3de8 d0984b96 d117bc95 027000c0
Feb 28 09:24:22 curie kernel: eefd3df0 eefd3df8 d11774e8 eefd3dcc ce3a506d 00000001 ffffd798 00000001
Feb 28 09:24:22 curie kernel: eefd3eb0 d0985686 027000c0 d11774e8 00002868 00000001 00000010 00000050
Feb 28 09:24:22 curie kernel: Call Trace:
Feb 28 09:24:22 curie kernel: [<d0b6bd10>] dump_stack+0x58/0x78
Feb 28 09:24:22 curie kernel: [<d0984b96>] warn_alloc+0xf6/0x110
Feb 28 09:24:22 curie kernel: [<d0985686>] __alloc_pages_nodemask+0xa66/0xd30
Feb 28 09:24:22 curie kernel: [<d09d4bc7>] ? kmem_cache_alloc+0xf7/0x1c0
Feb 28 09:24:22 curie kernel: [<d086aae9>] ? copy_process.part.44+0x549/0x14e0
Feb 28 09:24:22 curie kernel: [<d086a6a8>] copy_process.part.44+0x108/0x14e0
Feb 28 09:24:22 curie kernel: [<d089e6ee>] ? check_preempt_wakeup+0xfe/0x230
Feb 28 09:24:22 curie kernel: [<d089aa19>] ? sched_clock_local+0x49/0x180
Feb 28 09:24:22 curie kernel: [<d086bc44>] _do_fork+0xd4/0x370
Feb 28 09:24:22 curie kernel: [<d0982c40>] ? page_alloc_cpu_notify+0x40/0x40
Feb 28 09:24:22 curie kernel: [<d086bfcc>] SyS_clone+0x2c/0x30
Feb 28 09:24:22 curie kernel: [<d080369c>] do_int80_syscall_32+0x5c/0xc0
Feb 28 09:24:22 curie kernel: [<d0f72569>] entry_INT80_32+0x31/0x31
Feb 28 09:24:22 curie kernel: Mem-Info:
Feb 28 09:24:22 curie kernel: active_anon:15757 inactive_anon:15711 isolated_anon:0#012 active_file:108038 inactive_file:1395085 isolated_file:2#012 unevictable:1986 dirty:1 writeback:21 unstable:0#012 slab_reclaimable:67347 slab_unreclaimable:6744#012 mapped:11340 shmem:1365 pagetables:1671 bounce:0#012 free:453063 free_pcp:11 free_cma:0
Feb 28 09:24:22 curie kernel: Node 0 active_anon:63028kB inactive_anon:62844kB active_file:432152kB inactive_file:5580340kB unevictable:7944kB isolated(anon):0kB isolated(file):8kB mapped:45360kB dirty:4kB writeback:84kB shmem:5460kB writeback_tmp:0kB unstable:0kB pages_scanned:0 all_unreclaimable? no
Feb 28 09:24:22 curie kernel: DMA free:5568kB min:2580kB low:3224kB high:3868kB active_anon:0kB inactive_anon:0kB active_file:4808kB inactive_file:0kB unevictable:0kB writepending:4kB present:15996kB managed:15916kB mlocked:0kB slab_reclaimable:5292kB slab_unreclaimable:112kB kernel_stack:8kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Feb 28 09:24:22 curie kernel: lowmem_reserve[]: 0 751 8055 8055
Feb 28 09:24:22 curie kernel: Normal free:129656kB min:128488kB low:160608kB high:192728kB active_anon:0kB inactive_anon:0kB active_file:348152kB inactive_file:8640kB unevictable:0kB writepending:44kB present:892920kB managed:791504kB mlocked:0kB slab_reclaimable:264096kB slab_unreclaimable:26864kB kernel_stack:1800kB pagetables:0kB bounce:0kB free_pcp:44kB local_pcp:0kB free_cma:0kB
Feb 28 09:24:22 curie kernel: lowmem_reserve[]: 0 0 58430 58430
Feb 28 09:24:22 curie kernel: HighMem free:1677028kB min:512kB low:304036kB high:607560kB active_anon:63028kB inactive_anon:62844kB active_file:79236kB inactive_file:5571800kB unevictable:7944kB writepending:40kB present:7479040kB managed:7479040kB mlocked:7944kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:6684kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Feb 28 09:24:22 curie kernel: lowmem_reserve[]: 0 0 0 0
Feb 28 09:24:22 curie kernel: DMA: 6*4kB (UME) 3*8kB (UE) 1*16kB (U) 6*32kB (UME) 5*64kB (UM) 3*128kB (UME) 2*256kB (UM) 6*512kB (UME) 1*1024kB (E) 0*2048kB 0*4096kB = 5568kB
Feb 28 09:24:22 curie kernel: Normal: 297*4kB (UMEH) 348*8kB (UMEH) 29*16kB (UMEH) 23*32kB (UMEH) 606*64kB (MEH) 460*128kB (UMEH) 99*256kB (UMEH) 3*512kB (UH) 0*1024kB 0*2048kB 0*4096kB = 129716kB
Feb 28 09:24:22 curie kernel: HighMem: 71*4kB (UM) 43*8kB (UM) 1679*16kB (UM) 1426*32kB (UM) 595*64kB (UM) 297*128kB (UM) 852*256kB (UM) 392*512kB (UM) 185*1024kB (UM) 59*2048kB (UM) 195*4096kB (UM) = 1677028kB
Feb 28 09:24:22 curie kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Feb 28 09:24:22 curie kernel: 1506709 total pagecache pages
Feb 28 09:24:22 curie kernel: 599 pages in swap cache
Feb 28 09:24:22 curie kernel: Swap cache stats: add 12125, delete 11526, find 750/1372
Feb 28 09:24:22 curie kernel: Free swap = 8311948kB
Feb 28 09:24:22 curie kernel: Total swap = 8355836kB
Feb 28 09:24:22 curie kernel: 2096989 pages RAM
Feb 28 09:24:22 curie kernel: 1869760 pages HighMem/MovableOnly
Feb 28 09:24:22 curie kernel: 25374 pages reserved
Feb 28 09:24:22 curie kernel: 0 pages hwpoisoned
Feb 28 09:24:35 curie kernel: NetworkManager: page allocation stalls for 11311ms, order:1, mode:0x27000c0(GFP_KERNEL_ACCOUNT|__GFP_NOTRACK)
Feb 28 09:24:35 curie kernel: CPU: 2 PID: 788 Comm: NetworkManager Not tainted 4.9.11-200.fc25.i686+PAE #1
Feb 28 09:24:35 curie kernel: Hardware name: Dell Computer Corporation PowerEdge 1850/0D8266, BIOS A07 04/25/2008
Feb 28 09:24:35 curie kernel: ee41fdb8 d0b6bd10 d11774e8 00000000 ee41fde8 d0984b96 d117bc95 027000c0
Feb 28 09:24:35 curie kernel: ee41fdf0 ee41fdf8 d11774e8 ee41fdcc 50d2c4fa 00000001 ffffd3d1 00000001
Feb 28 09:24:35 curie kernel: ee41feb0 d0985686 027000c0 d11774e8 00002c2f 00000001 00000010 00000050
Feb 28 09:24:35 curie kernel: Call Trace:
Feb 28 09:24:35 curie kernel: [<d0b6bd10>] dump_stack+0x58/0x78
Feb 28 09:24:35 curie kernel: [<d0984b96>] warn_alloc+0xf6/0x110
Feb 28 09:24:35 curie kernel: [<d0985686>] __alloc_pages_nodemask+0xa66/0xd30
Feb 28 09:24:35 curie kernel: [<d09d4bc7>] ? kmem_cache_alloc+0xf7/0x1c0
Feb 28 09:24:35 curie kernel: [<d086aae9>] ? copy_process.part.44+0x549/0x14e0
Feb 28 09:24:35 curie kernel: [<d086a6a8>] copy_process.part.44+0x108/0x14e0
Feb 28 09:24:35 curie kernel: [<d086bc44>] _do_fork+0xd4/0x370
Feb 28 09:24:35 curie kernel: [<d086bfcc>] SyS_clone+0x2c/0x30
Feb 28 09:24:35 curie kernel: [<d080369c>] do_int80_syscall_32+0x5c/0xc0
Feb 28 09:24:35 curie kernel: [<d0f72569>] entry_INT80_32+0x31/0x31
Feb 28 09:24:35 curie kernel: Mem-Info:
Feb 28 09:24:35 curie kernel: active_anon:15757 inactive_anon:15712 isolated_anon:0#012 active_file:107809 inactive_file:1395107 isolated_file:0#012 unevictable:1986 dirty:120 writeback:0 unstable:0#012 slab_reclaimable:67628 slab_unreclaimable:6744#012 mapped:11356 shmem:1365 pagetables:1671 bounce:0#012 free:452943 free_pcp:0 free_cma:0
Feb 28 09:24:35 curie kernel: Node 0 active_anon:63028kB inactive_anon:62848kB active_file:431236kB inactive_file:5580428kB unevictable:7944kB isolated(anon):0kB isolated(file):0kB mapped:45424kB dirty:480kB writeback:0kB shmem:5460kB writeback_tmp:0kB unstable:0kB pages_scanned:0 all_unreclaimable? no
Feb 28 09:24:35 curie kernel: DMA free:5568kB min:2580kB low:3224kB high:3868kB active_anon:0kB inactive_anon:0kB active_file:4808kB inactive_file:0kB unevictable:0kB writepending:4kB present:15996kB managed:15916kB mlocked:0kB slab_reclaimable:5292kB slab_unreclaimable:112kB kernel_stack:8kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Feb 28 09:24:35 curie kernel: lowmem_reserve[]: 0 751 8055 8055
Feb 28 09:24:35 curie kernel: Normal free:129336kB min:128488kB low:160608kB high:192728kB active_anon:0kB inactive_anon:0kB active_file:347280kB inactive_file:8572kB unevictable:0kB writepending:52kB present:892920kB managed:791504kB mlocked:0kB slab_reclaimable:265220kB slab_unreclaimable:26864kB kernel_stack:1800kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Feb 28 09:24:35 curie kernel: lowmem_reserve[]: 0 0 58430 58430
Feb 28 09:24:35 curie kernel: HighMem free:1676868kB min:512kB low:304036kB high:607560kB active_anon:63028kB inactive_anon:62848kB active_file:79236kB inactive_file:5571956kB unevictable:7944kB writepending:424kB present:7479040kB managed:7479040kB mlocked:7944kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:6684kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Feb 28 09:24:35 curie kernel: lowmem_reserve[]: 0 0 0 0
Feb 28 09:24:35 curie kernel: DMA: 6*4kB (UME) 3*8kB (UE) 1*16kB (U) 6*32kB (UME) 5*64kB (UM) 3*128kB (UME) 2*256kB (UM) 6*512kB (UME) 1*1024kB (E) 0*2048kB 0*4096kB = 5568kB
Feb 28 09:24:35 curie kernel: Normal: 142*4kB (UMH) 280*8kB (UMEH) 34*16kB (UMEH) 32*32kB (UMEH) 609*64kB (MEH) 463*128kB (UMEH) 99*256kB (UMEH) 3*512kB (UH) 0*1024kB 0*2048kB 0*4096kB = 129496kB
Feb 28 09:24:35 curie kernel: HighMem: 35*4kB (UM) 41*8kB (UM) 1679*16kB (UM) 1426*32kB (UM) 595*64kB (UM) 297*128kB (UM) 852*256kB (UM) 392*512kB (UM) 185*1024kB (UM) 59*2048kB (UM) 195*4096kB (UM) = 1676868kB
Feb 28 09:24:35 curie kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Feb 28 09:24:35 curie kernel: 1506508 total pagecache pages
Feb 28 09:24:35 curie kernel: 599 pages in swap cache
Feb 28 09:24:35 curie kernel: Swap cache stats: add 12126, delete 11527, find 751/1374
Feb 28 09:24:35 curie kernel: Free swap = 8311952kB
Feb 28 09:24:35 curie kernel: Total swap = 8355836kB
Feb 28 09:24:35 curie kernel: 2096989 pages RAM
Feb 28 09:24:35 curie kernel: 1869760 pages HighMem/MovableOnly
Feb 28 09:24:35 curie kernel: 25374 pages reserved
Feb 28 09:24:35 curie kernel: 0 pages hwpoisoned
perf report:
Children Self Command Shared Object Symbol ◆
63.54% 0.06% swapper [kernel.kallsyms] [k] cpu_startup_entry
62.07% 0.01% swapper [kernel.kallsyms] [k] default_idle_call
62.06% 0.01% swapper [kernel.kallsyms] [k] arch_cpu_idle
54.73% 54.73% swapper [kernel.kallsyms] [k] mwait_idle
45.22% 0.00% swapper [kernel.kallsyms] [k] start_secondary
18.35% 0.00% swapper [kernel.kallsyms] [k] rest_init
18.35% 0.00% swapper [kernel.kallsyms] [k] start_kernel
18.35% 0.00% swapper [kernel.kallsyms] [k] i386_start_kernel
13.97% 0.01% rsync [vdso] [.] __kernel_vsyscall
13.93% 0.01% rsync [kernel.kallsyms] [k] sysenter_past_esp
13.92% 0.02% rsync [kernel.kallsyms] [k] do_fast_syscall_32
8.58% 0.01% rsync [kernel.kallsyms] [k] sys_write
8.56% 0.01% rsync [kernel.kallsyms] [k] vfs_write
8.55% 0.01% rsync [kernel.kallsyms] [k] __vfs_write
8.55% 0.00% rsync [kernel.kallsyms] [k] ext4_file_write_iter
8.54% 0.00% rsync [kernel.kallsyms] [k] __generic_file_write_iter
8.36% 0.04% rsync [kernel.kallsyms] [k] generic_perform_write
6.96% 0.00% swapper [kernel.kallsyms] [k] irq_exit
6.81% 0.01% swapper [kernel.kallsyms] [k] do_softirq_own_stack
6.80% 0.01% swapper [kernel.kallsyms] [k] __do_softirq
6.30% 0.00% swapper [kernel.kallsyms] [k] do_IRQ
6.30% 0.00% swapper [kernel.kallsyms] [k] common_interrupt
5.76% 0.01% swapper [kernel.kallsyms] [k] net_rx_action
5.75% 0.10% swapper [kernel.kallsyms] [k] e1000_clean
5.33% 0.01% rsync [kernel.kallsyms] [k] sys_read
5.30% 0.00% rsync [kernel.kallsyms] [k] vfs_read
5.28% 0.02% rsync [kernel.kallsyms] [k] __vfs_read
5.23% 0.10% rsync [kernel.kallsyms] [k] generic_file_read_iter
5.22% 0.00% swapper [kernel.kallsyms] [k] netif_receive_skb_internal
5.21% 0.01% swapper [kernel.kallsyms] [k] __netif_receive_skb
5.20% 0.01% swapper [kernel.kallsyms] [k] __netif_receive_skb_core
5.19% 0.02% swapper [kernel.kallsyms] [k] ip_rcv
4.93% 0.01% swapper [kernel.kallsyms] [k] ip_rcv_finish
4.90% 0.01% swapper [kernel.kallsyms] [k] ip_local_deliver
4.86% 0.05% swapper [kernel.kallsyms] [k] e1000_clean_rx_irq
4.80% 0.00% swapper [kernel.kallsyms] [k] ip_local_deliver_finish
4.80% 0.01% swapper [kernel.kallsyms] [k] tcp_v4_rcv
4.73% 0.01% swapper [kernel.kallsyms] [k] tcp_v4_do_rcv
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2017-03-01 19:21 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-02-27 21:36 rsync: page allocation stalls in kernel 4.9.10 to a VessRAID NAS Robert Kudyba
2017-02-28 14:15 ` Michal Hocko
[not found] ` <40F07E96-7468-4355-B8EA-4B42F575ACAB@fordham.edu>
2017-02-28 14:40 ` Michal Hocko
[not found] ` <3E4C7821-A93D-4956-A0E0-730BEC67C9F0@fordham.edu>
2017-02-28 15:15 ` Michal Hocko
2017-02-28 16:19 ` Robert Kudyba
2017-02-28 16:56 ` Michal Hocko
2017-02-28 19:32 ` Robert Kudyba
2017-03-01 8:06 ` Michal Hocko
[not found] ` <F77DA4E6-EF9B-427D-8FE9-9FB940A9B009@fordham.edu>
2017-03-01 17:36 ` Michal Hocko
[not found] ` <D2C3C9EB-7E99-4420-887A-13526002E267@fordham.edu>
2017-03-01 19:19 ` Michal Hocko
2017-02-28 16:13 Robert Kudyba
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.