Root filesystem read access for firmware load during hibernation image writing

Root filesystem read access for firmware load during hibernation image writing

[Maciej S. Szmigiero]

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>

Re: Root filesystem read access for firmware load during hibernation image writing

[Maciej S. Szmigiero]

The issue below still happens on kernel version 6.11.1.

Created a kernel bugzilla entry for it:
https://bugzilla.kernel.org/show_bug.cgi?id=219353

It would be nice to at least know whether the filesystem read access supposed is
to be working normally at PMSG_THAW hibernation stage to assign the issue accordingly.

CC: request_firmware() maintainers

Thanks,
Maciej

On 28.08.2024 21:08, Maciej S. Szmigiero wrote:
> 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.

Re: Root filesystem read access for firmware load during hibernation image writing

[Pavel Machek]

[-- Attachment #1: Type: text/plain, Size: 1418 bytes --]

Hi!

> 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?

I'd say not supported at this point. Reading file may still read to
atime update, etc, and we can't really can't support that easily.

Suggestion is to keep firmware cached in memory, or at least cache it
in memory when hibernation begins.

BR,
										Pavel
										
-- 
People of Russia, stop Putin before his war on Ukraine escalates.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 195 bytes --]

Re: Root filesystem read access for firmware load during hibernation image writing

[Maciej S. Szmigiero]

On 5.10.2024 19:40, Pavel Machek wrote:
> Hi!
> 
>> 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?
> 
> I'd say not supported at this point. Reading file may still read to
> atime update, etc, and we can't really can't support that easily.

Thanks for this clarification.

I've dropped btrfs folks from the CC list since this isn't a btrfs issue
after all and added rtw88/btrtl maintainers instead.
  
> Suggestion is to keep firmware cached in memory, or at least cache it
> in memory when hibernation begins.

Since a WiFi/BT NIC is hardly useful for hibernation snapshot writing
operation it seems that an easier option would be to simply return
something like -EPROBE_DEFER from both rtw88 and btrtl probe callbacks
during PMSG_THAW hibernation stage.
That -EPROBE_DEFER will hopefully handle the unlikely case that the
hibernation snapshot writing fails or someone is running a
HIBERNATION_TEST_RESUME.

In turn, the easiest trigger for this would be the "in_suspend"
variable being set, however this would require EXPORTing it - it looks
like system_entering_hibernation() only covers the case when the
system is hibernating using platform hibernation support.

I will see whether this workaround works for me, if someone wants
to implement the "firmware caching" approach instead then feel
free to do so.


By the way, I don't see any reason why other USB devices that load
firmware at their probe time can't be affected too since that
lock_device_hotplug() call in hibernate() seems to only prevent
CPU/RAM/ACPI hotplug, not USB hotplug.

So if such USB device happens to get reset during hibernation time
(for example from hub EMI) it would suffer the same issue.

> BR,
> 										Pavel
> 										

Thanks,
Maciej

Re: Root filesystem read access for firmware load during hibernation image writing

[Luis Chamberlain]

On Sat, Oct 05, 2024 at 03:16:27PM +0200, Maciej S. Szmigiero wrote:
> The issue below still happens on kernel version 6.11.1.
> 
> Created a kernel bugzilla entry for it:
> https://bugzilla.kernel.org/show_bug.cgi?id=219353
> 
> It would be nice to at least know whether the filesystem read access supposed is
> to be working normally at PMSG_THAW hibernation stage to assign the issue accordingly.

No, there are races possible if you trigger IO to a fs before a suspend
is going on. If you have *more* IO ongoing, then you are likely to stall
suspend and not be able to recover.

> CC: request_firmware() maintainers

If IO is ongoing suspend is broken today because of the kthread freezer
which puts kthreads which should sleep idle, but if IO is ongoing we
can stall. This is work which we've been working to remove for years and
after its removal we can gracefully freeze filesystems [0] [1]
properly on suspend.

Other than that, obviously upon resume we want firmware to be present,
and to prevent races on resume we have a firmware cache. So on suspend
we cache used firmware so its available in cache on resume. See
device_cache_fw_images().

So.. we just now gotta respin the latest effort. I had stopped because
I know Darrick had some changes which he needed to get in sooner but
since this is low hanging fruit I never got around to it. So someone
just needs to respin the series.

[0] https://lwn.net/Articles/752588/
[1] https://lwn.net/Articles/935602/

  Luis

Re: Root filesystem read access for firmware load during hibernation image writing

[Darrick J. Wong]

