Bug 192981 - page allocation stalls
Summary: page allocation stalls
Status: NEEDINFO
Alias: None
Product: Memory Management
Classification: Unclassified
Component: Page Allocator (show other bugs)
Hardware: x86-64 Linux
: P1 normal
Assignee: Andrew Morton
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-01-20 15:14 UTC by Alexander Polakov
Modified: 2020-05-01 16:57 UTC (History)
7 users (show)

See Also:
Kernel Version: 4.9
Tree: Mainline
Regression: No


Attachments
netconsole log with page allocation stalls (755.79 KB, application/octet-stream)
2017-01-20 15:14 UTC, Alexander Polakov
Details
memory alloc failure on Linux 4.12 (277.53 KB, text/plain)
2018-01-31 05:38 UTC, FF9988
Details

Description Alexander Polakov 2017-01-20 15:14:13 UTC
Created attachment 252621 [details]
netconsole log with page allocation stalls

We have been experiencing page allocation stalls regularly on our machines used as backup servers (many disks, mostly running rsync and rm).

A notable one (2102516ms):

2017-01-17T11:08:33.754562+03:00 storage8 [335170.452601] rsync: 
2017-01-17T11:08:33.754574+03:00 page allocation stalls for 2102516ms, order:0
2017-01-17T11:08:33.754825+03:00 storage8 , mode:0x26040d0(GFP_TEMPORARY|__GFP_COMP|__GFP_NOTRACK)
2017-01-17T11:08:33.755094+03:00 storage8 [335170.452896] CPU: 2 PID: 20383 Comm: rsync Tainted: G           O    4.9.0-0-beget-vanilla #1
2017-01-17T11:08:33.755337+03:00 storage8 [335170.453156] Hardware name: Supermicro X8DTL/X8DTL, BIOS 2.1b       11/16/2012
2017-01-17T11:08:33.755379+03:00 storage8 [335170.453414]  0000000000000000
2017-01-17T11:08:33.755379+03:00 storage8  ffffffff92441e0b
2017-01-17T11:08:33.755393+03:00 storage8  ffff8c4b0f30f430
2017-01-17T11:08:33.755484+03:00 storage8  0000000000000001
2017-01-17T11:08:33.755600+03:00 storage8  
2017-01-17T11:08:33.755603+03:00 storage8 [335170.453681]  ffffffff92c3d1f8
2017-01-17T11:08:33.755643+03:00 storage8  ffffffff92189594
2017-01-17T11:08:33.755648+03:00 storage8  ffff8c4b0f315088
2017-01-17T11:08:33.755754+03:00 storage8  026040d0026040d0
2017-01-17T11:08:33.755874+03:00 storage8  
2017-01-17T11:08:33.755874+03:00 storage8 [335170.453951]  0000000000000020
2017-01-17T11:08:33.755880+03:00 storage8  0000000000000010
2017-01-17T11:08:33.755913+03:00 storage8  ffffa449d15cb7f8
2017-01-17T11:08:33.756024+03:00 storage8  ffffa449d15cb7a8
2017-01-17T11:08:33.756163+03:00 storage8  
2017-01-17T11:08:33.756278+03:00 storage8 [335170.454216] Call Trace:
2017-01-17T11:08:33.756401+03:00 storage8 [335170.454347]  [<ffffffff92441e0b>] ? dump_stack+0x47/0x5c
2017-01-17T11:08:33.756537+03:00 storage8 [335170.454479]  [<ffffffff92189594>] ? warn_alloc+0x134/0x150
2017-01-17T11:08:33.756677+03:00 storage8 [335170.454612]  [<ffffffff92189f2d>] ? __alloc_pages_nodemask+0x90d/0xdb0
2017-01-17T11:08:33.756808+03:00 storage8 [335170.454753]  [<ffffffff923a5da4>] ? _xfs_trans_bjoin+0xe4/0x110
2017-01-17T11:08:33.756955+03:00 storage8 [335170.454892]  [<ffffffff921d76fa>] ? alloc_pages_current+0x9a/0x120
2017-01-17T11:08:33.757096+03:00 storage8 [335170.455027]  [<ffffffff921de440>] ? new_slab+0x550/0x5f0
2017-01-17T11:08:33.757218+03:00 storage8 [335170.455162]  [<ffffffff921df2eb>] ? ___slab_alloc.isra.59+0x3db/0x500
2017-01-17T11:08:33.757346+03:00 storage8 [335170.455297]  [<ffffffff923a683a>] ? xfs_trans_brelse+0x1aa/0x270
2017-01-17T11:08:33.757489+03:00 storage8 [335170.455427]  [<ffffffff921f4612>] ? memcg_kmem_get_cache+0x72/0x170
2017-01-17T11:08:33.757632+03:00 storage8 [335170.455567]  [<ffffffff92447837>] ? __radix_tree_create+0xa7/0x320
2017-01-17T11:08:33.757762+03:00 storage8 [335170.455706]  [<ffffffff92200be5>] ? __slab_alloc.isra.60+0xe/0x12
2017-01-17T11:08:33.757897+03:00 storage8 [335170.455842]  [<ffffffff921df5b0>] ? kmem_cache_alloc+0x1a0/0x1b0
2017-01-17T11:08:33.758034+03:00 storage8 [335170.455978]  [<ffffffff9221b746>] ? __d_alloc+0x26/0x1c0
2017-01-17T11:08:33.758160+03:00 storage8 [335170.456108]  [<ffffffff9221bb67>] ? d_alloc+0x17/0x80
2017-01-17T11:08:33.758290+03:00 storage8 [335170.456236]  [<ffffffff9221bdf1>] ? d_alloc_parallel+0x31/0x4b0
2017-01-17T11:08:33.758429+03:00 storage8 [335170.456370]  [<ffffffff9220f836>] ? lookup_fast+0x56/0x2f0
2017-01-17T11:08:33.758579+03:00 storage8 [335170.456505]  [<ffffffff923804de>] ? xfs_iunlock+0x17e/0x210
2017-01-17T11:08:33.758694+03:00 storage8 [335170.456635]  [<ffffffff922237f2>] ? legitimize_mnt+0x12/0x40
2017-01-17T11:08:33.758818+03:00 storage8 [335170.456770]  [<ffffffff9220d8f0>] ? lookup_slow+0x80/0x170
2017-01-17T11:08:33.758955+03:00 storage8 [335170.456897]  [<ffffffff9220fd08>] ? walk_component+0x1a8/0x270
2017-01-17T11:08:33.759086+03:00 storage8 [335170.457024]  [<ffffffff92210398>] ? path_lookupat+0x48/0xf0
2017-01-17T11:08:33.759200+03:00 storage8 [335170.457153]  [<ffffffff92212e75>] ? filename_lookup+0xb5/0x190
2017-01-17T11:08:33.759336+03:00 storage8 [335170.457282]  [<ffffffff92474992>] ? strncpy_from_user+0x42/0x140
2017-01-17T11:08:33.759462+03:00 storage8 [335170.457411]  [<ffffffff9221305b>] ? getname_flags+0x7b/0x200
2017-01-17T11:08:33.759593+03:00 storage8 [335170.457538]  [<ffffffff92208b66>] ? vfs_fstatat+0x46/0x90
2017-01-17T11:08:33.759719+03:00 storage8 [335170.457666]  [<ffffffff9221aaf4>] ? dput+0x34/0x200
2017-01-17T11:08:33.759859+03:00 storage8 [335170.457793]  [<ffffffff92208d47>] ? SyS_newlstat+0x17/0x30
2017-01-17T11:08:33.759977+03:00 storage8 [335170.457923]  [<ffffffff9282b7a0>] ? entry_SYSCALL_64_fastpath+0x13/0x94


# sysctl vm
vm.admin_reserve_kbytes = 1048576
vm.block_dump = 0
error: permission denied on key 'vm.compact_memory'
vm.compact_unevictable_allowed = 1
vm.dirty_background_bytes = 0
vm.dirty_background_ratio = 1
vm.dirty_bytes = 0
vm.dirty_expire_centisecs = 1000
vm.dirty_ratio = 1
vm.dirty_writeback_centisecs = 100
vm.dirtytime_expire_seconds = 43200
vm.drop_caches = 0
vm.extfrag_threshold = 500
vm.hugepages_treat_as_movable = 0
vm.hugetlb_shm_group = 0
vm.laptop_mode = 0
vm.legacy_va_layout = 0
vm.lowmem_reserve_ratio = 128   128     16
vm.max_map_count = 65530
vm.memory_failure_early_kill = 0
vm.memory_failure_recovery = 1
vm.min_free_kbytes = 4194304
vm.min_slab_ratio = 1
vm.min_unmapped_ratio = 1
vm.mmap_min_addr = 65536
vm.mmap_rnd_bits = 28
vm.nr_hugepages = 0
vm.nr_hugepages_mempolicy = 0
vm.nr_overcommit_hugepages = 0
vm.nr_pdflush_threads = 0
vm.numa_zonelist_order = default
vm.oom_dump_tasks = 1
vm.oom_kill_allocating_task = 0
vm.overcommit_kbytes = 0
vm.overcommit_memory = 1
vm.overcommit_ratio = 50
vm.page-cluster = 3
vm.panic_on_oom = 0
vm.percpu_pagelist_fraction = 0
vm.stat_interval = 1
error: permission denied on key 'vm.stat_refresh'
vm.swappiness = 0
vm.user_reserve_kbytes = 131072
vm.vfs_cache_pressure = 200
vm.watermark_scale_factor = 100
vm.zone_reclaim_mode = 7

# free -m
             total       used       free     shared    buffers     cached
Mem:         96646      46330      50315          0      25529       1228
-/+ buffers/cache:      19572      77073
Swap:            0          0          0

