Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

hung_task by filling FS with 32 dds #58

Open
naota opened this issue Sep 3, 2021 · 2 comments
Open

hung_task by filling FS with 32 dds #58

naota opened this issue Sep 3, 2021 · 2 comments

Comments

@naota
Copy link
Owner

naota commented Sep 3, 2021

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
Copy link
Owner Author

naota commented Sep 3, 2021

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
Copy link
Owner Author

naota commented Sep 8, 2021

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

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

naota pushed a commit that referenced this issue Apr 22, 2022
[ Upstream commit 8d3ea3d ]

GCC12 appears to be much smarter about its dependency tracking and is
aware that the relaxed variants are just normal loads and stores and
this is causing problems like:

[  210.074549] ------------[ cut here ]------------
[  210.079223] NETDEV WATCHDOG: enabcm6e4ei0 (bcmgenet): transmit queue 1 timed out
[  210.086717] WARNING: CPU: 1 PID: 0 at net/sched/sch_generic.c:529 dev_watchdog+0x234/0x240
[  210.095044] Modules linked in: genet(E) nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat]
[  210.146561] ACPI CPPC: PCC check channel failed for ss: 0. ret=-110
[  210.146927] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G            E     5.17.0-rc7G12+ #58
[  210.153226] CPPC Cpufreq:cppc_scale_freq_workfn: failed to read perf counters
[  210.161349] Hardware name: Raspberry Pi Foundation Raspberry Pi 4 Model B/Raspberry Pi 4 Model B, BIOS EDK2-DEV 02/08/2022
[  210.161353] pstate: 80400005 (Nzcv daif +PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[  210.161358] pc : dev_watchdog+0x234/0x240
[  210.161364] lr : dev_watchdog+0x234/0x240
[  210.161368] sp : ffff8000080a3a40
[  210.161370] x29: ffff8000080a3a40 x28: ffffcd425af87000 x27: ffff8000080a3b20
[  210.205150] x26: ffffcd425aa00000 x25: 0000000000000001 x24: ffffcd425af8ec08
[  210.212321] x23: 0000000000000100 x22: ffffcd425af87000 x21: ffff55b142688000
[  210.219491] x20: 0000000000000001 x19: ffff55b1426884c8 x18: ffffffffffffffff
[  210.226661] x17: 64656d6974203120 x16: 0000000000000001 x15: 6d736e617274203a
[  210.233831] x14: 2974656e65676d63 x13: ffffcd4259c300d8 x12: ffffcd425b07d5f0
[  210.241001] x11: 00000000ffffffff x10: ffffcd425b07d5f0 x9 : ffffcd4258bdad9c
[  210.248171] x8 : 00000000ffffdfff x7 : 000000000000003f x6 : 0000000000000000
[  210.255341] x5 : 0000000000000000 x4 : 0000000000000000 x3 : 0000000000001000
[  210.262511] x2 : 0000000000001000 x1 : 0000000000000005 x0 : 0000000000000044
[  210.269682] Call trace:
[  210.272133]  dev_watchdog+0x234/0x240
[  210.275811]  call_timer_fn+0x3c/0x15c
[  210.279489]  __run_timers.part.0+0x288/0x310
[  210.283777]  run_timer_softirq+0x48/0x80
[  210.287716]  __do_softirq+0x128/0x360
[  210.291392]  __irq_exit_rcu+0x138/0x140
[  210.295243]  irq_exit_rcu+0x1c/0x30
[  210.298745]  el1_interrupt+0x38/0x54
[  210.302334]  el1h_64_irq_handler+0x18/0x24
[  210.306445]  el1h_64_irq+0x7c/0x80
[  210.309857]  arch_cpu_idle+0x18/0x2c
[  210.313445]  default_idle_call+0x4c/0x140
[  210.317470]  cpuidle_idle_call+0x14c/0x1a0
[  210.321584]  do_idle+0xb0/0x100
[  210.324737]  cpu_startup_entry+0x30/0x8c
[  210.328675]  secondary_start_kernel+0xe4/0x110
[  210.333138]  __secondary_switched+0x94/0x98

The assumption when these were relaxed seems to be that device memory
would be mapped non reordering, and that other constructs
(spinlocks/etc) would provide the barriers to assure that packet data
and in memory rings/queues were ordered with respect to device
register reads/writes. This itself seems a bit sketchy, but the real
problem with GCC12 is that it is moving the actual reads/writes around
at will as though they were independent operations when in truth they
are not, but the compiler can't know that. When looking at the
assembly dumps for many of these routines its possible to see very
clean, but not strictly in program order operations occurring as the
compiler would be free to do if these weren't actually register
reads/write operations.

Its possible to suppress the timeout with a liberal bit of dma_mb()'s
sprinkled around but the device still seems unable to reliably
send/receive data. A better plan is to use the safer readl/writel
everywhere.

Since this partially reverts an older commit, which notes the use of
the relaxed variants for performance reasons. I would suggest that
any performance problems with this commit are targeted at relaxing only
the performance critical code paths after assuring proper barriers.

Fixes: 69d2ea9 ("net: bcmgenet: Use correct I/O accessors")
Reported-by: Peter Robinson <pbrobinson@gmail.com>
Signed-off-by: Jeremy Linton <jeremy.linton@arm.com>
Acked-by: Peter Robinson <pbrobinson@gmail.com>
Tested-by: Peter Robinson <pbrobinson@gmail.com>
Acked-by: Florian Fainelli <f.fainelli@gmail.com>
Link: https://lore.kernel.org/r/20220310045358.224350-1-jeremy.linton@arm.com
Signed-off-by: Jakub Kicinski <kuba@kernel.org>
Signed-off-by: Sasha Levin <sashal@kernel.org>
naota pushed a commit that referenced this issue Oct 31, 2022
Since commit 262ca38 ("clk: Stop forwarding clk_rate_requests
to the parent"), the clk_rate_request is .. as the title says, not
forwarded anymore to the parent: this produces an issue with the
MediaTek clock MUX driver during GPU DVFS on MT8195, but not on
MT8192 or others.

This is because, differently from others, like MT8192 where all of
the clocks in the MFG parents tree are of mtk_mux type, but in the
parent tree of MT8195's MFG clock, we have one mtk_mux clock and
one (clk framework generic) mux clock, like so:

names: mfg_bg3d -> mfg_ck_fast_ref -> top_mfg_core_tmp (or) mfgpll
types: mtk_gate ->      mux        ->     mtk_mux      (or) mtk_pll

To solve this issue and also keep the GPU DVFS clocks code working
as expected, wire up a .determine_rate() callback for the mtk_mux
ops; for that, the standard clk_mux_determine_rate_flags() was used
as it was possible to.

This commit was successfully tested on MT6795 Xperia M5, MT8173 Elm,
MT8192 Spherion and MT8195 Tomato; no regressions were seen.

For the sake of some more documentation about this issue here's the
trace of it:

[   12.211587] ------------[ cut here ]------------
[   12.211589] WARNING: CPU: 6 PID: 78 at drivers/clk/clk.c:1462 clk_core_init_rate_req+0x84/0x90
[   12.211593] Modules linked in: stp crct10dif_ce mtk_adsp_common llc rfkill snd_sof_xtensa_dsp
               panfrost(+) sbs_battery cros_ec_lid_angle cros_ec_sensors snd_sof_of
               cros_ec_sensors_core hid_multitouch cros_usbpd_logger snd_sof gpu_sched
               snd_sof_utils fuse ipv6
[   12.211614] CPU: 6 PID: 78 Comm: kworker/u16:2 Tainted: G        W          6.0.0-next-20221011+ #58
[   12.211616] Hardware name: Acer Tomato (rev2) board (DT)
[   12.211617] Workqueue: devfreq_wq devfreq_monitor
[   12.211620] pstate: 40400009 (nZcv daif +PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[   12.211622] pc : clk_core_init_rate_req+0x84/0x90
[   12.211625] lr : clk_core_forward_rate_req+0xa4/0xe4
[   12.211627] sp : ffff80000893b8e0
[   12.211628] x29: ffff80000893b8e0 x28: ffffdddf92f9b000 x27: ffff46a2c0e8bc05
[   12.211632] x26: ffff46a2c1041200 x25: 0000000000000000 x24: 00000000173eed80
[   12.211636] x23: ffff80000893b9c0 x22: ffff80000893b940 x21: 0000000000000000
[   12.211641] x20: ffff46a2c1039f00 x19: ffff46a2c1039f00 x18: 0000000000000000
[   12.211645] x17: 0000000000000038 x16: 000000000000d904 x15: 0000000000000003
[   12.211649] x14: ffffdddf9357ce48 x13: ffffdddf935e71c8 x12: 000000000004803c
[   12.211653] x11: 00000000a867d7ad x10: 00000000a867d7ad x9 : ffffdddf90c28df4
[   12.211657] x8 : ffffdddf9357a980 x7 : 0000000000000000 x6 : 0000000000000004
[   12.211661] x5 : ffffffffffffffc8 x4 : 00000000173eed80 x3 : ffff80000893b940
[   12.211665] x2 : 00000000173eed80 x1 : ffff80000893b940 x0 : 0000000000000000
[   12.211669] Call trace:
[   12.211670]  clk_core_init_rate_req+0x84/0x90
[   12.211673]  clk_core_round_rate_nolock+0xe8/0x10c
[   12.211675]  clk_mux_determine_rate_flags+0x174/0x1f0
[   12.211677]  clk_mux_determine_rate+0x1c/0x30
[   12.211680]  clk_core_determine_round_nolock+0x74/0x130
[   12.211682]  clk_core_round_rate_nolock+0x58/0x10c
[   12.211684]  clk_core_round_rate_nolock+0xf4/0x10c
[   12.211686]  clk_core_set_rate_nolock+0x194/0x2ac
[   12.211688]  clk_set_rate+0x40/0x94
[   12.211691]  _opp_config_clk_single+0x38/0xa0
[   12.211693]  _set_opp+0x1b0/0x500
[   12.211695]  dev_pm_opp_set_rate+0x120/0x290
[   12.211697]  panfrost_devfreq_target+0x3c/0x50 [panfrost]
[   12.211705]  devfreq_set_target+0x8c/0x2d0
[   12.211707]  devfreq_update_target+0xcc/0xf4
[   12.211708]  devfreq_monitor+0x40/0x1d0
[   12.211710]  process_one_work+0x294/0x664
[   12.211712]  worker_thread+0x7c/0x45c
[   12.211713]  kthread+0x104/0x110
[   12.211716]  ret_from_fork+0x10/0x20
[   12.211718] irq event stamp: 7102
[   12.211719] hardirqs last  enabled at (7101): [<ffffdddf904ea5a0>] finish_task_switch.isra.0+0xec/0x2f0
[   12.211723] hardirqs last disabled at (7102): [<ffffdddf91794b74>] el1_dbg+0x24/0x90
[   12.211726] softirqs last  enabled at (6716): [<ffffdddf90410be4>] __do_softirq+0x414/0x588
[   12.211728] softirqs last disabled at (6507): [<ffffdddf904171d8>] ____do_softirq+0x18/0x24
[   12.211730] ---[ end trace 0000000000000000 ]---

Fixes: 262ca38 ("clk: Stop forwarding clk_rate_requests to the parent")
Signed-off-by: AngeloGioacchino Del Regno <angelogioacchino.delregno@collabora.com>
Link: https://lore.kernel.org/r/20221011135548.318323-1-angelogioacchino.delregno@collabora.com
Signed-off-by: Stephen Boyd <sboyd@kernel.org>
naota pushed a commit that referenced this issue Feb 27, 2024
When trying to use copy_from_kernel_nofault() to read vsyscall page
through a bpf program, the following oops was reported:

  BUG: unable to handle page fault for address: ffffffffff600000
  #PF: supervisor read access in kernel mode
  #PF: error_code(0x0000) - not-present page
  PGD 3231067 P4D 3231067 PUD 3233067 PMD 3235067 PTE 0
  Oops: 0000 [#1] PREEMPT SMP PTI
  CPU: 1 PID: 20390 Comm: test_progs ...... 6.7.0+ #58
  Hardware name: QEMU Standard PC (i440FX + PIIX, 1996) ......
  RIP: 0010:copy_from_kernel_nofault+0x6f/0x110
  ......
  Call Trace:
   <TASK>
   ? copy_from_kernel_nofault+0x6f/0x110
   bpf_probe_read_kernel+0x1d/0x50
   bpf_prog_2061065e56845f08_do_probe_read+0x51/0x8d
   trace_call_bpf+0xc5/0x1c0
   perf_call_bpf_enter.isra.0+0x69/0xb0
   perf_syscall_enter+0x13e/0x200
   syscall_trace_enter+0x188/0x1c0
   do_syscall_64+0xb5/0xe0
   entry_SYSCALL_64_after_hwframe+0x6e/0x76
   </TASK>
  ......
  ---[ end trace 0000000000000000 ]---

The oops is triggered when:

1) A bpf program uses bpf_probe_read_kernel() to read from the vsyscall
page and invokes copy_from_kernel_nofault() which in turn calls
__get_user_asm().

2) Because the vsyscall page address is not readable from kernel space,
a page fault exception is triggered accordingly.

3) handle_page_fault() considers the vsyscall page address as a user
space address instead of a kernel space address. This results in the
fix-up setup by bpf not being applied and a page_fault_oops() is invoked
due to SMAP.

Considering handle_page_fault() has already considered the vsyscall page
address as a userspace address, fix the problem by disallowing vsyscall
page read for copy_from_kernel_nofault().

Originally-by: Thomas Gleixner <tglx@linutronix.de>
Reported-by: syzbot+72aa0161922eba61b50e@syzkaller.appspotmail.com
Closes: https://lore.kernel.org/bpf/CAG48ez06TZft=ATH1qh2c5mpS5BT8UakwNkzi6nvK5_djC-4Nw@mail.gmail.com
Reported-by: xingwei lee <xrivendell7@gmail.com>
Closes: https://lore.kernel.org/bpf/CABOYnLynjBoFZOf3Z4BhaZkc5hx_kHfsjiW+UWLoB=w33LvScw@mail.gmail.com
Signed-off-by: Hou Tao <houtao1@huawei.com>
Reviewed-by: Sohil Mehta <sohil.mehta@intel.com>
Acked-by: Thomas Gleixner <tglx@linutronix.de>
Link: https://lore.kernel.org/r/20240202103935.3154011-3-houtao@huaweicloud.com
Signed-off-by: Alexei Starovoitov <ast@kernel.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant