mm: Why WQ_MEM_RECLAIM workqueue remains pending?

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



I hit an unable to invoke the OOM killer lockup shown below. According to
"cpus=1 node=0 flags=0x0 nice=0" part, it seems that drain_local_pages_wq
work stuck despite it is on WQ_MEM_RECLAIM mm_percpu_wq workqueue.

    mm_percpu_wq = alloc_workqueue("mm_percpu_wq", WQ_MEM_RECLAIM, 0);

Complete log is at http://I-love.SAKURA.ne.jp/tmp/serial-20170629.txt.xz .
----------
[  423.393025] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 75s!
[  423.405078] Showing busy workqueues and worker pools:
[  423.411988] workqueue events: flags=0x0
[  423.417675]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
[  423.425512]     pending: vmpressure_work_fn
[  423.431489]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=3/256
[  423.435671]     pending: vmstat_shepherd, rht_deferred_worker, vmw_fb_dirty_flush [vmwgfx]
[  423.439838] workqueue events_power_efficient: flags=0x80
[  423.442709]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=2/256
[  423.445870]     pending: neigh_periodic_work, do_cache_clean
[  423.448884] workqueue events_freezable_power_: flags=0x84
[  423.451809]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
[  423.454953]     pending: disk_events_workfn
[  423.457371] workqueue mm_percpu_wq: flags=0x8
[  423.459883]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=2/256
[  423.463018]     pending: drain_local_pages_wq BAR(8775), vmstat_update
[  423.465553] workqueue writeback: flags=0x4e
[  423.467221]   pwq 128: cpus=0-63 flags=0x4 nice=0 active=2/256
[  423.469645]     in-flight: 355:wb_workfn wb_workfn
[  423.472129] workqueue ipv6_addrconf: flags=0x40008
[  423.474416]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/1
[  423.476725]     pending: addrconf_verify_work
[  423.478513] workqueue mpt_poll_0: flags=0x8
[  423.480199]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256
[  423.482462]     pending: mpt_fault_reset_work [mptbase]
[  423.484533] workqueue xfs-data/sda1: flags=0xc
[  423.486388]   pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=4/256
[  423.488674]     in-flight: 95:xfs_end_io [xfs], 8978:xfs_end_io [xfs], 65:xfs_end_io [xfs], 8979:xfs_end_io [xfs]
[  423.492249]   pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=2/256
[  423.494519]     in-flight: 205:xfs_end_io [xfs], 23:xfs_end_io [xfs]
[  423.496943]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=17/256 MAYDAY
[  423.499432]     in-flight: 17:xfs_end_io [xfs], 8985:xfs_end_io [xfs], 8980:xfs_end_io [xfs], 7805:xfs_end_io [xfs], 8984:xfs_end_io [xfs]
[  423.503673]     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]
[  423.511095]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=8/256 MAYDAY
[  423.513586]     in-flight: 8981:xfs_end_io [xfs], 375(RESCUER):xfs_end_io [xfs] xfs_end_io [xfs], 33:xfs_end_io [xfs], 3:xfs_end_io [xfs], 7839:xfs_end_io [xfs], 8976:xfs_end_io [xfs]
[  423.519583]     pending: xfs_end_io [xfs]
[  423.521566] workqueue xfs-eofblocks/sda1: flags=0xc
[  423.523645]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
[  423.526041]     in-flight: 168:xfs_eofblocks_worker [xfs]
[  423.528253] pool 0: cpus=0 node=0 flags=0x0 nice=0 hung=75s workers=6 manager: 217
[  423.531114] pool 2: cpus=1 node=0 flags=0x0 nice=0 hung=76s workers=7 manager: 43
[  423.534038] pool 4: cpus=2 node=0 flags=0x0 nice=0 hung=0s workers=8 idle: 8977 7840 60 7837 8983 8982
[  423.537554] pool 6: cpus=3 node=0 flags=0x0 nice=0 hung=0s workers=7 idle: 464 42 29
[  423.540547] pool 128: cpus=0-63 flags=0x4 nice=0 hung=48s workers=3 idle: 354 356
[  453.599480] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 105s!
[  453.613056] BUG: workqueue lockup - pool cpus=1 node=0 flags=0x0 nice=0 stuck for 106s!
[  453.623744] Showing busy workqueues and worker pools:
[  453.631182] workqueue events: flags=0x0
[  453.638161]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
[  453.644207]     pending: vmpressure_work_fn
[  453.647411]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=3/256
[  453.651569]     pending: vmstat_shepherd, rht_deferred_worker, vmw_fb_dirty_flush [vmwgfx]
[  453.656989] workqueue events_power_efficient: flags=0x80
[  453.660815]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=2/256
[  453.665043]     pending: neigh_periodic_work, do_cache_clean
[  453.669263] workqueue events_freezable_power_: flags=0x84
[  453.672641]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
[  453.675053]     pending: disk_events_workfn
[  453.676885] workqueue mm_percpu_wq: flags=0x8
[  453.678730]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=2/256
[  453.681075]     pending: drain_local_pages_wq BAR(8775), vmstat_update
[  453.683610] workqueue writeback: flags=0x4e
[  453.685412]   pwq 128: cpus=0-63 flags=0x4 nice=0 active=2/256
[  453.687703]     in-flight: 355:wb_workfn wb_workfn
[  453.690022] workqueue ipv6_addrconf: flags=0x40008
[  453.692018]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/1
[  453.694295]     pending: addrconf_verify_work
[  453.696139] workqueue mpt_poll_0: flags=0x8
[  453.698024]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256
[  453.700362]     pending: mpt_fault_reset_work [mptbase]
[  453.702515] workqueue xfs-data/sda1: flags=0xc
[  453.704470]   pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=4/256
[  453.706809]     in-flight: 95:xfs_end_io [xfs], 8978:xfs_end_io [xfs], 65:xfs_end_io [xfs], 8979:xfs_end_io [xfs]
[  453.710578]   pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=2/256
[  453.712956]     in-flight: 205:xfs_end_io [xfs], 23:xfs_end_io [xfs]
[  453.715424]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=17/256 MAYDAY
[  453.717958]     in-flight: 17:xfs_end_io [xfs], 8985:xfs_end_io [xfs], 8980:xfs_end_io [xfs], 7805:xfs_end_io [xfs], 8984:xfs_end_io [xfs]
[  453.722214]     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]
[  453.729761]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=8/256 MAYDAY
[  453.732276]     in-flight: 8981:xfs_end_io [xfs], 375(RESCUER):xfs_end_io [xfs] xfs_end_io [xfs], 33:xfs_end_io [xfs], 3:xfs_end_io [xfs], 7839:xfs_end_io [xfs], 8976:xfs_end_io [xfs]
[  453.738334]     pending: xfs_end_io [xfs]
[  453.740136] workqueue xfs-eofblocks/sda1: flags=0xc
[  453.742165]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
[  453.744507]     in-flight: 168:xfs_eofblocks_worker [xfs]
[  453.746655] pool 0: cpus=0 node=0 flags=0x0 nice=0 hung=106s workers=6 manager: 217
[  453.749528] pool 2: cpus=1 node=0 flags=0x0 nice=0 hung=106s workers=7 manager: 43
[  453.752382] pool 4: cpus=2 node=0 flags=0x0 nice=0 hung=0s workers=8 idle: 8977 7840 60 7837 8983 8982
[  453.755740] pool 6: cpus=3 node=0 flags=0x0 nice=0 hung=0s workers=7 idle: 464 42 29
[  453.758603] pool 128: cpus=0-63 flags=0x4 nice=0 hung=78s workers=3 idle: 354 356
----------

This might be just another example of being caught by too_many_isolated() trap
in shrink_inactive_list(). But I expected that works in mm_percpu_wq workqueue is
always processed immediately as long as in-flight work calls schedule().

Why "pending: drain_local_pages_wq" was not processed despite all in-flight works on
"pool 2: cpus=1 node=0 flags=0x0 nice=0" (that is, 17, 8985, 8980, 7805, 8984 and 168
shown below) were all sleeping at schedule() ? Or, am I just fooled by appearances that
drain_local_pages_wq was actually processed but constantly/immediately re-queued as if
drain_local_pages_wq was never processed?

----------
[  521.100167] kworker/1:0     D12608    17      2 0x00000000
[  521.102148] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[  521.103916] Call Trace:
[  521.104962]  __schedule+0x23f/0x5d0
[  521.106326]  schedule+0x31/0x80
[  521.107569]  schedule_timeout+0x189/0x290
[  521.109033]  ? del_timer_sync+0x40/0x40
[  521.110496]  io_schedule_timeout+0x19/0x40
[  521.112035]  ? io_schedule_timeout+0x19/0x40
[  521.113609]  congestion_wait+0x7d/0xd0
[  521.115128]  ? wait_woken+0x80/0x80
[  521.116440]  shrink_inactive_list+0x3e3/0x4d0
[  521.118048]  shrink_node_memcg+0x360/0x780
[  521.119592]  shrink_node+0xdc/0x310
[  521.120903]  ? shrink_node+0xdc/0x310
[  521.122293]  do_try_to_free_pages+0xea/0x370
[  521.123828]  try_to_free_pages+0xc3/0x100
[  521.125351]  __alloc_pages_slowpath+0x441/0xd50
[  521.126999]  __alloc_pages_nodemask+0x20c/0x250
[  521.128611]  alloc_pages_current+0x65/0xd0
[  521.130129]  new_slab+0x472/0x600
[  521.131405]  ___slab_alloc+0x41b/0x590
[  521.132835]  ? kmem_alloc+0x8a/0x110 [xfs]
[  521.134361]  ? ___slab_alloc+0x1b6/0x590
[  521.135803]  ? kmem_alloc+0x8a/0x110 [xfs]
[  521.137344]  __slab_alloc+0x1b/0x30
[  521.138653]  ? __slab_alloc+0x1b/0x30
[  521.140217]  __kmalloc+0x17e/0x200
[  521.141507]  kmem_alloc+0x8a/0x110 [xfs]
[  521.142980]  xfs_log_commit_cil+0x276/0x750 [xfs]
[  521.144692]  __xfs_trans_commit+0x7d/0x280 [xfs]
[  521.146332]  xfs_trans_commit+0xb/0x10 [xfs]
[  521.147898]  __xfs_setfilesize+0x7c/0xb0 [xfs]
[  521.149522]  xfs_setfilesize_ioend+0x41/0x60 [xfs]
[  521.151215]  xfs_end_io+0x44/0x130 [xfs]
[  521.152724]  process_one_work+0x1f5/0x390
[  521.154187]  worker_thread+0x46/0x410
[  521.155594]  kthread+0xff/0x140
[  521.156836]  ? process_one_work+0x390/0x390
[  521.158356]  ? kthread_create_on_node+0x60/0x60
[  521.160024]  ret_from_fork+0x25/0x30

