All of lore.kernel.org
 help / color / mirror / Atom feed
From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
To: bfoster@redhat.com
Cc: mhocko@kernel.org, linux-xfs@vger.kernel.org, linux-mm@kvack.org
Subject: Re: How to favor memory allocations for WQ_MEM_RECLAIM threads?
Date: Tue, 7 Mar 2017 01:08:24 +0900	[thread overview]
Message-ID: <201703070108.DFD48978.SMOVJHFFLFtOOQ@I-love.SAKURA.ne.jp> (raw)
In-Reply-To: <20170306132517.GB3223@bfoster.bfoster>

Brian Foster wrote:
> As noted in my previous reply, I'm not sure there's enough here to point
> at allocation failure as the root cause. E.g., kswapd is stuck here:
> 
> [ 1095.632985] kswapd0         D10776    69      2 0x00000000
> [ 1095.632988] Call Trace:
> [ 1095.632991]  __schedule+0x336/0xe00
> [ 1095.632994]  schedule+0x3d/0x90
> [ 1095.632996]  io_schedule+0x16/0x40
> [ 1095.633017]  __xfs_iflock+0x129/0x140 [xfs]
> [ 1095.633021]  ? autoremove_wake_function+0x60/0x60
> [ 1095.633051]  xfs_reclaim_inode+0x162/0x440 [xfs]
> [ 1095.633072]  xfs_reclaim_inodes_ag+0x2cf/0x4f0 [xfs]
> [ 1095.633106]  ? xfs_reclaim_inodes_ag+0xf2/0x4f0 [xfs]
> [ 1095.633114]  ? trace_hardirqs_on+0xd/0x10
> [ 1095.633116]  ? try_to_wake_up+0x59/0x7a0
> [ 1095.633120]  ? wake_up_process+0x15/0x20
> [ 1095.633156]  xfs_reclaim_inodes_nr+0x33/0x40 [xfs]
> [ 1095.633178]  xfs_fs_free_cached_objects+0x19/0x20 [xfs]
> [ 1095.633180]  super_cache_scan+0x181/0x190
> [ 1095.633183]  shrink_slab+0x29f/0x6d0
> [ 1095.633189]  shrink_node+0x2fa/0x310
> [ 1095.633193]  kswapd+0x362/0x9b0
> [ 1095.633200]  kthread+0x10f/0x150
> [ 1095.633201]  ? mem_cgroup_shrink_node+0x3b0/0x3b0
> [ 1095.633202]  ? kthread_create_on_node+0x70/0x70
> [ 1095.633205]  ret_from_fork+0x31/0x40
> 
> ... which is waiting on an inode flush lock. It can't get the lock
> (presumably) because xfsaild has it:
> 
> [ 1041.772095] xfsaild/sda1    D13216   457      2 0x00000000
> [ 1041.773726] Call Trace:
> [ 1041.774734]  __schedule+0x336/0xe00
> [ 1041.775956]  schedule+0x3d/0x90
> [ 1041.777105]  schedule_timeout+0x26a/0x510
> [ 1041.778426]  ? wait_for_completion+0x4c/0x190
> [ 1041.779824]  wait_for_completion+0x12c/0x190
> [ 1041.781273]  ? wake_up_q+0x80/0x80
> [ 1041.782597]  ? _xfs_buf_read+0x44/0x90 [xfs]
> [ 1041.784086]  xfs_buf_submit_wait+0xe9/0x5c0 [xfs]
> [ 1041.785659]  _xfs_buf_read+0x44/0x90 [xfs]
> [ 1041.787067]  xfs_buf_read_map+0xfa/0x400 [xfs]
> [ 1041.788501]  ? xfs_trans_read_buf_map+0x186/0x830 [xfs]
> [ 1041.790103]  xfs_trans_read_buf_map+0x186/0x830 [xfs]
> [ 1041.791672]  xfs_imap_to_bp+0x71/0x110 [xfs]
> [ 1041.793090]  xfs_iflush+0x122/0x3b0 [xfs]
> [ 1041.794444]  xfs_inode_item_push+0x108/0x1c0 [xfs]
> [ 1041.795956]  xfsaild_push+0x1d8/0xb70 [xfs]
> [ 1041.797344]  xfsaild+0x150/0x270 [xfs]
> [ 1041.798623]  kthread+0x10f/0x150
> [ 1041.799819]  ? xfsaild_push+0xb70/0xb70 [xfs]
> [ 1041.801217]  ? kthread_create_on_node+0x70/0x70
> [ 1041.802652]  ret_from_fork+0x31/0x40
> 
> xfsaild is flushing an inode, but is waiting on a read of the underlying
> inode cluster buffer such that it can flush out the in-core inode data
> structure. I cannot tell if the read had actually completed and is
> blocked somewhere else before running the completion. As Dave notes
> earlier, buffer I/O completion relies on the xfs-buf wq. What is evident
> from the logs is that xfs-buf has a rescuer thread that is sitting idle:
> 
> [ 1041.555227] xfs-buf/sda1    S14904   450      2 0x00000000
> [ 1041.556813] Call Trace:
> [ 1041.557796]  __schedule+0x336/0xe00
> [ 1041.558983]  schedule+0x3d/0x90
> [ 1041.560085]  rescuer_thread+0x322/0x3d0
> [ 1041.561333]  kthread+0x10f/0x150
> [ 1041.562464]  ? worker_thread+0x4b0/0x4b0
> [ 1041.563732]  ? kthread_create_on_node+0x70/0x70
> [ 1041.565123]  ret_from_fork+0x31/0x40
> 
> So AFAICT if the buffer I/O completion would run, it would allow xfsaild
> to progress, which would eventually flush the underlying buffer, write
> it, release the flush lock and allow kswapd to continue. The question is
> has the actually I/O completed? If so, is the xfs-buf workqueue stuck
> (waiting on an allocation perhaps)? And if that is the case, why is the
> xfs-buf rescuer thread not doing anything?

[ 1116.803780] workqueue xfs-data/sda1: flags=0xc
[ 1116.805324]   pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=27/256 MAYDAY
[ 1116.807272]     in-flight: 5356:xfs_end_io [xfs], 451(RESCUER):xfs_end_io [xfs] xfs_end_io [xfs] xfs_end_io [xfs] xfs_end_io [xfs] xfs_end_io [xfs], 10498:xfs_end_io [xfs], 6386:xfs_end_io [xfs]
[ 1116.812145]     pending: xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io\
 [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs]
[ 1116.820988]   pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=21/256 MAYDAY
[ 1116.823105]     in-flight: 535:xfs_end_io [xfs], 7416:xfs_end_io [xfs], 7415:xfs_end_io [xfs], 65:xfs_end_io [xfs]
[ 1116.826062]     pending: xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io\
 [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs]
[ 1116.834549]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=4/256 MAYDAY
[ 1116.837139]     in-flight: 5357:xfs_end_io [xfs], 193:xfs_end_io [xfs], 52:xfs_end_io [xfs], 5358:xfs_end_io [xfs]
[ 1116.840182]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256
[ 1116.842297]     in-flight: 2486:xfs_end_io [xfs]
[ 1116.844230] workqueue xfs-reclaim/sda1: flags=0xc
[ 1116.846168]   pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=1/256
[ 1116.848323]     pending: xfs_reclaim_worker [xfs]
[ 1116.850280] workqueue xfs-eofblocks/sda1: flags=0xc
[ 1116.852358]   pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=1/256
[ 1116.854601]     in-flight: 456(RESCUER):xfs_eofblocks_worker [xfs]

As listed below, all in-flight workqueues for processing xfs_end_io (PID = 5356,
451(RESCUER), 10498, 6386, 535, 7416, 7415, 65, 5357, 193, 52, 5358, 2486) are
stuck at memory allocation, and thus cannot call complete() when xfsaild/sda1
(PID = 457) is waiting at wait_for_completion(&bp->b_iowait) in xfs_buf_submit_wait().