(Yes, we don't have any swap configured)

On this particular one we have 56 disks, using both XFS and EXT4. I attach full netconsole log for 18/01/2017. You can see there that we run drop_caches regularly as it helps to keep the machine alive.

Since then we've also tried mounting filesystems with sync flag to avoid writeback and it seems to have helped a lot (full day without stalls).
Comment 1 Andrew Morton 2017-01-23 21:51:16 UTC
(switched to email.  Please respond via emailed reply-to-all, not via the
bugzilla web interface).

A 2100 second page allocation stall!


On Fri, 20 Jan 2017 15:14:13 +0000 bugzilla-daemon@bugzilla.kernel.org wrote:

> https://bugzilla.kernel.org/show_bug.cgi?id=192981
> 
>             Bug ID: 192981
>            Summary: page allocation stalls
>            Product: Memory Management
>            Version: 2.5
>     Kernel Version: 4.9
>           Hardware: x86-64
>                 OS: Linux
>               Tree: Mainline
>             Status: NEW
>           Severity: normal
>           Priority: P1
>          Component: Page Allocator
>           Assignee: akpm@linux-foundation.org
>           Reporter: apolyakov@beget.ru
>         Regression: No
> 
> Created attachment 252621 [details]
>   --> https://bugzilla.kernel.org/attachment.cgi?id=252621&action=edit
> netconsole log with page allocation stalls
> 
> We have been experiencing page allocation stalls regularly on our machines
> used
> as backup servers (many disks, mostly running rsync and rm).
> 
> A notable one (2102516ms):
> 
> 2017-01-17T11:08:33.754562+03:00 storage8 [335170.452601] rsync: 
> 2017-01-17T11:08:33.754574+03:00 page allocation stalls for 2102516ms,
> order:0
> 2017-01-17T11:08:33.754825+03:00 storage8 ,
> mode:0x26040d0(GFP_TEMPORARY|__GFP_COMP|__GFP_NOTRACK)
> 2017-01-17T11:08:33.755094+03:00 storage8 [335170.452896] CPU: 2 PID: 20383
> Comm: rsync Tainted: G           O    4.9.0-0-beget-vanilla #1
> 2017-01-17T11:08:33.755337+03:00 storage8 [335170.453156] Hardware name:
> Supermicro X8DTL/X8DTL, BIOS 2.1b       11/16/2012
> 2017-01-17T11:08:33.755379+03:00 storage8 [335170.453414]  0000000000000000
> 2017-01-17T11:08:33.755379+03:00 storage8  ffffffff92441e0b
> 2017-01-17T11:08:33.755393+03:00 storage8  ffff8c4b0f30f430
> 2017-01-17T11:08:33.755484+03:00 storage8  0000000000000001
> 2017-01-17T11:08:33.755600+03:00 storage8  
> 2017-01-17T11:08:33.755603+03:00 storage8 [335170.453681]  ffffffff92c3d1f8
> 2017-01-17T11:08:33.755643+03:00 storage8  ffffffff92189594
> 2017-01-17T11:08:33.755648+03:00 storage8  ffff8c4b0f315088
> 2017-01-17T11:08:33.755754+03:00 storage8  026040d0026040d0
> 2017-01-17T11:08:33.755874+03:00 storage8  
> 2017-01-17T11:08:33.755874+03:00 storage8 [335170.453951]  0000000000000020
> 2017-01-17T11:08:33.755880+03:00 storage8  0000000000000010
> 2017-01-17T11:08:33.755913+03:00 storage8  ffffa449d15cb7f8
> 2017-01-17T11:08:33.756024+03:00 storage8  ffffa449d15cb7a8
> 2017-01-17T11:08:33.756163+03:00 storage8  
> 2017-01-17T11:08:33.756278+03:00 storage8 [335170.454216] Call Trace:
> 2017-01-17T11:08:33.756401+03:00 storage8 [335170.454347] 
> [<ffffffff92441e0b>]
> ? dump_stack+0x47/0x5c
> 2017-01-17T11:08:33.756537+03:00 storage8 [335170.454479] 
> [<ffffffff92189594>]
> ? warn_alloc+0x134/0x150
> 2017-01-17T11:08:33.756677+03:00 storage8 [335170.454612] 
> [<ffffffff92189f2d>]
> ? __alloc_pages_nodemask+0x90d/0xdb0
> 2017-01-17T11:08:33.756808+03:00 storage8 [335170.454753] 
> [<ffffffff923a5da4>]
> ? _xfs_trans_bjoin+0xe4/0x110
> 2017-01-17T11:08:33.756955+03:00 storage8 [335170.454892] 
> [<ffffffff921d76fa>]
> ? alloc_pages_current+0x9a/0x120
> 2017-01-17T11:08:33.757096+03:00 storage8 [335170.455027] 
> [<ffffffff921de440>]
> ? new_slab+0x550/0x5f0
> 2017-01-17T11:08:33.757218+03:00 storage8 [335170.455162] 
> [<ffffffff921df2eb>]
> ? ___slab_alloc.isra.59+0x3db/0x500
> 2017-01-17T11:08:33.757346+03:00 storage8 [335170.455297] 
> [<ffffffff923a683a>]
> ? xfs_trans_brelse+0x1aa/0x270
> 2017-01-17T11:08:33.757489+03:00 storage8 [335170.455427] 
> [<ffffffff921f4612>]
> ? memcg_kmem_get_cache+0x72/0x170
> 2017-01-17T11:08:33.757632+03:00 storage8 [335170.455567] 
> [<ffffffff92447837>]
> ? __radix_tree_create+0xa7/0x320
> 2017-01-17T11:08:33.757762+03:00 storage8 [335170.455706] 
> [<ffffffff92200be5>]
> ? __slab_alloc.isra.60+0xe/0x12
> 2017-01-17T11:08:33.757897+03:00 storage8 [335170.455842] 
> [<ffffffff921df5b0>]
> ? kmem_cache_alloc+0x1a0/0x1b0
> 2017-01-17T11:08:33.758034+03:00 storage8 [335170.455978] 
> [<ffffffff9221b746>]
> ? __d_alloc+0x26/0x1c0
> 2017-01-17T11:08:33.758160+03:00 storage8 [335170.456108] 
> [<ffffffff9221bb67>]
> ? d_alloc+0x17/0x80
> 2017-01-17T11:08:33.758290+03:00 storage8 [335170.456236] 
> [<ffffffff9221bdf1>]
> ? d_alloc_parallel+0x31/0x4b0
> 2017-01-17T11:08:33.758429+03:00 storage8 [335170.456370] 
> [<ffffffff9220f836>]
> ? lookup_fast+0x56/0x2f0
> 2017-01-17T11:08:33.758579+03:00 storage8 [335170.456505] 
> [<ffffffff923804de>]
> ? xfs_iunlock+0x17e/0x210
> 2017-01-17T11:08:33.758694+03:00 storage8 [335170.456635] 
> [<ffffffff922237f2>]
> ? legitimize_mnt+0x12/0x40
> 2017-01-17T11:08:33.758818+03:00 storage8 [335170.456770] 
> [<ffffffff9220d8f0>]
> ? lookup_slow+0x80/0x170
> 2017-01-17T11:08:33.758955+03:00 storage8 [335170.456897] 
> [<ffffffff9220fd08>]
> ? walk_component+0x1a8/0x270
> 2017-01-17T11:08:33.759086+03:00 storage8 [335170.457024] 
> [<ffffffff92210398>]
> ? path_lookupat+0x48/0xf0
> 2017-01-17T11:08:33.759200+03:00 storage8 [335170.457153] 
> [<ffffffff92212e75>]
> ? filename_lookup+0xb5/0x190
> 2017-01-17T11:08:33.759336+03:00 storage8 [335170.457282] 
> [<ffffffff92474992>]
> ? strncpy_from_user+0x42/0x140
> 2017-01-17T11:08:33.759462+03:00 storage8 [335170.457411] 
> [<ffffffff9221305b>]
> ? getname_flags+0x7b/0x200
> 2017-01-17T11:08:33.759593+03:00 storage8 [335170.457538] 
> [<ffffffff92208b66>]
> ? vfs_fstatat+0x46/0x90
> 2017-01-17T11:08:33.759719+03:00 storage8 [335170.457666] 
> [<ffffffff9221aaf4>]
> ? dput+0x34/0x200
> 2017-01-17T11:08:33.759859+03:00 storage8 [335170.457793] 
> [<ffffffff92208d47>]
> ? SyS_newlstat+0x17/0x30
> 2017-01-17T11:08:33.759977+03:00 storage8 [335170.457923] 
> [<ffffffff9282b7a0>]
> ? entry_SYSCALL_64_fastpath+0x13/0x94
> 
> 
> # sysctl vm
> vm.admin_reserve_kbytes = 1048576
> vm.block_dump = 0
> error: permission denied on key 'vm.compact_memory'
> vm.compact_unevictable_allowed = 1
> vm.dirty_background_bytes = 0
> vm.dirty_background_ratio = 1
> vm.dirty_bytes = 0
> vm.dirty_expire_centisecs = 1000
> vm.dirty_ratio = 1
> vm.dirty_writeback_centisecs = 100
> vm.dirtytime_expire_seconds = 43200
> vm.drop_caches = 0
> vm.extfrag_threshold = 500
> vm.hugepages_treat_as_movable = 0
> vm.hugetlb_shm_group = 0
> vm.laptop_mode = 0
> vm.legacy_va_layout = 0
> vm.lowmem_reserve_ratio = 128   128     16
> vm.max_map_count = 65530
> vm.memory_failure_early_kill = 0
> vm.memory_failure_recovery = 1
> vm.min_free_kbytes = 4194304
> vm.min_slab_ratio = 1
> vm.min_unmapped_ratio = 1
> vm.mmap_min_addr = 65536
> vm.mmap_rnd_bits = 28
> vm.nr_hugepages = 0
> vm.nr_hugepages_mempolicy = 0
> vm.nr_overcommit_hugepages = 0
> vm.nr_pdflush_threads = 0
> vm.numa_zonelist_order = default
> vm.oom_dump_tasks = 1
> vm.oom_kill_allocating_task = 0
> vm.overcommit_kbytes = 0
> vm.overcommit_memory = 1
> vm.overcommit_ratio = 50
> vm.page-cluster = 3
> vm.panic_on_oom = 0
> vm.percpu_pagelist_fraction = 0
> vm.stat_interval = 1
> error: permission denied on key 'vm.stat_refresh'
> vm.swappiness = 0
> vm.user_reserve_kbytes = 131072
> vm.vfs_cache_pressure = 200
> vm.watermark_scale_factor = 100
> vm.zone_reclaim_mode = 7
> 
> # free -m
>              total       used       free     shared    buffers     cached
> Mem:         96646      46330      50315          0      25529       1228
> -/+ buffers/cache:      19572      77073
> Swap:            0          0          0
> 
> (Yes, we don't have any swap configured)
> 
> On this particular one we have 56 disks, using both XFS and EXT4. I attach
> full
> netconsole log for 18/01/2017. You can see there that we run drop_caches
> regularly as it helps to keep the machine alive.
> 
> Since then we've also tried mounting filesystems with sync flag to avoid
> writeback and it seems to have helped a lot (full day without stalls).
> 
> -- 
> You are receiving this mail because:
> You are the assignee for the bug.
Comment 2 Alexander Polakov 2017-01-30 15:29:20 UTC
On 01/24/2017 12:51 AM, Andrew Morton wrote:

Tetsuo Handa suggested applying kmallocwd patch 
(http://lkml.kernel.org/r/1478416501-10104-1-git-send-email-penguin-kernel@I-love.SAKURA.ne.jp)
and sending netconsole logs to this list.

I uploaded them here: http://aplkv.beget.tech/lkml/

>
>
> (switched to email.  Please respond via emailed reply-to-all, not via the
> bugzilla web interface).
>
> A 2100 second page allocation stall!
>
>
> On Fri, 20 Jan 2017 15:14:13 +0000 bugzilla-daemon@bugzilla.kernel.org wrote:
>
>> https://bugzilla.kernel.org/show_bug.cgi?id=192981
>>
>>             Bug ID: 192981
>>            Summary: page allocation stalls
>>            Product: Memory Management
>>            Version: 2.5
>>     Kernel Version: 4.9
>>           Hardware: x86-64
>>                 OS: Linux
>>               Tree: Mainline
>>             Status: NEW
>>           Severity: normal
>>           Priority: P1
>>          Component: Page Allocator
>>           Assignee: akpm@linux-foundation.org
>>           Reporter: apolyakov@beget.ru
>>         Regression: No
>>
>> Created attachment 252621 [details]
>>   --> https://bugzilla.kernel.org/attachment.cgi?id=252621&action=edit
>> netconsole log with page allocation stalls
>>
>> We have been experiencing page allocation stalls regularly on our machines
>> used
>> as backup servers (many disks, mostly running rsync and rm).
>>
>> A notable one (2102516ms):
>>
>> 2017-01-17T11:08:33.754562+03:00 storage8 [335170.452601] rsync:
>> 2017-01-17T11:08:33.754574+03:00 page allocation stalls for 2102516ms,
>> order:0
>> 2017-01-17T11:08:33.754825+03:00 storage8 ,
>> mode:0x26040d0(GFP_TEMPORARY|__GFP_COMP|__GFP_NOTRACK)
>> 2017-01-17T11:08:33.755094+03:00 storage8 [335170.452896] CPU: 2 PID: 20383
>> Comm: rsync Tainted: G           O    4.9.0-0-beget-vanilla #1
>> 2017-01-17T11:08:33.755337+03:00 storage8 [335170.453156] Hardware name:
>> Supermicro X8DTL/X8DTL, BIOS 2.1b       11/16/2012
>> 2017-01-17T11:08:33.755379+03:00 storage8 [335170.453414]  0000000000000000
>> 2017-01-17T11:08:33.755379+03:00 storage8  ffffffff92441e0b
>> 2017-01-17T11:08:33.755393+03:00 storage8  ffff8c4b0f30f430
>> 2017-01-17T11:08:33.755484+03:00 storage8  0000000000000001
>> 2017-01-17T11:08:33.755600+03:00 storage8
>> 2017-01-17T11:08:33.755603+03:00 storage8 [335170.453681]  ffffffff92c3d1f8
>> 2017-01-17T11:08:33.755643+03:00 storage8  ffffffff92189594
>> 2017-01-17T11:08:33.755648+03:00 storage8  ffff8c4b0f315088
>> 2017-01-17T11:08:33.755754+03:00 storage8  026040d0026040d0
>> 2017-01-17T11:08:33.755874+03:00 storage8
>> 2017-01-17T11:08:33.755874+03:00 storage8 [335170.453951]  0000000000000020
>> 2017-01-17T11:08:33.755880+03:00 storage8  0000000000000010
>> 2017-01-17T11:08:33.755913+03:00 storage8  ffffa449d15cb7f8
>> 2017-01-17T11:08:33.756024+03:00 storage8  ffffa449d15cb7a8
>> 2017-01-17T11:08:33.756163+03:00 storage8
>> 2017-01-17T11:08:33.756278+03:00 storage8 [335170.454216] Call Trace:
>> 2017-01-17T11:08:33.756401+03:00 storage8 [335170.454347] 
>> [<ffffffff92441e0b>]
>> ? dump_stack+0x47/0x5c
>> 2017-01-17T11:08:33.756537+03:00 storage8 [335170.454479] 
>> [<ffffffff92189594>]
>> ? warn_alloc+0x134/0x150
>> 2017-01-17T11:08:33.756677+03:00 storage8 [335170.454612] 
>> [<ffffffff92189f2d>]
>> ? __alloc_pages_nodemask+0x90d/0xdb0
>> 2017-01-17T11:08:33.756808+03:00 storage8 [335170.454753] 
>> [<ffffffff923a5da4>]
>> ? _xfs_trans_bjoin+0xe4/0x110
>> 2017-01-17T11:08:33.756955+03:00 storage8 [335170.454892] 
>> [<ffffffff921d76fa>]
>> ? alloc_pages_current+0x9a/0x120
>> 2017-01-17T11:08:33.757096+03:00 storage8 [335170.455027] 
>> [<ffffffff921de440>]
>> ? new_slab+0x550/0x5f0
>> 2017-01-17T11:08:33.757218+03:00 storage8 [335170.455162] 
>> [<ffffffff921df2eb>]
>> ? ___slab_alloc.isra.59+0x3db/0x500
>> 2017-01-17T11:08:33.757346+03:00 storage8 [335170.455297] 
>> [<ffffffff923a683a>]
>> ? xfs_trans_brelse+0x1aa/0x270
>> 2017-01-17T11:08:33.757489+03:00 storage8 [335170.455427] 
>> [<ffffffff921f4612>]
>> ? memcg_kmem_get_cache+0x72/0x170
>> 2017-01-17T11:08:33.757632+03:00 storage8 [335170.455567] 
>> [<ffffffff92447837>]
>> ? __radix_tree_create+0xa7/0x320
>> 2017-01-17T11:08:33.757762+03:00 storage8 [335170.455706] 
>> [<ffffffff92200be5>]
>> ? __slab_alloc.isra.60+0xe/0x12
>> 2017-01-17T11:08:33.757897+03:00 storage8 [335170.455842] 
>> [<ffffffff921df5b0>]
>> ? kmem_cache_alloc+0x1a0/0x1b0
>> 2017-01-17T11:08:33.758034+03:00 storage8 [335170.455978] 
>> [<ffffffff9221b746>]
>> ? __d_alloc+0x26/0x1c0
>> 2017-01-17T11:08:33.758160+03:00 storage8 [335170.456108] 
>> [<ffffffff9221bb67>]
>> ? d_alloc+0x17/0x80
>> 2017-01-17T11:08:33.758290+03:00 storage8 [335170.456236] 
>> [<ffffffff9221bdf1>]
>> ? d_alloc_parallel+0x31/0x4b0
>> 2017-01-17T11:08:33.758429+03:00 storage8 [335170.456370] 
>> [<ffffffff9220f836>]
>> ? lookup_fast+0x56/0x2f0
>> 2017-01-17T11:08:33.758579+03:00 storage8 [335170.456505] 
>> [<ffffffff923804de>]
>> ? xfs_iunlock+0x17e/0x210
>> 2017-01-17T11:08:33.758694+03:00 storage8 [335170.456635] 
>> [<ffffffff922237f2>]
>> ? legitimize_mnt+0x12/0x40
>> 2017-01-17T11:08:33.758818+03:00 storage8 [335170.456770] 
>> [<ffffffff9220d8f0>]
>> ? lookup_slow+0x80/0x170
>> 2017-01-17T11:08:33.758955+03:00 storage8 [335170.456897] 
>> [<ffffffff9220fd08>]
>> ? walk_component+0x1a8/0x270
>> 2017-01-17T11:08:33.759086+03:00 storage8 [335170.457024] 
>> [<ffffffff92210398>]
>> ? path_lookupat+0x48/0xf0
>> 2017-01-17T11:08:33.759200+03:00 storage8 [335170.457153] 
>> [<ffffffff92212e75>]
>> ? filename_lookup+0xb5/0x190
>> 2017-01-17T11:08:33.759336+03:00 storage8 [335170.457282] 
>> [<ffffffff92474992>]
>> ? strncpy_from_user+0x42/0x140
>> 2017-01-17T11:08:33.759462+03:00 storage8 [335170.457411] 
>> [<ffffffff9221305b>]
>> ? getname_flags+0x7b/0x200
>> 2017-01-17T11:08:33.759593+03:00 storage8 [335170.457538] 
>> [<ffffffff92208b66>]
>> ? vfs_fstatat+0x46/0x90
>> 2017-01-17T11:08:33.759719+03:00 storage8 [335170.457666] 
>> [<ffffffff9221aaf4>]
>> ? dput+0x34/0x200
>> 2017-01-17T11:08:33.759859+03:00 storage8 [335170.457793] 
>> [<ffffffff92208d47>]
>> ? SyS_newlstat+0x17/0x30
>> 2017-01-17T11:08:33.759977+03:00 storage8 [335170.457923] 
>> [<ffffffff9282b7a0>]
>> ? entry_SYSCALL_64_fastpath+0x13/0x94
>>
>>
>> # sysctl vm
>> vm.admin_reserve_kbytes = 1048576
>> vm.block_dump = 0
>> error: permission denied on key 'vm.compact_memory'
>> vm.compact_unevictable_allowed = 1
>> vm.dirty_background_bytes = 0
>> vm.dirty_background_ratio = 1
>> vm.dirty_bytes = 0
>> vm.dirty_expire_centisecs = 1000
>> vm.dirty_ratio = 1
>> vm.dirty_writeback_centisecs = 100
>> vm.dirtytime_expire_seconds = 43200
>> vm.drop_caches = 0
>> vm.extfrag_threshold = 500
>> vm.hugepages_treat_as_movable = 0
>> vm.hugetlb_shm_group = 0
>> vm.laptop_mode = 0
>> vm.legacy_va_layout = 0
>> vm.lowmem_reserve_ratio = 128   128     16
>> vm.max_map_count = 65530
>> vm.memory_failure_early_kill = 0
>> vm.memory_failure_recovery = 1
>> vm.min_free_kbytes = 4194304
>> vm.min_slab_ratio = 1
>> vm.min_unmapped_ratio = 1
>> vm.mmap_min_addr = 65536
>> vm.mmap_rnd_bits = 28
>> vm.nr_hugepages = 0
>> vm.nr_hugepages_mempolicy = 0
>> vm.nr_overcommit_hugepages = 0
>> vm.nr_pdflush_threads = 0
>> vm.numa_zonelist_order = default
>> vm.oom_dump_tasks = 1
>> vm.oom_kill_allocating_task = 0
>> vm.overcommit_kbytes = 0
>> vm.overcommit_memory = 1
>> vm.overcommit_ratio = 50
>> vm.page-cluster = 3
>> vm.panic_on_oom = 0
>> vm.percpu_pagelist_fraction = 0
>> vm.stat_interval = 1
>> error: permission denied on key 'vm.stat_refresh'
>> vm.swappiness = 0
>> vm.user_reserve_kbytes = 131072
>> vm.vfs_cache_pressure = 200
>> vm.watermark_scale_factor = 100
>> vm.zone_reclaim_mode = 7
>>
>> # free -m
>>              total       used       free     shared    buffers     cached
>> Mem:         96646      46330      50315          0      25529       1228
>> -/+ buffers/cache:      19572      77073
>> Swap:            0          0          0
>>
>> (Yes, we don't have any swap configured)
>>
>> On this particular one we have 56 disks, using both XFS and EXT4. I attach
>> full
>> netconsole log for 18/01/2017. You can see there that we run drop_caches
>> regularly as it helps to keep the machine alive.
>>
>> Since then we've also tried mounting filesystems with sync flag to avoid
>> writeback and it seems to have helped a lot (full day without stalls).
>>
>> --
>> You are receiving this mail because:
>> You are the assignee for the bug.
Comment 3 Michal Hocko 2017-02-01 15:27:48 UTC
[Sorry for a late reply]

On Mon 23-01-17 13:51:11, Andrew Morton wrote:
[...]
> > We have been experiencing page allocation stalls regularly on our machines
> used
> > as backup servers (many disks, mostly running rsync and rm).
> > 
> > A notable one (2102516ms):
> > 
> > 2017-01-17T11:08:33.754562+03:00 storage8 [335170.452601] rsync: 
> > 2017-01-17T11:08:33.754574+03:00 page allocation stalls for 2102516ms,
> order:0
> > 2017-01-17T11:08:33.754825+03:00 storage8 ,
> > mode:0x26040d0(GFP_TEMPORARY|__GFP_COMP|__GFP_NOTRACK)

I have checked the log https://bugzilla.kernel.org/attachment.cgi?id=252621
and there are more problems than just this allocation stall.
2017-01-18T02:01:17.613811+03:00 storage8 [24768.850743] INFO: task mcpu:8505 blocked for more than 30 seconds.
2017-01-18T02:01:17.619823+03:00 storage8 [24768.856784] INFO: task mcpu:8506 blocked for more than 30 seconds.
2017-01-18T02:01:17.623022+03:00 storage8 [24768.859983] INFO: task mcpu:8507 blocked for more than 30 seconds.
2017-01-18T02:01:17.626262+03:00 storage8 [24768.863212] INFO: task mcpu:8508 blocked for more than 30 seconds.
2017-01-18T04:24:39.204636+03:00 storage8 [33370.536543] INFO: task atop:18760 blocked for more than 30 seconds.
2017-01-18T04:25:09.924667+03:00 storage8 [33401.256617] INFO: task kswapd0:136 blocked for more than 30 seconds.
2017-01-18T04:25:09.928503+03:00 storage8 [33401.260427] INFO: task kswapd1:137 blocked for more than 30 seconds.
2017-01-18T04:25:09.935268+03:00 storage8 [33401.267236] INFO: task atop:18760 blocked for more than 30 seconds.
2017-01-18T04:25:09.938539+03:00 storage8 [33401.270503] INFO: task rsync:29177 blocked for more than 30 seconds.
2017-01-18T11:40:44.709603+03:00 storage8 [  743.887448] INFO: task rsync:18111 blocked for more than 30 seconds.
2017-01-18T11:40:44.720724+03:00 storage8 [  743.898581] INFO: task rsync:19378 blocked for more than 30 seconds.
2017-01-18T11:42:47.589968+03:00 storage8 [  866.767027] INFO: task kswapd1:139 blocked for more than 30 seconds.
2017-01-18T11:42:47.594015+03:00 storage8 [  866.771109] INFO: task rsync:6909 blocked for more than 30 seconds.
2017-01-18T11:42:47.604005+03:00 storage8 [  866.781098] INFO: task rsync:17582 blocked for more than 30 seconds.
2017-01-18T11:42:47.611063+03:00 storage8 [  866.788159] INFO: task rsync:18111 blocked for more than 30 seconds.
2017-01-18T11:42:47.619089+03:00 storage8 [  866.796183] INFO: task rsync:18776 blocked for more than 30 seconds.
2017-01-18T11:42:47.631557+03:00 storage8 [  866.808652] INFO: task rsync:18777 blocked for more than 30 seconds.
2017-01-18T11:42:47.641018+03:00 storage8 [  866.818099] INFO: task rsync:19281 blocked for more than 30 seconds.
2017-01-18T11:42:47.647701+03:00 storage8 [  866.824797] INFO: task rsync:19740 blocked for more than 30 seconds.

Most of them are waiting for mmap_sem for read but there are cases where
the direct reclaim is waiting for a FS lock (in xfs_reclaim_inodes_ag).
I do not see the 2102516ms stall in the attached log and the information
given here doesn't contain the memory counters. When checking few random
stalls the picture seems to be pretty much consistent

[slightly edited to fix the broken new lines in the output]

2017-01-18T13:28:41.783833+03:00 page allocation stalls for 10380ms, order:0, mode:0x2604050(GFP_NOFS|__GFP_COMP|__GFP_RECLAIMABLE|__GFP_NOTRACK)
[...]
7221.937932]  free:1142851 free_pcp:20 free_cma:2942
2017-01-18T13:28:42.743176+03:00 storage8 [ 7221.938674] Node 0 active_anon:3352112kB inactive_anon:2120kB active_file:87308kB inactive_file:85252kB unevictable:3532kB isolated(anon):0kB iso
lated(file):2852kB mapped:5492kB dirty:0kB writeback:0kB shmem:0kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 2128kB writeback_tmp:0kB unstable:0kB pages_scanned:592392 all_unreclaimable?
 yes
2017-01-18T13:28:42.743780+03:00 storage8 [ 7221.939273] Node 1 active_anon:3472092kB inactive_anon:292kB active_file:73592kB inactive_file:72548kB unevictable:61700kB isolated(anon):0kB isolated(file):6640kB mapped:3268kB dirty:0kB writeback:0kB shmem:0kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 292kB writeback_tmp:0kB unstable:0kB pages_scanned:1064 all_unreclaimable? no
[...]
2017-01-18T13:28:42.744551+03:00 storage8 [ 7221.940642] Node 0 DMA32 free: 491744kB min:129476kB low:161844kB high:194212kB active_anon:59952kB inactive_anon:0kB active_file:148kB inactive_file:108kB unevictable:0kB writepending:0kB present:3120640kB managed:3055072kB mlocked:0kB slab_reclaimable:2317296kB slab_unreclaimable:96572kB kernel_stack:32kB pagetables:136kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
2017-01-18T13:28:42.892456+03:00 storage8 [ 7222.088527] lowmem_reserve[]: 90576 90576 0 0
2017-01-18T13:28:42.892592+03:00 storage8 [ 7222.088696] Node 0 Normal free: 1965392kB min:1965456kB low:2456820kB high:2948184kB active_anon:3292160kB inactive_anon:2120kB active_file:87560kB inactive_file:85192kB unevictable:3532kB writepending:0kB present:47185920kB managed:46375368kB mlocked:3532kB slab_reclaimable:24725412kB slab_unreclaimable:2591604kB kernel_stack:15944kB pagetables:98056kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
2017-01-18T13:28:42.893512+03:00 storage8 [ 7222.089602] Node 1 Normal free: 2099044kB min:2098692kB low:2623364kB high:3148036kB active_anon:3472092kB inactive_anon:292kB active_file:71624kB inactive_file:71456kB unevictable:61700kB writepending:0kB present:50331648kB managed:49519168kB mlocked:61700kB slab_reclaimable:28674160kB slab_unreclaimable:2597592kB kernel_stack:8472kB pagetables:51836kB bounce:0kB free_pcp:296kB local_pcp:0kB free_cma:11768kB

All the eligible zones are low on memoyr (DMA32 with the lowmem
protection). Anon memory is not reclaimable because you do not have
any swap. The file LRU seems to contain quite some memory. Dirty
and writeback counters would suggest that the page cache should be
reclaimable but maybe something is pinning those pages. I suspect the
reclaim blocked waiting for IO for metadata. I am not an expert on the
fs side of this but this smells like the IO cannot keep pace with the
load.
Comment 5 Alexander Polakov 2017-02-15 13:06:49 UTC
On 01/24/2017 12:51 AM, Andrew Morton wrote:
>
>
> (switched to email.  Please respond via emailed reply-to-all, not via the
> bugzilla web interface).
>
> A 2100 second page allocation stall!
>

I think we finally figured out the problem using Tetsuo Handa's mallocwd 
patch. It seems like it is in XFS direct reclaim path.

Here's how it goes:

memory is low, rsync goes into direct reclaim, locking xfs mutex in 
xfs_reclaim_inodes_nr():

2017-02-14T00:12:59.811447+03:00 storage9 [24646.497290] MemAlloc: 
rsync(19706) flags=0x404840 switches=8692 seq=340 
gfp=0x27080c0(GFP_KERNEL_ACCOUNT|__GFP_ZERO|__GFP_NOTRACK) order=0 
delay=6795
2017-02-14T00:12:59.811447+03:00 storage9 [24646.497550] rsync           R
2017-02-14T00:12:59.811579+03:00 storage9     0 19706   5000 0x00000000
2017-02-14T00:12:59.811579+03:00 storage9 [24646.497690]  ffffa4361dc36c00
2017-02-14T00:12:59.811591+03:00 storage9  0000000c1dc36c00
2017-02-14T00:12:59.811591+03:00 storage9  ffffa4361dc36c00
2017-02-14T00:12:59.811724+03:00 storage9  ffffa44347792580
2017-02-14T00:12:59.811841+03:00 storage9
2017-02-14T00:12:59.811841+03:00 storage9 [24646.497951]  0000000000000000
2017-02-14T00:12:59.811846+03:00 storage9  ffffb1cab6343458
2017-02-14T00:12:59.811885+03:00 storage9  ffffffffb383e799
2017-02-14T00:12:59.811987+03:00 storage9  0000000000000000
2017-02-14T00:12:59.812103+03:00 storage9
2017-02-14T00:12:59.812103+03:00 storage9 [24646.498208]  ffffa443ffff7a00
2017-02-14T00:12:59.812103+03:00 storage9  0000000000000001
2017-02-14T00:12:59.812104+03:00 storage9  ffffb1cab6343448
2017-02-14T00:12:59.812233+03:00 storage9  0000000000000002
2017-02-14T00:12:59.812350+03:00 storage9
2017-02-14T00:12:59.812475+03:00 storage9 [24646.498462] Call Trace:
2017-02-14T00:12:59.812610+03:00 storage9 [24646.498587] 
[<ffffffffb383e799>] ? __schedule+0x179/0x5c8
2017-02-14T00:12:59.812733+03:00 storage9 [24646.498718] 
[<ffffffffb383ecc2>] ? schedule+0x32/0x80
2017-02-14T00:12:59.812869+03:00 storage9 [24646.498846] 
[<ffffffffb3841229>] ? schedule_timeout+0x159/0x2a0
2017-02-14T00:12:59.812997+03:00 storage9 [24646.498977] 
[<ffffffffb30f1450>] ? add_timer_on+0x130/0x130
2017-02-14T00:12:59.813130+03:00 storage9 [24646.499108] 
[<ffffffffb318ff13>] ? __alloc_pages_nodemask+0xe73/0x16b0
2017-02-14T00:12:59.813263+03:00 storage9 [24646.499240] 
[<ffffffffb31deb2a>] ? alloc_pages_current+0x9a/0x120
2017-02-14T00:12:59.813388+03:00 storage9 [24646.499371] 
[<ffffffffb33d1a51>] ? xfs_buf_allocate_memory+0x171/0x2c0
2017-02-14T00:12:59.813564+03:00 storage9 [24646.499503] 
[<ffffffffb337c48b>] ? xfs_buf_get_map+0x18b/0x1d0
2017-02-14T00:12:59.813654+03:00 storage9 [24646.499634] 
[<ffffffffb337cdcb>] ? xfs_buf_read_map+0x3b/0x160
2017-02-14T00:12:59.813783+03:00 storage9 [24646.499765] 
[<ffffffffb33b71b0>] ? xfs_trans_read_buf_map+0x1f0/0x490
2017-02-14T00:12:59.813931+03:00 storage9 [24646.499897] 
[<ffffffffb3362859>] ? xfs_imap_to_bp+0x79/0x120
2017-02-14T00:12:59.814056+03:00 storage9 [24646.500029] 
[<ffffffffb3394a38>] ? xfs_iflush+0x118/0x380
2017-02-14T00:12:59.814196+03:00 storage9 [24646.500158] 
[<ffffffffb30d6130>] ? wake_atomic_t_function+0x40/0x40
2017-02-14T00:12:59.814314+03:00 storage9 [24646.500289] 
[<ffffffffb3385af4>] ? xfs_reclaim_inode+0x274/0x3f0
2017-02-14T00:12:59.814444+03:00 storage9 [24646.500421] 
[<ffffffffb3385e29>] ? xfs_reclaim_inodes_ag+0x1b9/0x2c0
2017-02-14T00:12:59.814573+03:00 storage9 [24646.500553] 
[<ffffffffb345c6b8>] ? radix_tree_next_chunk+0x108/0x2a0
2017-02-14T00:12:59.814701+03:00 storage9 [24646.500685] 
[<ffffffffb30f0e31>] ? lock_timer_base+0x51/0x70
2017-02-14T00:12:59.814846+03:00 storage9 [24646.500814] 
[<ffffffffb345ca4e>] ? radix_tree_gang_lookup_tag+0xae/0x180
2017-02-14T00:12:59.814966+03:00 storage9 [24646.500946] 
[<ffffffffb336f588>] ? xfs_perag_get_tag+0x48/0x100
2017-02-14T00:12:59.815104+03:00 storage9 [24646.501079] 
[<ffffffffb31b63c1>] ? __list_lru_walk_one.isra.7+0x31/0x120
2017-02-14T00:12:59.815231+03:00 storage9 [24646.501212] 
[<ffffffffb322aed0>] ? iget5_locked+0x240/0x240
2017-02-14T00:12:59.815360+03:00 storage9 [24646.501342] 
[<ffffffffb33873c1>] ? xfs_reclaim_inodes_nr+0x31/0x40
2017-02-14T00:12:59.815489+03:00 storage9 [24646.501472] 
[<ffffffffb3213160>] ? super_cache_scan+0x1a0/0x1b0
2017-02-14T00:12:59.815629+03:00 storage9 [24646.501603] 
[<ffffffffb319bf62>] ? shrink_slab+0x262/0x440
2017-02-14T00:12:59.815760+03:00 storage9 [24646.501734] 
[<ffffffffb319cc8b>] ? drop_slab_node+0x2b/0x60
2017-02-14T00:12:59.815891+03:00 storage9 [24646.501864] 
[<ffffffffb319cd02>] ? drop_slab+0x42/0x70
2017-02-14T00:12:59.816020+03:00 storage9 [24646.501994] 
[<ffffffffb318abc0>] ? out_of_memory+0x220/0x560
2017-02-14T00:12:59.816160+03:00 storage9 [24646.502122] 
[<ffffffffb31903b2>] ? __alloc_pages_nodemask+0x1312/0x16b0
2017-02-14T00:12:59.816285+03:00 storage9 [24646.502255] 
[<ffffffffb31deb2a>] ? alloc_pages_current+0x9a/0x120
2017-02-14T00:12:59.816407+03:00 storage9 [24646.502386] 
[<ffffffffb304b803>] ? pte_alloc_one+0x13/0x40
2017-02-14T00:12:59.816536+03:00 storage9 [24646.502517] 
[<ffffffffb31be21f>] ? handle_mm_fault+0xc7f/0x14b0
2017-02-14T00:12:59.816659+03:00 storage9 [24646.502648] 
[<ffffffffb30461ff>] ? __do_page_fault+0x1cf/0x5a0
2017-02-14T00:12:59.816851+03:00 storage9 [24646.502777] 
[<ffffffffb3843362>] ? page_fault+0x22/0x30

But it cannot get memory, because it's low (?). So it stays blocked.

Other processes do the same but they can't get past the mutex in 
xfs_reclaim_inodes_nr():

2017-02-14T00:12:59.817057+03:00 storage9 [24646.502909] MemAlloc: 
rsync(19707) flags=0x404840 switches=6344 seq=638 
gfp=0x24201ca(GFP_HIGHUSER_MOVABLE|__GFP_COLD) order=0 delay=3257 
uninterruptible
2017-02-14T00:12:59.817062+03:00 storage9 [24646.503167] rsync           D
2017-02-14T00:12:59.817189+03:00 storage9     0 19707   5000 0x00000000
2017-02-14T00:12:59.817197+03:00 storage9 [24646.503299]  0000000000000000
2017-02-14T00:12:59.817197+03:00 storage9  ffffa44347793840
2017-02-14T00:12:59.817207+03:00 storage9  ffffa4277a36ec00
2017-02-14T00:12:59.817316+03:00 storage9  ffffa4361dc35100
2017-02-14T00:12:59.817446+03:00 storage9
2017-02-14T00:12:59.817446+03:00 storage9 [24646.503554]  ffffa4437a514300
2017-02-14T00:12:59.817461+03:00 storage9  ffffb1cab0823638
2017-02-14T00:12:59.817461+03:00 storage9  ffffffffb383e799
2017-02-14T00:12:59.817598+03:00 storage9  ffffa44365967b00
2017-02-14T00:12:59.817699+03:00 storage9
2017-02-14T00:12:59.817699+03:00 storage9 [24646.503809]  ffffb1cab0823680
2017-02-14T00:12:59.817717+03:00 storage9  0000000000000001
2017-02-14T00:12:59.817717+03:00 storage9  ffffa443424062a8
2017-02-14T00:12:59.817832+03:00 storage9  0000000000000000
2017-02-14T00:12:59.817948+03:00 storage9
2017-02-14T00:12:59.818078+03:00 storage9 [24646.504061] Call Trace:
2017-02-14T00:12:59.818211+03:00 storage9 [24646.504189] 
[<ffffffffb383e799>] ? __schedule+0x179/0x5c8
2017-02-14T00:12:59.818339+03:00 storage9 [24646.504321] 
[<ffffffffb383ecc2>] ? schedule+0x32/0x80
2017-02-14T00:12:59.818471+03:00 storage9 [24646.504451] 
[<ffffffffb383ee6e>] ? schedule_preempt_disabled+0xe/0x20
2017-02-14T00:12:59.818611+03:00 storage9 [24646.504582] 
[<ffffffffb38400aa>] ? __mutex_lock_slowpath+0x8a/0x100
2017-02-14T00:12:59.818737+03:00 storage9 [24646.504715] 
[<ffffffffb3840133>] ? mutex_lock+0x13/0x22
2017-02-14T00:12:59.818870+03:00 storage9 [24646.504846] 
[<ffffffffb3385e98>] ? xfs_reclaim_inodes_ag+0x228/0x2c0
2017-02-14T00:12:59.819024+03:00 storage9 [24646.504977] 
[<ffffffffb345c6b8>] ? radix_tree_next_chunk+0x108/0x2a0
2017-02-14T00:12:59.819124+03:00 storage9 [24646.505107] 
[<ffffffffb345ca4e>] ? radix_tree_gang_lookup_tag+0xae/0x180
2017-02-14T00:12:59.819273+03:00 storage9 [24646.505238] 
[<ffffffffb336f588>] ? xfs_perag_get_tag+0x48/0x100
2017-02-14T00:12:59.819397+03:00 storage9 [24646.505370] 
[<ffffffffb31b63c1>] ? __list_lru_walk_one.isra.7+0x31/0x120
2017-02-14T00:12:59.819528+03:00 storage9 [24646.505502] 
[<ffffffffb322aed0>] ? iget5_locked+0x240/0x240
2017-02-14T00:12:59.819657+03:00 storage9 [24646.505634] 
[<ffffffffb33873c1>] ? xfs_reclaim_inodes_nr+0x31/0x40
2017-02-14T00:12:59.819781+03:00 storage9 [24646.505766] 
[<ffffffffb3213160>] ? super_cache_scan+0x1a0/0x1b0
2017-02-14T00:12:59.819915+03:00 storage9 [24646.505897] 
[<ffffffffb319bf62>] ? shrink_slab+0x262/0x440
2017-02-14T00:12:59.820100+03:00 storage9 [24646.506028] 
[<ffffffffb319fa6f>] ? shrink_node+0xef/0x2d0
2017-02-14T00:12:59.820176+03:00 storage9 [24646.506158] 
[<ffffffffb319ff42>] ? do_try_to_free_pages+0xc2/0x2b0
2017-02-14T00:12:59.820300+03:00 storage9 [24646.506288] 
[<ffffffffb31a03e2>] ? try_to_free_pages+0xe2/0x1c0
2017-02-14T00:12:59.820442+03:00 storage9 [24646.506415] 
[<ffffffffb318c1a9>] ? __perform_reclaim.isra.80+0x79/0xc0
2017-02-14T00:12:59.820556+03:00 storage9 [24646.506542] 
[<ffffffffb318f901>] ? __alloc_pages_nodemask+0x861/0x16b0
2017-02-14T00:12:59.820683+03:00 storage9 [24646.506669] 
[<ffffffffb345d64b>] ? __radix_tree_lookup+0x7b/0xe0
2017-02-14T00:12:59.820851+03:00 storage9 [24646.506796] 
[<ffffffffb31deb2a>] ? alloc_pages_current+0x9a/0x120
2017-02-14T00:12:59.820942+03:00 storage9 [24646.506922] 
[<ffffffffb3188b56>] ? filemap_fault+0x396/0x540
2017-02-14T00:12:59.821072+03:00 storage9 [24646.507048] 
[<ffffffffb345c6b8>] ? radix_tree_next_chunk+0x108/0x2a0
2017-02-14T00:12:59.821192+03:00 storage9 [24646.507176] 
[<ffffffffb32a5bdf>] ? ext4_filemap_fault+0x3f/0x60
2017-02-14T00:12:59.821318+03:00 storage9 [24646.507303] 
[<ffffffffb31b8591>] ? __do_fault+0x71/0x120
2017-02-14T00:12:59.821441+03:00 storage9 [24646.507428] 
[<ffffffffb31be36d>] ? handle_mm_fault+0xdcd/0x14b0
2017-02-14T00:12:59.821574+03:00 storage9 [24646.507555] 
[<ffffffffb31ea9a4>] ? kmem_cache_free+0x204/0x220
2017-02-14T00:12:59.821697+03:00 storage9 [24646.507682] 
[<ffffffffb32114b9>] ? __fput+0x149/0x200
2017-02-14T00:12:59.821824+03:00 storage9 [24646.507806] 
[<ffffffffb30461ff>] ? __do_page_fault+0x1cf/0x5a0
2017-02-14T00:12:59.821954+03:00 storage9 [24646.507934] 
[<ffffffffb3843362>] ? page_fault+0x22/0x30

Even kswapd gets stuck:

2017-02-14T00:13:10.306351+03:00 storage9 [24656.991375] MemAlloc: 
kswapd0(114) flags=0xa40840 switches=22109 uninterruptible
2017-02-14T00:13:10.306351+03:00 storage9 [24656.991622] kswapd0         D
2017-02-14T00:13:10.306473+03:00 storage9     0   114      2 0x00000000
2017-02-14T00:13:10.306482+03:00 storage9 [24656.991753]  0000000000000000
2017-02-14T00:13:10.306482+03:00 storage9  ffffa43830be0f00
2017-02-14T00:13:10.306488+03:00 storage9  ffffa44342ff2880
2017-02-14T00:13:10.306601+03:00 storage9  ffffa443600e0d80
2017-02-14T00:13:10.306714+03:00 storage9
2017-02-14T00:13:10.306723+03:00 storage9 [24656.992000]  ffffa4437ad14300
2017-02-14T00:13:10.306723+03:00 storage9  ffffb1ca8d2737d8
2017-02-14T00:13:10.306731+03:00 storage9  ffffffffb383e799
2017-02-14T00:13:10.306846+03:00 storage9  ffffb1ca8d273788
2017-02-14T00:13:10.306956+03:00 storage9
2017-02-14T00:13:10.306957+03:00 storage9 [24656.992245]  ffffb1ca8d273788
2017-02-14T00:13:10.306957+03:00 storage9  ffffb1ca8d273798
2017-02-14T00:13:10.307011+03:00 storage9  ffffb1ca8d273798
2017-02-14T00:13:10.307087+03:00 storage9  0000000002400001
2017-02-14T00:13:10.307200+03:00 storage9
2017-02-14T00:13:10.307321+03:00 storage9 [24656.992489] Call Trace:
2017-02-14T00:13:10.307475+03:00 storage9 [24656.992611] 
[<ffffffffb383e799>] ? __schedule+0x179/0x5c8
2017-02-14T00:13:10.307572+03:00 storage9 [24656.992736] 
[<ffffffffb383ecc2>] ? schedule+0x32/0x80
2017-02-14T00:13:10.307703+03:00 storage9 [24656.992861] 
[<ffffffffb3841002>] ? rwsem_down_read_failed+0xb2/0x100
2017-02-14T00:13:10.307831+03:00 storage9 [24656.992987] 
[<ffffffffb3466004>] ? call_rwsem_down_read_failed+0x14/0x30
2017-02-14T00:13:10.307949+03:00 storage9 [24656.993114] 
[<ffffffffb3840443>] ? down_read+0x13/0x30
2017-02-14T00:13:10.308075+03:00 storage9 [24656.993239] 
[<ffffffffb3373420>] ? xfs_map_blocks+0x90/0x2f0
2017-02-14T00:13:10.308214+03:00 storage9 [24656.993366] 
[<ffffffffb3375256>] ? xfs_do_writepage+0x2b6/0x6a0
2017-02-14T00:13:10.308337+03:00 storage9 [24656.993496] 
[<ffffffffb3245589>] ? submit_bh_wbc+0x169/0x200
2017-02-14T00:13:10.308518+03:00 storage9 [24656.993627] 
[<ffffffffb337566c>] ? xfs_vm_writepage+0x2c/0x50
2017-02-14T00:13:10.308603+03:00 storage9 [24656.993760] 
[<ffffffffb319bb0b>] ? pageout.isra.60+0xeb/0x2e0
2017-02-14T00:13:10.308728+03:00 storage9 [24656.993891] 
[<ffffffffb319df06>] ? shrink_page_list+0x736/0xa50
2017-02-14T00:13:10.308935+03:00 storage9 [24656.994022] 
[<ffffffffb319eb52>] ? shrink_inactive_list+0x202/0x4b0
2017-02-14T00:13:10.308993+03:00 storage9 [24656.994152] 
[<ffffffffb319f4d1>] ? shrink_node_memcg+0x2e1/0x790
2017-02-14T00:13:10.309148+03:00 storage9 [24656.994282] 
[<ffffffffb319fa49>] ? shrink_node+0xc9/0x2d0
2017-02-14T00:13:10.309258+03:00 storage9 [24656.994416] 
[<ffffffffb31a0944>] ? kswapd+0x2e4/0x690
2017-02-14T00:13:10.309854+03:00 storage9 [24656.994546] 
[<ffffffffb31a0660>] ? mem_cgroup_shrink_node+0x1a0/0x1a0
2017-02-14T00:13:10.309854+03:00 storage9 [24656.994678] 
[<ffffffffb31a0660>] ? mem_cgroup_shrink_node+0x1a0/0x1a0
2017-02-14T00:13:10.309854+03:00 storage9 [24656.994808] 
[<ffffffffb30b4fc2>] ? kthread+0xc2/0xe0
2017-02-14T00:13:10.309854+03:00 storage9 [24656.994937] 
[<ffffffffb30b4f00>] ? __kthread_init_worker+0xb0/0xb0
2017-02-14T00:13:10.309910+03:00 storage9 [24656.995069] 
[<ffffffffb38425e2>] ? ret_from_fork+0x22/0x30

Which finally leads to "Kernel panic - not syncing: Out of memory and no 
killable processes..." as no process is able to proceed.

I quickly hacked this:

diff --git a/fs/xfs/xfs_icache.c b/fs/xfs/xfs_icache.c
index 9ef152b..8adfb0a 100644
--- a/fs/xfs/xfs_icache.c
+++ b/fs/xfs/xfs_icache.c
@@ -1254,7 +1254,7 @@ struct xfs_inode *
         xfs_reclaim_work_queue(mp);
         xfs_ail_push_all(mp->m_ail);

-       return xfs_reclaim_inodes_ag(mp, SYNC_TRYLOCK | SYNC_WAIT, 
&nr_to_scan);
+       return 0; // xfs_reclaim_inodes_ag(mp, SYNC_TRYLOCK | SYNC_WAIT, 
&nr_to_scan);
  }


We ran 2 of our machines with this patch for a night, no more 
lockups/stalls were detected.

xfsaild does its work asynchronously, so xfs_inodes don't run wild as 
confirmed by slabtop.

I put netconsole logs here: http://aplkv.beget.tech/lkml/xfs/ for anyone 
interested.
Comment 6 bfoster 2017-02-15 16:15:21 UTC
On Wed, Feb 15, 2017 at 03:56:56PM +0300, Alexander Polakov wrote:
> On 01/24/2017 12:51 AM, Andrew Morton wrote:
> > 
> > 
> > (switched to email.  Please respond via emailed reply-to-all, not via the
> > bugzilla web interface).
> > 
> > A 2100 second page allocation stall!
> > 
> 
> I think we finally figured out the problem using Tetsuo Handa's mallocwd
> patch. It seems like it is in XFS direct reclaim path.
> 
> Here's how it goes:
> 
> memory is low, rsync goes into direct reclaim, locking xfs mutex in
> xfs_reclaim_inodes_nr():
> 
> 2017-02-14T00:12:59.811447+03:00 storage9 [24646.497290] MemAlloc:
> rsync(19706) flags=0x404840 switches=8692 seq=340
> gfp=0x27080c0(GFP_KERNEL_ACCOUNT|__GFP_ZERO|__GFP_NOTRACK) order=0
> delay=6795
> 2017-02-14T00:12:59.811447+03:00 storage9 [24646.497550] rsync           R
> 2017-02-14T00:12:59.811579+03:00 storage9     0 19706   5000 0x00000000
> 2017-02-14T00:12:59.811579+03:00 storage9 [24646.497690]  ffffa4361dc36c00
> 2017-02-14T00:12:59.811591+03:00 storage9  0000000c1dc36c00
> 2017-02-14T00:12:59.811591+03:00 storage9  ffffa4361dc36c00
> 2017-02-14T00:12:59.811724+03:00 storage9  ffffa44347792580
> 2017-02-14T00:12:59.811841+03:00 storage9
> 2017-02-14T00:12:59.811841+03:00 storage9 [24646.497951]  0000000000000000
> 2017-02-14T00:12:59.811846+03:00 storage9  ffffb1cab6343458
> 2017-02-14T00:12:59.811885+03:00 storage9  ffffffffb383e799
> 2017-02-14T00:12:59.811987+03:00 storage9  0000000000000000
> 2017-02-14T00:12:59.812103+03:00 storage9
> 2017-02-14T00:12:59.812103+03:00 storage9 [24646.498208]  ffffa443ffff7a00
> 2017-02-14T00:12:59.812103+03:00 storage9  0000000000000001
> 2017-02-14T00:12:59.812104+03:00 storage9  ffffb1cab6343448
> 2017-02-14T00:12:59.812233+03:00 storage9  0000000000000002
> 2017-02-14T00:12:59.812350+03:00 storage9
> 2017-02-14T00:12:59.812475+03:00 storage9 [24646.498462] Call Trace:
> 2017-02-14T00:12:59.812610+03:00 storage9 [24646.498587]
> [<ffffffffb383e799>] ? __schedule+0x179/0x5c8
> 2017-02-14T00:12:59.812733+03:00 storage9 [24646.498718]
> [<ffffffffb383ecc2>] ? schedule+0x32/0x80
> 2017-02-14T00:12:59.812869+03:00 storage9 [24646.498846]
> [<ffffffffb3841229>] ? schedule_timeout+0x159/0x2a0
> 2017-02-14T00:12:59.812997+03:00 storage9 [24646.498977]
> [<ffffffffb30f1450>] ? add_timer_on+0x130/0x130
> 2017-02-14T00:12:59.813130+03:00 storage9 [24646.499108]
> [<ffffffffb318ff13>] ? __alloc_pages_nodemask+0xe73/0x16b0
> 2017-02-14T00:12:59.813263+03:00 storage9 [24646.499240]
> [<ffffffffb31deb2a>] ? alloc_pages_current+0x9a/0x120
> 2017-02-14T00:12:59.813388+03:00 storage9 [24646.499371]
> [<ffffffffb33d1a51>] ? xfs_buf_allocate_memory+0x171/0x2c0
> 2017-02-14T00:12:59.813564+03:00 storage9 [24646.499503]
> [<ffffffffb337c48b>] ? xfs_buf_get_map+0x18b/0x1d0
> 2017-02-14T00:12:59.813654+03:00 storage9 [24646.499634]
> [<ffffffffb337cdcb>] ? xfs_buf_read_map+0x3b/0x160
> 2017-02-14T00:12:59.813783+03:00 storage9 [24646.499765]
> [<ffffffffb33b71b0>] ? xfs_trans_read_buf_map+0x1f0/0x490
> 2017-02-14T00:12:59.813931+03:00 storage9 [24646.499897]
> [<ffffffffb3362859>] ? xfs_imap_to_bp+0x79/0x120
> 2017-02-14T00:12:59.814056+03:00 storage9 [24646.500029]
> [<ffffffffb3394a38>] ? xfs_iflush+0x118/0x380
> 2017-02-14T00:12:59.814196+03:00 storage9 [24646.500158]
> [<ffffffffb30d6130>] ? wake_atomic_t_function+0x40/0x40
> 2017-02-14T00:12:59.814314+03:00 storage9 [24646.500289]
> [<ffffffffb3385af4>] ? xfs_reclaim_inode+0x274/0x3f0
> 2017-02-14T00:12:59.814444+03:00 storage9 [24646.500421]
> [<ffffffffb3385e29>] ? xfs_reclaim_inodes_ag+0x1b9/0x2c0
> 2017-02-14T00:12:59.814573+03:00 storage9 [24646.500553]
> [<ffffffffb345c6b8>] ? radix_tree_next_chunk+0x108/0x2a0
> 2017-02-14T00:12:59.814701+03:00 storage9 [24646.500685]
> [<ffffffffb30f0e31>] ? lock_timer_base+0x51/0x70
> 2017-02-14T00:12:59.814846+03:00 storage9 [24646.500814]
> [<ffffffffb345ca4e>] ? radix_tree_gang_lookup_tag+0xae/0x180
> 2017-02-14T00:12:59.814966+03:00 storage9 [24646.500946]
> [<ffffffffb336f588>] ? xfs_perag_get_tag+0x48/0x100
> 2017-02-14T00:12:59.815104+03:00 storage9 [24646.501079]
> [<ffffffffb31b63c1>] ? __list_lru_walk_one.isra.7+0x31/0x120
> 2017-02-14T00:12:59.815231+03:00 storage9 [24646.501212]
> [<ffffffffb322aed0>] ? iget5_locked+0x240/0x240
> 2017-02-14T00:12:59.815360+03:00 storage9 [24646.501342]
> [<ffffffffb33873c1>] ? xfs_reclaim_inodes_nr+0x31/0x40
> 2017-02-14T00:12:59.815489+03:00 storage9 [24646.501472]
> [<ffffffffb3213160>] ? super_cache_scan+0x1a0/0x1b0
> 2017-02-14T00:12:59.815629+03:00 storage9 [24646.501603]
> [<ffffffffb319bf62>] ? shrink_slab+0x262/0x440
> 2017-02-14T00:12:59.815760+03:00 storage9 [24646.501734]
> [<ffffffffb319cc8b>] ? drop_slab_node+0x2b/0x60
> 2017-02-14T00:12:59.815891+03:00 storage9 [24646.501864]
> [<ffffffffb319cd02>] ? drop_slab+0x42/0x70
> 2017-02-14T00:12:59.816020+03:00 storage9 [24646.501994]
> [<ffffffffb318abc0>] ? out_of_memory+0x220/0x560
> 2017-02-14T00:12:59.816160+03:00 storage9 [24646.502122]
> [<ffffffffb31903b2>] ? __alloc_pages_nodemask+0x1312/0x16b0
> 2017-02-14T00:12:59.816285+03:00 storage9 [24646.502255]
> [<ffffffffb31deb2a>] ? alloc_pages_current+0x9a/0x120
> 2017-02-14T00:12:59.816407+03:00 storage9 [24646.502386]
> [<ffffffffb304b803>] ? pte_alloc_one+0x13/0x40
> 2017-02-14T00:12:59.816536+03:00 storage9 [24646.502517]
> [<ffffffffb31be21f>] ? handle_mm_fault+0xc7f/0x14b0
> 2017-02-14T00:12:59.816659+03:00 storage9 [24646.502648]
> [<ffffffffb30461ff>] ? __do_page_fault+0x1cf/0x5a0
> 2017-02-14T00:12:59.816851+03:00 storage9 [24646.502777]
> [<ffffffffb3843362>] ? page_fault+0x22/0x30
> 

You're in inode reclaim, blocked on a memory allocation for an inode
buffer required to flush a dirty inode. I suppose this means that the
backing buffer for the inode has already been reclaimed and must be
re-read, which ideally wouldn't have occurred before the inode is
flushed.

> But it cannot get memory, because it's low (?). So it stays blocked.
> 
> Other processes do the same but they can't get past the mutex in
> xfs_reclaim_inodes_nr():
> 
...
> Which finally leads to "Kernel panic - not syncing: Out of memory and no
> killable processes..." as no process is able to proceed.
> 
> I quickly hacked this:
> 
> diff --git a/fs/xfs/xfs_icache.c b/fs/xfs/xfs_icache.c
> index 9ef152b..8adfb0a 100644
> --- a/fs/xfs/xfs_icache.c
> +++ b/fs/xfs/xfs_icache.c
> @@ -1254,7 +1254,7 @@ struct xfs_inode *
>         xfs_reclaim_work_queue(mp);
>         xfs_ail_push_all(mp->m_ail);
> 
> -       return xfs_reclaim_inodes_ag(mp, SYNC_TRYLOCK | SYNC_WAIT,
> &nr_to_scan);
> +       return 0; // xfs_reclaim_inodes_ag(mp, SYNC_TRYLOCK | SYNC_WAIT,
> &nr_to_scan);
>  }
> 