[  521.760190] kswapd0         D11640    51      2 0x00000000
[  521.762176] Call Trace:
[  521.763204]  __schedule+0x23f/0x5d0
[  521.764581]  schedule+0x31/0x80
[  521.765826]  schedule_timeout+0x1c1/0x290
[  521.767351]  ? save_stack_trace+0x16/0x20
[  521.768827]  ? set_track+0x6b/0x140
[  521.770204]  ? init_object+0x64/0xa0
[  521.771561]  __down+0x85/0xd0
[  521.772765]  ? __down+0x85/0xd0
[  521.773982]  ? cmpxchg_double_slab.isra.73+0x140/0x150
[  521.775827]  down+0x3c/0x50
[  521.776991]  ? down+0x3c/0x50
[  521.778190]  xfs_buf_lock+0x21/0x50 [xfs]
[  521.779716]  _xfs_buf_find+0x3cd/0x640 [xfs]
[  521.781267]  xfs_buf_get_map+0x25/0x150 [xfs]
[  521.782952]  xfs_buf_read_map+0x25/0xc0 [xfs]
[  521.784610]  xfs_trans_read_buf_map+0xef/0x2f0 [xfs]
[  521.786358]  xfs_read_agf+0x86/0x110 [xfs]
[  521.787898]  ? wakeup_preempt_entity.isra.76+0x39/0x50
[  521.789746]  xfs_alloc_read_agf+0x3e/0x140 [xfs]
[  521.791416]  xfs_alloc_fix_freelist+0x3e8/0x4e0 [xfs]
[  521.793231]  ? ttwu_do_activate.isra.66+0x6d/0x80
[  521.794951]  ? try_to_wake_up+0x23b/0x3c0
[  521.796443]  ? radix_tree_lookup+0xd/0x10
[  521.798011]  ? xfs_perag_get+0x16/0x50 [xfs]
[  521.799592]  ? xfs_bmap_longest_free_extent+0x8e/0xb0 [xfs]
[  521.801515]  xfs_alloc_vextent+0x15a/0x4a0 [xfs]
[  521.803210]  xfs_bmap_btalloc+0x33f/0x910 [xfs]
[  521.804884]  xfs_bmap_alloc+0x9/0x10 [xfs]
[  521.806382]  xfs_bmapi_write+0x7ca/0x1170 [xfs]
[  521.808072]  xfs_iomap_write_allocate+0x191/0x3b0 [xfs]
[  521.809953]  xfs_map_blocks+0x180/0x240 [xfs]
[  521.811527]  xfs_do_writepage+0x259/0x780 [xfs]
[  521.813200]  ? list_lru_add+0x3d/0xe0
[  521.814602]  xfs_vm_writepage+0x36/0x70 [xfs]
[  521.816171]  pageout.isra.53+0x195/0x2c0
[  521.817645]  shrink_page_list+0xa72/0xd50
[  521.819112]  shrink_inactive_list+0x239/0x4d0
[  521.820709]  ? radix_tree_gang_lookup_tag+0xd7/0x150
[  521.822599]  shrink_node_memcg+0x360/0x780
[  521.824238]  shrink_node+0xdc/0x310
[  521.825805]  ? shrink_node+0xdc/0x310
[  521.827318]  kswapd+0x373/0x6a0
[  521.828580]  kthread+0xff/0x140
[  521.829912]  ? mem_cgroup_shrink_node+0xb0/0xb0
[  521.831541]  ? kthread_create_on_node+0x60/0x60
[  521.833218]  ret_from_fork+0x25/0x30