[ 1095.644936] MemAlloc: kworker/3:3(5356) flags=0x4228860 switches=29192 seq=6 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652086
[ 1095.644937] kworker/3:3     R  running task    12760  5356      2 0x00000080
[ 1095.644959] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.644960] Call Trace:
[ 1095.644962]  __schedule+0x336/0xe00
[ 1095.644965]  preempt_schedule_common+0x1f/0x31
[ 1095.644966]  _cond_resched+0x1c/0x30
[ 1095.644968]  shrink_slab+0x339/0x6d0
[ 1095.644973]  shrink_node+0x2fa/0x310
[ 1095.644977]  do_try_to_free_pages+0xe1/0x300
[ 1095.644979]  try_to_free_pages+0x131/0x3f0
[ 1095.644984]  __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.644985]  ? cpuacct_charge+0xf3/0x1e0
[ 1095.644986]  ? cpuacct_charge+0x38/0x1e0
[ 1095.644992]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.644995]  alloc_pages_current+0x97/0x1b0
[ 1095.644998]  new_slab+0x4cb/0x6b0
[ 1095.645001]  ___slab_alloc+0x3a3/0x620
[ 1095.645023]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645026]  ? ___slab_alloc+0x5c6/0x620
[ 1095.645027]  ? trace_hardirqs_on+0xd/0x10
[ 1095.645058]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645066]  __slab_alloc+0x46/0x7d
[ 1095.645069]  __kmalloc+0x301/0x3b0
[ 1095.645088]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.645089]  ? kfree+0x1fa/0x330
[ 1095.645110]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.645132]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.645151]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.645169]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.645188]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.645204]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.645221]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.645223]  process_one_work+0x22b/0x760
[ 1095.645224]  ? process_one_work+0x194/0x760
[ 1095.645228]  worker_thread+0x137/0x4b0
[ 1095.645231]  kthread+0x10f/0x150
[ 1095.645232]  ? process_one_work+0x760/0x760
[ 1095.645233]  ? kthread_create_on_node+0x70/0x70
[ 1095.645236]  ret_from_fork+0x31/0x40

[ 1095.633625] MemAlloc: xfs-data/sda1(451) flags=0x4228060 switches=45509 seq=1 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652073
[ 1095.633626] xfs-data/sda1   R  running task    12696   451      2 0x00000000
[ 1095.633663] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.633665] Call Trace:
[ 1095.633668]  __schedule+0x336/0xe00
[ 1095.633671]  schedule+0x3d/0x90
[ 1095.633672]  schedule_timeout+0x20d/0x510
[ 1095.633675]  ? lock_timer_base+0xa0/0xa0
[ 1095.633678]  schedule_timeout_uninterruptible+0x2a/0x30
[ 1095.633680]  __alloc_pages_slowpath+0x2b5/0xd95
[ 1095.633687]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.633699]  alloc_pages_current+0x97/0x1b0
[ 1095.633702]  new_slab+0x4cb/0x6b0
[ 1095.633706]  ___slab_alloc+0x3a3/0x620
[ 1095.633728]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.633730]  ? ___slab_alloc+0x5c6/0x620
[ 1095.633732]  ? cpuacct_charge+0x38/0x1e0
[ 1095.633767]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.633770]  __slab_alloc+0x46/0x7d
[ 1095.633773]  __kmalloc+0x301/0x3b0
[ 1095.633802]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.633804]  ? kfree+0x1fa/0x330
[ 1095.633842]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.633864]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.633883]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.633901]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.633936]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.633954]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.633971]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.633973]  process_one_work+0x22b/0x760
[ 1095.633975]  ? process_one_work+0x194/0x760
[ 1095.633997]  rescuer_thread+0x1f2/0x3d0
[ 1095.634002]  kthread+0x10f/0x150
[ 1095.634003]  ? worker_thread+0x4b0/0x4b0
[ 1095.634004]  ? kthread_create_on_node+0x70/0x70
[ 1095.634007]  ret_from_fork+0x31/0x40

[ 1095.806606] MemAlloc: kworker/3:0(10498) flags=0x4228060 switches=16222 seq=1 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652087
[ 1095.806607] kworker/3:0     R  running task    11352 10498      2 0x00000080
[ 1095.806631] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.806633] Call Trace:
[ 1095.806636]  __schedule+0x336/0xe00
[ 1095.806640]  schedule+0x3d/0x90
[ 1095.806641]  schedule_timeout+0x20d/0x510
[ 1095.806644]  ? lock_timer_base+0xa0/0xa0
[ 1095.806649]  schedule_timeout_uninterruptible+0x2a/0x30
[ 1095.806651]  __alloc_pages_slowpath+0x2b5/0xd95
[ 1095.806652]  ? cpuacct_charge+0xf3/0x1e0
[ 1095.806654]  ? cpuacct_charge+0x38/0x1e0
[ 1095.806663]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.806667]  alloc_pages_current+0x97/0x1b0
[ 1095.806671]  new_slab+0x4cb/0x6b0
[ 1095.806675]  ___slab_alloc+0x3a3/0x620
[ 1095.806698]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.806701]  ? ___slab_alloc+0x5c6/0x620
[ 1095.806721]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.806724]  __slab_alloc+0x46/0x7d
[ 1095.806727]  __kmalloc+0x301/0x3b0
[ 1095.806747]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.806749]  ? kfree+0x1fa/0x330
[ 1095.806771]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.806794]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.806813]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.806832]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.806852]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.806868]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.806886]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.806889]  process_one_work+0x22b/0x760
[ 1095.806890]  ? process_one_work+0x194/0x760
[ 1095.806896]  worker_thread+0x137/0x4b0
[ 1095.806899]  kthread+0x10f/0x150
[ 1095.806901]  ? process_one_work+0x760/0x760
[ 1095.806902]  ? kthread_create_on_node+0x70/0x70
[ 1095.806904]  ? do_syscall_64+0x195/0x200
[ 1095.806906]  ret_from_fork+0x31/0x40

[ 1095.647293] MemAlloc: kworker/3:5(6386) flags=0x4228860 switches=43427 seq=15 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652087
[ 1095.647294] kworker/3:5     R  running task    11048  6386      2 0x00000080
[ 1095.647754] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.648203] Call Trace:
[ 1095.648207]  __schedule+0x336/0xe00
[ 1095.648504]  preempt_schedule_common+0x1f/0x31
[ 1095.648806]  _cond_resched+0x1c/0x30
[ 1095.648952]  shrink_slab+0x339/0x6d0
[ 1095.649252]  shrink_node+0x2fa/0x310
[ 1095.649694]  do_try_to_free_pages+0xe1/0x300
[ 1095.649699]  try_to_free_pages+0x131/0x3f0
[ 1095.649996]  __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.650296]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.650743]  alloc_pages_current+0x97/0x1b0
[ 1095.650892]  new_slab+0x4cb/0x6b0
[ 1095.651193]  ___slab_alloc+0x3a3/0x620
[ 1095.652087]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.652400]  ? ___slab_alloc+0x5c6/0x620
[ 1095.653457]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.653901]  __slab_alloc+0x46/0x7d
[ 1095.654050]  __kmalloc+0x301/0x3b0
[ 1095.654948]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.655396]  ? kfree+0x1fa/0x330
[ 1095.656589]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.656919]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.656941]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.656961]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.658006]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.659053]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.660098]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.660846]  process_one_work+0x22b/0x760
[ 1095.660994]  ? process_one_work+0x194/0x760
[ 1095.661292]  worker_thread+0x137/0x4b0
[ 1095.661439]  kthread+0x10f/0x150
[ 1095.661741]  ? process_one_work+0x760/0x760
[ 1095.661743]  ? kthread_create_on_node+0x70/0x70
[ 1095.661891]  ret_from_fork+0x31/0x40

[ 1095.635223] MemAlloc: kworker/2:3(535) flags=0x4228860 switches=49285 seq=57 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652084
[ 1095.635224] kworker/2:3     R  running task    12272   535      2 0x00000000
[ 1095.635246] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.635247] Call Trace:
[ 1095.635250]  __schedule+0x336/0xe00
[ 1095.635253]  preempt_schedule_common+0x1f/0x31
[ 1095.635254]  _cond_resched+0x1c/0x30
[ 1095.635256]  shrink_slab+0x339/0x6d0
[ 1095.635263]  shrink_node+0x2fa/0x310
[ 1095.635267]  do_try_to_free_pages+0xe1/0x300
[ 1095.635271]  try_to_free_pages+0x131/0x3f0
[ 1095.635293]  __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.635301]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.635305]  alloc_pages_current+0x97/0x1b0
[ 1095.635308]  new_slab+0x4cb/0x6b0
[ 1095.635312]  ___slab_alloc+0x3a3/0x620
[ 1095.635351]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.635355]  ? ___slab_alloc+0x5c6/0x620
[ 1095.635375]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.635377]  __slab_alloc+0x46/0x7d
[ 1095.635380]  __kmalloc+0x301/0x3b0
[ 1095.635399]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.635400]  ? kfree+0x1fa/0x330
[ 1095.635421]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.635460]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.635494]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.635529]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.635549]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.635566]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.635583]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.635586]  process_one_work+0x22b/0x760
[ 1095.635587]  ? process_one_work+0x194/0x760
[ 1095.635591]  worker_thread+0x137/0x4b0
[ 1095.635594]  kthread+0x10f/0x150
[ 1095.635595]  ? process_one_work+0x760/0x760
[ 1095.635596]  ? kthread_create_on_node+0x70/0x70
[ 1095.635598]  ret_from_fork+0x31/0x40