So you've disabled inode reclaim completely...

The bz shows you have non-default vm settings such as
'vm.vfs_cache_pressure = 200.' My understanding is that prefers
aggressive inode reclaim, yet the code workaround here is to bypass XFS
inode reclaim. Out of curiousity, have you reproduced this problem using
the default vfs_cache_pressure value (or if so, possibly moving it in
the other direction)?

Brian

> 
> We ran 2 of our machines with this patch for a night, no more lockups/stalls
> were detected.
> 
> xfsaild does its work asynchronously, so xfs_inodes don't run wild as
> confirmed by slabtop.
> 
> I put netconsole logs here: http://aplkv.beget.tech/lkml/xfs/ for anyone
> interested.
> 
> -- 
> Alexander Polakov | system software engineer | https://beget.com
> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
Comment 7 Alexander Polakov 2017-02-15 16:52:19 UTC
On 02/15/2017 07:05 PM, Brian Foster wrote:
> You're in inode reclaim, blocked on a memory allocation for an inode
> buffer required to flush a dirty inode. I suppose this means that the
> backing buffer for the inode has already been reclaimed and must be
> re-read, which ideally wouldn't have occurred before the inode is
> flushed.
>
>> But it cannot get memory, because it's low (?). So it stays blocked.
>>
>> Other processes do the same but they can't get past the mutex in
>> xfs_reclaim_inodes_nr():
>>
> ...
>> Which finally leads to "Kernel panic - not syncing: Out of memory and no
>> killable processes..." as no process is able to proceed.
>>
>> I quickly hacked this:
>>
>> diff --git a/fs/xfs/xfs_icache.c b/fs/xfs/xfs_icache.c
>> index 9ef152b..8adfb0a 100644
>> --- a/fs/xfs/xfs_icache.c
>> +++ b/fs/xfs/xfs_icache.c
>> @@ -1254,7 +1254,7 @@ struct xfs_inode *
>>         xfs_reclaim_work_queue(mp);
>>         xfs_ail_push_all(mp->m_ail);
>>
>> -       return xfs_reclaim_inodes_ag(mp, SYNC_TRYLOCK | SYNC_WAIT,
>> &nr_to_scan);
>> +       return 0; // xfs_reclaim_inodes_ag(mp, SYNC_TRYLOCK | SYNC_WAIT,
>> &nr_to_scan);
>>  }
>>
>
> So you've disabled inode reclaim completely...