[  522.064227] kworker/1:2     D11688   168      2 0x00000000
[  522.066193] Workqueue: xfs-eofblocks/sda1 xfs_eofblocks_worker [xfs]
[  522.068401] Call Trace:
[  522.069479]  __schedule+0x23f/0x5d0
[  522.070807]  schedule+0x31/0x80
[  522.072085]  schedule_timeout+0x1c1/0x290
[  522.073561]  ? init_object+0x64/0xa0
[  522.074956]  __down+0x85/0xd0
[  522.076122]  ? __down+0x85/0xd0
[  522.077381]  ? deactivate_slab.isra.83+0xa0/0x4b0
[  522.079052]  down+0x3c/0x50
[  522.080228]  ? down+0x3c/0x50
[  522.081403]  xfs_buf_lock+0x21/0x50 [xfs]
[  522.082919]  _xfs_buf_find+0x3cd/0x640 [xfs]
[  522.084521]  xfs_buf_get_map+0x25/0x150 [xfs]
[  522.086098]  xfs_buf_read_map+0x25/0xc0 [xfs]
[  522.087723]  xfs_trans_read_buf_map+0xef/0x2f0 [xfs]
[  522.089532]  xfs_read_agf+0x86/0x110 [xfs]
[  522.091034]  xfs_alloc_read_agf+0x3e/0x140 [xfs]
[  522.092730]  xfs_alloc_fix_freelist+0x3e8/0x4e0 [xfs]
[  522.094561]  ? kmem_zone_alloc+0x8a/0x110 [xfs]
[  522.096186]  ? set_track+0x6b/0x140
[  522.097565]  ? init_object+0x64/0xa0
[  522.098912]  ? ___slab_alloc+0x1b6/0x590
[  522.100391]  ? ___slab_alloc+0x1b6/0x590
[  522.101886]  xfs_free_extent_fix_freelist+0x78/0xe0 [xfs]
[  522.103767]  xfs_free_extent+0x6a/0x1d0 [xfs]
[  522.105396]  xfs_trans_free_extent+0x2c/0xb0 [xfs]
[  522.107145]  xfs_extent_free_finish_item+0x21/0x40 [xfs]
[  522.109003]  xfs_defer_finish+0x143/0x2b0 [xfs]
[  522.110686]  xfs_itruncate_extents+0x1a5/0x3d0 [xfs]
[  522.112499]  xfs_free_eofblocks+0x1a8/0x200 [xfs]
[  522.114191]  xfs_inode_free_eofblocks+0xe3/0x110 [xfs]
[  522.116056]  ? xfs_inode_ag_walk_grab+0x63/0xa0 [xfs]
[  522.117888]  xfs_inode_ag_walk.isra.23+0x20a/0x450 [xfs]
[  522.119808]  ? __xfs_inode_clear_eofblocks_tag+0x120/0x120 [xfs]
[  522.121921]  xfs_inode_ag_iterator_tag+0x6e/0xa0 [xfs]
[  522.123744]  ? __xfs_inode_clear_eofblocks_tag+0x120/0x120 [xfs]
[  522.125870]  xfs_eofblocks_worker+0x28/0x40 [xfs]
[  522.127617]  process_one_work+0x1f5/0x390
[  522.129111]  worker_thread+0x46/0x410
[  522.130531]  ? __schedule+0x247/0x5d0
[  522.132044]  kthread+0xff/0x140
[  522.133673]  ? process_one_work+0x390/0x390
[  522.135320]  ? kthread_create_on_node+0x60/0x60
[  522.137024]  ret_from_fork+0x25/0x30