[ 1095.663708] MemAlloc: kworker/2:5(7416) flags=0x4228060 switches=22830 seq=2 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652069 uninterruptible
[ 1095.663708] kworker/2:5     D12272  7416      2 0x00000080
[ 1095.663738] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.663740] Call Trace:
[ 1095.663743]  __schedule+0x336/0xe00
[ 1095.663746]  schedule+0x3d/0x90
[ 1095.663747]  schedule_timeout+0x20d/0x510
[ 1095.663749]  ? lock_timer_base+0xa0/0xa0
[ 1095.663753]  schedule_timeout_uninterruptible+0x2a/0x30
[ 1095.663755]  __alloc_pages_slowpath+0x2b5/0xd95
[ 1095.663761]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.663765]  alloc_pages_current+0x97/0x1b0
[ 1095.663768]  new_slab+0x4cb/0x6b0
[ 1095.663771]  ___slab_alloc+0x3a3/0x620
[ 1095.663793]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.663795]  ? ___slab_alloc+0x5c6/0x620
[ 1095.663815]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.663817]  __slab_alloc+0x46/0x7d
[ 1095.663820]  __kmalloc+0x301/0x3b0
[ 1095.663859]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.663861]  ? kfree+0x1fa/0x330
[ 1095.663883]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.663905]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.663924]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.663942]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.663961]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.663996]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.664015]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.664017]  process_one_work+0x22b/0x760
[ 1095.664018]  ? process_one_work+0x194/0x760
[ 1095.664022]  worker_thread+0x137/0x4b0
[ 1095.664025]  kthread+0x10f/0x150
[ 1095.664026]  ? process_one_work+0x760/0x760
[ 1095.664027]  ? kthread_create_on_node+0x70/0x70
[ 1095.664030]  ret_from_fork+0x31/0x40

[ 1095.663334] MemAlloc: kworker/2:4(7415) flags=0x4228060 switches=23221 seq=2 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652078 uninterruptible
[ 1095.663335] kworker/2:4     D11496  7415      2 0x00000080
[ 1095.663361] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.663362] Call Trace:
[ 1095.663366]  __schedule+0x336/0xe00
[ 1095.663369]  schedule+0x3d/0x90
[ 1095.663371]  schedule_timeout+0x20d/0x510
[ 1095.663407]  ? lock_timer_base+0xa0/0xa0
[ 1095.663412]  schedule_timeout_uninterruptible+0x2a/0x30
[ 1095.663414]  __alloc_pages_slowpath+0x2b5/0xd95
[ 1095.663421]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.663425]  alloc_pages_current+0x97/0x1b0
[ 1095.663428]  new_slab+0x4cb/0x6b0
[ 1095.663431]  ___slab_alloc+0x3a3/0x620
[ 1095.663457]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.663459]  ? ___slab_alloc+0x5c6/0x620
[ 1095.663481]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.663483]  __slab_alloc+0x46/0x7d
[ 1095.663485]  __kmalloc+0x301/0x3b0
[ 1095.663505]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.663507]  ? kfree+0x1fa/0x330
[ 1095.663548]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.663572]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.663591]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.663611]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.663630]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.663647]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.663664]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.663667]  process_one_work+0x22b/0x760
[ 1095.663668]  ? process_one_work+0x194/0x760
[ 1095.663672]  worker_thread+0x137/0x4b0
[ 1095.663674]  kthread+0x10f/0x150
[ 1095.663676]  ? process_one_work+0x760/0x760
[ 1095.663696]  ? kthread_create_on_node+0x70/0x70
[ 1095.663699]  ? do_syscall_64+0x195/0x200
[ 1095.663701]  ret_from_fork+0x31/0x40

[ 1095.632604] MemAlloc: kworker/2:1(65) flags=0x4228060 switches=22879 seq=2 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652043
[ 1095.632604] kworker/2:1     R  running task    12184    65      2 0x00000000
[ 1095.632641] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.632642] Call Trace:
[ 1095.632646]  __schedule+0x336/0xe00
[ 1095.632649]  schedule+0x3d/0x90
[ 1095.632651]  schedule_timeout+0x20d/0x510
[ 1095.632654]  ? lock_timer_base+0xa0/0xa0
[ 1095.632658]  schedule_timeout_uninterruptible+0x2a/0x30
[ 1095.632660]  __alloc_pages_slowpath+0x2b5/0xd95
[ 1095.632668]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.632672]  alloc_pages_current+0x97/0x1b0
[ 1095.632675]  new_slab+0x4cb/0x6b0
[ 1095.632678]  ___slab_alloc+0x3a3/0x620
[ 1095.632700]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.632702]  ? ___slab_alloc+0x5c6/0x620
[ 1095.632704]  ? free_debug_processing+0x27d/0x2af
[ 1095.632723]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.632725]  __slab_alloc+0x46/0x7d
[ 1095.632728]  __kmalloc+0x301/0x3b0
[ 1095.632765]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.632767]  ? kfree+0x1fa/0x330
[ 1095.632804]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.632828]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.632847]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.632865]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.632884]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.632916]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.632935]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.632938]  process_one_work+0x22b/0x760
[ 1095.632939]  ? process_one_work+0x194/0x760
[ 1095.632944]  worker_thread+0x137/0x4b0
[ 1095.632947]  kthread+0x10f/0x150
[ 1095.632949]  ? process_one_work+0x760/0x760
[ 1095.632960]  ? kthread_create_on_node+0x70/0x70
[ 1095.632963]  ret_from_fork+0x31/0x40

[ 1095.645241] MemAlloc: kworker/1:3(5357) flags=0x4228860 switches=30893 seq=3 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652084
[ 1095.645242] kworker/1:3     R  running task    12184  5357      2 0x00000080
[ 1095.645261] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.645262] Call Trace:
[ 1095.645263]  ? shrink_node+0x2fa/0x310
[ 1095.645267]  ? do_try_to_free_pages+0xe1/0x300
[ 1095.645270]  ? try_to_free_pages+0x131/0x3f0
[ 1095.645274]  ? __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.645280]  ? __alloc_pages_nodemask+0x3e4/0x460
[ 1095.645283]  ? alloc_pages_current+0x97/0x1b0
[ 1095.645286]  ? new_slab+0x4cb/0x6b0
[ 1095.645289]  ? ___slab_alloc+0x3a3/0x620
[ 1095.645310]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645312]  ? ___slab_alloc+0x5c6/0x620
[ 1095.645331]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645333]  ? __slab_alloc+0x46/0x7d
[ 1095.645335]  ? __kmalloc+0x301/0x3b0
[ 1095.645355]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645356]  ? kfree+0x1fa/0x330
[ 1095.645377]  ? xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.645398]  ? __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.645417]  ? xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.645435]  ? __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.645453]  ? xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.645470]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.645486]  ? xfs_end_io+0x81/0x110 [xfs]
[ 1095.645489]  ? process_one_work+0x22b/0x760
[ 1095.645490]  ? process_one_work+0x194/0x760
[ 1095.645493]  ? worker_thread+0x137/0x4b0
[ 1095.645496]  ? kthread+0x10f/0x150
[ 1095.645497]  ? process_one_work+0x760/0x760
[ 1095.645498]  ? kthread_create_on_node+0x70/0x70
[ 1095.645501]  ? ret_from_fork+0x31/0x40

[ 1095.633213] MemAlloc: kworker/1:2(193) flags=0x4228860 switches=28494 seq=1 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652084
[ 1095.633213] kworker/1:2     R  running task    12760   193      2 0x00000000
[ 1095.633236] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.633237] Call Trace:
[ 1095.633240]  __schedule+0x336/0xe00
[ 1095.633260]  preempt_schedule_common+0x1f/0x31
[ 1095.633261]  _cond_resched+0x1c/0x30
[ 1095.633263]  shrink_slab+0x339/0x6d0
[ 1095.633270]  shrink_node+0x2fa/0x310
[ 1095.633275]  do_try_to_free_pages+0xe1/0x300
[ 1095.633278]  try_to_free_pages+0x131/0x3f0
[ 1095.633283]  __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.633292]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.633295]  alloc_pages_current+0x97/0x1b0
[ 1095.633298]  new_slab+0x4cb/0x6b0
[ 1095.633318]  ___slab_alloc+0x3a3/0x620
[ 1095.633349]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.633353]  ? ___slab_alloc+0x5c6/0x620
[ 1095.633373]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.633375]  __slab_alloc+0x46/0x7d
[ 1095.633378]  __kmalloc+0x301/0x3b0
[ 1095.633397]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.633398]  ? kfree+0x1fa/0x330
[ 1095.633436]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.633464]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.633500]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.633520]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.633538]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.633555]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.633572]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.633575]  process_one_work+0x22b/0x760
[ 1095.633576]  ? process_one_work+0x194/0x760
[ 1095.633597]  worker_thread+0x137/0x4b0
[ 1095.633602]  kthread+0x10f/0x150
[ 1095.633603]  ? process_one_work+0x760/0x760
[ 1095.633604]  ? kthread_create_on_node+0x70/0x70
[ 1095.633607]  ret_from_fork+0x31/0x40

[ 1095.632186] MemAlloc: kworker/1:1(52) flags=0x4228860 switches=28036 seq=1 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652083
[ 1095.632186] kworker/1:1     R  running task    12760    52      2 0x00000000
[ 1095.632209] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.632210] Call Trace:
[ 1095.632213]  ? _raw_spin_lock+0x69/0x80
[ 1095.632214]  ? __list_lru_count_one.isra.2+0x22/0x80
[ 1095.632216]  ? __list_lru_count_one.isra.2+0x22/0x80
[ 1095.632217]  ? list_lru_count_one+0x23/0x30
[ 1095.632219]  ? super_cache_count+0x6c/0xe0
[ 1095.632221]  ? shrink_slab+0x15c/0x6d0
[ 1095.632241]  ? mem_cgroup_iter+0x14d/0x720
[ 1095.632244]  ? css_next_child+0x17/0xd0
[ 1095.632247]  ? shrink_node+0x2fa/0x310
[ 1095.632251]  ? do_try_to_free_pages+0xe1/0x300
[ 1095.632254]  ? try_to_free_pages+0x131/0x3f0
[ 1095.632258]  ? __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.632265]  ? __alloc_pages_nodemask+0x3e4/0x460
[ 1095.632268]  ? alloc_pages_current+0x97/0x1b0
[ 1095.632271]  ? new_slab+0x4cb/0x6b0
[ 1095.632274]  ? ___slab_alloc+0x3a3/0x620
[ 1095.632313]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.632317]  ? ___slab_alloc+0x5c6/0x620
[ 1095.632337]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.632339]  ? __slab_alloc+0x46/0x7d
[ 1095.632341]  ? __kmalloc+0x301/0x3b0
[ 1095.632371]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.632373]  ? kfree+0x1fa/0x330
[ 1095.632412]  ? xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.632443]  ? __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.632480]  ? xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.632500]  ? __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.632519]  ? xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.632536]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.632553]  ? xfs_end_io+0x81/0x110 [xfs]
[ 1095.632556]  ? process_one_work+0x22b/0x760
[ 1095.632558]  ? process_one_work+0x194/0x760
[ 1095.632588]  ? worker_thread+0x137/0x4b0
[ 1095.632591]  ? kthread+0x10f/0x150
[ 1095.632592]  ? process_one_work+0x760/0x760
[ 1095.632593]  ? kthread_create_on_node+0x70/0x70
[ 1095.632596]  ? ret_from_fork+0x31/0x40

[ 1095.645506] MemAlloc: kworker/1:4(5358) flags=0x4228060 switches=27329 seq=1 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652084
[ 1095.645506] kworker/1:4     R  running task    12272  5358      2 0x00000080
[ 1095.645525] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.645526] Call Trace:
[ 1095.645528]  __schedule+0x336/0xe00
[ 1095.645531]  schedule+0x3d/0x90
[ 1095.645532]  schedule_timeout+0x20d/0x510
[ 1095.645534]  ? lock_timer_base+0xa0/0xa0
[ 1095.645538]  schedule_timeout_uninterruptible+0x2a/0x30
[ 1095.645540]  __alloc_pages_slowpath+0x2b5/0xd95
[ 1095.645546]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.645550]  alloc_pages_current+0x97/0x1b0
[ 1095.645552]  new_slab+0x4cb/0x6b0
[ 1095.645555]  ___slab_alloc+0x3a3/0x620
[ 1095.645576]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645578]  ? ___slab_alloc+0x5c6/0x620
[ 1095.645597]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645599]  __slab_alloc+0x46/0x7d
[ 1095.645601]  __kmalloc+0x301/0x3b0
[ 1095.645620]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.645621]  ? kfree+0x1fa/0x330
[ 1095.645642]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.645663]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.645681]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.645699]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.646636]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.647249]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.647269]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.647273]  process_one_work+0x22b/0x760
[ 1095.647274]  ? process_one_work+0x194/0x760
[ 1095.647277]  worker_thread+0x137/0x4b0
[ 1095.647280]  kthread+0x10f/0x150
[ 1095.647281]  ? process_one_work+0x760/0x760
[ 1095.647283]  ? kthread_create_on_node+0x70/0x70
[ 1095.647285]  ret_from_fork+0x31/0x40

[ 1095.638807] MemAlloc: kworker/0:3(2486) flags=0x4228860 switches=76240 seq=10 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652064
[ 1095.638807] kworker/0:3     R  running task    11608  2486      2 0x00000080
[ 1095.638829] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.638830] Call Trace:
[ 1095.638833]  __schedule+0x336/0xe00
[ 1095.638837]  preempt_schedule_common+0x1f/0x31
[ 1095.638838]  _cond_resched+0x1c/0x30
[ 1095.638839]  shrink_slab+0x339/0x6d0
[ 1095.638846]  shrink_node+0x2fa/0x310
[ 1095.638850]  do_try_to_free_pages+0xe1/0x300
[ 1095.638854]  try_to_free_pages+0x131/0x3f0
[ 1095.638859]  __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.638866]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.638871]  alloc_pages_current+0x97/0x1b0
[ 1095.638874]  new_slab+0x4cb/0x6b0
[ 1095.638878]  ___slab_alloc+0x3a3/0x620
[ 1095.638900]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.638903]  ? ___slab_alloc+0x5c6/0x620
[ 1095.638923]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.638925]  __slab_alloc+0x46/0x7d
[ 1095.638928]  __kmalloc+0x301/0x3b0
[ 1095.638947]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.638948]  ? kfree+0x1fa/0x330
[ 1095.638970]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.638992]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.639011]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.639030]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.639066]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.639083]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.639100]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.639103]  process_one_work+0x22b/0x760
[ 1095.639104]  ? process_one_work+0x194/0x760
[ 1095.639108]  worker_thread+0x137/0x4b0
[ 1095.639111]  kthread+0x10f/0x150
[ 1095.639112]  ? process_one_work+0x760/0x760
[ 1095.639113]  ? kthread_create_on_node+0x70/0x70
[ 1095.639116]  ? do_syscall_64+0x6c/0x200
[ 1095.639118]  ret_from_fork+0x31/0x40

WARNING: multiple messages have this Message-ID
From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
To: bfoster@redhat.com
Cc: mhocko@kernel.org, linux-xfs@vger.kernel.org, linux-mm@kvack.org
Subject: Re: How to favor memory allocations for WQ_MEM_RECLAIM threads?
Date: Tue, 7 Mar 2017 01:08:24 +0900	[thread overview]
Message-ID: <201703070108.DFD48978.SMOVJHFFLFtOOQ@I-love.SAKURA.ne.jp> (raw)
In-Reply-To: <20170306132517.GB3223@bfoster.bfoster>