I don't think this is correct. I disabled direct / kswapd reclaim.
XFS uses background worker for async reclaim:

http://lxr.free-electrons.com/source/fs/xfs/xfs_icache.c#L178
http://lxr.free-electrons.com/source/fs/xfs/xfs_super.c#L1534

Confirmed by running trace-cmd on a patched kernel:

# trace-cmd record -p function -l xfs_reclaim_inodes -l xfs_reclaim_worker
# # trace-cmd report
CPU 0 is empty
CPU 2 is empty
CPU 3 is empty
CPU 5 is empty
CPU 8 is empty
CPU 10 is empty
CPU 11 is empty
cpus=16
     kworker/12:2-31208 [012] 106450.590216: function: 
xfs_reclaim_worker
     kworker/12:2-31208 [012] 106450.590226: function: 
xfs_reclaim_inodes
     kworker/12:2-31208 [012] 106450.756879: function: 
xfs_reclaim_worker
     kworker/12:2-31208 [012] 106450.756882: function: 
xfs_reclaim_inodes
     kworker/12:2-31208 [012] 106450.920212: function: 
xfs_reclaim_worker
     kworker/12:2-31208 [012] 106450.920215: function: 
xfs_reclaim_inodes
     kworker/12:2-31208 [012] 106451.083549: function: 