[  526.558822] kworker/1:3     D12608  7805      2 0x00000080
[  526.560825] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[  526.562636] Call Trace:
[  526.563678]  __schedule+0x23f/0x5d0
[  526.565058]  schedule+0x31/0x80
[  526.566295]  schedule_timeout+0x189/0x290
[  526.567823]  ? del_timer_sync+0x40/0x40
[  526.569339]  io_schedule_timeout+0x19/0x40
[  526.570849]  ? io_schedule_timeout+0x19/0x40
[  526.572434]  congestion_wait+0x7d/0xd0
[  526.573841]  ? wait_woken+0x80/0x80
[  526.575209]  shrink_inactive_list+0x3e3/0x4d0
[  526.576848]  shrink_node_memcg+0x360/0x780
[  526.578358]  shrink_node+0xdc/0x310
[  526.579760]  ? shrink_node+0xdc/0x310
[  526.581142]  do_try_to_free_pages+0xea/0x370
[  526.582720]  try_to_free_pages+0xc3/0x100
[  526.584251]  __alloc_pages_slowpath+0x441/0xd50
[  526.585882]  __alloc_pages_nodemask+0x20c/0x250
[  526.587539]  alloc_pages_current+0x65/0xd0
[  526.589045]  new_slab+0x472/0x600
[  526.590364]  ___slab_alloc+0x41b/0x590
[  526.591805]  ? kmem_alloc+0x8a/0x110 [xfs]
[  526.593313]  ? ___slab_alloc+0x1b6/0x590
[  526.594838]  ? kmem_alloc+0x8a/0x110 [xfs]
[  526.596346]  __slab_alloc+0x1b/0x30
[  526.598171]  ? __slab_alloc+0x1b/0x30
[  526.599658]  __kmalloc+0x17e/0x200
[  526.600959]  ? __slab_free+0x9f/0x300
[  526.602382]  kmem_alloc+0x8a/0x110 [xfs]
[  526.603839]  xfs_log_commit_cil+0x276/0x750 [xfs]
[  526.605563]  __xfs_trans_commit+0x7d/0x280 [xfs]
[  526.607256]  xfs_trans_commit+0xb/0x10 [xfs]
[  526.608814]  __xfs_setfilesize+0x7c/0xb0 [xfs]
[  526.610494]  xfs_setfilesize_ioend+0x41/0x60 [xfs]
[  526.612224]  xfs_end_io+0x44/0x130 [xfs]
[  526.613680]  process_one_work+0x1f5/0x390
[  526.615232]  worker_thread+0x46/0x410
[  526.616641]  ? __schedule+0x247/0x5d0
[  526.618029]  kthread+0xff/0x140
[  526.619319]  ? process_one_work+0x390/0x390
[  526.620845]  ? kthread_create_on_node+0x60/0x60
[  526.622497]  ret_from_fork+0x25/0x30

[  551.327823] c.out           D11000  8775   7943 0x00000080
[  551.329829] Call Trace:
[  551.330945]  __schedule+0x23f/0x5d0
[  551.332300]  schedule+0x31/0x80
[  551.333552]  schedule_timeout+0x189/0x290
[  551.335052]  ? release_pages+0x30f/0x3d0
[  551.336564]  ? del_timer_sync+0x40/0x40
[  551.338013]  io_schedule_timeout+0x19/0x40
[  551.339583]  ? io_schedule_timeout+0x19/0x40
[  551.341270]  congestion_wait+0x7d/0xd0
[  551.342696]  ? wait_woken+0x80/0x80
[  551.344077]  shrink_inactive_list+0x3e3/0x4d0
[  551.345672]  shrink_node_memcg+0x360/0x780
[  551.347237]  shrink_node+0xdc/0x310
[  551.348636]  ? shrink_node+0xdc/0x310
[  551.350027]  do_try_to_free_pages+0xea/0x370
[  551.351627]  try_to_free_pages+0xc3/0x100
[  551.353115]  __alloc_pages_slowpath+0x441/0xd50
[  551.355045]  ? account_page_dirtied+0x109/0x160
[  551.356768]  __alloc_pages_nodemask+0x20c/0x250
[  551.358458]  alloc_pages_current+0x65/0xd0
[  551.359980]  __page_cache_alloc+0x95/0xb0
[  551.361584]  __do_page_cache_readahead+0x10a/0x2d0
[  551.363307]  ? radix_tree_lookup_slot+0x22/0x50
[  551.364950]  ? find_get_entry+0x19/0x140
[  551.366458]  filemap_fault+0x4b1/0x760
[  551.367872]  ? filemap_fault+0x4b1/0x760
[  551.369430]  ? iomap_apply+0xc8/0x110
[  551.370909]  ? _cond_resched+0x15/0x40
[  551.372895]  xfs_filemap_fault+0x34/0x50 [xfs]
[  551.374640]  __do_fault+0x19/0xf0
[  551.376074]  __handle_mm_fault+0xb0b/0x1030
[  551.377612]  handle_mm_fault+0xf4/0x220
[  551.379086]  __do_page_fault+0x25b/0x4a0
[  551.380540]  do_page_fault+0x30/0x80
[  551.381940]  ? do_syscall_64+0xfd/0x140
[  551.383419]  page_fault+0x28/0x30
[  551.384693] RIP: 0033:0x7f9efff4fc90
[  551.386114] RSP: 002b:00007ffecf5cc0c8 EFLAGS: 00010246
[  551.388004] RAX: 0000000000001000 RBX: 0000000000000003 RCX: 00007f9efff4fc90
[  551.390470] RDX: 0000000000001000 RSI: 00000000006010c0 RDI: 0000000000000003
[  551.392898] RBP: 0000000000000003 R08: 00007f9effeaf938 R09: 000000000000000e
[  551.395300] R10: 00007ffecf5cbe50 R11: 0000000000000246 R12: 000000000040085d
[  551.397912] R13: 00007ffecf5cc1d0 R14: 0000000000000000 R15: 0000000000000000