Brian Foster wrote:
> As noted in my previous reply, I'm not sure there's enough here to point
> at allocation failure as the root cause. E.g., kswapd is stuck here:
> 
> [ 1095.632985] kswapd0         D10776    69      2 0x00000000
> [ 1095.632988] Call Trace:
> [ 1095.632991]  __schedule+0x336/0xe00
> [ 1095.632994]  schedule+0x3d/0x90
> [ 1095.632996]  io_schedule+0x16/0x40
> [ 1095.633017]  __xfs_iflock+0x129/0x140 [xfs]
> [ 1095.633021]  ? autoremove_wake_function+0x60/0x60
> [ 1095.633051]  xfs_reclaim_inode+0x162/0x440 [xfs]
> [ 1095.633072]  xfs_reclaim_inodes_ag+0x2cf/0x4f0 [xfs]
> [ 1095.633106]  ? xfs_reclaim_inodes_ag+0xf2/0x4f0 [xfs]
> [ 1095.633114]  ? trace_hardirqs_on+0xd/0x10
> [ 1095.633116]  ? try_to_wake_up+0x59/0x7a0
> [ 1095.633120]  ? wake_up_process+0x15/0x20
> [ 1095.633156]  xfs_reclaim_inodes_nr+0x33/0x40 [xfs]
> [ 1095.633178]  xfs_fs_free_cached_objects+0x19/0x20 [xfs]
> [ 1095.633180]  super_cache_scan+0x181/0x190
> [ 1095.633183]  shrink_slab+0x29f/0x6d0
> [ 1095.633189]  shrink_node+0x2fa/0x310
> [ 1095.633193]  kswapd+0x362/0x9b0
> [ 1095.633200]  kthread+0x10f/0x150
> [ 1095.633201]  ? mem_cgroup_shrink_node+0x3b0/0x3b0
> [ 1095.633202]  ? kthread_create_on_node+0x70/0x70
> [ 1095.633205]  ret_from_fork+0x31/0x40
> 
> ... which is waiting on an inode flush lock. It can't get the lock
> (presumably) because xfsaild has it:
> 
> [ 1041.772095] xfsaild/sda1    D13216   457      2 0x00000000
> [ 1041.773726] Call Trace:
> [ 1041.774734]  __schedule+0x336/0xe00
> [ 1041.775956]  schedule+0x3d/0x90
> [ 1041.777105]  schedule_timeout+0x26a/0x510
> [ 1041.778426]  ? wait_for_completion+0x4c/0x190
> [ 1041.779824]  wait_for_completion+0x12c/0x190
> [ 1041.781273]  ? wake_up_q+0x80/0x80
> [ 1041.782597]  ? _xfs_buf_read+0x44/0x90 [xfs]
> [ 1041.784086]  xfs_buf_submit_wait+0xe9/0x5c0 [xfs]
> [ 1041.785659]  _xfs_buf_read+0x44/0x90 [xfs]
> [ 1041.787067]  xfs_buf_read_map+0xfa/0x400 [xfs]
> [ 1041.788501]  ? xfs_trans_read_buf_map+0x186/0x830 [xfs]
> [ 1041.790103]  xfs_trans_read_buf_map+0x186/0x830 [xfs]
> [ 1041.791672]  xfs_imap_to_bp+0x71/0x110 [xfs]
> [ 1041.793090]  xfs_iflush+0x122/0x3b0 [xfs]
> [ 1041.794444]  xfs_inode_item_push+0x108/0x1c0 [xfs]
> [ 1041.795956]  xfsaild_push+0x1d8/0xb70 [xfs]
> [ 1041.797344]  xfsaild+0x150/0x270 [xfs]
> [ 1041.798623]  kthread+0x10f/0x150
> [ 1041.799819]  ? xfsaild_push+0xb70/0xb70 [xfs]
> [ 1041.801217]  ? kthread_create_on_node+0x70/0x70
> [ 1041.802652]  ret_from_fork+0x31/0x40
> 
> xfsaild is flushing an inode, but is waiting on a read of the underlying
> inode cluster buffer such that it can flush out the in-core inode data
> structure. I cannot tell if the read had actually completed and is
> blocked somewhere else before running the completion. As Dave notes
> earlier, buffer I/O completion relies on the xfs-buf wq. What is evident
> from the logs is that xfs-buf has a rescuer thread that is sitting idle:
> 
> [ 1041.555227] xfs-buf/sda1    S14904   450      2 0x00000000
> [ 1041.556813] Call Trace:
> [ 1041.557796]  __schedule+0x336/0xe00
> [ 1041.558983]  schedule+0x3d/0x90
> [ 1041.560085]  rescuer_thread+0x322/0x3d0
> [ 1041.561333]  kthread+0x10f/0x150
> [ 1041.562464]  ? worker_thread+0x4b0/0x4b0
> [ 1041.563732]  ? kthread_create_on_node+0x70/0x70
> [ 1041.565123]  ret_from_fork+0x31/0x40
> 
> So AFAICT if the buffer I/O completion would run, it would allow xfsaild
> to progress, which would eventually flush the underlying buffer, write
> it, release the flush lock and allow kswapd to continue. The question is
> has the actually I/O completed? If so, is the xfs-buf workqueue stuck
> (waiting on an allocation perhaps)? And if that is the case, why is the
> xfs-buf rescuer thread not doing anything?

[ 1116.803780] workqueue xfs-data/sda1: flags=0xc
[ 1116.805324]   pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=27/256 MAYDAY
[ 1116.807272]     in-flight: 5356:xfs_end_io [xfs], 451(RESCUER):xfs_end_io [xfs] xfs_end_io [xfs] xfs_end_io [xfs] xfs_end_io [xfs] xfs_end_io [xfs], 10498:xfs_end_io [xfs], 6386:xfs_end_io [xfs]
[ 1116.812145]     pending: xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io\
 [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs]
[ 1116.820988]   pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=21/256 MAYDAY
[ 1116.823105]     in-flight: 535:xfs_end_io [xfs], 7416:xfs_end_io [xfs], 7415:xfs_end_io [xfs], 65:xfs_end_io [xfs]
[ 1116.826062]     pending: xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io\
 [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs], xfs_end_io [xfs]
[ 1116.834549]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=4/256 MAYDAY
[ 1116.837139]     in-flight: 5357:xfs_end_io [xfs], 193:xfs_end_io [xfs], 52:xfs_end_io [xfs], 5358:xfs_end_io [xfs]
[ 1116.840182]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256
[ 1116.842297]     in-flight: 2486:xfs_end_io [xfs]
[ 1116.844230] workqueue xfs-reclaim/sda1: flags=0xc
[ 1116.846168]   pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=1/256
[ 1116.848323]     pending: xfs_reclaim_worker [xfs]
[ 1116.850280] workqueue xfs-eofblocks/sda1: flags=0xc
[ 1116.852358]   pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=1/256
[ 1116.854601]     in-flight: 456(RESCUER):xfs_eofblocks_worker [xfs]

As listed below, all in-flight workqueues for processing xfs_end_io (PID = 5356,
451(RESCUER), 10498, 6386, 535, 7416, 7415, 65, 5357, 193, 52, 5358, 2486) are
stuck at memory allocation, and thus cannot call complete() when xfsaild/sda1
(PID = 457) is waiting at wait_for_completion(&bp->b_iowait) in xfs_buf_submit_wait().

[ 1095.644936] MemAlloc: kworker/3:3(5356) flags=0x4228860 switches=29192 seq=6 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652086
[ 1095.644937] kworker/3:3     R  running task    12760  5356      2 0x00000080
[ 1095.644959] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.644960] Call Trace:
[ 1095.644962]  __schedule+0x336/0xe00
[ 1095.644965]  preempt_schedule_common+0x1f/0x31
[ 1095.644966]  _cond_resched+0x1c/0x30
[ 1095.644968]  shrink_slab+0x339/0x6d0
[ 1095.644973]  shrink_node+0x2fa/0x310
[ 1095.644977]  do_try_to_free_pages+0xe1/0x300
[ 1095.644979]  try_to_free_pages+0x131/0x3f0
[ 1095.644984]  __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.644985]  ? cpuacct_charge+0xf3/0x1e0
[ 1095.644986]  ? cpuacct_charge+0x38/0x1e0
[ 1095.644992]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.644995]  alloc_pages_current+0x97/0x1b0
[ 1095.644998]  new_slab+0x4cb/0x6b0
[ 1095.645001]  ___slab_alloc+0x3a3/0x620
[ 1095.645023]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645026]  ? ___slab_alloc+0x5c6/0x620
[ 1095.645027]  ? trace_hardirqs_on+0xd/0x10
[ 1095.645058]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645066]  __slab_alloc+0x46/0x7d
[ 1095.645069]  __kmalloc+0x301/0x3b0
[ 1095.645088]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.645089]  ? kfree+0x1fa/0x330
[ 1095.645110]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.645132]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.645151]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.645169]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.645188]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.645204]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.645221]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.645223]  process_one_work+0x22b/0x760
[ 1095.645224]  ? process_one_work+0x194/0x760
[ 1095.645228]  worker_thread+0x137/0x4b0
[ 1095.645231]  kthread+0x10f/0x150
[ 1095.645232]  ? process_one_work+0x760/0x760
[ 1095.645233]  ? kthread_create_on_node+0x70/0x70
[ 1095.645236]  ret_from_fork+0x31/0x40

