linux-btrfs.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* Root filesystem read access for firmware load during hibernation image writing
@ 2024-08-28 19:08 Maciej S. Szmigiero
  2024-10-05 13:16 ` Maciej S. Szmigiero
  2024-10-05 17:40 ` Pavel Machek
  0 siblings, 2 replies; 6+ messages in thread
From: Maciej S. Szmigiero @ 2024-08-28 19:08 UTC (permalink / raw)
  To: Rafael J. Wysocki, Len Brown, Pavel Machek
  Cc: linux-pm, linux-kernel, Chris Mason, Josef Bacik, David Sterba,
	linux-btrfs

Hi,

I have a quick question about hibernation "image writing" state - is
(root) filesystem *read* access supposed to be working normally at that point?

Specifically, I know that devices are resumed (PMSG_THAW) after preparing
the hibernation image.

In my case, a USB device (RTL8821CU) gets reset at that stage due to
commit 04b8c8143d46 ("btusb: fix Realtek suspend/resume") and so it tries
to request_firmware() from the root filesystem after that thaw/reset,
when the hibernation image is being written.

It usually succeeds, however often it deadlocks somewhere in Btrfs code
resulting in the system failing to power off after writing the hibernate
image:
power_off() calls dpm_suspend_start(), which calls dpm_prepare(), which
waits for device probe to finish.

And device probe is stuck forever trying to load that USB stick firmware
from the filesystem - so in the end the system never powers off during
(after) hibernation.

That's why I wonder whether this firmware load is supposed to work correctly
during that hibernation state and so the system may be hitting some kind of
a swsusp/btrfs/block layer race condition.

Or, alternatively, maybe  reading files is not supported at this point and
so this is really a btrtl/rtw88 bug?

CCing Btrfs people in case it is some known Btrfs issue.

Btw, this is on upstream kernel 6.10.6 and the "Show Blocked State" trace
during that failed power off is attached below.

Thanks,
Maciej