[  563.729125] kworker/1:4     D11568  8980      2 0x00000080
[  563.731075] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[  563.732874] Call Trace:
[  563.733893]  __schedule+0x23f/0x5d0
[  563.735218]  schedule+0x31/0x80
[  563.736493]  schedule_timeout+0x189/0x290
[  563.737985]  ? del_timer_sync+0x40/0x40
[  563.739399]  io_schedule_timeout+0x19/0x40
[  563.741018]  ? io_schedule_timeout+0x19/0x40
[  563.742560]  congestion_wait+0x7d/0xd0
[  563.743979]  ? wait_woken+0x80/0x80
[  563.745311]  shrink_inactive_list+0x3e3/0x4d0
[  563.746909]  shrink_node_memcg+0x360/0x780
[  563.748425]  shrink_node+0xdc/0x310
[  563.749739]  ? shrink_node+0xdc/0x310
[  563.751437]  do_try_to_free_pages+0xea/0x370
[  563.753020]  try_to_free_pages+0xc3/0x100
[  563.754486]  __alloc_pages_slowpath+0x441/0xd50
[  563.756234]  __alloc_pages_nodemask+0x20c/0x250
[  563.757884]  alloc_pages_current+0x65/0xd0
[  563.759375]  new_slab+0x472/0x600
[  563.760771]  ___slab_alloc+0x41b/0x590
[  563.762221]  ? kmem_alloc+0x8a/0x110 [xfs]
[  563.763751]  ? ___slab_alloc+0x1b6/0x590
[  563.765198]  ? kmem_alloc+0x8a/0x110 [xfs]
[  563.766741]  __slab_alloc+0x1b/0x30
[  563.768092]  ? __slab_alloc+0x1b/0x30
[  563.769450]  __kmalloc+0x17e/0x200
[  563.770786]  kmem_alloc+0x8a/0x110 [xfs]
[  563.772260]  xfs_log_commit_cil+0x276/0x750 [xfs]
[  563.773982]  __xfs_trans_commit+0x7d/0x280 [xfs]
[  563.775684]  xfs_trans_commit+0xb/0x10 [xfs]
[  563.777231]  __xfs_setfilesize+0x7c/0xb0 [xfs]
[  563.778850]  xfs_setfilesize_ioend+0x41/0x60 [xfs]
[  563.780580]  xfs_end_io+0x44/0x130 [xfs]
[  563.782051]  process_one_work+0x1f5/0x390
[  563.783573]  worker_thread+0x46/0x410
[  563.784938]  ? __schedule+0x247/0x5d0
[  563.786368]  kthread+0xff/0x140
[  563.787576]  ? process_one_work+0x390/0x390
[  563.789131]  ? kthread_create_on_node+0x60/0x60
[  563.790789]  ? do_syscall_64+0x13a/0x140
[  563.792221]  ret_from_fork+0x25/0x30

[  563.887126] kworker/1:5     D11320  8984      2 0x00000080
[  563.889083] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[  563.890905] Call Trace:
[  563.891922]  __schedule+0x23f/0x5d0
[  563.893279]  schedule+0x31/0x80
[  563.894501]  schedule_timeout+0x189/0x290
[  563.896034]  ? del_timer_sync+0x40/0x40
[  563.897450]  io_schedule_timeout+0x19/0x40
[  563.898967]  ? io_schedule_timeout+0x19/0x40
[  563.900541]  congestion_wait+0x7d/0xd0
[  563.901937]  ? wait_woken+0x80/0x80
[  563.903282]  shrink_inactive_list+0x3e3/0x4d0
[  563.904853]  shrink_node_memcg+0x360/0x780
[  563.906403]  shrink_node+0xdc/0x310
[  563.907720]  ? shrink_node+0xdc/0x310
[  563.909133]  do_try_to_free_pages+0xea/0x370
[  563.910731]  try_to_free_pages+0xc3/0x100
[  563.912198]  __alloc_pages_slowpath+0x441/0xd50
[  563.913836]  __alloc_pages_nodemask+0x20c/0x250
[  563.915526]  alloc_pages_current+0x65/0xd0
[  563.917012]  new_slab+0x472/0x600
[  563.918291]  ___slab_alloc+0x41b/0x590
[  563.919687]  ? kmem_alloc+0x8a/0x110 [xfs]
[  563.921204]  ? ___slab_alloc+0x1b6/0x590
[  563.922647]  ? kmem_alloc+0x8a/0x110 [xfs]
[  563.924159]  __slab_alloc+0x1b/0x30
[  563.925593]  ? __slab_alloc+0x1b/0x30
[  563.926952]  __kmalloc+0x17e/0x200
[  563.928286]  kmem_alloc+0x8a/0x110 [xfs]
[  563.929724]  xfs_log_commit_cil+0x276/0x750 [xfs]
[  563.931446]  __xfs_trans_commit+0x7d/0x280 [xfs]
[  563.933086]  xfs_trans_commit+0xb/0x10 [xfs]
[  563.934631]  __xfs_setfilesize+0x7c/0xb0 [xfs]
[  563.936279]  xfs_setfilesize_ioend+0x41/0x60 [xfs]
[  563.938007]  xfs_end_io+0x44/0x130 [xfs]
[  563.939445]  process_one_work+0x1f5/0x390
[  563.941032]  worker_thread+0x46/0x410
[  563.942439]  ? __schedule+0x247/0x5d0
[  563.943850]  kthread+0xff/0x140
[  563.945056]  ? process_one_work+0x390/0x390
[  563.946616]  ? kthread_create_on_node+0x60/0x60
[  563.948261]  ? do_syscall_64+0x13a/0x140
[  563.949698]  ret_from_fork+0x25/0x30

