naota / linux

Linux kernel source tree
Other
3 stars 1 forks source link

hung_task by filling FS with 32 dds #58

Open naota opened 3 years ago

naota commented 3 years ago

While I'm filling an FS to test #57, I got hung_task issue.

[67975.428612] BTRFS: device fsid 79c5063a-6604-41b6-afd6-64950b4c043f devid 1 transid 5 /dev/sda scanned by mkfs.btrfs (58203)
[67975.471953] ISOFS: unsupported/invalid hardware sector size 4096
[67975.574395] BTRFS info (device sda): flagging fs with big metadata feature
[67975.582154] BTRFS info (device sda): has skinny extents
[67976.338484] BTRFS info (device sda): host-managed zoned block device /dev/sda, 55880 zones of 268435456 bytes
[67976.349890] BTRFS info (device sda): zoned mode enabled with zone size 268435456
[67976.360438] BTRFS info (device sda): checking UUID tree
[72259.973939] INFO: task kworker/u64:1:62986 blocked for more than 122 seconds.
[72259.983158]       Not tainted 5.14.0-rc7-BTRFS-ZNS+ #34
[72259.989165] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[72259.997793] task:kworker/u64:1   state:D stack:    0 pid:62986 ppid:     2 flags:0x00004000
[72260.007028] Workqueue: btrfs-endio-write btrfs_work_helper [btrfs]
[72260.014111] Call Trace:
[72260.017319]  __schedule+0x9fb/0x2370
[72260.021662]  ? io_schedule_timeout+0x160/0x160
[72260.028683]  ? mark_held_locks+0xad/0xf0
[72260.035219]  ? rwsem_down_write_slowpath+0x887/0x1220
[72260.042710]  schedule+0xea/0x290
[72260.048372]  rwsem_down_write_slowpath+0x924/0x1220
[72260.055667]  ? rwsem_mark_wake+0x930/0x930
[72260.062152]  ? find_held_lock+0x3c/0x130
[72260.068579]  ? lock_contended+0x578/0xd40
[72260.074910]  ? debug_check_no_locks_held+0xa0/0xa0
[72260.082043]  down_write_nested+0x38c/0x3e0
[72260.088859]  ? down_write_nested+0x38c/0x3e0
[72260.095432]  ? down_write_trylock+0x320/0x320
[72260.102117]  ? btrfs_release_path+0x1a0/0x1a0 [btrfs]
[72260.109588]  __btrfs_tree_lock+0x2d/0x240 [btrfs]
[72260.116694]  btrfs_tree_lock+0x10/0x20 [btrfs]
[72260.123571]  btrfs_search_slot+0x57f/0x1f10 [btrfs]
[72260.130900]  ? split_leaf+0x11e0/0x11e0 [btrfs]
[72260.137884]  ? __kasan_check_write+0x14/0x20
[72260.144548]  ? free_extent_buffer.part.0+0xdc/0x200 [btrfs]
[72260.152602]  btrfs_insert_empty_items+0x98/0x140 [btrfs]
[72260.160413]  ? free_extent_buffer+0x13/0x20 [btrfs]
[72260.168469]  ? btrfs_release_path+0x4b/0x1a0 [btrfs]
[72260.175968]  btrfs_csum_file_blocks+0x4eb/0x14d0 [btrfs]
[72260.183807]  ? sched_clock+0x9/0x10
[72260.189912]  ? sched_clock_cpu+0x18/0x170
[72260.196356]  ? find_held_lock+0x3c/0x130
[72260.202677]  ? btrfs_del_csums+0x8f0/0x8f0 [btrfs]
[72260.209905]  ? lock_downgrade+0x7b0/0x7b0
[72260.216258]  ? _raw_write_unlock+0x23/0x30
[72260.222633]  ? unpin_extent_cache+0x1e3/0x390 [btrfs]
[72260.230021]  btrfs_finish_ordered_io.isra.0+0xa43/0x1c60 [btrfs]
[72260.238423]  ? btrfs_unlink_subvol+0xda0/0xda0 [btrfs]
[72260.245883]  ? lock_is_held_type+0xa4/0x110
[72260.252432]  ? lock_acquire+0x1a1/0x4b0
[72260.258427]  ? process_one_work+0x719/0x1430
[72260.264816]  ? lock_is_held_type+0xa4/0x110
[72260.271138]  finish_ordered_fn+0x15/0x20 [btrfs]
[72260.277938]  btrfs_work_helper+0x1af/0xa50 [btrfs]
[72260.284871]  ? process_one_work+0x6fa/0x1430
[72260.291238]  ? lock_is_held_type+0xa4/0x110
[72260.297464]  ? _raw_spin_unlock_irq+0x28/0x40
[72260.303855]  process_one_work+0x7cd/0x1430
[72260.310057]  ? pwq_dec_nr_in_flight+0x290/0x290
[72260.316567]  worker_thread+0x59b/0x1050
[72260.322352]  ? process_one_work+0x1430/0x1430
[72260.329135]  kthread+0x38c/0x460
[72260.334316]  ? set_kthread_struct+0x110/0x110
[72260.340589]  ret_from_fork+0x22/0x30
[72260.362822] INFO: task kworker/u64:8:68808 blocked for more than 123 seconds.
[72260.372055]       Not tainted 5.14.0-rc7-BTRFS-ZNS+ #34
[72260.379262] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[72260.389096] task:kworker/u64:8   state:D stack:    0 pid:68808 ppid:     2 flags:0x00004000
[72260.399487] Workqueue: btrfs-endio-write btrfs_work_helper [btrfs]
[72260.407760] Call Trace:
[72260.412612]  __schedule+0x9fb/0x2370
[72260.418214]  ? io_schedule_timeout+0x160/0x160
[72260.424770]  ? mark_held_locks+0xad/0xf0
[72260.430721]  ? lock_contended+0xd40/0xd40
[72260.436771]  ? rwsem_down_read_slowpath+0x289/0x9f0
[72260.443830]  schedule+0xea/0x290
[72260.449090]  rwsem_down_read_slowpath+0x542/0x9f0
[72260.455855]  ? down_write_killable+0x420/0x420
[72260.462324]  ? lock_downgrade+0x7b0/0x7b0
[72260.468361]  ? sched_clock+0x9/0x10
[72260.473867]  ? sched_clock_cpu+0x18/0x170
[72260.479900]  ? find_held_lock+0x3c/0x130
[72260.485831]  __down_read_common+0xac/0x4a0
[72260.492038]  ? up_write+0x610/0x610
[72260.497517]  down_read_nested+0x8e/0x90
[72260.503338]  __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72260.510699]  btrfs_tree_read_lock+0x10/0x20 [btrfs]
[72260.517647]  btrfs_search_slot+0xddc/0x1f10 [btrfs]
[72260.524659]  ? process_one_work+0x7cd/0x1430
[72260.531107]  ? worker_thread+0x59b/0x1050
[72260.537111]  ? native_sched_clock_from_tsc+0x42/0x60
[72260.544072]  ? split_leaf+0x11e0/0x11e0 [btrfs]
[72260.550678]  ? lock_release+0x640/0xf70
[72260.556516]  btrfs_lookup_csum+0x122/0x3d0 [btrfs]
[72260.563366]  ? btrfs_delete_one_dir_name+0x1c0/0x1c0 [btrfs]
[72260.571093]  ? rcu_read_lock_sched_held+0x46/0x80
[72260.577792]  ? kmem_cache_alloc+0x328/0x3d0
[72260.583956]  ? lockdep_hardirqs_on_prepare+0x3f0/0x3f0
[72260.591113]  ? btrfs_alloc_path+0x35/0x50 [btrfs]
[72260.597916]  btrfs_csum_file_blocks+0x3bd/0x14d0 [btrfs]
[72260.605568]  ? sched_clock+0x9/0x10
[72260.611083]  ? sched_clock_cpu+0x18/0x170
[72260.617091]  ? find_held_lock+0x3c/0x130
[72260.623016]  ? lock_release+0x640/0xf70
[72260.628859]  ? btrfs_del_csums+0x8f0/0x8f0 [btrfs]
[72260.635703]  ? lock_downgrade+0x7b0/0x7b0
[72260.641740]  ? _raw_write_unlock+0x23/0x30
[72260.648023]  ? unpin_extent_cache+0x1e3/0x390 [btrfs]
[72260.655203]  btrfs_finish_ordered_io.isra.0+0xa43/0x1c60 [btrfs]
[72260.663319]  ? btrfs_unlink_subvol+0xda0/0xda0 [btrfs]
[72260.670559]  ? lock_is_held_type+0xa4/0x110
[72260.676783]  ? lock_acquire+0x1a1/0x4b0
[72260.682624]  ? process_one_work+0x719/0x1430
[72260.688891]  ? lock_is_held_type+0xa4/0x110
[72260.695046]  finish_ordered_fn+0x15/0x20 [btrfs]
[72260.701640]  btrfs_work_helper+0x1af/0xa50 [btrfs]
[72260.708677]  ? process_one_work+0x6fa/0x1430
[72260.715218]  ? lock_is_held_type+0xa4/0x110
[72260.721296]  ? _raw_spin_unlock_irq+0x28/0x40
[72260.727558]  process_one_work+0x7cd/0x1430
[72260.733554]  ? pwq_dec_nr_in_flight+0x290/0x290
[72260.740038]  worker_thread+0x59b/0x1050
[72260.745802]  ? process_one_work+0x1430/0x1430
[72260.752219]  kthread+0x38c/0x460
[72260.757340]  ? set_kthread_struct+0x110/0x110
[72260.763608]  ret_from_fork+0x22/0x30
[72260.785769] INFO: task kworker/u64:0:79416 blocked for more than 123 seconds.
[72260.794975]       Not tainted 5.14.0-rc7-BTRFS-ZNS+ #34
[72260.802169] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[72260.812201] task:kworker/u64:0   state:D stack:    0 pid:79416 ppid:     2 flags:0x00004000
[72260.822596] Workqueue: btrfs-endio-write btrfs_work_helper [btrfs]
[72260.830930] Call Trace:
[72260.835441]  __schedule+0x9fb/0x2370
[72260.841090]  ? io_schedule_timeout+0x160/0x160
[72260.847653]  ? mark_held_locks+0xad/0xf0
[72260.853610]  ? lock_contended+0xd40/0xd40
[72260.859658]  ? rwsem_down_read_slowpath+0x289/0x9f0
[72260.866582]  schedule+0xea/0x290
[72260.871834]  rwsem_down_read_slowpath+0x542/0x9f0
[72260.878592]  ? down_write_killable+0x420/0x420
[72260.885065]  ? lock_downgrade+0x7b0/0x7b0
[72260.891141]  ? sched_clock+0x9/0x10
[72260.896652]  ? sched_clock_cpu+0x18/0x170
[72260.902635]  ? find_held_lock+0x3c/0x130
[72260.908542]  __down_read_common+0xac/0x4a0
[72260.914623]  ? up_write+0x610/0x610
[72260.920100]  down_read_nested+0x8e/0x90
[72260.926086]  __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72260.933632]  btrfs_tree_read_lock+0x10/0x20 [btrfs]
[72260.940561]  btrfs_search_slot+0xddc/0x1f10 [btrfs]
[72260.947484]  ? process_one_work+0x7cd/0x1430
[72260.953858]  ? worker_thread+0x59b/0x1050
[72260.959868]  ? native_sched_clock_from_tsc+0x42/0x60
[72260.966835]  ? split_leaf+0x11e0/0x11e0 [btrfs]
[72260.973429]  ? lock_release+0x640/0xf70
[72260.979268]  btrfs_lookup_csum+0x122/0x3d0 [btrfs]
[72260.986135]  ? btrfs_delete_one_dir_name+0x1c0/0x1c0 [btrfs]
[72260.993883]  ? rcu_read_lock_sched_held+0x46/0x80
[72261.000578]  ? kmem_cache_alloc+0x328/0x3d0
[72261.006744]  ? lockdep_hardirqs_on_prepare+0x3f0/0x3f0
[72261.013909]  ? btrfs_alloc_path+0x35/0x50 [btrfs]
[72261.020691]  btrfs_csum_file_blocks+0x3bd/0x14d0 [btrfs]
[72261.028093]  ? sched_clock+0x9/0x10
[72261.033585]  ? sched_clock_cpu+0x18/0x170
[72261.039598]  ? find_held_lock+0x3c/0x130
[72261.045554]  ? lock_release+0x640/0xf70
[72261.051559]  ? btrfs_del_csums+0x8f0/0x8f0 [btrfs]
[72261.058419]  ? lock_downgrade+0x7b0/0x7b0
[72261.064442]  ? _raw_write_unlock+0x23/0x30
[72261.070529]  ? unpin_extent_cache+0x1e3/0x390 [btrfs]
[72261.077679]  btrfs_finish_ordered_io.isra.0+0xa43/0x1c60 [btrfs]
[72261.085798]  ? btrfs_unlink_subvol+0xda0/0xda0 [btrfs]
[72261.093040]  ? lock_is_held_type+0xa4/0x110
[72261.099525]  ? lock_acquire+0x1a1/0x4b0
[72261.105372]  ? process_one_work+0x719/0x1430
[72261.111647]  ? lock_is_held_type+0xa4/0x110
[72261.117783]  finish_ordered_fn+0x15/0x20 [btrfs]
[72261.124378]  btrfs_work_helper+0x1af/0xa50 [btrfs]
[72261.131135]  ? process_one_work+0x6fa/0x1430
[72261.137300]  ? lock_is_held_type+0xa4/0x110
[72261.143389]  ? _raw_spin_unlock_irq+0x28/0x40
[72261.149654]  process_one_work+0x7cd/0x1430
[72261.155668]  ? pwq_dec_nr_in_flight+0x290/0x290
[72261.162138]  worker_thread+0x59b/0x1050
[72261.167868]  ? _raw_spin_unlock_irqrestore+0x31/0x40
[72261.174771]  ? process_one_work+0x1430/0x1430
[72261.181043]  kthread+0x38c/0x460
[72261.186266]  ? set_kthread_struct+0x110/0x110
[72261.192517]  ret_from_fork+0x22/0x30
[72261.214692] INFO: task kworker/u64:2:79804 blocked for more than 124 seconds.
[72261.223898]       Not tainted 5.14.0-rc7-BTRFS-ZNS+ #34
[72261.231253] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[72261.241112] task:kworker/u64:2   state:D stack:    0 pid:79804 ppid:     2 flags:0x00004000
[72261.251527] Workqueue: btrfs-endio-write btrfs_work_helper [btrfs]
[72261.259843] Call Trace:
[72261.264486]  __schedule+0x9fb/0x2370
[72261.270104]  ? io_schedule_timeout+0x160/0x160
[72261.276598]  ? mark_held_locks+0xad/0xf0
[72261.282566]  ? rwsem_down_write_slowpath+0x887/0x1220
[72261.289679]  schedule+0xea/0x290
[72261.294963]  rwsem_down_write_slowpath+0x924/0x1220
[72261.301908]  ? rwsem_mark_wake+0x930/0x930
[72261.308073]  ? find_held_lock+0x3c/0x130
[72261.314032]  ? lock_contended+0x578/0xd40
[72261.320084]  ? debug_check_no_locks_held+0xa0/0xa0
[72261.326930]  down_write_nested+0x38c/0x3e0
[72261.333198]  ? down_write_nested+0x38c/0x3e0
[72261.339508]  ? down_write_trylock+0x320/0x320
[72261.346015]  ? btrfs_release_path+0x1a0/0x1a0 [btrfs]
[72261.353146]  __btrfs_tree_lock+0x2d/0x240 [btrfs]
[72261.359920]  btrfs_tree_lock+0x10/0x20 [btrfs]
[72261.366427]  btrfs_search_slot+0x57f/0x1f10 [btrfs]
[72261.373396]  ? split_leaf+0x11e0/0x11e0 [btrfs]
[72261.380018]  ? __kasan_check_write+0x14/0x20
[72261.386318]  ? free_extent_buffer.part.0+0xdc/0x200 [btrfs]
[72261.394013]  btrfs_insert_empty_items+0x98/0x140 [btrfs]
[72261.401439]  ? free_extent_buffer+0x13/0x20 [btrfs]
[72261.408391]  ? btrfs_release_path+0x4b/0x1a0 [btrfs]
[72261.415440]  btrfs_csum_file_blocks+0x4eb/0x14d0 [btrfs]
[72261.422868]  ? sched_clock+0x9/0x10
[72261.428384]  ? sched_clock_cpu+0x18/0x170
[72261.434417]  ? find_held_lock+0x3c/0x130
[72261.440364]  ? btrfs_del_csums+0x8f0/0x8f0 [btrfs]
[72261.447295]  ? lock_downgrade+0x7b0/0x7b0
[72261.453351]  ? _raw_write_unlock+0x23/0x30
[72261.459482]  ? unpin_extent_cache+0x1e3/0x390 [btrfs]
[72261.466673]  btrfs_finish_ordered_io.isra.0+0xa43/0x1c60 [btrfs]
[72261.474827]  ? btrfs_unlink_subvol+0xda0/0xda0 [btrfs]
[72261.482314]  ? lock_is_held_type+0xa4/0x110
[72261.488561]  ? lock_acquire+0x1a1/0x4b0
[72261.494422]  ? process_one_work+0x719/0x1430
[72261.500759]  ? lock_is_held_type+0xa4/0x110
[72261.507001]  finish_ordered_fn+0x15/0x20 [btrfs]
[72261.513713]  btrfs_work_helper+0x1af/0xa50 [btrfs]
[72261.520659]  ? process_one_work+0x6fa/0x1430
[72261.526958]  ? lock_is_held_type+0xa4/0x110
[72261.533192]  ? _raw_spin_unlock_irq+0x28/0x40
[72261.539584]  process_one_work+0x7cd/0x1430
[72261.545684]  ? pwq_dec_nr_in_flight+0x290/0x290
[72261.552207]  worker_thread+0x59b/0x1050
[72261.557981]  ? _raw_spin_unlock_irqrestore+0x31/0x40
[72261.565050]  ? process_one_work+0x1430/0x1430
[72261.571565]  kthread+0x38c/0x460
[72261.576707]  ? set_kthread_struct+0x110/0x110
[72261.583117]  ret_from_fork+0x22/0x30
[72261.605295] INFO: task kworker/u64:4:80342 blocked for more than 124 seconds.
[72261.614514]       Not tainted 5.14.0-rc7-BTRFS-ZNS+ #34
[72261.621701] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[72261.631528] task:kworker/u64:4   state:D stack:    0 pid:80342 ppid:     2 flags:0x00004000
[72261.642279] Workqueue: btrfs-endio-write btrfs_work_helper [btrfs]
[72261.650552] Call Trace:
[72261.655053]  __schedule+0x9fb/0x2370
[72261.660681]  ? io_schedule_timeout+0x160/0x160
[72261.667165]  ? mark_held_locks+0xad/0xf0
[72261.673127]  ? lock_contended+0xd40/0xd40
[72261.679168]  ? rwsem_down_read_slowpath+0x289/0x9f0
[72261.686102]  schedule+0xea/0x290
[72261.691366]  rwsem_down_read_slowpath+0x542/0x9f0
[72261.698121]  ? down_write_killable+0x420/0x420
[72261.704618]  ? lock_downgrade+0x7b0/0x7b0
[72261.710714]  ? lock_is_held_type+0xa4/0x110
[72261.716923]  ? sched_clock+0x9/0x10
[72261.722424]  ? sched_clock_cpu+0x18/0x170
[72261.728605]  ? find_held_lock+0x3c/0x130
[72261.734511]  __down_read_common+0xac/0x4a0
[72261.740609]  ? up_write+0x610/0x610
[72261.746526]  down_read_nested+0x8e/0x90
[72261.752355]  __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72261.759573]  btrfs_tree_read_lock+0x10/0x20 [btrfs]
[72261.766533]  btrfs_search_slot+0xddc/0x1f10 [btrfs]
[72261.773467]  ? do_raw_spin_unlock+0x5c/0x200
[72261.779910]  ? split_leaf+0x11e0/0x11e0 [btrfs]
[72261.786496]  ? free_extent_buffer+0x13/0x20 [btrfs]
[72261.793445]  ? btrfs_release_path+0x4b/0x1a0 [btrfs]
[72261.800451]  btrfs_next_old_leaf+0x51e/0xdd0 [btrfs]
[72261.807463]  ? btrfs_search_forward+0xbb0/0xbb0 [btrfs]
[72261.815071]  ? memcpy+0x4e/0x60
[72261.820185]  ? read_extent_buffer+0xa0/0x140 [btrfs]
[72261.827217]  ? btrfs_lookup_csum+0x2d4/0x3d0 [btrfs]
[72261.834249]  find_next_csum_offset+0x1a6/0x3d0 [btrfs]
[72261.841444]  ? btrfs_lookup_csum+0x3d0/0x3d0 [btrfs]
[72261.848472]  ? kmem_cache_alloc+0x328/0x3d0
[72261.854638]  ? lockdep_hardirqs_on_prepare+0x3f0/0x3f0
[72261.861794]  ? btrfs_alloc_path+0x35/0x50 [btrfs]
[72261.868575]  btrfs_csum_file_blocks+0x623/0x14d0 [btrfs]
[72261.875973]  ? sched_clock+0x9/0x10
[72261.881477]  ? sched_clock_cpu+0x18/0x170
[72261.887493]  ? find_held_lock+0x3c/0x130
[72261.893436]  ? lock_release+0x640/0xf70
[72261.899359]  ? btrfs_del_csums+0x8f0/0x8f0 [btrfs]
[72261.906224]  ? lock_downgrade+0x7b0/0x7b0
[72261.912369]  ? _raw_write_unlock+0x23/0x30
[72261.918469]  ? unpin_extent_cache+0x1e3/0x390 [btrfs]
[72261.925614]  btrfs_finish_ordered_io.isra.0+0xa43/0x1c60 [btrfs]
[72261.933690]  ? btrfs_unlink_subvol+0xda0/0xda0 [btrfs]
[72261.940872]  ? lock_is_held_type+0xa4/0x110
[72261.946998]  ? lock_acquire+0x1a1/0x4b0
[72261.952748]  ? process_one_work+0x719/0x1430
[72261.958906]  ? lock_is_held_type+0xa4/0x110
[72261.964985]  finish_ordered_fn+0x15/0x20 [btrfs]
[72261.971551]  btrfs_work_helper+0x1af/0xa50 [btrfs]
[72261.978663]  ? process_one_work+0x6fa/0x1430
[72261.984849]  ? lock_is_held_type+0xa4/0x110
[72261.990917]  ? _raw_spin_unlock_irq+0x28/0x40
[72261.997162]  process_one_work+0x7cd/0x1430
[72262.003165]  ? pwq_dec_nr_in_flight+0x290/0x290
[72262.009798]  worker_thread+0x59b/0x1050
[72262.015551]  ? process_one_work+0x1430/0x1430
[72262.021820]  kthread+0x38c/0x460
[72262.026943]  ? set_kthread_struct+0x110/0x110
[72262.033237]  ret_from_fork+0x22/0x30
[72262.055414] INFO: task kworker/u64:7:80355 blocked for more than 124 seconds.
[72262.064617]       Not tainted 5.14.0-rc7-BTRFS-ZNS+ #34
[72262.072167] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[72262.082021] task:kworker/u64:7   state:D stack:    0 pid:80355 ppid:     2 flags:0x00004000
[72262.092572] Workqueue: btrfs-endio-write btrfs_work_helper [btrfs]
[72262.100880] Call Trace:
[72262.105352]  __schedule+0x9fb/0x2370
[72262.110978]  ? io_schedule_timeout+0x160/0x160
[72262.117471]  ? mark_held_locks+0xad/0xf0
[72262.123419]  ? rwsem_down_write_slowpath+0x887/0x1220
[72262.130507]  schedule+0xea/0x290
[72262.135785]  rwsem_down_write_slowpath+0x924/0x1220
[72262.142703]  ? rwsem_mark_wake+0x930/0x930
[72262.148839]  ? find_held_lock+0x3c/0x130
[72262.154794]  ? lock_contended+0x578/0xd40
[72262.160995]  ? debug_check_no_locks_held+0xa0/0xa0
[72262.167847]  down_write_nested+0x38c/0x3e0
[72262.173968]  ? down_write_nested+0x38c/0x3e0
[72262.180247]  ? down_write_trylock+0x320/0x320
[72262.186623]  ? btrfs_release_path+0x1a0/0x1a0 [btrfs]
[72262.193919]  __btrfs_tree_lock+0x2d/0x240 [btrfs]
[72262.200724]  btrfs_tree_lock+0x10/0x20 [btrfs]
[72262.207226]  btrfs_search_slot+0x57f/0x1f10 [btrfs]
[72262.214176]  ? split_leaf+0x11e0/0x11e0 [btrfs]
[72262.220770]  ? __kasan_check_write+0x14/0x20
[72262.227174]  ? free_extent_buffer.part.0+0xdc/0x200 [btrfs]
[72262.234874]  btrfs_insert_empty_items+0x98/0x140 [btrfs]
[72262.242430]  ? free_extent_buffer+0x13/0x20 [btrfs]
[72262.249418]  ? btrfs_release_path+0x4b/0x1a0 [btrfs]
[72262.256480]  btrfs_csum_file_blocks+0x4eb/0x14d0 [btrfs]
[72262.263896]  ? sched_clock+0x9/0x10
[72262.269393]  ? sched_clock_cpu+0x18/0x170
[72262.275458]  ? find_held_lock+0x3c/0x130
[72262.281400]  ? btrfs_del_csums+0x8f0/0x8f0 [btrfs]
[72262.288262]  ? lock_downgrade+0x7b0/0x7b0
[72262.294544]  ? _raw_write_unlock+0x23/0x30
[72262.300665]  ? unpin_extent_cache+0x1e3/0x390 [btrfs]
[72262.307817]  btrfs_finish_ordered_io.isra.0+0xa43/0x1c60 [btrfs]
[72262.315945]  ? btrfs_unlink_subvol+0xda0/0xda0 [btrfs]
[72262.323184]  ? lock_is_held_type+0xa4/0x110
[72262.329413]  ? lock_acquire+0x1a1/0x4b0
[72262.335273]  ? process_one_work+0x719/0x1430
[72262.341562]  ? lock_is_held_type+0xa4/0x110
[72262.347800]  finish_ordered_fn+0x15/0x20 [btrfs]
[72262.354518]  btrfs_work_helper+0x1af/0xa50 [btrfs]
[72262.361404]  ? process_one_work+0x6fa/0x1430
[72262.367722]  ? lock_is_held_type+0xa4/0x110
[72262.373937]  ? _raw_spin_unlock_irq+0x28/0x40
[72262.380304]  process_one_work+0x7cd/0x1430
[72262.386690]  ? pwq_dec_nr_in_flight+0x290/0x290
[72262.393219]  worker_thread+0x59b/0x1050
[72262.399010]  ? process_one_work+0x1430/0x1430
[72262.405290]  kthread+0x38c/0x460
[72262.410576]  ? set_kthread_struct+0x110/0x110
[72262.416874]  ret_from_fork+0x22/0x30
[72262.439022] INFO: task kworker/u64:10:80398 blocked for more than 125 seconds.
[72262.448309]       Not tainted 5.14.0-rc7-BTRFS-ZNS+ #34
[72262.455670] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[72262.465501] task:kworker/u64:10  state:D stack:    0 pid:80398 ppid:     2 flags:0x00004000
[72262.475900] Workqueue: btrfs-endio-write btrfs_work_helper [btrfs]
[72262.484184] Call Trace:
[72262.488808]  __schedule+0x9fb/0x2370
[72262.494416]  ? io_schedule_timeout+0x160/0x160
[72262.500881]  ? mark_held_locks+0xad/0xf0
[72262.506834]  ? lock_contended+0xd40/0xd40
[72262.512875]  ? rwsem_down_read_slowpath+0x289/0x9f0
[72262.519906]  schedule+0xea/0x290
[72262.525166]  rwsem_down_read_slowpath+0x542/0x9f0
[72262.531917]  ? down_write_killable+0x420/0x420
[72262.538393]  ? lock_downgrade+0x7b0/0x7b0
[72262.544438]  ? lock_is_held_type+0xa4/0x110
[72262.550656]  ? sched_clock+0x9/0x10
[72262.556312]  ? sched_clock_cpu+0x18/0x170
[72262.562330]  ? find_held_lock+0x3c/0x130
[72262.568260]  __down_read_common+0xac/0x4a0
[72262.574498]  ? up_write+0x610/0x610
[72262.579987]  down_read_nested+0x8e/0x90
[72262.585801]  __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72262.592989]  btrfs_tree_read_lock+0x10/0x20 [btrfs]
[72262.599931]  btrfs_search_slot+0xddc/0x1f10 [btrfs]
[72262.606857]  ? do_raw_spin_unlock+0x5c/0x200
[72262.613131]  ? split_leaf+0x11e0/0x11e0 [btrfs]
[72262.619725]  ? free_extent_buffer+0x13/0x20 [btrfs]
[72262.626680]  ? btrfs_release_path+0x4b/0x1a0 [btrfs]
[72262.633723]  btrfs_next_old_leaf+0x51e/0xdd0 [btrfs]
[72262.640737]  ? btrfs_search_forward+0xbb0/0xbb0 [btrfs]
[72262.647976]  ? memcpy+0x4e/0x60
[72262.653085]  ? read_extent_buffer+0xa0/0x140 [btrfs]
[72262.660125]  ? btrfs_lookup_csum+0x2d4/0x3d0 [btrfs]
[72262.667134]  find_next_csum_offset+0x1a6/0x3d0 [btrfs]
[72262.674326]  ? btrfs_lookup_csum+0x3d0/0x3d0 [btrfs]
[72262.681325]  ? kmem_cache_alloc+0x328/0x3d0
[72262.687502]  ? lockdep_hardirqs_on_prepare+0x3f0/0x3f0
[72262.694766]  ? btrfs_alloc_path+0x35/0x50 [btrfs]
[72262.701576]  btrfs_csum_file_blocks+0x623/0x14d0 [btrfs]
[72262.708969]  ? sched_clock+0x9/0x10
[72262.714451]  ? sched_clock_cpu+0x18/0x170
[72262.720464]  ? find_held_lock+0x3c/0x130
[72262.726380]  ? lock_release+0x640/0xf70
[72262.732314]  ? btrfs_del_csums+0x8f0/0x8f0 [btrfs]
[72262.739321]  ? lock_downgrade+0x7b0/0x7b0
[72262.745358]  ? _raw_write_unlock+0x23/0x30
[72262.751439]  ? unpin_extent_cache+0x1e3/0x390 [btrfs]
[72262.758552]  btrfs_finish_ordered_io.isra.0+0xa43/0x1c60 [btrfs]
[72262.766612]  ? btrfs_unlink_subvol+0xda0/0xda0 [btrfs]
[72262.773803]  ? lock_is_held_type+0xa4/0x110
[72262.779919]  ? lock_acquire+0x1a1/0x4b0
[72262.785643]  ? process_one_work+0x719/0x1430
[72262.791808]  ? lock_is_held_type+0xa4/0x110
[72262.797895]  finish_ordered_fn+0x15/0x20 [btrfs]
[72262.804475]  btrfs_work_helper+0x1af/0xa50 [btrfs]
[72262.811221]  ? process_one_work+0x6fa/0x1430
[72262.817385]  ? lock_is_held_type+0xa4/0x110
[72262.823469]  ? _raw_spin_unlock_irq+0x28/0x40
[72262.829728]  process_one_work+0x7cd/0x1430
[72262.835712]  ? pwq_dec_nr_in_flight+0x290/0x290
[72262.842156]  worker_thread+0x59b/0x1050
[72262.847874]  ? _raw_spin_unlock_irqrestore+0x31/0x40
[72262.854756]  ? process_one_work+0x1430/0x1430
[72262.861029]  kthread+0x38c/0x460
[72262.866169]  ? set_kthread_struct+0x110/0x110
[72262.872436]  ret_from_fork+0x22/0x30
[72262.894597] 
Showing all locks held in the system:
[72262.904732] 1 lock held by khungtaskd/209:
[72262.910771]  #0: ffffffff847e8740 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x5f/0x288
[72262.922156] 3 locks held by kswapd0/285:
[72262.928101] 1 lock held by systemd-journal/773:
[72262.934613] 3 locks held by irqbalance/1060:
[72262.940865] 3 locks held by gpg-agent/16173:
[72262.947102] 2 locks held by tmux: server/16190:
[72262.953592] 6 locks held by zsh/16393:
[72262.959283] 5 locks held by zsh/16398:
[72262.964959] 6 locks held by btrfs-transacti/58240:
[72262.971830] 6 locks held by zsh/60685:
[72262.977552] 3 locks held by watch/62122:
[72262.983381] 5 locks held by kworker/u64:1/62986:
[72262.989894]  #0: ffff8899cc62d148 ((wq_completion)btrfs-endio-write){+.+.}-{0:0}, at: process_one_work+0x6e8/0x1430
[72263.002316]  #1: ffffc90022997da8 ((work_completion)(&work->normal_work)){+.+.}-{0:0}, at: process_one_work+0x719/0x1430
[72263.016454]  #2: ffff88813ab2a6b0 (sb_internal#3){.+.+}-{0:0}, at: btrfs_join_transaction+0x1d/0x20 [btrfs]
[72263.028361]  #3: ffff888252bbc758 (btrfs-csum-02#2){++++}-{3:3}, at: __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72263.040574]  #4: ffff888252bbb240 (btrfs-csum-01#2){++++}-{3:3}, at: __btrfs_tree_lock+0x2d/0x240 [btrfs]
[72263.052397] 5 locks held by kworker/u64:8/68808:
[72263.059321]  #0: ffff8899cc62d148 ((wq_completion)btrfs-endio-write){+.+.}-{0:0}, at: process_one_work+0x6e8/0x1430
[72263.071995]  #1: ffffc9002b807da8 ((work_completion)(&work->normal_work)){+.+.}-{0:0}, at: process_one_work+0x719/0x1430
[72263.086764]  #2: ffff88813ab2a6b0 (sb_internal#3){.+.+}-{0:0}, at: btrfs_join_transaction+0x1d/0x20 [btrfs]
[72263.098901]  #3: ffff888252bbc758 (btrfs-csum-02#2){++++}-{3:3}, at: __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72263.111363]  #4: ffff888252bbb240 (btrfs-csum-01#2){++++}-{3:3}, at: __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72263.123789] 5 locks held by kworker/u64:0/79416:
[72263.130731]  #0: ffff8899cc62d148 ((wq_completion)btrfs-endio-write){+.+.}-{0:0}, at: process_one_work+0x6e8/0x1430
[72263.143622]  #1: ffffc9002706fda8 ((work_completion)(&work->normal_work)){+.+.}-{0:0}, at: process_one_work+0x719/0x1430
[72263.158645]  #2: ffff88813ab2a6b0 (sb_internal#3){.+.+}-{0:0}, at: btrfs_join_transaction+0x1d/0x20 [btrfs]
[72263.171015]  #3: ffff888252bbc758 (btrfs-csum-02#2){++++}-{3:3}, at: __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72263.184304]  #4: ffff888252bbb240 (btrfs-csum-01#2){++++}-{3:3}, at: __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72263.196938] 5 locks held by kworker/u64:2/79804:
[72263.204105]  #0: ffff8899cc62d148 ((wq_completion)btrfs-endio-write){+.+.}-{0:0}, at: process_one_work+0x6e8/0x1430
[72263.217187]  #1: ffffc90032f8fda8 ((work_completion)(&work->normal_work)){+.+.}-{0:0}, at: process_one_work+0x719/0x1430
[72263.232665]  #2: ffff88813ab2a6b0 (sb_internal#3){.+.+}-{0:0}, at: btrfs_join_transaction+0x1d/0x20 [btrfs]
[72263.245256]  #3: ffff888252bbc758 (btrfs-csum-02#2){++++}-{3:3}, at: __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72263.258148]  #4: ffff888252bbb240 (btrfs-csum-01#2){++++}-{3:3}, at: __btrfs_tree_lock+0x2d/0x240 [btrfs]
[72263.270588] 5 locks held by kworker/u64:4/80342:
[72263.277991]  #0: ffff8899cc62d148 ((wq_completion)btrfs-endio-write){+.+.}-{0:0}, at: process_one_work+0x6e8/0x1430
[72263.291696]  #1: ffffc9002847fda8 ((work_completion)(&work->normal_work)){+.+.}-{0:0}, at: process_one_work+0x719/0x1430
[72263.307672]  #2: ffff88813ab2a6b0 (sb_internal#3){.+.+}-{0:0}, at: btrfs_join_transaction+0x1d/0x20 [btrfs]
[72263.320486]  #3: ffff888252bbc758 (btrfs-csum-02#2){++++}-{3:3}, at: __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72263.333583]  #4: ffff888252bbb240 (btrfs-csum-01#2){++++}-{3:3}, at: __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72263.346675] 7 locks held by kworker/u64:5/80344:
[72263.354295] 5 locks held by kworker/u64:7/80355:
[72263.361855]  #0: ffff8899cc62d148 ((wq_completion)btrfs-endio-write){+.+.}-{0:0}, at: process_one_work+0x6e8/0x1430
[72263.375354]  #1: ffffc900284bfda8 ((work_completion)(&work->normal_work)){+.+.}-{0:0}, at: process_one_work+0x719/0x1430
[72263.391656]  #2: ffff88813ab2a6b0 (sb_internal#3){.+.+}-{0:0}, at: btrfs_join_transaction+0x1d/0x20 [btrfs]
[72263.404808]  #3: ffff888252bbc758 (btrfs-csum-02#2){++++}-{3:3}, at: __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72263.418069]  #4: ffff888252bbb240 (btrfs-csum-01#2){++++}-{3:3}, at: __btrfs_tree_lock+0x2d/0x240 [btrfs]
[72263.430922] 5 locks held by kworker/u64:10/80398:
[72263.438855]  #0: ffff8899cc62d148 ((wq_completion)btrfs-endio-write){+.+.}-{0:0}, at: process_one_work+0x6e8/0x1430
[72263.452771]  #1: ffffc900285dfda8 ((work_completion)(&work->normal_work)){+.+.}-{0:0}, at: process_one_work+0x719/0x1430
[72263.469749]  #2: ffff88813ab2a6b0 (sb_internal#3){.+.+}-{0:0}, at: btrfs_join_transaction+0x1d/0x20 [btrfs]
[72263.482999]  #3: ffff888252bbc758 (btrfs-csum-02#2){++++}-{3:3}, at: __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72263.497341]  #4: ffff888252bbb240 (btrfs-csum-01#2){++++}-{3:3}, at: __btrfs_tree_read_lock+0x2d/0x240 [btrfs]
[72263.510842] 4 locks held by dd/80436:
[72263.517834] 4 locks held by dd/80450:
[72263.524789] 4 locks held by dd/80473:
[72263.531659] 4 locks held by dd/80506:
[72263.538674] 4 locks held by dd/80528:
[72263.545493] 5 locks held by dd/80532:
[72263.552232] 4 locks held by dd/80536:
[72263.559093] 4 locks held by dd/80545:
[72263.565762] 4 locks held by dd/80582:
[72263.572350] 2 locks held by systemd-userwor/80587:
[72263.580219] 4 locks held by systemd-userwor/80588:
[72263.587903] 2 locks held by powerline-rende/80596:
[72263.595558] 4 locks held by dd/80600:
[72263.602017] 4 locks held by dd/80604:
[72263.608563] 2 locks held by dd/80608:
[72263.615062] 5 locks held by dd/80612:
[72263.621336] 4 locks held by dd/80616:
[72263.627952] 4 locks held by dd/80620:
[72263.634177] 4 locks held by dd/80641:
[72263.640346] 4 locks held by dd/80645:
[72263.646449] 4 locks held by wc/80648:
[72263.652520] 4 locks held by tmux: server/80649:
[72263.659395] 
[72263.663166] =============================================