[ 1095.633625] MemAlloc: xfs-data/sda1(451) flags=0x4228060 switches=45509 seq=1 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652073
[ 1095.633626] xfs-data/sda1   R  running task    12696   451      2 0x00000000
[ 1095.633663] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.633665] Call Trace:
[ 1095.633668]  __schedule+0x336/0xe00
[ 1095.633671]  schedule+0x3d/0x90
[ 1095.633672]  schedule_timeout+0x20d/0x510
[ 1095.633675]  ? lock_timer_base+0xa0/0xa0
[ 1095.633678]  schedule_timeout_uninterruptible+0x2a/0x30
[ 1095.633680]  __alloc_pages_slowpath+0x2b5/0xd95
[ 1095.633687]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.633699]  alloc_pages_current+0x97/0x1b0
[ 1095.633702]  new_slab+0x4cb/0x6b0
[ 1095.633706]  ___slab_alloc+0x3a3/0x620
[ 1095.633728]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.633730]  ? ___slab_alloc+0x5c6/0x620
[ 1095.633732]  ? cpuacct_charge+0x38/0x1e0
[ 1095.633767]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.633770]  __slab_alloc+0x46/0x7d
[ 1095.633773]  __kmalloc+0x301/0x3b0
[ 1095.633802]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.633804]  ? kfree+0x1fa/0x330
[ 1095.633842]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.633864]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.633883]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.633901]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.633936]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.633954]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.633971]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.633973]  process_one_work+0x22b/0x760
[ 1095.633975]  ? process_one_work+0x194/0x760
[ 1095.633997]  rescuer_thread+0x1f2/0x3d0
[ 1095.634002]  kthread+0x10f/0x150
[ 1095.634003]  ? worker_thread+0x4b0/0x4b0
[ 1095.634004]  ? kthread_create_on_node+0x70/0x70
[ 1095.634007]  ret_from_fork+0x31/0x40

[ 1095.806606] MemAlloc: kworker/3:0(10498) flags=0x4228060 switches=16222 seq=1 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652087
[ 1095.806607] kworker/3:0     R  running task    11352 10498      2 0x00000080
[ 1095.806631] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.806633] Call Trace:
[ 1095.806636]  __schedule+0x336/0xe00
[ 1095.806640]  schedule+0x3d/0x90
[ 1095.806641]  schedule_timeout+0x20d/0x510
[ 1095.806644]  ? lock_timer_base+0xa0/0xa0
[ 1095.806649]  schedule_timeout_uninterruptible+0x2a/0x30
[ 1095.806651]  __alloc_pages_slowpath+0x2b5/0xd95
[ 1095.806652]  ? cpuacct_charge+0xf3/0x1e0
[ 1095.806654]  ? cpuacct_charge+0x38/0x1e0
[ 1095.806663]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.806667]  alloc_pages_current+0x97/0x1b0
[ 1095.806671]  new_slab+0x4cb/0x6b0
[ 1095.806675]  ___slab_alloc+0x3a3/0x620
[ 1095.806698]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.806701]  ? ___slab_alloc+0x5c6/0x620
[ 1095.806721]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.806724]  __slab_alloc+0x46/0x7d
[ 1095.806727]  __kmalloc+0x301/0x3b0
[ 1095.806747]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.806749]  ? kfree+0x1fa/0x330
[ 1095.806771]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.806794]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.806813]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.806832]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.806852]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.806868]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.806886]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.806889]  process_one_work+0x22b/0x760
[ 1095.806890]  ? process_one_work+0x194/0x760
[ 1095.806896]  worker_thread+0x137/0x4b0
[ 1095.806899]  kthread+0x10f/0x150
[ 1095.806901]  ? process_one_work+0x760/0x760
[ 1095.806902]  ? kthread_create_on_node+0x70/0x70
[ 1095.806904]  ? do_syscall_64+0x195/0x200
[ 1095.806906]  ret_from_fork+0x31/0x40

[ 1095.647293] MemAlloc: kworker/3:5(6386) flags=0x4228860 switches=43427 seq=15 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652087
[ 1095.647294] kworker/3:5     R  running task    11048  6386      2 0x00000080
[ 1095.647754] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.648203] Call Trace:
[ 1095.648207]  __schedule+0x336/0xe00
[ 1095.648504]  preempt_schedule_common+0x1f/0x31
[ 1095.648806]  _cond_resched+0x1c/0x30
[ 1095.648952]  shrink_slab+0x339/0x6d0
[ 1095.649252]  shrink_node+0x2fa/0x310
[ 1095.649694]  do_try_to_free_pages+0xe1/0x300
[ 1095.649699]  try_to_free_pages+0x131/0x3f0
[ 1095.649996]  __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.650296]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.650743]  alloc_pages_current+0x97/0x1b0
[ 1095.650892]  new_slab+0x4cb/0x6b0
[ 1095.651193]  ___slab_alloc+0x3a3/0x620
[ 1095.652087]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.652400]  ? ___slab_alloc+0x5c6/0x620
[ 1095.653457]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.653901]  __slab_alloc+0x46/0x7d
[ 1095.654050]  __kmalloc+0x301/0x3b0
[ 1095.654948]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.655396]  ? kfree+0x1fa/0x330
[ 1095.656589]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.656919]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.656941]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.656961]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.658006]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.659053]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.660098]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.660846]  process_one_work+0x22b/0x760
[ 1095.660994]  ? process_one_work+0x194/0x760
[ 1095.661292]  worker_thread+0x137/0x4b0
[ 1095.661439]  kthread+0x10f/0x150
[ 1095.661741]  ? process_one_work+0x760/0x760
[ 1095.661743]  ? kthread_create_on_node+0x70/0x70
[ 1095.661891]  ret_from_fork+0x31/0x40

[ 1095.635223] MemAlloc: kworker/2:3(535) flags=0x4228860 switches=49285 seq=57 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652084
[ 1095.635224] kworker/2:3     R  running task    12272   535      2 0x00000000
[ 1095.635246] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.635247] Call Trace:
[ 1095.635250]  __schedule+0x336/0xe00
[ 1095.635253]  preempt_schedule_common+0x1f/0x31
[ 1095.635254]  _cond_resched+0x1c/0x30
[ 1095.635256]  shrink_slab+0x339/0x6d0
[ 1095.635263]  shrink_node+0x2fa/0x310
[ 1095.635267]  do_try_to_free_pages+0xe1/0x300
[ 1095.635271]  try_to_free_pages+0x131/0x3f0
[ 1095.635293]  __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.635301]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.635305]  alloc_pages_current+0x97/0x1b0
[ 1095.635308]  new_slab+0x4cb/0x6b0
[ 1095.635312]  ___slab_alloc+0x3a3/0x620
[ 1095.635351]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.635355]  ? ___slab_alloc+0x5c6/0x620
[ 1095.635375]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.635377]  __slab_alloc+0x46/0x7d
[ 1095.635380]  __kmalloc+0x301/0x3b0
[ 1095.635399]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.635400]  ? kfree+0x1fa/0x330
[ 1095.635421]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.635460]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.635494]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.635529]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.635549]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.635566]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.635583]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.635586]  process_one_work+0x22b/0x760
[ 1095.635587]  ? process_one_work+0x194/0x760
[ 1095.635591]  worker_thread+0x137/0x4b0
[ 1095.635594]  kthread+0x10f/0x150
[ 1095.635595]  ? process_one_work+0x760/0x760
[ 1095.635596]  ? kthread_create_on_node+0x70/0x70
[ 1095.635598]  ret_from_fork+0x31/0x40

[ 1095.663708] MemAlloc: kworker/2:5(7416) flags=0x4228060 switches=22830 seq=2 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652069 uninterruptible
[ 1095.663708] kworker/2:5     D12272  7416      2 0x00000080
[ 1095.663738] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.663740] Call Trace:
[ 1095.663743]  __schedule+0x336/0xe00
[ 1095.663746]  schedule+0x3d/0x90
[ 1095.663747]  schedule_timeout+0x20d/0x510
[ 1095.663749]  ? lock_timer_base+0xa0/0xa0
[ 1095.663753]  schedule_timeout_uninterruptible+0x2a/0x30
[ 1095.663755]  __alloc_pages_slowpath+0x2b5/0xd95
[ 1095.663761]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.663765]  alloc_pages_current+0x97/0x1b0
[ 1095.663768]  new_slab+0x4cb/0x6b0
[ 1095.663771]  ___slab_alloc+0x3a3/0x620
[ 1095.663793]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.663795]  ? ___slab_alloc+0x5c6/0x620
[ 1095.663815]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.663817]  __slab_alloc+0x46/0x7d
[ 1095.663820]  __kmalloc+0x301/0x3b0
[ 1095.663859]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.663861]  ? kfree+0x1fa/0x330
[ 1095.663883]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.663905]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.663924]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.663942]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.663961]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.663996]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.664015]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.664017]  process_one_work+0x22b/0x760
[ 1095.664018]  ? process_one_work+0x194/0x760
[ 1095.664022]  worker_thread+0x137/0x4b0
[ 1095.664025]  kthread+0x10f/0x150
[ 1095.664026]  ? process_one_work+0x760/0x760
[ 1095.664027]  ? kthread_create_on_node+0x70/0x70
[ 1095.664030]  ret_from_fork+0x31/0x40

[ 1095.663334] MemAlloc: kworker/2:4(7415) flags=0x4228060 switches=23221 seq=2 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652078 uninterruptible
[ 1095.663335] kworker/2:4     D11496  7415      2 0x00000080
[ 1095.663361] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.663362] Call Trace:
[ 1095.663366]  __schedule+0x336/0xe00
[ 1095.663369]  schedule+0x3d/0x90
[ 1095.663371]  schedule_timeout+0x20d/0x510
[ 1095.663407]  ? lock_timer_base+0xa0/0xa0
[ 1095.663412]  schedule_timeout_uninterruptible+0x2a/0x30
[ 1095.663414]  __alloc_pages_slowpath+0x2b5/0xd95
[ 1095.663421]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.663425]  alloc_pages_current+0x97/0x1b0
[ 1095.663428]  new_slab+0x4cb/0x6b0
[ 1095.663431]  ___slab_alloc+0x3a3/0x620
[ 1095.663457]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.663459]  ? ___slab_alloc+0x5c6/0x620
[ 1095.663481]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.663483]  __slab_alloc+0x46/0x7d
[ 1095.663485]  __kmalloc+0x301/0x3b0
[ 1095.663505]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.663507]  ? kfree+0x1fa/0x330
[ 1095.663548]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.663572]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.663591]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.663611]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.663630]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.663647]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.663664]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.663667]  process_one_work+0x22b/0x760
[ 1095.663668]  ? process_one_work+0x194/0x760
[ 1095.663672]  worker_thread+0x137/0x4b0
[ 1095.663674]  kthread+0x10f/0x150
[ 1095.663676]  ? process_one_work+0x760/0x760
[ 1095.663696]  ? kthread_create_on_node+0x70/0x70
[ 1095.663699]  ? do_syscall_64+0x195/0x200
[ 1095.663701]  ret_from_fork+0x31/0x40

[ 1095.632604] MemAlloc: kworker/2:1(65) flags=0x4228060 switches=22879 seq=2 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652043
[ 1095.632604] kworker/2:1     R  running task    12184    65      2 0x00000000
[ 1095.632641] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.632642] Call Trace:
[ 1095.632646]  __schedule+0x336/0xe00
[ 1095.632649]  schedule+0x3d/0x90
[ 1095.632651]  schedule_timeout+0x20d/0x510
[ 1095.632654]  ? lock_timer_base+0xa0/0xa0
[ 1095.632658]  schedule_timeout_uninterruptible+0x2a/0x30
[ 1095.632660]  __alloc_pages_slowpath+0x2b5/0xd95
[ 1095.632668]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.632672]  alloc_pages_current+0x97/0x1b0
[ 1095.632675]  new_slab+0x4cb/0x6b0
[ 1095.632678]  ___slab_alloc+0x3a3/0x620
[ 1095.632700]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.632702]  ? ___slab_alloc+0x5c6/0x620
[ 1095.632704]  ? free_debug_processing+0x27d/0x2af
[ 1095.632723]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.632725]  __slab_alloc+0x46/0x7d
[ 1095.632728]  __kmalloc+0x301/0x3b0
[ 1095.632765]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.632767]  ? kfree+0x1fa/0x330
[ 1095.632804]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.632828]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.632847]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.632865]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.632884]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.632916]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.632935]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.632938]  process_one_work+0x22b/0x760
[ 1095.632939]  ? process_one_work+0x194/0x760
[ 1095.632944]  worker_thread+0x137/0x4b0
[ 1095.632947]  kthread+0x10f/0x150
[ 1095.632949]  ? process_one_work+0x760/0x760
[ 1095.632960]  ? kthread_create_on_node+0x70/0x70
[ 1095.632963]  ret_from_fork+0x31/0x40

[ 1095.645241] MemAlloc: kworker/1:3(5357) flags=0x4228860 switches=30893 seq=3 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652084
[ 1095.645242] kworker/1:3     R  running task    12184  5357      2 0x00000080
[ 1095.645261] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.645262] Call Trace:
[ 1095.645263]  ? shrink_node+0x2fa/0x310
[ 1095.645267]  ? do_try_to_free_pages+0xe1/0x300
[ 1095.645270]  ? try_to_free_pages+0x131/0x3f0
[ 1095.645274]  ? __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.645280]  ? __alloc_pages_nodemask+0x3e4/0x460
[ 1095.645283]  ? alloc_pages_current+0x97/0x1b0
[ 1095.645286]  ? new_slab+0x4cb/0x6b0
[ 1095.645289]  ? ___slab_alloc+0x3a3/0x620
[ 1095.645310]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645312]  ? ___slab_alloc+0x5c6/0x620
[ 1095.645331]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645333]  ? __slab_alloc+0x46/0x7d
[ 1095.645335]  ? __kmalloc+0x301/0x3b0
[ 1095.645355]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645356]  ? kfree+0x1fa/0x330
[ 1095.645377]  ? xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.645398]  ? __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.645417]  ? xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.645435]  ? __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.645453]  ? xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.645470]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.645486]  ? xfs_end_io+0x81/0x110 [xfs]
[ 1095.645489]  ? process_one_work+0x22b/0x760
[ 1095.645490]  ? process_one_work+0x194/0x760
[ 1095.645493]  ? worker_thread+0x137/0x4b0
[ 1095.645496]  ? kthread+0x10f/0x150
[ 1095.645497]  ? process_one_work+0x760/0x760
[ 1095.645498]  ? kthread_create_on_node+0x70/0x70
[ 1095.645501]  ? ret_from_fork+0x31/0x40

[ 1095.633213] MemAlloc: kworker/1:2(193) flags=0x4228860 switches=28494 seq=1 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652084
[ 1095.633213] kworker/1:2     R  running task    12760   193      2 0x00000000
[ 1095.633236] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.633237] Call Trace:
[ 1095.633240]  __schedule+0x336/0xe00
[ 1095.633260]  preempt_schedule_common+0x1f/0x31
[ 1095.633261]  _cond_resched+0x1c/0x30
[ 1095.633263]  shrink_slab+0x339/0x6d0
[ 1095.633270]  shrink_node+0x2fa/0x310
[ 1095.633275]  do_try_to_free_pages+0xe1/0x300
[ 1095.633278]  try_to_free_pages+0x131/0x3f0
[ 1095.633283]  __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.633292]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.633295]  alloc_pages_current+0x97/0x1b0
[ 1095.633298]  new_slab+0x4cb/0x6b0
[ 1095.633318]  ___slab_alloc+0x3a3/0x620
[ 1095.633349]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.633353]  ? ___slab_alloc+0x5c6/0x620
[ 1095.633373]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.633375]  __slab_alloc+0x46/0x7d
[ 1095.633378]  __kmalloc+0x301/0x3b0
[ 1095.633397]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.633398]  ? kfree+0x1fa/0x330
[ 1095.633436]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.633464]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.633500]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.633520]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.633538]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.633555]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.633572]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.633575]  process_one_work+0x22b/0x760
[ 1095.633576]  ? process_one_work+0x194/0x760
[ 1095.633597]  worker_thread+0x137/0x4b0
[ 1095.633602]  kthread+0x10f/0x150
[ 1095.633603]  ? process_one_work+0x760/0x760
[ 1095.633604]  ? kthread_create_on_node+0x70/0x70
[ 1095.633607]  ret_from_fork+0x31/0x40