[  563.951084] kworker/1:6     D12128  8985      2 0x00000080
[  563.953006] Workqueue: xfs-data/sda1 xfs_end_io [xfs]
[  563.954773] Call Trace:
[  563.955861]  __schedule+0x23f/0x5d0
[  563.957178]  schedule+0x31/0x80
[  563.958430]  schedule_timeout+0x189/0x290
[  563.959893]  ? del_timer_sync+0x40/0x40
[  563.961344]  io_schedule_timeout+0x19/0x40
[  563.962852]  ? io_schedule_timeout+0x19/0x40
[  563.964390]  congestion_wait+0x7d/0xd0
[  563.965843]  ? wait_woken+0x80/0x80
[  563.967153]  shrink_inactive_list+0x3e3/0x4d0
[  563.968781]  shrink_node_memcg+0x360/0x780
[  563.970268]  shrink_node+0xdc/0x310
[  563.971602]  ? shrink_node+0xdc/0x310
[  563.972983]  do_try_to_free_pages+0xea/0x370
[  563.974519]  try_to_free_pages+0xc3/0x100
[  563.976045]  __alloc_pages_slowpath+0x441/0xd50
[  563.977658]  __alloc_pages_nodemask+0x20c/0x250
[  563.979303]  alloc_pages_current+0x65/0xd0
[  563.980818]  new_slab+0x472/0x600
[  563.982079]  ___slab_alloc+0x41b/0x590
[  563.983499]  ? kmem_alloc+0x8a/0x110 [xfs]
[  563.984987]  ? ___slab_alloc+0x1b6/0x590
[  563.986552]  ? kmem_alloc+0x8a/0x110 [xfs]
[  563.988076]  __slab_alloc+0x1b/0x30
[  563.989384]  ? __slab_alloc+0x1b/0x30
[  563.990788]  __kmalloc+0x17e/0x200
[  563.992077]  kmem_alloc+0x8a/0x110 [xfs]
[  563.993586]  xfs_log_commit_cil+0x276/0x750 [xfs]
[  563.995257]  __xfs_trans_commit+0x7d/0x280 [xfs]
[  563.996950]  xfs_trans_commit+0xb/0x10 [xfs]
[  563.998530]  __xfs_setfilesize+0x7c/0xb0 [xfs]
[  564.000132]  xfs_setfilesize_ioend+0x41/0x60 [xfs]
[  564.001882]  xfs_end_io+0x44/0x130 [xfs]
[  564.003348]  process_one_work+0x1f5/0x390
[  564.004814]  worker_thread+0x46/0x410
[  564.006217]  ? __schedule+0x247/0x5d0
[  564.007578]  kthread+0xff/0x140
[  564.008837]  ? process_one_work+0x390/0x390
[  564.010392]  ? kthread_create_on_node+0x60/0x60
[  564.012005]  ret_from_fork+0x25/0x30
----------

I wish we can print how long each work remains
pending or in-flight. Something like below...

----------
diff --git a/include/linux/workqueue.h b/include/linux/workqueue.h
index c102ef6..444f86f 100644
--- a/include/linux/workqueue.h
+++ b/include/linux/workqueue.h
@@ -101,6 +101,7 @@ struct work_struct {
 	atomic_long_t data;
 	struct list_head entry;
 	work_func_t func;
+	unsigned long stamp;
 #ifdef CONFIG_LOCKDEP
 	struct lockdep_map lockdep_map;
 #endif
diff --git a/kernel/workqueue.c b/kernel/workqueue.c
index a86688f..6be185a 100644
--- a/kernel/workqueue.c
+++ b/kernel/workqueue.c
@@ -1296,6 +1296,7 @@ static void insert_work(struct pool_workqueue *pwq, struct work_struct *work,
 	struct worker_pool *pool = pwq->pool;
 
 	/* we own @work, set data and link */
+	work->stamp = jiffies;
 	set_work_pwq(work, pwq, extra_flags);
 	list_add_tail(&work->entry, head);
 	get_pwq(pwq);
@@ -4316,10 +4317,10 @@ static void pr_cont_work(bool comma, struct work_struct *work)
 
 		barr = container_of(work, struct wq_barrier, work);
 
-		pr_cont("%s BAR(%d)", comma ? "," : "",
-			task_pid_nr(barr->task));
+		pr_cont("%s BAR(%d){%lu}", comma ? "," : "",
+			task_pid_nr(barr->task), jiffies - work->stamp);
 	} else {
-		pr_cont("%s %pf", comma ? "," : "", work->func);
+		pr_cont("%s %pf{%lu}", comma ? "," : "", work->func, jiffies - work->stamp);
 	}
 }
 