xfs_reclaim_worker
     kworker/12:2-31208 [012] 106451.083552: function: 
xfs_reclaim_inodes
     kworker/12:2-31208 [012] 106451.246882: function: 
xfs_reclaim_worker
     kworker/12:2-31208 [012] 106451.246885: function: 
xfs_reclaim_inodes
     kworker/12:2-31208 [012] 106451.413546: function: 
xfs_reclaim_worker
     kworker/12:2-31208 [012] 106451.413548: function: 
xfs_reclaim_inodes
     kworker/12:2-31208 [012] 106451.580215: function: 
xfs_reclaim_worker
     kworker/12:2-31208 [012] 106451.580217: function: 
xfs_reclaim_inodes
     kworker/12:2-31208 [012] 106451.743549: function: 
xfs_reclaim_worker
     kworker/12:2-31208 [012] 106451.743550: function: 
xfs_reclaim_inodes
     kworker/12:2-31208 [012] 106451.906882: function: 
xfs_reclaim_worker
     kworker/12:2-31208 [012] 106451.906885: function: 
xfs_reclaim_inodes
     kworker/12:2-31208 [012] 106452.070216: function: 
xfs_reclaim_worker
     kworker/12:2-31208 [012] 106452.070219: function: 
xfs_reclaim_inodes
      kworker/7:0-14419 [007] 106454.730218: function: 
xfs_reclaim_worker
      kworker/7:0-14419 [007] 106454.730227: function: 
xfs_reclaim_inodes
      kworker/1:0-14025 [001] 106455.340221: function: 
xfs_reclaim_worker
      kworker/1:0-14025 [001] 106455.340225: function: 
xfs_reclaim_inodes

> The bz shows you have non-default vm settings such as
> 'vm.vfs_cache_pressure = 200.' My understanding is that prefers
> aggressive inode reclaim, yet the code workaround here is to bypass XFS
> inode reclaim. Out of curiousity, have you reproduced this problem using
> the default vfs_cache_pressure value (or if so, possibly moving it in
> the other direction)?

Yes, we've tried that, it had about 0 influence.
Comment 8 bfoster 2017-02-15 18:09:10 UTC
On Wed, Feb 15, 2017 at 07:52:13PM +0300, Alexander Polakov wrote:
> On 02/15/2017 07:05 PM, Brian Foster wrote:
> > You're in inode reclaim, blocked on a memory allocation for an inode
> > buffer required to flush a dirty inode. I suppose this means that the
> > backing buffer for the inode has already been reclaimed and must be
> > re-read, which ideally wouldn't have occurred before the inode is
> > flushed.
> > 
> > > But it cannot get memory, because it's low (?). So it stays blocked.
> > > 
> > > Other processes do the same but they can't get past the mutex in
> > > xfs_reclaim_inodes_nr():
> > > 
> > ...
> > > Which finally leads to "Kernel panic - not syncing: Out of memory and no
> > > killable processes..." as no process is able to proceed.
> > > 
> > > I quickly hacked this:
> > > 
> > > diff --git a/fs/xfs/xfs_icache.c b/fs/xfs/xfs_icache.c
> > > index 9ef152b..8adfb0a 100644
> > > --- a/fs/xfs/xfs_icache.c
> > > +++ b/fs/xfs/xfs_icache.c
> > > @@ -1254,7 +1254,7 @@ struct xfs_inode *
> > >         xfs_reclaim_work_queue(mp);
> > >         xfs_ail_push_all(mp->m_ail);
> > > 
> > > -       return xfs_reclaim_inodes_ag(mp, SYNC_TRYLOCK | SYNC_WAIT,
> > > &nr_to_scan);
> > > +       return 0; // xfs_reclaim_inodes_ag(mp, SYNC_TRYLOCK | SYNC_WAIT,
> > > &nr_to_scan);
> > >  }
> > > 
> > 
> > So you've disabled inode reclaim completely...
> 
> I don't think this is correct. I disabled direct / kswapd reclaim.
> XFS uses background worker for async reclaim:
> 
> http://lxr.free-electrons.com/source/fs/xfs/xfs_icache.c#L178
> http://lxr.free-electrons.com/source/fs/xfs/xfs_super.c#L1534
> 

Ah, Ok. It sounds like this allows the reclaim thread to carry on into
other shrinkers and free up memory that way, perhaps. This sounds kind
of similar to the issue brought up previously here[1], but not quite the
same in that instead of backing off of locking to allow other shrinkers
to progress, we back off of memory allocations required to free up
inodes (memory).

In theory, I think something analogous to a trylock for inode to buffer
mappings that are no longer cached (or more specifically, cannot
currently be allocated) may work around this, but it's not immediately
clear to me whether that's a proper fix (it's also probably not a
trivial change either). I'm still kind of curious why we end up with
dirty inodes with reclaimed buffers. If this problem repeats, is it
always with a similar stack (i.e., reclaim -> xfs_iflush() ->
xfs_imap_to_bp())?

How many independent filesystems are you running this workload against?
Can you describe the workload in more detail?

...
> > The bz shows you have non-default vm settings such as
> > 'vm.vfs_cache_pressure = 200.' My understanding is that prefers
> > aggressive inode reclaim, yet the code workaround here is to bypass XFS
> > inode reclaim. Out of curiousity, have you reproduced this problem using
> > the default vfs_cache_pressure value (or if so, possibly moving it in
> > the other direction)?
> 
> Yes, we've tried that, it had about 0 influence.
> 

Which.. with what values? And by zero influence, do you simply mean the
stall still occurred or you have some other measurement of slab sizes or
some such that are unaffected?

Brian