[72263.674771] Kernel panic - not syncing: hung_task: blocked tasks
[72263.683027] CPU: 20 PID: 209 Comm: khungtaskd Kdump: loaded Not tainted 5.14.0-rc7-BTRFS-ZNS+ #34
[72263.694156] Hardware name: Supermicro Super Server/H12SSL-NT, BIOS 2.0 02/22/2021
[72263.703880] Call Trace:
[72263.708510]  dump_stack_lvl+0x49/0x5e
[72263.714322]  dump_stack+0x10/0x12
[72263.719732]  panic+0x224/0x4cb
[72263.724887]  ? __warn_printk+0xf3/0xf3
[72263.730708]  ? touch_all_softlockup_watchdogs+0x95/0x100
[72263.738137]  watchdog.cold+0x118/0x137
[72263.744290]  ? reset_hung_task_detector+0x30/0x30
[72263.751035]  kthread+0x38c/0x460
[72263.756211]  ? set_kthread_struct+0x110/0x110
[72263.762498]  ret_from_fork+0x22/0x30
naota commented 3 years ago

The filling script

#!/bin/bash

DEV=/dev/sda
MNT=/mnt/test

set -e

findmnt ${MNT} && umount ${MNT}

mkfs.btrfs -d single -m single -f ${DEV}
mount ${DEV} ${MNT}

cd ${MNT}
x=0
maxx=$(ls | sed -e 's/file//' | sort -rn | head -n 1)
if [[ -n "${maxx}" ]]; then
    x=${maxx}
fi
while : ; do
    while [[ $(jobs | wc -l) -gt 30 ]]; do
        wait -n
    done
    if [[ $((x % 100)) == 0 ]]; then
        echo $(date) file $x / $(blkzone report ${DEV}|grep em|wc -l) empty zones left
    fi

    dd if=/dev/zero of=file${x} oflag=direct bs=256M count=1 >/dev/null 2>/dev/null &
    x=$((x+1))
done

umount ${DEV}
naota commented 3 years ago

This one is caused by memory pressure introduced by page leak. The page leak issue is fixed with commit d9cf3bd53184 ("bio: fix page leak bio_add_hw_page failure").

But, we might be still suffering the hung with memory pressure situation...?