[ 1095.632186] MemAlloc: kworker/1:1(52) flags=0x4228860 switches=28036 seq=1 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652083
[ 1095.632186] kworker/1:1     R  running task    12760    52      2 0x00000000
[ 1095.632209] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.632210] Call Trace:
[ 1095.632213]  ? _raw_spin_lock+0x69/0x80
[ 1095.632214]  ? __list_lru_count_one.isra.2+0x22/0x80
[ 1095.632216]  ? __list_lru_count_one.isra.2+0x22/0x80
[ 1095.632217]  ? list_lru_count_one+0x23/0x30
[ 1095.632219]  ? super_cache_count+0x6c/0xe0
[ 1095.632221]  ? shrink_slab+0x15c/0x6d0
[ 1095.632241]  ? mem_cgroup_iter+0x14d/0x720
[ 1095.632244]  ? css_next_child+0x17/0xd0
[ 1095.632247]  ? shrink_node+0x2fa/0x310
[ 1095.632251]  ? do_try_to_free_pages+0xe1/0x300
[ 1095.632254]  ? try_to_free_pages+0x131/0x3f0
[ 1095.632258]  ? __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.632265]  ? __alloc_pages_nodemask+0x3e4/0x460
[ 1095.632268]  ? alloc_pages_current+0x97/0x1b0
[ 1095.632271]  ? new_slab+0x4cb/0x6b0
[ 1095.632274]  ? ___slab_alloc+0x3a3/0x620
[ 1095.632313]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.632317]  ? ___slab_alloc+0x5c6/0x620
[ 1095.632337]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.632339]  ? __slab_alloc+0x46/0x7d
[ 1095.632341]  ? __kmalloc+0x301/0x3b0
[ 1095.632371]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.632373]  ? kfree+0x1fa/0x330
[ 1095.632412]  ? xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.632443]  ? __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.632480]  ? xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.632500]  ? __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.632519]  ? xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.632536]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.632553]  ? xfs_end_io+0x81/0x110 [xfs]
[ 1095.632556]  ? process_one_work+0x22b/0x760
[ 1095.632558]  ? process_one_work+0x194/0x760
[ 1095.632588]  ? worker_thread+0x137/0x4b0
[ 1095.632591]  ? kthread+0x10f/0x150
[ 1095.632592]  ? process_one_work+0x760/0x760
[ 1095.632593]  ? kthread_create_on_node+0x70/0x70
[ 1095.632596]  ? ret_from_fork+0x31/0x40

[ 1095.645506] MemAlloc: kworker/1:4(5358) flags=0x4228060 switches=27329 seq=1 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652084
[ 1095.645506] kworker/1:4     R  running task    12272  5358      2 0x00000080
[ 1095.645525] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.645526] Call Trace:
[ 1095.645528]  __schedule+0x336/0xe00
[ 1095.645531]  schedule+0x3d/0x90
[ 1095.645532]  schedule_timeout+0x20d/0x510
[ 1095.645534]  ? lock_timer_base+0xa0/0xa0
[ 1095.645538]  schedule_timeout_uninterruptible+0x2a/0x30
[ 1095.645540]  __alloc_pages_slowpath+0x2b5/0xd95
[ 1095.645546]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.645550]  alloc_pages_current+0x97/0x1b0
[ 1095.645552]  new_slab+0x4cb/0x6b0
[ 1095.645555]  ___slab_alloc+0x3a3/0x620
[ 1095.645576]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645578]  ? ___slab_alloc+0x5c6/0x620
[ 1095.645597]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.645599]  __slab_alloc+0x46/0x7d
[ 1095.645601]  __kmalloc+0x301/0x3b0
[ 1095.645620]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.645621]  ? kfree+0x1fa/0x330
[ 1095.645642]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.645663]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.645681]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.645699]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.646636]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.647249]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.647269]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.647273]  process_one_work+0x22b/0x760
[ 1095.647274]  ? process_one_work+0x194/0x760
[ 1095.647277]  worker_thread+0x137/0x4b0
[ 1095.647280]  kthread+0x10f/0x150
[ 1095.647281]  ? process_one_work+0x760/0x760
[ 1095.647283]  ? kthread_create_on_node+0x70/0x70
[ 1095.647285]  ret_from_fork+0x31/0x40

[ 1095.638807] MemAlloc: kworker/0:3(2486) flags=0x4228860 switches=76240 seq=10 gfp=0x1604240(GFP_NOFS|__GFP_NOWARN|__GFP_COMP|__GFP_NOTRACK) order=0 delay=652064
[ 1095.638807] kworker/0:3     R  running task    11608  2486      2 0x00000080
[ 1095.638829] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[ 1095.638830] Call Trace:
[ 1095.638833]  __schedule+0x336/0xe00
[ 1095.638837]  preempt_schedule_common+0x1f/0x31
[ 1095.638838]  _cond_resched+0x1c/0x30
[ 1095.638839]  shrink_slab+0x339/0x6d0
[ 1095.638846]  shrink_node+0x2fa/0x310
[ 1095.638850]  do_try_to_free_pages+0xe1/0x300
[ 1095.638854]  try_to_free_pages+0x131/0x3f0
[ 1095.638859]  __alloc_pages_slowpath+0x3ec/0xd95
[ 1095.638866]  __alloc_pages_nodemask+0x3e4/0x460
[ 1095.638871]  alloc_pages_current+0x97/0x1b0
[ 1095.638874]  new_slab+0x4cb/0x6b0
[ 1095.638878]  ___slab_alloc+0x3a3/0x620
[ 1095.638900]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.638903]  ? ___slab_alloc+0x5c6/0x620
[ 1095.638923]  ? kmem_alloc+0x96/0x120 [xfs]
[ 1095.638925]  __slab_alloc+0x46/0x7d
[ 1095.638928]  __kmalloc+0x301/0x3b0
[ 1095.638947]  kmem_alloc+0x96/0x120 [xfs]
[ 1095.638948]  ? kfree+0x1fa/0x330
[ 1095.638970]  xfs_log_commit_cil+0x489/0x710 [xfs]
[ 1095.638992]  __xfs_trans_commit+0x83/0x260 [xfs]
[ 1095.639011]  xfs_trans_commit+0x10/0x20 [xfs]
[ 1095.639030]  __xfs_setfilesize+0xdb/0x240 [xfs]
[ 1095.639066]  xfs_setfilesize_ioend+0x89/0xb0 [xfs]
[ 1095.639083]  ? xfs_setfilesize_ioend+0x5/0xb0 [xfs]
[ 1095.639100]  xfs_end_io+0x81/0x110 [xfs]
[ 1095.639103]  process_one_work+0x22b/0x760
[ 1095.639104]  ? process_one_work+0x194/0x760
[ 1095.639108]  worker_thread+0x137/0x4b0
[ 1095.639111]  kthread+0x10f/0x150
[ 1095.639112]  ? process_one_work+0x760/0x760
[ 1095.639113]  ? kthread_create_on_node+0x70/0x70
[ 1095.639116]  ? do_syscall_64+0x6c/0x200
[ 1095.639118]  ret_from_fork+0x31/0x40

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

  reply	other threads:[~2017-03-06 16:08 UTC|newest]

Thread overview: 30+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2017-03-03 10:48 How to favor memory allocations for WQ_MEM_RECLAIM threads? Tetsuo Handa
2017-03-03 10:48 ` Tetsuo Handa
2017-03-03 13:39 ` Michal Hocko
2017-03-03 13:39   ` Michal Hocko
2017-03-03 15:37   ` Brian Foster
2017-03-03 15:37     ` Brian Foster
2017-03-03 15:52     ` Michal Hocko
2017-03-03 15:52       ` Michal Hocko
2017-03-03 17:29       ` Brian Foster
2017-03-03 17:29         ` Brian Foster
2017-03-04 14:54         ` Tetsuo Handa
2017-03-04 14:54           ` Tetsuo Handa
2017-03-06 13:25           ` Brian Foster
2017-03-06 13:25             ` Brian Foster
2017-03-06 16:08             ` Tetsuo Handa [this message]
2017-03-06 16:08               ` Tetsuo Handa
2017-03-06 16:17               ` Brian Foster
2017-03-06 16:17                 ` Brian Foster
2017-03-03 23:25   ` Dave Chinner
2017-03-03 23:25     ` Dave Chinner
2017-03-07 12:15     ` Michal Hocko
2017-03-07 12:15       ` Michal Hocko
2017-03-07 19:36       ` Tejun Heo
2017-03-07 19:36         ` Tejun Heo
2017-03-07 21:21         ` Dave Chinner
2017-03-07 21:21           ` Dave Chinner
2017-03-07 21:48           ` Tejun Heo
2017-03-07 21:48             ` Tejun Heo
2017-03-08 23:03             ` Tejun Heo
2017-03-08 23:03               ` Tejun Heo

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=201703070108.DFD48978.SMOVJHFFLFtOOQ@I-love.SAKURA.ne.jp \
    --to=penguin-kernel@i-love.sakura.ne.jp \
    --cc=bfoster@redhat.com \
    --cc=linux-mm@kvack.org \
    --cc=linux-xfs@vger.kernel.org \
    --cc=mhocko@kernel.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.