> -- 
> Alexander Polakov | system software engineer | https://beget.com
> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
Comment 9 Alexander Polakov 2017-02-16 10:56:35 UTC
On 02/15/2017 09:09 PM, Brian Foster wrote:
> Ah, Ok. It sounds like this allows the reclaim thread to carry on into
> other shrinkers and free up memory that way, perhaps. This sounds kind
> of similar to the issue brought up previously here[1], but not quite the
> same in that instead of backing off of locking to allow other shrinkers
> to progress, we back off of memory allocations required to free up
> inodes (memory).
>
> In theory, I think something analogous to a trylock for inode to buffer
> mappings that are no longer cached (or more specifically, cannot
> currently be allocated) may work around this, but it's not immediately
> clear to me whether that's a proper fix (it's also probably not a
> trivial change either). I'm still kind of curious why we end up with
> dirty inodes with reclaimed buffers. If this problem repeats, is it
> always with a similar stack (i.e., reclaim -> xfs_iflush() ->
> xfs_imap_to_bp())?

Looks like it is.

> How many independent filesystems are you running this workload against?

storage9 : ~ [0] # mount|grep storage|grep xfs|wc -l
15
storage9 : ~ [0] # mount|grep storage|grep ext4|wc -l
44

> Can you describe the workload in more detail?

This is a backup server, we're running rsync. At night our production 
servers rsync their files to this server (a lot of small files).

> ...
>>> The bz shows you have non-default vm settings such as
>>> 'vm.vfs_cache_pressure = 200.' My understanding is that prefers
>>> aggressive inode reclaim, yet the code workaround here is to bypass XFS
>>> inode reclaim. Out of curiousity, have you reproduced this problem using
>>> the default vfs_cache_pressure value (or if so, possibly moving it in
>>> the other direction)?
>>
>> Yes, we've tried that, it had about 0 influence.
>>
>
> Which.. with what values? And by zero influence, do you simply mean the
> stall still occurred or you have some other measurement of slab sizes or
> some such that are unaffected?

Unfortunately I don't have slab statistics at hand. Stalls and following 
OOM situation still occured with this setting at 100.
Comment 10 bfoster 2017-02-16 17:20:39 UTC
On Thu, Feb 16, 2017 at 01:56:30PM +0300, Alexander Polakov wrote:
> On 02/15/2017 09:09 PM, Brian Foster wrote:
> > Ah, Ok. It sounds like this allows the reclaim thread to carry on into
> > other shrinkers and free up memory that way, perhaps. This sounds kind
> > of similar to the issue brought up previously here[1], but not quite the
> > same in that instead of backing off of locking to allow other shrinkers
> > to progress, we back off of memory allocations required to free up
> > inodes (memory).
> > 
> > In theory, I think something analogous to a trylock for inode to buffer
> > mappings that are no longer cached (or more specifically, cannot
> > currently be allocated) may work around this, but it's not immediately
> > clear to me whether that's a proper fix (it's also probably not a
> > trivial change either). I'm still kind of curious why we end up with
> > dirty inodes with reclaimed buffers. If this problem repeats, is it
> > always with a similar stack (i.e., reclaim -> xfs_iflush() ->
> > xfs_imap_to_bp())?
> 
> Looks like it is.
> 
> > How many independent filesystems are you running this workload against?
> 
> storage9 : ~ [0] # mount|grep storage|grep xfs|wc -l
> 15
> storage9 : ~ [0] # mount|grep storage|grep ext4|wc -l
> 44
> 

So a decent number of fs', more ext4 than XFS. Are the XFS fs' all of
similar size/geometry? If so, can you send representative xfs_info
output for the fs'?

I'm reading back through that reclaim thread[1] and it appears this
indeed is not a straightforward issue. It sounds like the summary is
Chris hit the same general behavior you have and is helped by bypassing
the synchronous nature of the shrinker. This allows other shrinkers to
proceed, but this is not a general solution because other workloads
depend on the synchronous shrinker behavior to throttle direct reclaim.
I can't say I understand all of the details and architecture of how/why
that is the case.

FWIW, it sounds like the first order problem is that we generally don't
want to find/flush dirty inodes from reclaim. A couple things that might
help avoid this situation are more aggressive
/proc/sys/fs/xfs/xfssyncd_centisecs tuning or perhaps considering a
smaller log size would cause more tail pushing pressure on the AIL
instead of pressure originating from memory reclaim. The latter might
not be so convenient if this is an already populated backup server,
though.

Beyond that, there's Chris' patch, another patch that Dave proposed[2],
and obviously your hack here to defer inode reclaim entirely to the
workqueue (I've CC'd Dave since it sounds like he might have been
working on this further..). Unfortunately, it sounds like [1] or your
hack aren't things we can pull into mainline for the time being until
the broader reclaim queueing/throttling mechanism is in place. I suppose
we might be able to revisit [2] if it actually does enough to prevent
this problem...

[1] http://www.spinics.net/lists/linux-xfs/msg01541.html
[2] http://www.spinics.net/lists/linux-xfs/msg02212.html

Brian

> > Can you describe the workload in more detail?
> 
> This is a backup server, we're running rsync. At night our production
> servers rsync their files to this server (a lot of small files).
> 
> > ...
> > > > The bz shows you have non-default vm settings such as
> > > > 'vm.vfs_cache_pressure = 200.' My understanding is that prefers
> > > > aggressive inode reclaim, yet the code workaround here is to bypass XFS
> > > > inode reclaim. Out of curiousity, have you reproduced this problem
> using
> > > > the default vfs_cache_pressure value (or if so, possibly moving it in
> > > > the other direction)?
> > > 
> > > Yes, we've tried that, it had about 0 influence.
> > > 
> > 
> > Which.. with what values? And by zero influence, do you simply mean the
> > stall still occurred or you have some other measurement of slab sizes or
> > some such that are unaffected?
> 
> Unfortunately I don't have slab statistics at hand. Stalls and following OOM
> situation still occured with this setting at 100.
> 
> -- 
> Alexander Polakov | system software engineer | https://beget.com
> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
Comment 11 Dave Chinner 2017-02-16 22:26:38 UTC
On Thu, Feb 16, 2017 at 12:20:34PM -0500, Brian Foster wrote:
> On Thu, Feb 16, 2017 at 01:56:30PM +0300, Alexander Polakov wrote:
> > On 02/15/2017 09:09 PM, Brian Foster wrote:
> > > Ah, Ok. It sounds like this allows the reclaim thread to carry on into
> > > other shrinkers and free up memory that way, perhaps. This sounds kind
> > > of similar to the issue brought up previously here[1], but not quite the
> > > same in that instead of backing off of locking to allow other shrinkers
> > > to progress, we back off of memory allocations required to free up
> > > inodes (memory).
> > > 
> > > In theory, I think something analogous to a trylock for inode to buffer
> > > mappings that are no longer cached (or more specifically, cannot
> > > currently be allocated) may work around this, but it's not immediately
> > > clear to me whether that's a proper fix (it's also probably not a
> > > trivial change either). I'm still kind of curious why we end up with
> > > dirty inodes with reclaimed buffers. If this problem repeats, is it
> > > always with a similar stack (i.e., reclaim -> xfs_iflush() ->
> > > xfs_imap_to_bp())?
> > 
> > Looks like it is.
> > 
> > > How many independent filesystems are you running this workload against?
> > 
> > storage9 : ~ [0] # mount|grep storage|grep xfs|wc -l
> > 15
> > storage9 : ~ [0] # mount|grep storage|grep ext4|wc -l
> > 44
> > 
> 
> So a decent number of fs', more ext4 than XFS. Are the XFS fs' all of
> similar size/geometry? If so, can you send representative xfs_info
> output for the fs'?
> 
> I'm reading back through that reclaim thread[1] and it appears this
> indeed is not a straightforward issue. It sounds like the summary is
> Chris hit the same general behavior you have and is helped by bypassing
> the synchronous nature of the shrinker. This allows other shrinkers to
> proceed, but this is not a general solution because other workloads
> depend on the synchronous shrinker behavior to throttle direct reclaim.
> I can't say I understand all of the details and architecture of how/why
> that is the case.

It's complicated, made worse by the state of flux of the mm reclaim
subsystem and the frequent regressions in behaviour that come and
go. This makes testing modifications to the shrinker behaviour
extremely challenging - trying to separate shirnker artifacts from
"something else has changed in memory reclaim" takes a lot of
time....

> FWIW, it sounds like the first order problem is that we generally don't
> want to find/flush dirty inodes from reclaim.

Right. because that forces out-of-order inode writeback and it
degenerates into blocking small random writes.

> A couple things that might
> help avoid this situation are more aggressive
> /proc/sys/fs/xfs/xfssyncd_centisecs tuning or perhaps considering a
> smaller log size would cause more tail pushing pressure on the AIL
> instead of pressure originating from memory reclaim. The latter might
> not be so convenient if this is an already populated backup server,
> though.
> 
> Beyond that, there's Chris' patch, another patch that Dave proposed[2],
> and obviously your hack here to defer inode reclaim entirely to the
> workqueue (I've CC'd Dave since it sounds like he might have been
> working on this further..).

I was working on a more solid set of changes, but every time I
updated the kernel tree I used as my base for development, the
baseline kernel reclaim behaviour would change. I'd isolate the
behavioural change, upgrade to the kernel that contained the fix,
and then trip over some new whacky behaviour that made no sense. I
spent more time in this loop than actually trying to fix the XFS
problem - chasing a moving target makes finding the root cause of
the reclaim stalls just about impossible. 

Brian, I can send you what I have but it's really just a bag of
bolts at this point because I was never able to validate that any of
the patches made a measurable improvement to reclaim behaviour under
any workload I ran.....

FWIW, the major problem with removing the blocking in inode reclaim
is the ease with which you can then trigger the OOM killer from
userspace.  The high level memory reclaim algorithms break down when
there are hundreds of direct reclaim processes hammering on reclaim
and reclaim stops making progress because it's skipping dirty
objects.  Direct reclaim ends up insufficiently throttled, so rather
than blocking it winds up reclaim priority and then declares OOM
because reclaim runs out of retries before sufficient memory has
been freed.

That, right now, looks to be an unsolvable problem without a major
rework of direct reclaim.  I've pretty much given up on ever getting
the unbound direct reclaim concurrency problem that is causing us
these problems fixed, so we are left to handle it in the subsystem
shrinkers as best we can. That leaves us with an unfortunate choice: 

	a) throttle excessive concurrency in the shrinker to prevent
	   IO breakdown, thereby causing reclaim latency bubbles
	   under load but having a stable, reliable system; or
	b) optimise for minimal reclaim latency and risk userspace
	   memory demand triggering the OOM killer whenever there
	   are lots of dirty inodes in the system.

Quite frankly, there's only one choice we can make in this
situation: reliability is always more important than performance.

Cheers,

Dave.
Comment 12 Tetsuo Handa 2017-02-17 11:46:37 UTC
On 2017/02/17 7:21, Dave Chinner wrote:
> FWIW, the major problem with removing the blocking in inode reclaim
> is the ease with which you can then trigger the OOM killer from
> userspace.  The high level memory reclaim algorithms break down when
> there are hundreds of direct reclaim processes hammering on reclaim
> and reclaim stops making progress because it's skipping dirty
> objects.  Direct reclaim ends up insufficiently throttled, so rather
> than blocking it winds up reclaim priority and then declares OOM
> because reclaim runs out of retries before sufficient memory has
> been freed.
> 
> That, right now, looks to be an unsolvable problem without a major
> rework of direct reclaim.  I've pretty much given up on ever getting
> the unbound direct reclaim concurrency problem that is causing us
> these problems fixed, so we are left to handle it in the subsystem
> shrinkers as best we can. That leaves us with an unfortunate choice: 
> 
>       a) throttle excessive concurrency in the shrinker to prevent
>          IO breakdown, thereby causing reclaim latency bubbles
>          under load but having a stable, reliable system; or
>       b) optimise for minimal reclaim latency and risk userspace
>          memory demand triggering the OOM killer whenever there
>          are lots of dirty inodes in the system.
> 
> Quite frankly, there's only one choice we can make in this
> situation: reliability is always more important than performance.

Is it possible to get rid of direct reclaim and let allocating thread
wait on queue? I wished such change in context of __GFP_KILLABLE at
http://lkml.kernel.org/r/201702012049.BAG95379.VJFFOHMStLQFOO@I-love.SAKURA.ne.jp .
Comment 13 bfoster 2017-02-17 19:05:04 UTC
On Fri, Feb 17, 2017 at 09:21:29AM +1100, Dave Chinner wrote:
> On Thu, Feb 16, 2017 at 12:20:34PM -0500, Brian Foster wrote:
> > On Thu, Feb 16, 2017 at 01:56:30PM +0300, Alexander Polakov wrote:
> > > On 02/15/2017 09:09 PM, Brian Foster wrote:
> > > > Ah, Ok. It sounds like this allows the reclaim thread to carry on into
> > > > other shrinkers and free up memory that way, perhaps. This sounds kind
> > > > of similar to the issue brought up previously here[1], but not quite
> the
> > > > same in that instead of backing off of locking to allow other shrinkers
> > > > to progress, we back off of memory allocations required to free up
> > > > inodes (memory).
> > > > 
> > > > In theory, I think something analogous to a trylock for inode to buffer
> > > > mappings that are no longer cached (or more specifically, cannot
> > > > currently be allocated) may work around this, but it's not immediately
> > > > clear to me whether that's a proper fix (it's also probably not a
> > > > trivial change either). I'm still kind of curious why we end up with
> > > > dirty inodes with reclaimed buffers. If this problem repeats, is it
> > > > always with a similar stack (i.e., reclaim -> xfs_iflush() ->
> > > > xfs_imap_to_bp())?
> > > 
> > > Looks like it is.
> > > 
> > > > How many independent filesystems are you running this workload against?
> > > 
> > > storage9 : ~ [0] # mount|grep storage|grep xfs|wc -l
> > > 15
> > > storage9 : ~ [0] # mount|grep storage|grep ext4|wc -l
> > > 44
> > > 
> > 
> > So a decent number of fs', more ext4 than XFS. Are the XFS fs' all of
> > similar size/geometry? If so, can you send representative xfs_info
> > output for the fs'?
> > 
> > I'm reading back through that reclaim thread[1] and it appears this
> > indeed is not a straightforward issue. It sounds like the summary is
> > Chris hit the same general behavior you have and is helped by bypassing
> > the synchronous nature of the shrinker. This allows other shrinkers to
> > proceed, but this is not a general solution because other workloads
> > depend on the synchronous shrinker behavior to throttle direct reclaim.
> > I can't say I understand all of the details and architecture of how/why
> > that is the case.
> 
> It's complicated, made worse by the state of flux of the mm reclaim
> subsystem and the frequent regressions in behaviour that come and
> go. This makes testing modifications to the shrinker behaviour
> extremely challenging - trying to separate shirnker artifacts from
> "something else has changed in memory reclaim" takes a lot of
> time....
> 
> > FWIW, it sounds like the first order problem is that we generally don't
> > want to find/flush dirty inodes from reclaim.
> 
> Right. because that forces out-of-order inode writeback and it
> degenerates into blocking small random writes.
> 
> > A couple things that might
> > help avoid this situation are more aggressive
> > /proc/sys/fs/xfs/xfssyncd_centisecs tuning or perhaps considering a
> > smaller log size would cause more tail pushing pressure on the AIL
> > instead of pressure originating from memory reclaim. The latter might
> > not be so convenient if this is an already populated backup server,
> > though.
> > 
> > Beyond that, there's Chris' patch, another patch that Dave proposed[2],
> > and obviously your hack here to defer inode reclaim entirely to the
> > workqueue (I've CC'd Dave since it sounds like he might have been
> > working on this further..).
> 
> I was working on a more solid set of changes, but every time I
> updated the kernel tree I used as my base for development, the
> baseline kernel reclaim behaviour would change. I'd isolate the
> behavioural change, upgrade to the kernel that contained the fix,
> and then trip over some new whacky behaviour that made no sense. I
> spent more time in this loop than actually trying to fix the XFS
> problem - chasing a moving target makes finding the root cause of
> the reclaim stalls just about impossible. 
> 
> Brian, I can send you what I have but it's really just a bag of
> bolts at this point because I was never able to validate that any of
> the patches made a measurable improvement to reclaim behaviour under
> any workload I ran.....
> 