> [59782.982908][    C0] sysrq: Show Blocked State                                
> [59782.987522][    C0] task:kworker/u19:0   state:D stack:0     pid:84    tgid:84    ppid:2      flags:0x00004000
> [59782.998043][    C0] Workqueue: hci0 hci_power_on [bluetooth]
> [59783.004047][    C0] Call Trace:
> [59783.007356][    C0]  <TASK>
> [59783.010303][    C0]  __schedule+0x3a2/0x1520
> [59783.014805][    C0]  schedule+0x23/0xf0
> [59783.018846][    C0]  io_schedule+0x4d/0x80
> [59783.023157][    C0]  bit_wait_io+0xd/0x60
> [59783.027373][    C0]  __wait_on_bit+0x41/0x100
> [59783.031952][    C0]  ? wait_for_completion_killable+0x1c0/0x1c0
> [59783.038182][    C0]  out_of_line_wait_on_bit+0x90/0xb0
> [59783.043598][    C0]  ? swake_up_locked+0x50/0x50
> [59783.048462][    C0]  read_extent_buffer_pages+0x1e8/0x210
> [59783.054155][    C0]  btrfs_read_extent_buffer+0x89/0x170
> [59783.059754][    C0]  read_tree_block+0x3c/0x90
> [59783.064428][    C0]  read_block_for_search+0x24b/0x350
> [59783.069846][    C0]  btrfs_search_slot+0x31e/0xc30
> [59783.074898][    C0]  ? btrfs_alloc_inode+0x4e/0x2a0
> [59783.080024][    C0]  btrfs_lookup_inode+0x3a/0xc0
> [59783.084980][    C0]  ? btrfs_fill_inode+0x49/0x220
> [59783.090019][    C0]  btrfs_read_locked_inode+0x543/0x620
> [59783.095610][    C0]  ? can_cow_file_range_inline+0x70/0x70
> [59783.101381][    C0]  btrfs_iget_path+0x8f/0xe0
> [59783.106054][    C0]  btrfs_lookup_dentry+0x347/0x610
> [59783.111274][    C0]  ? d_alloc_parallel+0x225/0x3d0
> [59783.116415][    C0]  btrfs_lookup+0xe/0x30
> [59783.120733][    C0]  __lookup_slow+0x9a/0x170
> [59783.125314][    C0]  walk_component+0x13e/0x1d0
> [59783.130075][    C0]  ? inode_permission+0x154/0x1b0
> [59783.135207][    C0]  link_path_walk.part.0.constprop.0+0x26b/0x370
> [59783.141704][    C0]  ? path_init+0x5f/0x430
> [59783.146102][    C0]  path_openat+0xa3/0x1270
> [59783.150590][    C0]  do_file_open_root+0x10b/0x1f0
> [59783.155633][    C0]  ? alloc_lookup_fw_priv+0x14e/0x270
> [59783.161138][    C0]  file_open_root+0x9f/0x170
> [59783.165820][    C0]  kernel_read_file_from_path_initns+0xbd/0x140
> [59783.172223][    C0]  fw_get_filesystem_firmware+0x146/0x300
> [59783.178091][    C0]  _request_firmware+0x32d/0x520
> [59783.183134][    C0]  ? bt_info+0x6e/0x90 [bluetooth]
> [59783.188431][    C0]  request_firmware+0x45/0x70
> [59783.193192][    C0]  rtl_load_file+0x62/0x100 [btrtl]
> [59783.198508][    C0]  btrtl_initialize+0x1e2/0x690 [btrtl]
> [59783.204184][    C0]  ? work_grab_pending+0x169/0x1b0
> [59783.209419][    C0]  btrtl_setup_realtek+0x21/0x90 [btrtl]
> [59783.215191][    C0]  btusb_setup_realtek+0x12/0x30 [btusb]
> [59783.220955][    C0]  hci_dev_open_sync+0x101/0xb80 [bluetooth]
> [59783.227159][    C0]  hci_dev_do_open+0x2e/0x70 [bluetooth]
> [59783.232982][    C0]  hci_power_on+0x4d/0x250 [bluetooth]
> [59783.238624][    C0]  process_one_work+0x170/0x380
> [59783.243575][    C0]  worker_thread+0x2d8/0x400
> [59783.248248][    C0]  ? cancel_work_sync+0x80/0x80
> [59783.253198][    C0]  kthread+0xc8/0x100
> [59783.257234][    C0]  ? kthread_park+0x90/0x90
> [59783.261812][    C0]  ret_from_fork+0x4c/0x60
> [59783.266297][    C0]  ? kthread_park+0x90/0x90
> [59783.270885][    C0]  ret_from_fork_asm+0x11/0x20
> [59783.275736][    C0]  </TASK>
> [59783.278785][    C0] task:btrfs-transacti state:D stack:0     pid:3806  tgid:3806  ppid:2      flags:0x00004000
> [59783.289289][    C0] Call Trace:
> [59783.292598][    C0]  <TASK>
> [59783.295536][    C0]  __schedule+0x3a2/0x1520
> [59783.300031][    C0]  schedule+0x23/0xf0
> [59783.304065][    C0]  schedule_preempt_disabled+0x11/0x20
> [59783.309656][    C0]  rwsem_down_write_slowpath+0x238/0x5b0
> [59783.315430][    C0]  down_write+0x56/0x60
> [59783.319644][    C0]  btrfs_tree_lock_nested+0x22/0x90
> [59783.324958][    C0]  btrfs_search_slot+0x62b/0xc30
> [59783.330007][    C0]  btrfs_lookup_inode+0x3a/0xc0
> [59783.334964][    C0]  __btrfs_update_delayed_inode+0x85/0x310
> [59783.340927][    C0]  __btrfs_run_delayed_items+0x1cd/0x2c0
> [59783.346699][    C0]  btrfs_commit_transaction+0x232/0xe20
> [59783.352375][    C0]  ? start_transaction+0xc0/0x820
> [59783.357508][    C0]  transaction_kthread+0x15c/0x1c0
> [59783.362735][    C0]  ? close_ctree+0x490/0x490
> [59783.367408][    C0]  kthread+0xc8/0x100
> [59783.371437][    C0]  ? kthread_park+0x90/0x90
> [59783.376008][    C0]  ret_from_fork+0x4c/0x60
> [59783.380492][    C0]  ? kthread_park+0x90/0x90
> [59783.386462][    C0]  ret_from_fork_asm+0x11/0x20
> [59783.392531][    C0]  </TASK>
> [59783.396713][    C0] task:elogind-daemon  state:D stack:0     pid:6101  tgid:6101  ppid:1      flags:0x00004002
> [59783.408306][    C0] Call Trace:
> [59783.412679][    C0]  <TASK>
> [59783.416705][    C0]  __schedule+0x3a2/0x1520
> [59783.422270][    C0]  ? acpi_ut_repair_name+0x3c/0xc0
> [59783.428577][    C0]  ? acpi_ns_search_and_enter+0x55/0x220
> [59783.435422][    C0]  schedule+0x23/0xf0
> [59783.440553][    C0]  schedule_timeout+0x160/0x170
> [59783.446593][    C0]  wait_for_completion+0x81/0x130
> [59783.452815][    C0]  __flush_work+0x18a/0x2e0
> [59783.458474][    C0]  ? flush_workqueue_prep_pwqs+0x120/0x120
> [59783.465507][    C0]  wait_for_device_probe+0x25/0xa0
> [59783.471797][    C0]  ? __alloc_pages_noprof+0x1c3/0x320
> [59783.478363][    C0]  dpm_prepare+0x28/0x420
> [59783.483842][    C0]  dpm_suspend_start+0x28/0x70
> [59783.489779][    C0]  hibernation_platform_enter+0x58/0x140
> [59783.496621][    C0]  hibernate+0x3ae/0x420
> [59783.502013][    C0]  state_store+0xea/0x100
> [59783.507492][    C0]  kernfs_fop_write_iter+0x172/0x200
> [59783.513973][    C0]  vfs_write+0x265/0x4a0
> [59783.519366][    C0]  ksys_write+0x77/0x110
> [59783.524747][    C0]  do_syscall_64+0x64/0x130
> [59783.530399][    C0]  ? devkmsg_write+0xcf/0x1c0
> [59783.536231][    C0]  ? xas_load+0x8/0xc0
> [59783.541423][    C0]  ? xas_store+0x3b0/0x630
> [59783.546980][    C0]  ? do_iter_readv_writev+0x114/0x210
> [59783.553539][    C0]  ? __xa_erase+0x53/0xa0
> [59783.559001][    C0]  ? xa_erase+0x2e/0x50
> [59783.564279][    C0]  ? zswap_invalidate+0x32/0x50
> [59783.570292][    C0]  ? free_swap_slot+0x85/0xc0
> [59783.576108][    C0]  ? put_swap_folio+0x19c/0x3c0
> [59783.582114][    C0]  ? delete_from_swap_cache+0x6b/0xa0
> [59783.588663][    C0]  ? folio_free_swap+0x95/0x1d0
> [59783.594659][    C0]  ? do_writev+0x82/0x120
> [59783.600120][    C0]  ? do_wp_page+0x829/0xfa0
> [59783.605761][    C0]  ? sysvec_call_function_single+0x15/0x90
> [59783.612770][    C0]  ? asm_sysvec_call_function_single+0x16/0x20
> [59783.620139][    C0]  ? __pte_offset_map+0x25/0x1a0
> [59783.626241][    C0]  ? __handle_mm_fault+0x7e0/0x850
> [59783.632517][    C0]  ? __count_memcg_events+0x53/0xf0
> [59783.638882][    C0]  ? handle_mm_fault+0xc9/0x2c0
> [59783.644880][    C0]  ? do_user_addr_fault+0x476/0x750
> [59783.651248][    C0]  ? exc_page_fault+0x73/0x140
> [59783.657166][    C0]  ? irqentry_exit_to_user_mode+0x58/0x130
> [59783.664173][    C0]  entry_SYSCALL_64_after_hwframe+0x55/0x5d
> [59783.737346][    C0] task:kworker/u17:5   state:D stack:0     pid:228761 tgid:228761 ppid:2      flags:0x00004000
> [59783.749138][    C0] Workqueue: writeback wb_workfn (flush-btrfs-1)
> [59783.756741][    C0] Call Trace:
> [59783.761149][    C0]  <TASK>
> [59783.765194][    C0]  __schedule+0x3a2/0x1520
> [59783.770783][    C0]  ? blk_mq_flush_plug_list.part.0+0x185/0x5b0
> [59783.778208][    C0]  schedule+0x23/0xf0
> [59783.783346][    C0]  io_schedule+0x4d/0x80
> [59783.788764][    C0]  bit_wait_io+0xd/0x60
> [59783.794086][    C0]  __wait_on_bit+0x41/0x100
> [59783.799780][    C0]  ? wait_for_completion_killable+0x1c0/0x1c0
> [59783.807124][    C0]  out_of_line_wait_on_bit+0x90/0xb0
> [59783.813649][    C0]  ? swake_up_locked+0x50/0x50
> [59783.819628][    C0]  read_extent_buffer_pages+0x1e8/0x210
> [59783.826412][    C0]  btrfs_read_extent_buffer+0x89/0x170
> [59783.833092][    C0]  read_tree_block+0x3c/0x90
> [59783.838871][    C0]  read_block_for_search+0x24b/0x350
> [59783.845372][    C0]  btrfs_search_slot+0x31e/0xc30
> [59783.851514][    C0]  ? run_delalloc_nocow+0x72/0x780
> [59783.857839][    C0]  btrfs_lookup_file_extent+0x48/0x70
> [59783.864432][    C0]  run_delalloc_nocow+0xd0/0x780
> [59783.870584][    C0]  ? __wake_up+0x54/0x80
> [59783.876000][    C0]  ? merge_next_state+0x27/0xc0
> [59783.882059][    C0]  btrfs_run_delalloc_range+0x51/0x5e0
> [59783.888745][    C0]  ? find_lock_delalloc_range+0x147/0x210
> [59783.895702][    C0]  writepage_delalloc+0xaa/0x140
> [59783.901854][    C0]  extent_write_cache_pages+0x289/0x800
> [59783.908648][    C0]  ? sched_balance_find_src_group+0x4c4/0xc40
> [59783.915984][    C0]  btrfs_writepages+0x69/0xc0
> [59783.921851][    C0]  do_writepages+0xcf/0x260
> [59783.927544][    C0]  ? sched_balance_rq+0x213/0xe80
> [59783.933790][    C0]  __writeback_single_inode+0x51/0x370
> [59783.940486][    C0]  ? wbc_detach_inode+0x129/0x270
> [59783.946726][    C0]  writeback_sb_inodes+0x282/0x560
> [59783.953075][    C0]  __writeback_inodes_wb+0x4c/0xe0
> [59783.959410][    C0]  wb_writeback+0x187/0x300
> [59783.965122][    C0]  wb_workfn+0x2c2/0x4b0
> [59783.970538][    C0]  process_one_work+0x170/0x380
> [59783.976587][    C0]  worker_thread+0x2d8/0x400
> [59783.982359][    C0]  ? cancel_work_sync+0x80/0x80
> [59783.988413][    C0]  kthread+0xc8/0x100
> [59783.993556][    C0]  ? kthread_park+0x90/0x90
> [59783.999233][    C0]  ret_from_fork+0x4c/0x60
> [59784.004814][    C0]  ? kthread_park+0x90/0x90
> [59784.010482][    C0]  ret_from_fork_asm+0x11/0x20
> [59784.016430][    C0]  </TASK>
> [59784.020579][    C0] task:kworker/2:0     state:D stack:0     pid:235839 tgid:235839 ppid:2      flags:0x00004000
> [59784.032377][    C0] Workqueue: events request_firmware_work_func
> [59784.039807][    C0] Call Trace:
> [59784.044224][    C0]  <TASK>
> [59784.048276][    C0]  __schedule+0x3a2/0x1520
> [59784.053884][    C0]  ? blk_mq_flush_plug_list.part.0+0x185/0x5b0
> [59784.061317][    C0]  schedule+0x23/0xf0
> [59784.066472][    C0]  io_schedule+0x4d/0x80
> [59784.071897][    C0]  bit_wait_io+0xd/0x60
> [59784.077237][    C0]  __wait_on_bit+0x41/0x100
> [59784.082940][    C0]  ? wait_for_completion_killable+0x1c0/0x1c0
> [59784.090277][    C0]  out_of_line_wait_on_bit+0x90/0xb0
> [59784.096800][    C0]  ? swake_up_locked+0x50/0x50
> [59784.102778][    C0]  read_extent_buffer_pages+0x1e8/0x210
> [59784.109578][    C0]  btrfs_read_extent_buffer+0x89/0x170
> [59784.116300][    C0]  read_tree_block+0x3c/0x90
> [59784.122114][    C0]  read_block_for_search+0x24b/0x350
> [59784.128656][    C0]  btrfs_search_slot+0x31e/0xc30
> [59784.134834][    C0]  btrfs_lookup_csum+0x6d/0x170
> [59784.140915][    C0]  ? btrfs_csum_root+0x73/0xa0
> [59784.146911][    C0]  btrfs_lookup_bio_sums+0x12b/0x450
> [59784.153453][    C0]  btrfs_submit_chunk+0x134/0x580
> [59784.159718][    C0]  btrfs_submit_bio+0x16/0x30
> [59784.165617][    C0]  submit_one_bio+0x36/0x50
> [59784.171328][    C0]  btrfs_readahead+0x35f/0x390
> [59784.177324][    C0]  ? end_bbio_meta_write+0x320/0x320
> [59784.183857][    C0]  ? memcg_list_lru_alloc+0x3a0/0x3a0
> [59784.190484][    C0]  read_pages+0x58/0x220
> [59784.195920][    C0]  page_cache_ra_unbounded+0x103/0x180
> [59784.202633][    C0]  filemap_get_pages+0x105/0x580
> [59784.208813][    C0]  filemap_read+0xce/0x320
> [59784.214443][    C0]  ? alloc_vmap_area+0x2d2/0xb90
> [59784.220612][    C0]  ? alloc_pages_bulk_noprof+0x4af/0x570
> [59784.227507][    C0]  ? __vmalloc_node_range_noprof+0x381/0x8e0
> [59784.234780][    C0]  ? kernel_read_file+0x1ba/0x280
> [59784.241053][    C0]  __kernel_read+0x15e/0x2e0
> [59784.246853][    C0]  kernel_read_file+0x120/0x280
> [59784.252927][    C0]  kernel_read_file_from_path_initns+0xf2/0x140
> [59784.260443][    C0]  ? fw_map_paged_buf+0x60/0x60
> [59784.266489][    C0]  fw_get_filesystem_firmware+0x146/0x300
> [59784.273447][    C0]  _request_firmware+0x364/0x520
> [59784.279592][    C0]  request_firmware_work_func+0x41/0xa0
> [59784.286364][    C0]  process_one_work+0x170/0x380
> [59784.292422][    C0]  worker_thread+0x2d8/0x400
> [59784.298186][    C0]  ? cancel_work_sync+0x80/0x80
> [59784.304214][    C0]  kthread+0xc8/0x100
> [59784.309322][    C0]  ? kthread_park+0x90/0x90
> [59784.314963][    C0]  ret_from_fork+0x4c/0x60
> [59784.320528][    C0]  ? kthread_park+0x90/0x90
> [59784.326171][    C0]  ret_from_fork_asm+0x11/0x20
> [59784.332085][    C0]  </TASK>
> [59784.336195][    C0] task:kworker/u18:0   state:D stack:0     pid:236036 tgid:236036 ppid:2      flags:0x00004000
> [59784.347964][    C0] Workqueue: events_unbound deferred_probe_work_func
> [59784.355939][    C0] Call Trace:
> [59784.360337][    C0]  <TASK>
> [59784.364365][    C0]  __schedule+0x3a2/0x1520
> [59784.369950][    C0]  ? usb_start_wait_urb+0xbb/0x190 [usbcore]
> [59784.377180][    C0]  schedule+0x23/0xf0
> [59784.382303][    C0]  schedule_timeout+0x160/0x170
> [59784.388343][    C0]  wait_for_completion+0x81/0x130
> [59784.394559][    C0]  rtw_chip_info_setup+0x15a/0x750 [rtw88_core]
> [59784.402071][    C0]  rtw_usb_probe+0x431/0xd00 [rtw88_usb]
> [59784.408929][    C0]  usb_probe_interface+0xfe/0x310 [usbcore]
> [59784.416092][    C0]  really_probe+0xc8/0x3a0
> [59784.421688][    C0]  ? pm_runtime_barrier+0x61/0xb0
> [59784.427918][    C0]  ? driver_probe_device+0xb0/0xb0
> [59784.434233][    C0]  __driver_probe_device+0x78/0x150
> [59784.440637][    C0]  driver_probe_device+0x2d/0xb0
> [59784.446755][    C0]  __device_attach_driver+0x8c/0x100
> [59784.453243][    C0]  bus_for_each_drv+0x80/0xd0
> [59784.459091][    C0]  __device_attach+0xc0/0x1d0
> [59784.464941][    C0]  bus_probe_device+0x89/0xa0
> [59784.470775][    C0]  deferred_probe_work_func+0x8a/0xe0
> [59784.477340][    C0]  process_one_work+0x170/0x380
> [59784.483364][    C0]  worker_thread+0x2d8/0x400
> [59784.489117][    C0]  ? cancel_work_sync+0x80/0x80
> [59784.495138][    C0]  kthread+0xc8/0x100
> [59784.500246][    C0]  ? kthread_park+0x90/0x90
> [59784.505922][    C0]  ret_from_fork+0x4c/0x60
> [59784.511495][    C0]  ? kthread_park+0x90/0x90
> [59784.517147][    C0]  ret_from_fork_asm+0x11/0x20
> [59784.523077][    C0]  </TASK>

^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2024-10-11 23:44 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2024-08-28 19:08 Root filesystem read access for firmware load during hibernation image writing Maciej S. Szmigiero
2024-10-05 13:16 ` Maciej S. Szmigiero
2024-10-11 23:11   ` Luis Chamberlain
2024-10-11 23:39     ` Darrick J. Wong
2024-10-11 23:44       ` Luis Chamberlain
2024-10-05 17:40 ` Pavel Machek

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).