@@ -4351,10 +4352,11 @@ static void show_pwq(struct pool_workqueue *pwq)
 			if (worker->current_pwq != pwq)
 				continue;
 
-			pr_cont("%s %d%s:%pf", comma ? "," : "",
+			pr_cont("%s %d%s:%pf{%lu}", comma ? "," : "",
 				task_pid_nr(worker->task),
 				worker == pwq->wq->rescuer ? "(RESCUER)" : "",
-				worker->current_func);
+				worker->current_func, worker->current_work ?
+				jiffies - worker->current_work->stamp : 0);
 			list_for_each_entry(work, &worker->scheduled, entry)
 				pr_cont_work(false, work);
 			comma = true;
----------

----------
[  872.639478] Showing busy workqueues and worker pools:
[  872.641577] workqueue events_freezable_power_: flags=0x84
[  872.643751]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256
[  872.646118]     in-flight: 10905:disk_events_workfn{155066}
[  872.648446] workqueue writeback: flags=0x4e
[  872.650194]   pwq 128: cpus=0-63 flags=0x4 nice=0 active=2/256
[  872.652507]     in-flight: 354:wb_workfn{153828} wb_workfn{153828}
[  872.655406] workqueue xfs-eofblocks/sda1: flags=0xc
[  872.657444]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256
[  872.659827]     in-flight: 3:xfs_eofblocks_worker [xfs]{146617}
[  872.662295] pool 0: cpus=0 node=0 flags=0x0 nice=0 hung=0s workers=7 idle: 94 7730 9860 33 10902
[  872.665704] pool 128: cpus=0-63 flags=0x4 nice=0 hung=22s workers=3 idle: 353 352

[ 1107.349044] Showing busy workqueues and worker pools:
[ 1107.351129] workqueue events_freezable_power_: flags=0x84
[ 1107.353297]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256
[ 1107.355662]     in-flight: 10905:disk_events_workfn{389810}
[ 1107.357929] workqueue writeback: flags=0x4e
[ 1107.359674]   pwq 128: cpus=0-63 flags=0x4 nice=0 active=2/256
[ 1107.362093]     in-flight: 354:wb_workfn{388572} wb_workfn{388572}
[ 1107.364976] workqueue xfs-eofblocks/sda1: flags=0xc
[ 1107.366977]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256
[ 1107.369354]     in-flight: 3:xfs_eofblocks_worker [xfs]{381361}
[ 1107.371770] pool 0: cpus=0 node=0 flags=0x0 nice=0 hung=0s workers=4 idle: 94 7730
[ 1107.374847] pool 128: cpus=0-63 flags=0x4 nice=0 hung=257s workers=3 idle: 353 352

[ 1239.796406] Showing busy workqueues and worker pools:
[ 1239.798505] workqueue events_freezable_power_: flags=0x84
[ 1239.800809]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256
[ 1239.803200]     in-flight: 10905:disk_events_workfn{522257}
[ 1239.805537] workqueue writeback: flags=0x4e
[ 1239.807338]   pwq 128: cpus=0-63 flags=0x4 nice=0 active=2/256
[ 1239.809714]     in-flight: 354:wb_workfn{521034} wb_workfn{521034}
[ 1239.812589] workqueue xfs-eofblocks/sda1: flags=0xc
[ 1239.814682]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256
[ 1239.817207]     in-flight: 3:xfs_eofblocks_worker [xfs]{513823}
[ 1239.819686] pool 0: cpus=0 node=0 flags=0x0 nice=0 hung=0s workers=4 idle: 94 7730
[ 1239.822659] pool 128: cpus=0-63 flags=0x4 nice=0 hung=389s workers=3 idle: 353 352
----------

I haven't succeeded reproducing mm_percpu_wq with this patch applied.
What is strange, "BUG: workqueue lockup" messages do not show up even though
SysRq-t says that pool 128 is hung...

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



[Index of Archives]     [Linux ARM Kernel]     [Linux ARM]     [Linux Omap]     [Fedora ARM]     [IETF Annouce]     [Bugtraq]     [Linux OMAP]     [Linux MIPS]     [eCos]     [Asterisk Internet PBX]     [Linux API]
  Powered by Linux