Sure, I'm curious to see what direction this goes in. I would think
anything that provides a backoff to other shrinkers would help this
particular workload where many different filesystems are active. FWIW,
I'd probably also need more details about what workloads you're testing
and how you're measuring improvements and whatnot to try and take any of
that stuff any farther (particularly how you verify the problems with
dropping blocking behavior entirely), though..

> FWIW, the major problem with removing the blocking in inode reclaim
> is the ease with which you can then trigger the OOM killer from
> userspace.  The high level memory reclaim algorithms break down when
> there are hundreds of direct reclaim processes hammering on reclaim
> and reclaim stops making progress because it's skipping dirty
> objects.  Direct reclaim ends up insufficiently throttled, so rather
> than blocking it winds up reclaim priority and then declares OOM
> because reclaim runs out of retries before sufficient memory has
> been freed.
> 

I'd need to spend some time in the shrinker code to grok this, but if
there's such a priority, would switching blocking behavior based on
priority provide a way to mitigate this problem from within the
shrinker? For example, provide non-blocking behavior on the lowest
priority to kick off flushing and allow progress into other shrinkers,
otherwise we flush and wait if the priority is elevated..?

IOW, it sounds like the problem in this case is that we subject the rest
of the allocation infrastructure to delays in configurations where we
are one of N potential shrinkers with reclaimable objects, because we
have to deal with this situation where our one shrinker actually is the
main/primary choke point for multiple allocator -> direct reclaimers.
I'm wondering if some kind of severity parameter managed by the shrinker
infra would help us distinguish between those scenarios (even if it were
a dumb LOW/HIGH priority param, where LOW allows for one pass through
all of the shrinkers to kick off I/O and whatnot before any one of them
should actually block on locks or I/O). Then again, I'm just handwaving
as I'm only just familiarizing with the context and problem.

(I also see no priority in struct shrink_control, so I guess that's an
internal reclaim thing as it is.)

> That, right now, looks to be an unsolvable problem without a major
> rework of direct reclaim.  I've pretty much given up on ever getting
> the unbound direct reclaim concurrency problem that is causing us
> these problems fixed, so we are left to handle it in the subsystem
> shrinkers as best we can. That leaves us with an unfortunate choice: 
> 
>       a) throttle excessive concurrency in the shrinker to prevent
>          IO breakdown, thereby causing reclaim latency bubbles
>          under load but having a stable, reliable system; or
>       b) optimise for minimal reclaim latency and risk userspace
>          memory demand triggering the OOM killer whenever there
>          are lots of dirty inodes in the system.
> 
> Quite frankly, there's only one choice we can make in this
> situation: reliability is always more important than performance.
> 

Indeed, that certainly makes sense. Thanks.

Brian

> Cheers,
> 
> Dave.
> -- 
> Dave Chinner
> david@fromorbit.com
> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
Comment 14 Dave Chinner 2017-02-17 23:52:51 UTC
On Fri, Feb 17, 2017 at 02:05:00PM -0500, Brian Foster wrote:
> On Fri, Feb 17, 2017 at 09:21:29AM +1100, Dave Chinner wrote:
> > On Thu, Feb 16, 2017 at 12:20:34PM -0500, Brian Foster wrote:
> > > A couple things that might
> > > help avoid this situation are more aggressive
> > > /proc/sys/fs/xfs/xfssyncd_centisecs tuning or perhaps considering a
> > > smaller log size would cause more tail pushing pressure on the AIL
> > > instead of pressure originating from memory reclaim. The latter might
> > > not be so convenient if this is an already populated backup server,
> > > though.
> > > 
> > > Beyond that, there's Chris' patch, another patch that Dave proposed[2],
> > > and obviously your hack here to defer inode reclaim entirely to the
> > > workqueue (I've CC'd Dave since it sounds like he might have been
> > > working on this further..).
> > 
> > I was working on a more solid set of changes, but every time I
> > updated the kernel tree I used as my base for development, the
> > baseline kernel reclaim behaviour would change. I'd isolate the
> > behavioural change, upgrade to the kernel that contained the fix,
> > and then trip over some new whacky behaviour that made no sense. I
> > spent more time in this loop than actually trying to fix the XFS
> > problem - chasing a moving target makes finding the root cause of
> > the reclaim stalls just about impossible. 
> > 
> > Brian, I can send you what I have but it's really just a bag of
> > bolts at this point because I was never able to validate that any of
> > the patches made a measurable improvement to reclaim behaviour under
> > any workload I ran.....
> > 
> 
> Sure, I'm curious to see what direction this goes in. I would think
> anything that provides a backoff to other shrinkers would help this
> particular workload where many different filesystems are active. FWIW,
> I'd probably also need more details about what workloads you're testing
> and how you're measuring improvements and whatnot to try and take any of
> that stuff any farther (particularly how you verify the problems with
> dropping blocking behavior entirely), though..

Ok, I'll send you a copy...

> > FWIW, the major problem with removing the blocking in inode reclaim
> > is the ease with which you can then trigger the OOM killer from
> > userspace.  The high level memory reclaim algorithms break down when
> > there are hundreds of direct reclaim processes hammering on reclaim
> > and reclaim stops making progress because it's skipping dirty
> > objects.  Direct reclaim ends up insufficiently throttled, so rather
> > than blocking it winds up reclaim priority and then declares OOM
> > because reclaim runs out of retries before sufficient memory has
> > been freed.
> > 
> 
> I'd need to spend some time in the shrinker code to grok this, but if
> there's such a priority, would switching blocking behavior based on
> priority provide a way to mitigate this problem from within the
> shrinker? For example, provide non-blocking behavior on the lowest
> priority to kick off flushing and allow progress into other shrinkers,
> otherwise we flush and wait if the priority is elevated..?

I tried that - exporting the priority to the shrink_control and so
on. The system either behaved the same (i.e. stalled on reclaim) or
randomly fell into a screaming pile of OOM killer rage-death. There
was no in-between reliable state...

> IOW, it sounds like the problem in this case is that we subject the rest
> of the allocation infrastructure to delays in configurations where we
> are one of N potential shrinkers with reclaimable objects, because we
> have to deal with this situation where our one shrinker actually is the
> main/primary choke point for multiple allocator -> direct reclaimers.

Yup. The mm reclaim design sucks ass because if we use purely
non-blocking reclaim techniques in the shrinkers we have no way of
throttling allocation demand to the rate at which shrinkers can
reclaim objects and we end up with gross cache imbalances under
memory pressure.

> I'm wondering if some kind of severity parameter managed by the shrinker
> infra would help us distinguish between those scenarios (even if it were
> a dumb LOW/HIGH priority param, where LOW allows for one pass through
> all of the shrinkers to kick off I/O and whatnot before any one of them
> should actually block on locks or I/O). Then again, I'm just handwaving
> as I'm only just familiarizing with the context and problem.

Tried that, too. :( Several different ways over the past few years.
Remember that we also have the non-blocking background reclaim
thread - even triggering that immediately on reclaim doesn't
prevent stalls, and my last patchset specifically excluded it
from concurrency control so it always ran immediately on reclaim

Hmmm - I just had a thought.

Perhaps all we need to do is remove direct reclaim from the
shrinker. i.e. make the background reclaimer run on a ticket based
queuing system similar to the log reservations...

For non-blocking reclaim (i.e.  kswapd), we just queue the ticket
and return immediately, saying we've done the scan. 

For blocking reclaim, we take a ticket with the blocking scan count
on it and wait in the wakeup queue.  As background reclaim runs, it
decrements the lead ticket scan count. When it hits zero, wake up
the head of the wait queue. When the background thread has no
pending reclaim tickets or has nothing left to scan/reclaim (i.e.
goes idle), wake everyone....

This means waiting is ordered, it doesn't matter where in the fs we
reclaim from, direct reclaim itself doesn't get stuck waiting for
IO/transactions/log flushing, concurrency is managed by how we
process the ticket queue, and when we have lots of direct reclaim
demand then the background thread just keeps running as optimally as
possible and kswapd is never blocked...

> (I also see no priority in struct shrink_control, so I guess that's an
> internal reclaim thing as it is.)

Yup, I had to promote it all the way through from the struct
scan_control -> priority field.

Cheers,

Dave.
Comment 15 Dave Chinner 2017-02-17 23:58:10 UTC
On Fri, Feb 17, 2017 at 08:11:09PM +0900, Tetsuo Handa wrote:
> On 2017/02/17 7:21, Dave Chinner wrote:
> > FWIW, the major problem with removing the blocking in inode reclaim
> > is the ease with which you can then trigger the OOM killer from
> > userspace.  The high level memory reclaim algorithms break down when
> > there are hundreds of direct reclaim processes hammering on reclaim
> > and reclaim stops making progress because it's skipping dirty
> > objects.  Direct reclaim ends up insufficiently throttled, so rather
> > than blocking it winds up reclaim priority and then declares OOM
> > because reclaim runs out of retries before sufficient memory has
> > been freed.
> > 
> > That, right now, looks to be an unsolvable problem without a major
> > rework of direct reclaim.  I've pretty much given up on ever getting
> > the unbound direct reclaim concurrency problem that is causing us
> > these problems fixed, so we are left to handle it in the subsystem
> > shrinkers as best we can. That leaves us with an unfortunate choice: 
> > 
> >     a) throttle excessive concurrency in the shrinker to prevent
> >        IO breakdown, thereby causing reclaim latency bubbles
> >        under load but having a stable, reliable system; or
> >     b) optimise for minimal reclaim latency and risk userspace
> >        memory demand triggering the OOM killer whenever there
> >        are lots of dirty inodes in the system.
> > 
> > Quite frankly, there's only one choice we can make in this
> > situation: reliability is always more important than performance.
> 
> Is it possible to get rid of direct reclaim and let allocating thread
> wait on queue? I wished such change in context of __GFP_KILLABLE at
>
> http://lkml.kernel.org/r/201702012049.BAG95379.VJFFOHMStLQFOO@I-love.SAKURA.ne.jp
> .

Yup, that's similar to what I've been suggesting - offloading the
direct reclaim slowpath to a limited set of kswapd-like workers
and blocking the allocating processes until there is either memory
for them or OOM is declared...

Cheers,

Dave.
Comment 16 bfoster 2017-02-18 13:05:26 UTC
On Sat, Feb 18, 2017 at 10:52:45AM +1100, Dave Chinner wrote:
> On Fri, Feb 17, 2017 at 02:05:00PM -0500, Brian Foster wrote:
> > On Fri, Feb 17, 2017 at 09:21:29AM +1100, Dave Chinner wrote:
> > > On Thu, Feb 16, 2017 at 12:20:34PM -0500, Brian Foster wrote:
> > > > A couple things that might
> > > > help avoid this situation are more aggressive
> > > > /proc/sys/fs/xfs/xfssyncd_centisecs tuning or perhaps considering a
> > > > smaller log size would cause more tail pushing pressure on the AIL
> > > > instead of pressure originating from memory reclaim. The latter might
> > > > not be so convenient if this is an already populated backup server,
> > > > though.
> > > > 
> > > > Beyond that, there's Chris' patch, another patch that Dave proposed[2],
> > > > and obviously your hack here to defer inode reclaim entirely to the
> > > > workqueue (I've CC'd Dave since it sounds like he might have been
> > > > working on this further..).
> > > 
> > > I was working on a more solid set of changes, but every time I
> > > updated the kernel tree I used as my base for development, the
> > > baseline kernel reclaim behaviour would change. I'd isolate the
> > > behavioural change, upgrade to the kernel that contained the fix,
> > > and then trip over some new whacky behaviour that made no sense. I
> > > spent more time in this loop than actually trying to fix the XFS
> > > problem - chasing a moving target makes finding the root cause of
> > > the reclaim stalls just about impossible. 
> > > 
> > > Brian, I can send you what I have but it's really just a bag of
> > > bolts at this point because I was never able to validate that any of
> > > the patches made a measurable improvement to reclaim behaviour under
> > > any workload I ran.....
> > > 
> > 
> > Sure, I'm curious to see what direction this goes in. I would think
> > anything that provides a backoff to other shrinkers would help this
> > particular workload where many different filesystems are active. FWIW,
> > I'd probably also need more details about what workloads you're testing
> > and how you're measuring improvements and whatnot to try and take any of
> > that stuff any farther (particularly how you verify the problems with
> > dropping blocking behavior entirely), though..
> 
> Ok, I'll send you a copy...
> 

Thanks.

> > > FWIW, the major problem with removing the blocking in inode reclaim
> > > is the ease with which you can then trigger the OOM killer from
> > > userspace.  The high level memory reclaim algorithms break down when
> > > there are hundreds of direct reclaim processes hammering on reclaim
> > > and reclaim stops making progress because it's skipping dirty
> > > objects.  Direct reclaim ends up insufficiently throttled, so rather
> > > than blocking it winds up reclaim priority and then declares OOM
> > > because reclaim runs out of retries before sufficient memory has
> > > been freed.
> > > 
> > 
> > I'd need to spend some time in the shrinker code to grok this, but if
> > there's such a priority, would switching blocking behavior based on
> > priority provide a way to mitigate this problem from within the
> > shrinker? For example, provide non-blocking behavior on the lowest
> > priority to kick off flushing and allow progress into other shrinkers,
> > otherwise we flush and wait if the priority is elevated..?
> 
> I tried that - exporting the priority to the shrink_control and so
> on. The system either behaved the same (i.e. stalled on reclaim) or
> randomly fell into a screaming pile of OOM killer rage-death. There
> was no in-between reliable state...
> 

Hmm, Ok, well at least I'm not completely off the rails then. :)

