From: Brian Foster <bfoster@redhat.com> To: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> 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: Mon, 6 Mar 2017 11:17:50 -0500 [thread overview] Message-ID: <20170306161750.GD3223@bfoster.bfoster> (raw) In-Reply-To: <201703070108.DFD48978.SMOVJHFFLFtOOQ@I-love.SAKURA.ne.jp> On Tue, Mar 07, 2017 at 01:08:24AM +0900, Tetsuo Handa wrote: > 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(). > These are all in xfs_end_io(), which means they are either the xfs-data or xfs-conv workqueues. ->b_iowait is ultimately triggered via xfs_buf_ioend() by the xfs-buf workqueue (or xfs-log for log buffers). None of the following use xfs-buf. Brian > [ 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 (diff)
From: Brian Foster <bfoster@redhat.com> To: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> 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: Mon, 6 Mar 2017 11:17:50 -0500 [thread overview] Message-ID: <20170306161750.GD3223@bfoster.bfoster> (raw) In-Reply-To: <201703070108.DFD48978.SMOVJHFFLFtOOQ@I-love.SAKURA.ne.jp> On Tue, Mar 07, 2017 at 01:08:24AM +0900, Tetsuo Handa wrote: > 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(). > These are all in xfs_end_io(), which means they are either the xfs-data or xfs-conv workqueues. ->b_iowait is ultimately triggered via xfs_buf_ioend() by the xfs-buf workqueue (or xfs-log for log buffers). None of the following use xfs-buf. Brian > [ 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>
next prev parent reply other threads:[~2017-03-06 16:17 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 2017-03-06 16:08 ` Tetsuo Handa 2017-03-06 16:17 ` Brian Foster [this message] 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=20170306161750.GD3223@bfoster.bfoster \ --to=bfoster@redhat.com \ --cc=linux-mm@kvack.org \ --cc=linux-xfs@vger.kernel.org \ --cc=mhocko@kernel.org \ --cc=penguin-kernel@I-love.SAKURA.ne.jp \ /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: linkBe 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.