On Fri, Oct 11, 2024 at 04:11:49PM -0700, Luis Chamberlain wrote:
> On Sat, Oct 05, 2024 at 03:16:27PM +0200, Maciej S. Szmigiero wrote:
> > The issue below still happens on kernel version 6.11.1.
> > 
> > Created a kernel bugzilla entry for it:
> > https://bugzilla.kernel.org/show_bug.cgi?id=219353
> > 
> > It would be nice to at least know whether the filesystem read access supposed is
> > to be working normally at PMSG_THAW hibernation stage to assign the issue accordingly.
> 
> No, there are races possible if you trigger IO to a fs before a suspend
> is going on. If you have *more* IO ongoing, then you are likely to stall
> suspend and not be able to recover.
> 
> > CC: request_firmware() maintainers
> 
> If IO is ongoing suspend is broken today because of the kthread freezer
> which puts kthreads which should sleep idle, but if IO is ongoing we
> can stall. This is work which we've been working to remove for years and
> after its removal we can gracefully freeze filesystems [0] [1]
> properly on suspend.
> 
> Other than that, obviously upon resume we want firmware to be present,
> and to prevent races on resume we have a firmware cache. So on suspend
> we cache used firmware so its available in cache on resume. See
> device_cache_fw_images().

Reads are generally supposed to succeed on a suspended system but if the
read causes a write (e.g. atime update) they can block just like a write
would.  So in the end you probably have to cache the firmware blobs in a
tmpfs or something like that.

> So.. we just now gotta respin the latest effort. I had stopped because
> I know Darrick had some changes which he needed to get in sooner but

Do you remember what changes those were?  I don't. :(

--D

> since this is low hanging fruit I never got around to it. So someone
> just needs to respin the series.
> 
> [0] https://lwn.net/Articles/752588/
> [1] https://lwn.net/Articles/935602/
> 
>   Luis

Re: Root filesystem read access for firmware load during hibernation image writing

[Luis Chamberlain]

On Fri, Oct 11, 2024 at 04:39:53PM -0700, Darrick J. Wong wrote:
> On Fri, Oct 11, 2024 at 04:11:49PM -0700, Luis Chamberlain wrote:
> 
> Reads are generally supposed to succeed on a suspended system but if the
> read causes a write (e.g. atime update) they can block just like a write
> would.  So in the end you probably have to cache the firmware blobs in a
> tmpfs or something like that.

The fw cache stuff caches is it in memory to avoid these races on resume.

> > So.. we just now gotta respin the latest effort. I had stopped because
> > I know Darrick had some changes which he needed to get in sooner but
> 
> Do you remember what changes those were?  I don't. :(

Yeah I have a random tree somewhere lemme see...

https://git.kernel.org/pub/scm/linux/kernel/git/mcgrof/linux-next.git/log/?h=20230507-fs-freeze

Fortunately most of it is coccinelle smpl so should be easy to rebase.

  Luis

Re: Root filesystem read access for firmware load during hibernation image writing

[Maciej S. Szmigiero]

On 12.10.2024 01:11, Luis Chamberlain wrote:
> On Sat, Oct 05, 2024 at 03:16:27PM +0200, Maciej S. Szmigiero wrote:
>> The issue below still happens on kernel version 6.11.1.
>>
>> Created a kernel bugzilla entry for it:
>> https://bugzilla.kernel.org/show_bug.cgi?id=219353
>>
>> It would be nice to at least know whether the filesystem read access supposed is
>> to be working normally at PMSG_THAW hibernation stage to assign the issue accordingly.
> 
> No, there are races possible if you trigger IO to a fs before a suspend
> is going on. If you have *more* IO ongoing, then you are likely to stall
> suspend and not be able to recover.

That's more or less the same answer as Pavel wrote 2 weeks ago,
but thanks for confirming it and providing more details on the subject.

Since it essentially makes this an rtw88/btrtl specific issue (and not
a generic PM/hibernation one) I have updated and reassigned the
aforementioned kernel bug accordingly.

As it is just my personal system that is affected by this hibernation
issue I'm content with just patching its kernel with a simple
workaround [1].
WiFi/BT NIC is hardly useful for hibernation snapshot writing anyway.

But of course if someone has the bandwidth to get a clean fix merged
then it would be great to have this fixed upstream for everyone.

>    Luis

Thanks,
Maciej

[1]: https://github.com/maciejsszmigiero/linux/commit/f6188a940324b4bc8f51dcb1a9ae1a489e57bd1d