> > IOW, it sounds like the problem in this case is that we subject the rest
> > of the allocation infrastructure to delays in configurations where we
> > are one of N potential shrinkers with reclaimable objects, because we
> > have to deal with this situation where our one shrinker actually is the
> > main/primary choke point for multiple allocator -> direct reclaimers.
> 
> Yup. The mm reclaim design sucks ass because if we use purely
> non-blocking reclaim techniques in the shrinkers we have no way of
> throttling allocation demand to the rate at which shrinkers can
> reclaim objects and we end up with gross cache imbalances under
> memory pressure.
> 
> > I'm wondering if some kind of severity parameter managed by the shrinker
> > infra would help us distinguish between those scenarios (even if it were
> > a dumb LOW/HIGH priority param, where LOW allows for one pass through
> > all of the shrinkers to kick off I/O and whatnot before any one of them
> > should actually block on locks or I/O). Then again, I'm just handwaving
> > as I'm only just familiarizing with the context and problem.
> 
> Tried that, too. :( Several different ways over the past few years.
> Remember that we also have the non-blocking background reclaim
> thread - even triggering that immediately on reclaim doesn't
> prevent stalls, and my last patchset specifically excluded it
> from concurrency control so it always ran immediately on reclaim
> 
> Hmmm - I just had a thought.
> 
> Perhaps all we need to do is remove direct reclaim from the
> shrinker. i.e. make the background reclaimer run on a ticket based
> queuing system similar to the log reservations...
> 
> For non-blocking reclaim (i.e.  kswapd), we just queue the ticket
> and return immediately, saying we've done the scan. 
> 
> For blocking reclaim, we take a ticket with the blocking scan count
> on it and wait in the wakeup queue.  As background reclaim runs, it
> decrements the lead ticket scan count. When it hits zero, wake up
> the head of the wait queue. When the background thread has no
> pending reclaim tickets or has nothing left to scan/reclaim (i.e.
> goes idle), wake everyone....
> 
> This means waiting is ordered, it doesn't matter where in the fs we
> reclaim from, direct reclaim itself doesn't get stuck waiting for
> IO/transactions/log flushing, concurrency is managed by how we
> process the ticket queue, and when we have lots of direct reclaim
> demand then the background thread just keeps running as optimally as
> possible and kswapd is never blocked...
> 

Interesting.. IIUC, what this adds is smarter waiting logic by mapping
actual calling behavior into the shrinker to underlying reclaim
progress, rather than relying on whatever higher level priority is
calculated in the shrinker mechanism..? Sounds like a neat idea...

Brian

> > (I also see no priority in struct shrink_control, so I guess that's an
> > internal reclaim thing as it is.)
> 
> Yup, I had to promote it all the way through from the struct
> scan_control -> priority field.
> 
> Cheers,
> 
> Dave.
> 
> -- 
> Dave Chinner
> david@fromorbit.com
Comment 17 FF9988 2018-01-31 05:37:27 UTC
how to fix this issue? 

i have encounter this issue on my ubuntu system which run Linux 4.12 kernel.


Jan 31 16:53:21 figo-OptiPlex-9020 NetworkManager[1144]: <info>  [1517388801.3832] dhcp4 (eth0): state changed bound -> bound
Jan 31 19:14:36 figo-OptiPlex-9020 kernel: [424561.870060] gcc: page allocation stalls for 10100ms, order:0, mode:0x14280ca(GFP_HIGHUSER_MOVABLE|__GFP_ZERO), nodemask=(null)
Jan 31 19:15:07 figo-OptiPlex-9020 kernel: [424561.870066] gcc cpuset=/ mems_allowed=0
Jan 31 19:15:08 figo-OptiPlex-9020 kernel: [424561.870070] CPU: 3 PID: 26281 Comm: gcc Not tainted 4.12.0 #1
Jan 31 19:15:08 figo-OptiPlex-9020 kernel: [424561.870070] Hardware name: Dell Inc. OptiPlex 9020/0DNKMN, BIOS A05 12/05/2013
Jan 31 19:15:08 figo-OptiPlex-9020 kernel: [424561.870071] Call Trace:
Jan 31 19:15:08 figo-OptiPlex-9020 kernel: [424561.870077]  dump_stack+0x63/0x82
Jan 31 19:15:08 figo-OptiPlex-9020 kernel: [424561.870080]  warn_alloc+0x114/0x1b0
Jan 31 19:15:08 figo-OptiPlex-9020 kernel: [424561.870081]  __alloc_pages_slowpath+0x919/0xd90
Jan 31 19:15:08 figo-OptiPlex-9020 kernel: [424561.870084]  __alloc_pages_nodemask+0x245/0x260
Jan 31 19:15:08 figo-OptiPlex-9020 kernel: [424561.870085]  alloc_pages_vma+0xa2/0x270
Jan 31 19:15:08 figo-OptiPlex-9020 kernel: [424561.870090]  __handle_mm_fault+0xc20/0xfd0
Jan 31 19:15:09 figo-OptiPlex-9020 kernel: [424561.870092]  handle_mm_fault+0xf3/0x210
Jan 31 19:15:09 figo-OptiPlex-9020 kernel: [424561.870095]  __do_page_fault+0x240/0x4e0
Jan 31 19:15:09 figo-OptiPlex-9020 kernel: [424561.870097]  do_page_fault+0x22/0x30
Jan 31 19:15:09 figo-OptiPlex-9020 kernel: [424561.870101]  page_fault+0x28/0x30
Jan 31 19:15:09 figo-OptiPlex-9020 kernel: [424561.870103] RIP: 0033:0x7eff4fbb5786
Jan 31 19:15:09 figo-OptiPlex-9020 kernel: [424561.870104] RSP: 002b:00007ffcc8a349d0 EFLAGS: 00010202
Jan 31 19:15:12 figo-OptiPlex-9020 kernel: [424561.870105] RAX: 0000000000012a71 RBX: 00007eff4fef7b20 RCX: 0000000000000ff1
Jan 31 19:15:12 figo-OptiPlex-9020 kernel: [424561.870106] RDX: 00000000008bf5a0 RSI: 00000000008c0590 RDI: 0000000000000003
Jan 31 19:15:12 figo-OptiPlex-9020 kernel: [424561.870106] RBP: 0000000000000ff1 R08: 0000000000402620 R09: 000000000000000f
Jan 31 19:15:12 figo-OptiPlex-9020 kernel: [424561.870107] R10: 0000000000000001 R11: 0000000000000007 R12: 00007eff4fef7b78
Jan 31 19:15:12 figo-OptiPlex-9020 kernel: [424561.870108] R13: 00007eff4fef7b78 R14: 0000000000002710 R15: 0000000000000000
Jan 31 19:15:12 figo-OptiPlex-9020 kernel: [424561.870109] Mem-Info:
Jan 31 19:15:12 figo-OptiPlex-9020 kernel: [424561.870113] active_anon:1115156 inactive_anon:237168 isolated_anon:4097
Jan 31 19:15:12 figo-OptiPlex-9020 kernel: [424561.870113]  active_file:7103 inactive_file:3389 isolated_file:0
Jan 31 19:15:12 figo-OptiPlex-9020 kernel: [424561.870113]  unevictable:8 dirty:73 writeback:13149 unstable:0
Jan 31 19:15:12 figo-OptiPlex-9020 kernel: [424561.870113]  slab_reclaimable:13253 slab_unreclaimable:13798
Jan 31 19:15:12 figo-OptiPlex-9020 kernel: [424561.870113]  mapped:35303 shmem:260993 pagetables:23015 bounce:0
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870113]  free:23154 free_pcp:0 free_cma:0
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870115] Node 0 active_anon:4460624kB inactive_anon:948672kB active_file:28412kB inactive_file:13556kB unevictable:32kB isolated(anon):16388kB isolated(file):0kB mapped:141212kB dirty:292kB writeback:52596kB shmem:1043972kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 600064kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870116] Node 0 DMA free:15884kB min:140kB low:172kB high:204kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15984kB managed:15900kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:16kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870119] lowmem_reserve[]: 0 2966 5379 5379 5379
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870122] Node 0 DMA32 free:36316kB min:26936kB low:33668kB high:40400kB active_anon:2422096kB inactive_anon:797672kB active_file:8240kB inactive_file:9040kB unevictable:0kB writepending:43296kB present:3578492kB managed:3366332kB mlocked:0kB slab_reclaimable:14740kB slab_unreclaimable:12008kB kernel_stack:5892kB pagetables:33288kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870125] lowmem_reserve[]: 0 0 2412 2412 2412
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870127] Node 0 Normal free:40416kB min:40500kB low:50624kB high:60748kB active_anon:2036736kB inactive_anon:154336kB active_file:20172kB inactive_file:4516kB unevictable:32kB writepending:9416kB present:4700160kB managed:4567364kB mlocked:32kB slab_reclaimable:38272kB slab_unreclaimable:43168kB kernel_stack:15436kB pagetables:58772kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870130] lowmem_reserve[]: 0 0 0 0 0
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870133] Node 0 DMA: 1*4kB (U) 1*8kB (U) 0*16kB 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15884kB
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870141] Node 0 DMA32: 140*4kB (UME) 180*8kB (UME) 144*16kB (UME) 115*32kB (UME) 66*64kB (UME) 29*128kB (UME) 67*256kB (ME) 5*512kB (M) 0*1024kB 0*2048kB 0*4096kB = 35632kB
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870150] Node 0 Normal: 765*4kB (UMEH) 367*8kB (UMEH) 1004*16kB (UMEH) 172*32kB (UMEH) 78*64kB (UMEH) 39*128kB (UMEH) 19*256kB (UMEH) 1*512kB (H) 0*1024kB 0*2048kB 0*4096kB = 42924kB
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870160] Node 0 hugepages_total=2 hugepages_free=2 hugepages_surp=0 hugepages_size=1048576kB
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870161] 286218 total pagecache pages
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870164] 14738 pages in swap cache
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870165] Swap cache stats: add 510375, delete 495542, find 646/774
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870165] Free swap  = 14549500kB
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870166] Total swap = 16586748kB
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870166] 2073659 pages RAM
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870167] 0 pages HighMem/MovableOnly
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870167] 86260 pages reserved
Jan 31 19:15:14 figo-OptiPlex-9020 kernel: [424561.870168] 0 pages cma reserved
Jan 31 19:15:15 figo-OptiPlex-9020 kernel: [424561.870168] 0 pages hwpoisoned
Comment 18 FF9988 2018-01-31 05:38:20 UTC
Created attachment 273939 [details]
memory alloc failure on Linux 4.12

memory alloc failure on Linux 4.12
Comment 19 Denis Roy 2020-05-01 13:09:03 UTC
We're seeing this as well, on an NFS server with XFS and heavy disk I/O


Apr 30 14:23:43 fred kernel: nfsd: page allocation stalls for 10296ms, order:1, mode:0x1604040(GFP_NOFS|__GFP_COMP|__GFP_NOTRACK), nodemask=(null)
Apr 30 14:23:43 fred kernel: nfsd cpuset=/ mems_allowed=0
Apr 30 14:23:43 fred kernel: CPU: 11 PID: 3094 Comm: nfsd Not tainted 4.12.14-197.37-default #1 SLE15-SP1
Apr 30 14:23:43 fred kernel: Hardware name: Supermicro Super Server/X11SPi-TF, BIOS 3.2 10/17/2019
Apr 30 14:23:43 fred kernel: Call Trace:
Apr 30 14:23:43 fred kernel:  dump_stack+0x5c/0x86
Apr 30 14:23:43 fred kernel:  warn_alloc+0xe0/0x170
Apr 30 14:23:43 fred kernel:  __alloc_pages_slowpath+0x7e4/0xc10
Apr 30 14:23:43 fred kernel:  __alloc_pages_nodemask+0x21f/0x250
Apr 30 14:23:43 fred kernel:  cache_grow_begin+0x8d/0x550
Apr 30 14:23:43 fred kernel:  fallback_alloc+0x160/0x200
Apr 30 14:23:43 fred kernel:  ? kmem_alloc+0x55/0xd0 [xfs]
Apr 30 14:23:43 fred kernel:  __kmalloc+0x1c0/0x5a0
Apr 30 14:23:43 fred kernel:  ? xfs_buf_item_size_segment.isra.5+0x5d/0xc0 [xfs]
Apr 30 14:23:43 fred kernel:  kmem_alloc+0x55/0xd0 [xfs]
Apr 30 14:23:43 fred kernel:  xfs_log_commit_cil+0x12a/0x5e0 [xfs]
Apr 30 14:23:43 fred kernel:  __xfs_trans_commit+0x60/0x260 [xfs]
Apr 30 14:23:43 fred kernel:  xfs_trans_roll+0x38/0x60 [xfs]
Apr 30 14:23:43 fred kernel:  xfs_trans_roll_inode+0x26/0x50 [xfs]
Apr 30 14:23:43 fred kernel:  xfs_itruncate_extents+0x108/0x290 [xfs]
Apr 30 14:23:43 fred kernel:  xfs_inactive_truncate+0x7c/0xc0 [xfs]
Apr 30 14:23:43 fred kernel:  xfs_inactive+0xeb/0x100 [xfs]
Apr 30 14:23:43 fred kernel:  xfs_fs_destroy_inode+0xb2/0x220 [xfs]
Apr 30 14:23:43 fred kernel:  d_delete+0xa3/0xc0
Apr 30 14:23:43 fred kernel:  vfs_unlink+0x16b/0x1a0
Apr 30 14:23:43 fred kernel:  nfsd_unlink+0x19d/0x260 [nfsd]
Apr 30 14:23:43 fred kernel:  nfsd3_proc_remove+0x63/0xf0 [nfsd]
Apr 30 14:23:43 fred kernel:  nfsd_dispatch+0x10a/0x240 [nfsd]
Apr 30 14:23:43 fred kernel:  svc_process_common+0x374/0x7a0 [sunrpc]
Apr 30 14:23:43 fred kernel:  ? nfsd_destroy+0x60/0x60 [nfsd]
Apr 30 14:23:43 fred kernel:  svc_process+0xe4/0x190 [sunrpc]
Apr 30 14:23:43 fred kernel:  nfsd+0xe3/0x150 [nfsd]
Apr 30 14:23:43 fred kernel:  kthread+0x10d/0x130
Apr 30 14:23:43 fred kernel:  ? kthread_create_worker_on_cpu+0x50/0x50
Apr 30 14:23:43 fred kernel:  ret_from_fork+0x1f/0x40
Apr 30 14:23:43 fred kernel: warn_alloc_show_mem: 2 callbacks suppressed
Apr 30 14:23:43 fred kernel: Mem-Info:
Apr 30 14:23:43 fred kernel: active_anon:2180969 inactive_anon:260108 isolated_anon:0
                              active_file:10795361 inactive_file:539873 isolated_file:0
                              unevictable:4925 dirty:4896 writeback:0 unstable:0
                              slab_reclaimable:6412624 slab_unreclaimable:1026711
                              mapped:155700 shmem:263168 pagetables:7943 bounce:0
                              free:328347 free_pcp:0 free_cma:0
Apr 30 14:23:43 fred kernel: Node 0 active_anon:8723876kB inactive_anon:1040432kB active_file:43181444kB inactive_file:2159492kB unevictable:19700kB isolated(anon):0kB isolated(file):0kB mapped:622800kB dirty:19584kB writeback:0kB shmem>
Apr 30 14:23:43 fred kernel: Node 0 DMA free:15844kB min:8kB low:20kB high:32kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15928kB managed:15844kB mlocked:0kB slab_reclai>
Apr 30 14:23:43 fred kernel: lowmem_reserve[]: 0 1550 95035 95035 95035
Apr 30 14:23:43 fred kernel: Node 0 DMA32 free:376924kB min:1092kB low:2668kB high:4244kB active_anon:340272kB inactive_anon:363648kB active_file:287996kB inactive_file:14324kB unevictable:0kB writepending:0kB present:1726728kB managed:>
Apr 30 14:23:43 fred kernel: lowmem_reserve[]: 0 0 93485 93485 93485
Apr 30 14:23:43 fred kernel: Node 0 Normal free:920620kB min:324392kB low:420112kB high:515832kB active_anon:8383604kB inactive_anon:676784kB active_file:42893568kB inactive_file:2145168kB unevictable:19700kB writepending:19580kB presen>
Apr 30 14:23:43 fred kernel: lowmem_reserve[]: 0 0 0 0 0
Apr 30 14:23:43 fred kernel: Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 1*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15844kB
Apr 30 14:23:43 fred kernel: Node 0 DMA32: 7819*4kB (UMEH) 10186*8kB (UMEH) 4392*16kB (UMEH) 1305*32kB (UMEH) 577*64kB (UMEH) 268*128kB (UMEH) 146*256kB (UM) 71*512kB (UM) 7*1024kB (UM) 0*2048kB 0*4096kB = 376924kB
Apr 30 14:23:43 fred kernel: Node 0 Normal: 121787*4kB (UMEH) 39081*8kB (UMEH) 7184*16kB (UMEH) 231*32kB (UMEH) 20*64kB (UMEH) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 923412kB
Apr 30 14:23:43 fred kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Apr 30 14:23:43 fred kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Apr 30 14:23:43 fred kernel: 11618134 total pagecache pages
Apr 30 14:23:43 fred kernel: 17392 pages in swap cache
Apr 30 14:23:43 fred kernel: Swap cache stats: add 203674, delete 186383, find 1927779/1929638
Apr 30 14:23:43 fred kernel: Free swap  = 255740kB
Apr 30 14:23:43 fred kernel: Total swap = 1048572kB
Apr 30 14:23:43 fred kernel: 24815056 pages RAM
Apr 30 14:23:43 fred kernel: 0 pages HighMem/MovableOnly
Apr 30 14:23:43 fred kernel: 482004 pages reserved
Apr 30 14:23:43 fred kernel: 0 pages hwpoisoned
Comment 20 Luis Chamberlain 2020-05-01 16:57:55 UTC
(In reply to Denis Roy from comment #19)
> 4.12.14-197.37-default #1 SLE15-SP1

A few things. First 4.12 is not long term, try 4.19 if you want to report an issue against a stable kernel as that is the first kernel we're striving to do stable fixes for. Second, I see SEL15-SP1 is used, open up a bug with SUSE, I'm certain that can be addressed through their support channels as the kernels can vary from anything mainline.

Note You need to log in before you can comment on or make changes to this bug.