Intermittent storage (dm-crypt?) freeze - regression 6.4->6.5

Hi,

Since updating from 6.4.13 to 6.5.5 occasionally I hit a storage subsystem freeze - any I/O ends up frozen. I'm not sure what exactly triggers the issue, but often it happens when doing some LVM operations (lvremove, lvrename etc) on a dm-thin volume together with bulk data copy to/from another LVM thin volume with ext4 fs.

The storage stack I use is:
nvme -> dm-crypt (LUKS) -> dm-thin (LVM thin pool) -> ext4

And this whole thing running in a (PV) dom0 under Xen, on Qubes OS 4.2 to be specific.

I can reproduce the issue on at least 3 different machines. I did tried also 6.5.6 and the issue is still there. I haven't checked newer versions, but briefly reviewed git log and haven't found anything suggesting a fix to similar issue.

I managed to bisect it down to this commit:

commit 5054e778fcd9cd29ddaa8109077cd235527e4f94
Author: Mikulas Patocka <[email protected]>
Date: Mon May 1 09:19:17 2023 -0400

dm crypt: allocate compound pages if possible

It was reported that allocating pages for the write buffer in dm-crypt causes measurable overhead [1].

Change dm-crypt to allocate compound pages if they are available. If not, fall back to the mempool.

[1] https://listman.redhat.com/archives/dm-devel/2023-February/053284.html

Suggested-by Matthew Wilcox <[email protected]>

Signed-off-by Mikulas Patocka <[email protected]>

Signed-off-by Mike Snitzer <[email protected]>

TBH, I'm not sure if the bug is in this commit, or maybe in some functions it uses (I don't see dm-crypt functions directly involved in the stack traces I collected). But reverting this commit on top of 6.5.6 seems to fix the issue.

I tried also CONFIG_PROVE_LOCKING, but it didn't show any issue.

I managed to collect "blocked tasks" dump via sysrq below. Few more can be found at https://github.com/QubesOS/qubes-issues/issues/8575

    [ 4246.558313] sysrq: Show Blocked State
    [ 4246.558388] task:journal-offline state:D stack:0     pid:8098  ppid:1      flags:0x00000002
    [ 4246.558407] Call Trace:
    [ 4246.558414]  <TASK>
    [ 4246.558422]  __schedule+0x23d/0x670
    [ 4246.558440]  schedule+0x5e/0xd0
    [ 4246.558450]  io_schedule+0x46/0x70
    [ 4246.558461]  folio_wait_bit_common+0x13d/0x350
    [ 4246.558475]  ? __pfx_wake_page_function+0x10/0x10
    [ 4246.558488]  folio_wait_writeback+0x2c/0x90
    [ 4246.558498]  mpage_prepare_extent_to_map+0x15c/0x4d0
    [ 4246.558512]  ext4_do_writepages+0x25f/0x770
    [ 4246.558523]  ext4_writepages+0xad/0x180
    [ 4246.558533]  do_writepages+0xcf/0x1e0
    [ 4246.558543]  ? __seccomp_filter+0x32a/0x4f0
    [ 4246.558554]  filemap_fdatawrite_wbc+0x63/0x90
    [ 4246.558567]  __filemap_fdatawrite_range+0x5c/0x80
    [ 4246.558578]  file_write_and_wait_range+0x4a/0xb0
    [ 4246.558588]  ext4_sync_file+0x88/0x380
    [ 4246.558598]  __x64_sys_fsync+0x3b/0x70
    [ 4246.558609]  do_syscall_64+0x5c/0x90
    [ 4246.558621]  ? exit_to_user_mode_prepare+0xb2/0xd0
    [ 4246.558632]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
    [ 4246.558644] RIP: 0033:0x7710cf124d0a
    [ 4246.558654] RSP: 002b:00007710ccdfda40 EFLAGS: 00000293 ORIG_RAX: 000000000000004a
    [ 4246.558668] RAX: ffffffffffffffda RBX: 000064bb92f67e60 RCX: 00007710cf124d0a
    [ 4246.558679] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000028
    [ 4246.558691] RBP: 000064bb92f72670 R08: 0000000000000000 R09: 00007710ccdfe6c0
    [ 4246.558702] R10: 00007710cf0adfee R11: 0000000000000293 R12: 000064bb92505940
    [ 4246.558713] R13: 0000000000000002 R14: 00007ffc05649500 R15: 00007710cc5fe000
    [ 4246.558728]  </TASK>
    [ 4246.558836] task:lvm             state:D stack:0     pid:7835  ppid:5665   flags:0x00004006
    [ 4246.558852] Call Trace:
    [ 4246.558857]  <TASK>
    [ 4246.558863]  __schedule+0x23d/0x670
    [ 4246.558874]  schedule+0x5e/0xd0
    [ 4246.558884]  io_schedule+0x46/0x70
    [ 4246.558894]  dm_wait_for_bios_completion+0xfc/0x110
    [ 4246.558909]  ? __pfx_autoremove_wake_function+0x10/0x10
    [ 4246.558922]  __dm_suspend+0x7e/0x1b0
    [ 4246.558932]  dm_internal_suspend_noflush+0x5c/0x80
    [ 4246.558946]  pool_presuspend+0xcc/0x130 [dm_thin_pool]
    [ 4246.558968]  dm_table_presuspend_targets+0x3f/0x60
    [ 4246.558980]  __dm_suspend+0x41/0x1b0
    [ 4246.558991]  dm_suspend+0xc0/0xe0
    [ 4246.559001]  dev_suspend+0xa5/0xd0
    [ 4246.559011]  ctl_ioctl+0x26e/0x350
    [ 4246.559020]  ? __pfx_dev_suspend+0x10/0x10
    [ 4246.559032]  dm_ctl_ioctl+0xe/0x20
    [ 4246.559041]  __x64_sys_ioctl+0x94/0xd0
    [ 4246.559052]  do_syscall_64+0x5c/0x90
    [ 4246.559062]  ? do_syscall_64+0x6b/0x90
    [ 4246.559072]  ? do_syscall_64+0x6b/0x90
    [ 4246.559081]  ? xen_pv_evtchn_do_upcall+0x54/0xb0
    [ 4246.559093]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
    [ 4246.559104] RIP: 0033:0x7f1cb77cfe0f
    [ 4246.559112] RSP: 002b:00007fff870f2560 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
    [ 4246.559141] RAX: ffffffffffffffda RBX: 00005b8d13c16580 RCX: 00007f1cb77cfe0f
    [ 4246.559152] RDX: 00005b8d144a2180 RSI: 00000000c138fd06 RDI: 0000000000000003
    [ 4246.559164] RBP: 00005b8d144a2180 R08: 00005b8d132b1190 R09: 00007fff870f2420
    [ 4246.559175] R10: 0000000000000000 R11: 0000000000000246 R12: 000000000000000c
    [ 4246.559186] R13: 00005b8d132aacf0 R14: 00005b8d1324414d R15: 00005b8d144a21b0
    [ 4246.559199]  </TASK>
    [ 4246.559207] task:kworker/u8:3    state:D stack:0     pid:8033  ppid:2      flags:0x00004000
    [ 4246.559222] Workqueue: writeback wb_workfn (flush-253:4)
    [ 4246.559238] Call Trace:
    [ 4246.559244]  <TASK>
    [ 4246.559249]  __schedule+0x23d/0x670
    [ 4246.559260]  schedule+0x5e/0xd0
    [ 4246.559270]  io_schedule+0x46/0x70
    [ 4246.559280]  folio_wait_bit_common+0x13d/0x350
    [ 4246.559290]  ? __pfx_wake_page_function+0x10/0x10
    [ 4246.559302]  mpage_prepare_extent_to_map+0x309/0x4d0
    [ 4246.559314]  ext4_do_writepages+0x25f/0x770
    [ 4246.559324]  ext4_writepages+0xad/0x180
    [ 4246.559334]  do_writepages+0xcf/0x1e0
    [ 4246.559344]  ? find_busiest_group+0x42/0x1a0
    [ 4246.559354]  __writeback_single_inode+0x3d/0x280
    [ 4246.559368]  writeback_sb_inodes+0x1ed/0x4a0
    [ 4246.559381]  __writeback_inodes_wb+0x4c/0xf0
    [ 4246.559393]  wb_writeback+0x298/0x310
    [ 4246.559403]  wb_do_writeback+0x230/0x2b0
    [ 4246.559414]  wb_workfn+0x5f/0x260
    [ 4246.559424]  ? _raw_spin_unlock+0xe/0x30
    [ 4246.559434]  ? finish_task_switch.isra.0+0x95/0x2b0
    [ 4246.559447]  ? __schedule+0x245/0x670
    [ 4246.559457]  process_one_work+0x1df/0x3e0

    [ 4246.559466]  worker_thread+0x51/0x390
    [ 4246.559475]  ? __pfx_worker_thread+0x10/0x10
    [ 4246.559484]  kthread+0xe5/0x120
    [ 4246.559495]  ? __pfx_kthread+0x10/0x10
    [ 4246.559504]  ret_from_fork+0x31/0x50
    [ 4246.559514]  ? __pfx_kthread+0x10/0x10
    [ 4246.559523]  ret_from_fork_asm+0x1b/0x30
    [ 4246.559536]  </TASK>

Quoted 6 lines · Marek Marczykowski-Górecki

Since updating from 6.4.13 to 6.5.5 occasionally I hit a storage subsystem freeze - any I/O ends up frozen. I'm not sure what exactly triggers the issue, but often it happens when doing some LVM operations (lvremove, lvrename etc) on a dm-thin volume together with bulk data copy to/from another LVM thin volume with ext4 fs.

[...]
#regzbot ^introduced: 5054e778fcd9cd

Hi,

Since updating from 6.4.13 to 6.5.5 occasionally I hit a storage subsystem freeze - any I/O ends up frozen. I'm not sure what exactly triggers the issue, but often it happens when doing some LVM operations (lvremove, lvrename etc) on a dm-thin volume together with bulk data copy to/from another LVM thin volume with ext4 fs.

The storage stack I use is:
nvme -> dm-crypt (LUKS) -> dm-thin (LVM thin pool) -> ext4

And this whole thing running in a (PV) dom0 under Xen, on Qubes OS 4.2 to be specific.

I can reproduce the issue on at least 3 different machines. I did tried also 6.5.6 and the issue is still there. I haven't checked newer versions, but briefly reviewed git log and haven't found anything suggesting a fix to similar issue.

I managed to bisect it down to this commit:

commit 5054e778fcd9cd29ddaa8109077cd235527e4f94
Author: Mikulas Patocka <[email protected]>
Date: Mon May 1 09:19:17 2023 -0400

dm crypt: allocate compound pages if possible

It was reported that allocating pages for the write buffer in dm-crypt causes measurable overhead [1].

Change dm-crypt to allocate compound pages if they are available. If not, fall back to the mempool.

[1] https://listman.redhat.com/archives/dm-devel/2023-February/053284.html

Suggested-by Matthew Wilcox <[email protected]>

Signed-off-by Mikulas Patocka <[email protected]>

Signed-off-by Mike Snitzer <[email protected]>

TBH, I'm not sure if the bug is in this commit, or maybe in some functions it uses (I don't see dm-crypt functions directly involved in the stack traces I collected). But reverting this commit on top of 6.5.6 seems to fix the issue.

I tried also CONFIG_PROVE_LOCKING, but it didn't show any issue.

I managed to collect "blocked tasks" dump via sysrq below. Few more can be found at https://github.com/QubesOS/qubes-issues/issues/8575

    [ 4246.558313] sysrq: Show Blocked State
    [ 4246.558388] task:journal-offline state:D stack:0     pid:8098  ppid:1      flags:0x00000002
    [ 4246.558407] Call Trace:
    [ 4246.558414]  <TASK>
    [ 4246.558422]  __schedule+0x23d/0x670
    [ 4246.558440]  schedule+0x5e/0xd0
    [ 4246.558450]  io_schedule+0x46/0x70
    [ 4246.558461]  folio_wait_bit_common+0x13d/0x350
    [ 4246.558475]  ? __pfx_wake_page_function+0x10/0x10
    [ 4246.558488]  folio_wait_writeback+0x2c/0x90
    [ 4246.558498]  mpage_prepare_extent_to_map+0x15c/0x4d0
    [ 4246.558512]  ext4_do_writepages+0x25f/0x770
    [ 4246.558523]  ext4_writepages+0xad/0x180
    [ 4246.558533]  do_writepages+0xcf/0x1e0
    [ 4246.558543]  ? __seccomp_filter+0x32a/0x4f0
    [ 4246.558554]  filemap_fdatawrite_wbc+0x63/0x90
    [ 4246.558567]  __filemap_fdatawrite_range+0x5c/0x80
    [ 4246.558578]  file_write_and_wait_range+0x4a/0xb0
    [ 4246.558588]  ext4_sync_file+0x88/0x380
    [ 4246.558598]  __x64_sys_fsync+0x3b/0x70
    [ 4246.558609]  do_syscall_64+0x5c/0x90
    [ 4246.558621]  ? exit_to_user_mode_prepare+0xb2/0xd0
    [ 4246.558632]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
    [ 4246.558644] RIP: 0033:0x7710cf124d0a
    [ 4246.558654] RSP: 002b:00007710ccdfda40 EFLAGS: 00000293 ORIG_RAX: 000000000000004a
    [ 4246.558668] RAX: ffffffffffffffda RBX: 000064bb92f67e60 RCX: 00007710cf124d0a
    [ 4246.558679] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000028
    [ 4246.558691] RBP: 000064bb92f72670 R08: 0000000000000000 R09: 00007710ccdfe6c0
    [ 4246.558702] R10: 00007710cf0adfee R11: 0000000000000293 R12: 000064bb92505940
    [ 4246.558713] R13: 0000000000000002 R14: 00007ffc05649500 R15: 00007710cc5fe000
    [ 4246.558728]  </TASK>
    [ 4246.558836] task:lvm             state:D stack:0     pid:7835  ppid:5665   flags:0x00004006
    [ 4246.558852] Call Trace:
    [ 4246.558857]  <TASK>
    [ 4246.558863]  __schedule+0x23d/0x670
    [ 4246.558874]  schedule+0x5e/0xd0
    [ 4246.558884]  io_schedule+0x46/0x70
    [ 4246.558894]  dm_wait_for_bios_completion+0xfc/0x110
    [ 4246.558909]  ? __pfx_autoremove_wake_function+0x10/0x10
    [ 4246.558922]  __dm_suspend+0x7e/0x1b0
    [ 4246.558932]  dm_internal_suspend_noflush+0x5c/0x80
    [ 4246.558946]  pool_presuspend+0xcc/0x130 [dm_thin_pool]
    [ 4246.558968]  dm_table_presuspend_targets+0x3f/0x60
    [ 4246.558980]  __dm_suspend+0x41/0x1b0
    [ 4246.558991]  dm_suspend+0xc0/0xe0
    [ 4246.559001]  dev_suspend+0xa5/0xd0
    [ 4246.559011]  ctl_ioctl+0x26e/0x350
    [ 4246.559020]  ? __pfx_dev_suspend+0x10/0x10
    [ 4246.559032]  dm_ctl_ioctl+0xe/0x20
    [ 4246.559041]  __x64_sys_ioctl+0x94/0xd0
    [ 4246.559052]  do_syscall_64+0x5c/0x90
    [ 4246.559062]  ? do_syscall_64+0x6b/0x90
    [ 4246.559072]  ? do_syscall_64+0x6b/0x90
    [ 4246.559081]  ? xen_pv_evtchn_do_upcall+0x54/0xb0
    [ 4246.559093]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
    [ 4246.559104] RIP: 0033:0x7f1cb77cfe0f
    [ 4246.559112] RSP: 002b:00007fff870f2560 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
    [ 4246.559141] RAX: ffffffffffffffda RBX: 00005b8d13c16580 RCX: 00007f1cb77cfe0f
    [ 4246.559152] RDX: 00005b8d144a2180 RSI: 00000000c138fd06 RDI: 0000000000000003
    [ 4246.559164] RBP: 00005b8d144a2180 R08: 00005b8d132b1190 R09: 00007fff870f2420
    [ 4246.559175] R10: 0000000000000000 R11: 0000000000000246 R12: 000000000000000c
    [ 4246.559186] R13: 00005b8d132aacf0 R14: 00005b8d1324414d R15: 00005b8d144a21b0
    [ 4246.559199]  </TASK>
    [ 4246.559207] task:kworker/u8:3    state:D stack:0     pid:8033  ppid:2      flags:0x00004000
    [ 4246.559222] Workqueue: writeback wb_workfn (flush-253:4)
    [ 4246.559238] Call Trace:
    [ 4246.559244]  <TASK>
    [ 4246.559249]  __schedule+0x23d/0x670
    [ 4246.559260]  schedule+0x5e/0xd0
    [ 4246.559270]  io_schedule+0x46/0x70
    [ 4246.559280]  folio_wait_bit_common+0x13d/0x350
    [ 4246.559290]  ? __pfx_wake_page_function+0x10/0x10
    [ 4246.559302]  mpage_prepare_extent_to_map+0x309/0x4d0
    [ 4246.559314]  ext4_do_writepages+0x25f/0x770
    [ 4246.559324]  ext4_writepages+0xad/0x180
    [ 4246.559334]  do_writepages+0xcf/0x1e0
    [ 4246.559344]  ? find_busiest_group+0x42/0x1a0
    [ 4246.559354]  __writeback_single_inode+0x3d/0x280
    [ 4246.559368]  writeback_sb_inodes+0x1ed/0x4a0
    [ 4246.559381]  __writeback_inodes_wb+0x4c/0xf0
    [ 4246.559393]  wb_writeback+0x298/0x310
    [ 4246.559403]  wb_do_writeback+0x230/0x2b0
    [ 4246.559414]  wb_workfn+0x5f/0x260
    [ 4246.559424]  ? _raw_spin_unlock+0xe/0x30
    [ 4246.559434]  ? finish_task_switch.isra.0+0x95/0x2b0
    [ 4246.559447]  ? __schedule+0x245/0x670
    [ 4246.559457]  process_one_work+0x1df/0x3e0
    [ 4246.559466]  worker_thread+0x51/0x390
    [ 4246.559475]  ? __pfx_worker_thread+0x10/0x10
    [ 4246.559484]  kthread+0xe5/0x120
    [ 4246.559495]  ? __pfx_kthread+0x10/0x10
    [ 4246.559504]  ret_from_fork+0x31/0x50
    [ 4246.559514]  ? __pfx_kthread+0x10/0x10
    [ 4246.559523]  ret_from_fork_asm+0x1b/0x30
    [ 4246.559536]  </TASK>

Signature · 3 lines

Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

Hi

It's hard to say what causes this. Perhaps dm-crypt exhausts all the higher-order pages and some subsystem stalls because of it.

In drivers/md/dm-crypt.c in function crypt_alloc_buffer there is "unsigned int order = MAX_ORDER - 1"

What happens if you set the "order" variable to some small value, like 1, 2 or 3. Does the problem go away? Could you find a threshold value (something between 0 and MAX_ORDER-1) where the bug starts to appear?

What happens if you replace
"pages = alloc_pages(gfp_mask"
with
"pages = alloc_pages((gfp_mask & ~__GFP_KSWAPD_RECLAIM)" ? Does the bug go away?

Mikulas

Quoted 150 lines · Marek Marczykowski-Górecki

Hi,

Since updating from 6.4.13 to 6.5.5 occasionally I hit a storage subsystem freeze - any I/O ends up frozen. I'm not sure what exactly triggers the issue, but often it happens when doing some LVM operations (lvremove, lvrename etc) on a dm-thin volume together with bulk data copy to/from another LVM thin volume with ext4 fs.

The storage stack I use is:
nvme -> dm-crypt (LUKS) -> dm-thin (LVM thin pool) -> ext4

And this whole thing running in a (PV) dom0 under Xen, on Qubes OS 4.2 to be specific.

I can reproduce the issue on at least 3 different machines. I did tried also 6.5.6 and the issue is still there. I haven't checked newer versions, but briefly reviewed git log and haven't found anything suggesting a fix to similar issue.

I managed to bisect it down to this commit:

commit 5054e778fcd9cd29ddaa8109077cd235527e4f94
Author: Mikulas Patocka <[email protected]>
Date: Mon May 1 09:19:17 2023 -0400

dm crypt: allocate compound pages if possible

It was reported that allocating pages for the write buffer in dm-crypt causes measurable overhead [1].

Change dm-crypt to allocate compound pages if they are available. If not, fall back to the mempool.

[1] https://listman.redhat.com/archives/dm-devel/2023-February/053284.html

Suggested-by Matthew Wilcox <[email protected]>

Signed-off-by Mikulas Patocka <[email protected]>

Signed-off-by Mike Snitzer <[email protected]>

TBH, I'm not sure if the bug is in this commit, or maybe in some functions it uses (I don't see dm-crypt functions directly involved in the stack traces I collected). But reverting this commit on top of 6.5.6 seems to fix the issue.

I tried also CONFIG_PROVE_LOCKING, but it didn't show any issue.

I managed to collect "blocked tasks" dump via sysrq below. Few more can be found at https://github.com/QubesOS/qubes-issues/issues/8575

    [ 4246.558313] sysrq: Show Blocked State
    [ 4246.558388] task:journal-offline state:D stack:0     pid:8098  ppid:1      flags:0x00000002
    [ 4246.558407] Call Trace:
    [ 4246.558414]  <TASK>
    [ 4246.558422]  __schedule+0x23d/0x670
    [ 4246.558440]  schedule+0x5e/0xd0
    [ 4246.558450]  io_schedule+0x46/0x70
    [ 4246.558461]  folio_wait_bit_common+0x13d/0x350
    [ 4246.558475]  ? __pfx_wake_page_function+0x10/0x10
    [ 4246.558488]  folio_wait_writeback+0x2c/0x90
    [ 4246.558498]  mpage_prepare_extent_to_map+0x15c/0x4d0
    [ 4246.558512]  ext4_do_writepages+0x25f/0x770
    [ 4246.558523]  ext4_writepages+0xad/0x180
    [ 4246.558533]  do_writepages+0xcf/0x1e0
    [ 4246.558543]  ? __seccomp_filter+0x32a/0x4f0
    [ 4246.558554]  filemap_fdatawrite_wbc+0x63/0x90
    [ 4246.558567]  __filemap_fdatawrite_range+0x5c/0x80
    [ 4246.558578]  file_write_and_wait_range+0x4a/0xb0
    [ 4246.558588]  ext4_sync_file+0x88/0x380
    [ 4246.558598]  __x64_sys_fsync+0x3b/0x70
    [ 4246.558609]  do_syscall_64+0x5c/0x90
    [ 4246.558621]  ? exit_to_user_mode_prepare+0xb2/0xd0
    [ 4246.558632]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
    [ 4246.558644] RIP: 0033:0x7710cf124d0a
    [ 4246.558654] RSP: 002b:00007710ccdfda40 EFLAGS: 00000293 ORIG_RAX: 000000000000004a
    [ 4246.558668] RAX: ffffffffffffffda RBX: 000064bb92f67e60 RCX: 00007710cf124d0a
    [ 4246.558679] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000028
    [ 4246.558691] RBP: 000064bb92f72670 R08: 0000000000000000 R09: 00007710ccdfe6c0
    [ 4246.558702] R10: 00007710cf0adfee R11: 0000000000000293 R12: 000064bb92505940
    [ 4246.558713] R13: 0000000000000002 R14: 00007ffc05649500 R15: 00007710cc5fe000
    [ 4246.558728]  </TASK>
    [ 4246.558836] task:lvm             state:D stack:0     pid:7835  ppid:5665   flags:0x00004006
    [ 4246.558852] Call Trace:
    [ 4246.558857]  <TASK>
    [ 4246.558863]  __schedule+0x23d/0x670
    [ 4246.558874]  schedule+0x5e/0xd0
    [ 4246.558884]  io_schedule+0x46/0x70
    [ 4246.558894]  dm_wait_for_bios_completion+0xfc/0x110
    [ 4246.558909]  ? __pfx_autoremove_wake_function+0x10/0x10
    [ 4246.558922]  __dm_suspend+0x7e/0x1b0
    [ 4246.558932]  dm_internal_suspend_noflush+0x5c/0x80
    [ 4246.558946]  pool_presuspend+0xcc/0x130 [dm_thin_pool]
    [ 4246.558968]  dm_table_presuspend_targets+0x3f/0x60
    [ 4246.558980]  __dm_suspend+0x41/0x1b0
    [ 4246.558991]  dm_suspend+0xc0/0xe0
    [ 4246.559001]  dev_suspend+0xa5/0xd0
    [ 4246.559011]  ctl_ioctl+0x26e/0x350
    [ 4246.559020]  ? __pfx_dev_suspend+0x10/0x10
    [ 4246.559032]  dm_ctl_ioctl+0xe/0x20
    [ 4246.559041]  __x64_sys_ioctl+0x94/0xd0
    [ 4246.559052]  do_syscall_64+0x5c/0x90
    [ 4246.559062]  ? do_syscall_64+0x6b/0x90
    [ 4246.559072]  ? do_syscall_64+0x6b/0x90
    [ 4246.559081]  ? xen_pv_evtchn_do_upcall+0x54/0xb0
    [ 4246.559093]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
    [ 4246.559104] RIP: 0033:0x7f1cb77cfe0f
    [ 4246.559112] RSP: 002b:00007fff870f2560 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
    [ 4246.559141] RAX: ffffffffffffffda RBX: 00005b8d13c16580 RCX: 00007f1cb77cfe0f
    [ 4246.559152] RDX: 00005b8d144a2180 RSI: 00000000c138fd06 RDI: 0000000000000003
    [ 4246.559164] RBP: 00005b8d144a2180 R08: 00005b8d132b1190 R09: 00007fff870f2420
    [ 4246.559175] R10: 0000000000000000 R11: 0000000000000246 R12: 000000000000000c
    [ 4246.559186] R13: 00005b8d132aacf0 R14: 00005b8d1324414d R15: 00005b8d144a21b0
    [ 4246.559199]  </TASK>
    [ 4246.559207] task:kworker/u8:3    state:D stack:0     pid:8033  ppid:2      flags:0x00004000
    [ 4246.559222] Workqueue: writeback wb_workfn (flush-253:4)
    [ 4246.559238] Call Trace:
    [ 4246.559244]  <TASK>
    [ 4246.559249]  __schedule+0x23d/0x670
    [ 4246.559260]  schedule+0x5e/0xd0
    [ 4246.559270]  io_schedule+0x46/0x70
    [ 4246.559280]  folio_wait_bit_common+0x13d/0x350
    [ 4246.559290]  ? __pfx_wake_page_function+0x10/0x10
    [ 4246.559302]  mpage_prepare_extent_to_map+0x309/0x4d0
    [ 4246.559314]  ext4_do_writepages+0x25f/0x770
    [ 4246.559324]  ext4_writepages+0xad/0x180
    [ 4246.559334]  do_writepages+0xcf/0x1e0
    [ 4246.559344]  ? find_busiest_group+0x42/0x1a0
    [ 4246.559354]  __writeback_single_inode+0x3d/0x280
    [ 4246.559368]  writeback_sb_inodes+0x1ed/0x4a0
    [ 4246.559381]  __writeback_inodes_wb+0x4c/0xf0
    [ 4246.559393]  wb_writeback+0x298/0x310
    [ 4246.559403]  wb_do_writeback+0x230/0x2b0
    [ 4246.559414]  wb_workfn+0x5f/0x260
    [ 4246.559424]  ? _raw_spin_unlock+0xe/0x30
    [ 4246.559434]  ? finish_task_switch.isra.0+0x95/0x2b0
    [ 4246.559447]  ? __schedule+0x245/0x670
    [ 4246.559457]  process_one_work+0x1df/0x3e0
    [ 4246.559466]  worker_thread+0x51/0x390
    [ 4246.559475]  ? __pfx_worker_thread+0x10/0x10
    [ 4246.559484]  kthread+0xe5/0x120
    [ 4246.559495]  ? __pfx_kthread+0x10/0x10
    [ 4246.559504]  ret_from_fork+0x31/0x50
    [ 4246.559514]  ? __pfx_kthread+0x10/0x10
    [ 4246.559523]  ret_from_fork_asm+0x1b/0x30
    [ 4246.559536]  </TASK>

Signature · 3 lines

Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

Quoted 11 lines · Mikulas Patocka

Hi

It's hard to say what causes this. Perhaps dm-crypt exhausts all the higher-order pages and some subsystem stalls because of it.

In drivers/md/dm-crypt.c in function crypt_alloc_buffer there is "unsigned int order = MAX_ORDER - 1"

What happens if you set the "order" variable to some small value, like 1, 2 or 3. Does the problem go away? Could you find a threshold value (something between 0 and MAX_ORDER-1) where the bug starts to appear?

With 3 and lower it seems to work, with 4 it freezes. My test is not 100% reproducible, but I've repeated it a few times and got rather consistent results on this system (i3-1315U, NVMe).

BTW, when trying on a much older system (Thinkpad P52 with i7-8750H) I couldn't reproduce the issue at all. But OTOH, I hit it once on a system with i7-7600U and otherwise similar specs but much different workload (several more VMs accessing the data). I'm not sure if that info helps at all...

Quoted 6 lines

What happens if you replace
"pages = alloc_pages(gfp_mask"
with
"pages = alloc_pages((gfp_mask & ~__GFP_KSWAPD_RECLAIM)" ? Does the bug go away?

In a limited test, with order restored to MAX_ORDER - 1, no, still got the issue, and got this via sysrq (just one task listed):

[  516.375254] sysrq: Show Blocked State
[  516.375461] task:dd              state:D stack:13072 pid:4385  ppid:4371   flags:0x00004002
[  516.375496] Call Trace:
[  516.375507]  <TASK>
[  516.375518]  __schedule+0x30e/0x8b0
[  516.375549]  schedule+0x59/0xb0
[  516.375566]  io_schedule+0x41/0x70
[  516.375582]  folio_wait_bit_common+0x12c/0x300
[  516.375603]  ? __pfx_wake_page_function+0x10/0x10
[  516.375623]  folio_wait_writeback+0x27/0x80
[  516.375639]  __filemap_fdatawait_range+0x7b/0xe0
[  516.375656]  file_write_and_wait_range+0x86/0xb0
[  516.375672]  blkdev_fsync+0x33/0x60
[  516.375693]  __x64_sys_fdatasync+0x4a/0x90
[  516.375713]  do_syscall_64+0x3c/0x90
[  516.375729]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
[  516.375751] RIP: 0033:0x7fd718562da4
[  516.375764] RSP: 002b:00007ffea3815278 EFLAGS: 00000202 ORIG_RAX: 000000000000004b
[  516.375784] RAX: ffffffffffffffda RBX: 0000000000015200 RCX: 00007fd718562da4
[  516.375801] RDX: 0000000000028000 RSI: 0000000000000000 RDI: 0000000000000001
[  516.375817] RBP: 00007fd71845e6c0 R08: 00000000ffffffff R09: 0000000000000000
[  516.375833] R10: 0000000000000022 R11: 0000000000000202 R12: 0000000000000000
[  516.375848] R13: 0000000000000000 R14: 0000000000028000 R15: 0000000000000000
[  516.375865]  </TASK>

(it is dd writing to LVM thin volume, where PV is on dm-crypt)

Quoted 157 lines

Mikulas

Quoted 150 lines · Marek Marczykowski-Górecki

Hi,

Since updating from 6.4.13 to 6.5.5 occasionally I hit a storage subsystem freeze - any I/O ends up frozen. I'm not sure what exactly triggers the issue, but often it happens when doing some LVM operations (lvremove, lvrename etc) on a dm-thin volume together with bulk data copy to/from another LVM thin volume with ext4 fs.

The storage stack I use is:
nvme -> dm-crypt (LUKS) -> dm-thin (LVM thin pool) -> ext4

And this whole thing running in a (PV) dom0 under Xen, on Qubes OS 4.2 to be specific.

I can reproduce the issue on at least 3 different machines. I did tried also 6.5.6 and the issue is still there. I haven't checked newer versions, but briefly reviewed git log and haven't found anything suggesting a fix to similar issue.

I managed to bisect it down to this commit:

commit 5054e778fcd9cd29ddaa8109077cd235527e4f94
Author: Mikulas Patocka <[email protected]>
Date: Mon May 1 09:19:17 2023 -0400

dm crypt: allocate compound pages if possible

It was reported that allocating pages for the write buffer in dm-crypt causes measurable overhead [1].

Change dm-crypt to allocate compound pages if they are available. If not, fall back to the mempool.

[1] https://listman.redhat.com/archives/dm-devel/2023-February/053284.html

Suggested-by Matthew Wilcox <[email protected]>

Signed-off-by Mikulas Patocka <[email protected]>

Signed-off-by Mike Snitzer <[email protected]>

TBH, I'm not sure if the bug is in this commit, or maybe in some functions it uses (I don't see dm-crypt functions directly involved in the stack traces I collected). But reverting this commit on top of 6.5.6 seems to fix the issue.

I tried also CONFIG_PROVE_LOCKING, but it didn't show any issue.

I managed to collect "blocked tasks" dump via sysrq below. Few more can be found at https://github.com/QubesOS/qubes-issues/issues/8575

    [ 4246.558313] sysrq: Show Blocked State
    [ 4246.558388] task:journal-offline state:D stack:0     pid:8098  ppid:1      flags:0x00000002
    [ 4246.558407] Call Trace:
    [ 4246.558414]  <TASK>
    [ 4246.558422]  __schedule+0x23d/0x670
    [ 4246.558440]  schedule+0x5e/0xd0
    [ 4246.558450]  io_schedule+0x46/0x70
    [ 4246.558461]  folio_wait_bit_common+0x13d/0x350
    [ 4246.558475]  ? __pfx_wake_page_function+0x10/0x10
    [ 4246.558488]  folio_wait_writeback+0x2c/0x90
    [ 4246.558498]  mpage_prepare_extent_to_map+0x15c/0x4d0
    [ 4246.558512]  ext4_do_writepages+0x25f/0x770
    [ 4246.558523]  ext4_writepages+0xad/0x180
    [ 4246.558533]  do_writepages+0xcf/0x1e0
    [ 4246.558543]  ? __seccomp_filter+0x32a/0x4f0
    [ 4246.558554]  filemap_fdatawrite_wbc+0x63/0x90
    [ 4246.558567]  __filemap_fdatawrite_range+0x5c/0x80
    [ 4246.558578]  file_write_and_wait_range+0x4a/0xb0
    [ 4246.558588]  ext4_sync_file+0x88/0x380
    [ 4246.558598]  __x64_sys_fsync+0x3b/0x70
    [ 4246.558609]  do_syscall_64+0x5c/0x90
    [ 4246.558621]  ? exit_to_user_mode_prepare+0xb2/0xd0
    [ 4246.558632]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
    [ 4246.558644] RIP: 0033:0x7710cf124d0a
    [ 4246.558654] RSP: 002b:00007710ccdfda40 EFLAGS: 00000293 ORIG_RAX: 000000000000004a
    [ 4246.558668] RAX: ffffffffffffffda RBX: 000064bb92f67e60 RCX: 00007710cf124d0a
    [ 4246.558679] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000028
    [ 4246.558691] RBP: 000064bb92f72670 R08: 0000000000000000 R09: 00007710ccdfe6c0
    [ 4246.558702] R10: 00007710cf0adfee R11: 0000000000000293 R12: 000064bb92505940
    [ 4246.558713] R13: 0000000000000002 R14: 00007ffc05649500 R15: 00007710cc5fe000
    [ 4246.558728]  </TASK>
    [ 4246.558836] task:lvm             state:D stack:0     pid:7835  ppid:5665   flags:0x00004006
    [ 4246.558852] Call Trace:
    [ 4246.558857]  <TASK>
    [ 4246.558863]  __schedule+0x23d/0x670
    [ 4246.558874]  schedule+0x5e/0xd0
    [ 4246.558884]  io_schedule+0x46/0x70
    [ 4246.558894]  dm_wait_for_bios_completion+0xfc/0x110
    [ 4246.558909]  ? __pfx_autoremove_wake_function+0x10/0x10
    [ 4246.558922]  __dm_suspend+0x7e/0x1b0
    [ 4246.558932]  dm_internal_suspend_noflush+0x5c/0x80
    [ 4246.558946]  pool_presuspend+0xcc/0x130 [dm_thin_pool]
    [ 4246.558968]  dm_table_presuspend_targets+0x3f/0x60
    [ 4246.558980]  __dm_suspend+0x41/0x1b0
    [ 4246.558991]  dm_suspend+0xc0/0xe0
    [ 4246.559001]  dev_suspend+0xa5/0xd0
    [ 4246.559011]  ctl_ioctl+0x26e/0x350
    [ 4246.559020]  ? __pfx_dev_suspend+0x10/0x10
    [ 4246.559032]  dm_ctl_ioctl+0xe/0x20
    [ 4246.559041]  __x64_sys_ioctl+0x94/0xd0
    [ 4246.559052]  do_syscall_64+0x5c/0x90
    [ 4246.559062]  ? do_syscall_64+0x6b/0x90
    [ 4246.559072]  ? do_syscall_64+0x6b/0x90
    [ 4246.559081]  ? xen_pv_evtchn_do_upcall+0x54/0xb0
    [ 4246.559093]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
    [ 4246.559104] RIP: 0033:0x7f1cb77cfe0f
    [ 4246.559112] RSP: 002b:00007fff870f2560 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
    [ 4246.559141] RAX: ffffffffffffffda RBX: 00005b8d13c16580 RCX: 00007f1cb77cfe0f
    [ 4246.559152] RDX: 00005b8d144a2180 RSI: 00000000c138fd06 RDI: 0000000000000003
    [ 4246.559164] RBP: 00005b8d144a2180 R08: 00005b8d132b1190 R09: 00007fff870f2420
    [ 4246.559175] R10: 0000000000000000 R11: 0000000000000246 R12: 000000000000000c
    [ 4246.559186] R13: 00005b8d132aacf0 R14: 00005b8d1324414d R15: 00005b8d144a21b0
    [ 4246.559199]  </TASK>
    [ 4246.559207] task:kworker/u8:3    state:D stack:0     pid:8033  ppid:2      flags:0x00004000
    [ 4246.559222] Workqueue: writeback wb_workfn (flush-253:4)
    [ 4246.559238] Call Trace:
    [ 4246.559244]  <TASK>
    [ 4246.559249]  __schedule+0x23d/0x670
    [ 4246.559260]  schedule+0x5e/0xd0
    [ 4246.559270]  io_schedule+0x46/0x70
    [ 4246.559280]  folio_wait_bit_common+0x13d/0x350
    [ 4246.559290]  ? __pfx_wake_page_function+0x10/0x10
    [ 4246.559302]  mpage_prepare_extent_to_map+0x309/0x4d0
    [ 4246.559314]  ext4_do_writepages+0x25f/0x770
    [ 4246.559324]  ext4_writepages+0xad/0x180
    [ 4246.559334]  do_writepages+0xcf/0x1e0
    [ 4246.559344]  ? find_busiest_group+0x42/0x1a0
    [ 4246.559354]  __writeback_single_inode+0x3d/0x280
    [ 4246.559368]  writeback_sb_inodes+0x1ed/0x4a0
    [ 4246.559381]  __writeback_inodes_wb+0x4c/0xf0
    [ 4246.559393]  wb_writeback+0x298/0x310
    [ 4246.559403]  wb_do_writeback+0x230/0x2b0
    [ 4246.559414]  wb_workfn+0x5f/0x260
    [ 4246.559424]  ? _raw_spin_unlock+0xe/0x30
    [ 4246.559434]  ? finish_task_switch.isra.0+0x95/0x2b0
    [ 4246.559447]  ? __schedule+0x245/0x670
    [ 4246.559457]  process_one_work+0x1df/0x3e0
    [ 4246.559466]  worker_thread+0x51/0x390
    [ 4246.559475]  ? __pfx_worker_thread+0x10/0x10
    [ 4246.559484]  kthread+0xe5/0x120
    [ 4246.559495]  ? __pfx_kthread+0x10/0x10
    [ 4246.559504]  ret_from_fork+0x31/0x50
    [ 4246.559514]  ? __pfx_kthread+0x10/0x10
    [ 4246.559523]  ret_from_fork_asm+0x1b/0x30
    [ 4246.559536]  </TASK>

Signature · 3 lines

Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

Signature · 3 lines

Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

Quoted 58 lines · Marek Marczykowski-Górecki

Quoted 11 lines · Mikulas Patocka

Hi

It's hard to say what causes this. Perhaps dm-crypt exhausts all the higher-order pages and some subsystem stalls because of it.

In drivers/md/dm-crypt.c in function crypt_alloc_buffer there is "unsigned int order = MAX_ORDER - 1"

What happens if you set the "order" variable to some small value, like 1, 2 or 3. Does the problem go away? Could you find a threshold value (something between 0 and MAX_ORDER-1) where the bug starts to appear?

With 3 and lower it seems to work, with 4 it freezes. My test is not 100% reproducible, but I've repeated it a few times and got rather consistent results on this system (i3-1315U, NVMe).

BTW, when trying on a much older system (Thinkpad P52 with i7-8750H) I couldn't reproduce the issue at all. But OTOH, I hit it once on a system with i7-7600U and otherwise similar specs but much different workload (several more VMs accessing the data). I'm not sure if that info helps at all...

Quoted 6 lines

What happens if you replace
"pages = alloc_pages(gfp_mask"
with
"pages = alloc_pages((gfp_mask & ~__GFP_KSWAPD_RECLAIM)" ? Does the bug go away?

In a limited test, with order restored to MAX_ORDER - 1, no, still got the issue, and got this via sysrq (just one task listed):

[  516.375254] sysrq: Show Blocked State
[  516.375461] task:dd              state:D stack:13072 pid:4385  ppid:4371   flags:0x00004002
[  516.375496] Call Trace:
[  516.375507]  <TASK>
[  516.375518]  __schedule+0x30e/0x8b0
[  516.375549]  schedule+0x59/0xb0
[  516.375566]  io_schedule+0x41/0x70
[  516.375582]  folio_wait_bit_common+0x12c/0x300
[  516.375603]  ? __pfx_wake_page_function+0x10/0x10
[  516.375623]  folio_wait_writeback+0x27/0x80
[  516.375639]  __filemap_fdatawait_range+0x7b/0xe0
[  516.375656]  file_write_and_wait_range+0x86/0xb0
[  516.375672]  blkdev_fsync+0x33/0x60
[  516.375693]  __x64_sys_fdatasync+0x4a/0x90
[  516.375713]  do_syscall_64+0x3c/0x90
[  516.375729]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
[  516.375751] RIP: 0033:0x7fd718562da4
[  516.375764] RSP: 002b:00007ffea3815278 EFLAGS: 00000202 ORIG_RAX: 000000000000004b
[  516.375784] RAX: ffffffffffffffda RBX: 0000000000015200 RCX: 00007fd718562da4
[  516.375801] RDX: 0000000000028000 RSI: 0000000000000000 RDI: 0000000000000001
[  516.375817] RBP: 00007fd71845e6c0 R08: 00000000ffffffff R09: 0000000000000000
[  516.375833] R10: 0000000000000022 R11: 0000000000000202 R12: 0000000000000000
[  516.375848] R13: 0000000000000000 R14: 0000000000028000 R15: 0000000000000000
[  516.375865]  </TASK>

Quoted 1 line

(it is dd writing to LVM thin volume, where PV is on dm-crypt)

In this bad state, I extracted some more info on memory:

/proc/meminfo:

MemTotal:        3983088 kB
MemFree:          349264 kB
MemAvailable:    3474744 kB
Buffers:         1511732 kB
Cached:          1608132 kB
SwapCached:           12 kB
Active:           203136 kB
Inactive:        3147696 kB
Active(anon):       1288 kB
Inactive(anon):   252128 kB
Active(file):     201848 kB
Inactive(file):  2895568 kB
Unevictable:       46064 kB
Mlocked:           39920 kB
SwapTotal:       4112380 kB
SwapFree:        4112124 kB
Dirty:                 0 kB
Writeback:          8556 kB
AnonPages:        277020 kB
Mapped:           137424 kB
Shmem:             13792 kB
KReclaimable:      91728 kB
Slab:             182428 kB
SReclaimable:      91728 kB
SUnreclaim:        90700 kB
KernelStack:        5776 kB
PageTables:         7480 kB
SecPageTables:         0 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:     6103924 kB
Committed_AS:     990924 kB
VmallocTotal:   34359738367 kB
VmallocUsed:       11560 kB
VmallocChunk:          0 kB
Percpu:             2528 kB
DirectMap4k:     4325764 kB
DirectMap2M:           0 kB

and also:

[ 1168.537096] sysrq: Show Memory
[ 1168.537192] Mem-Info:
[ 1168.537206] active_anon:322 inactive_anon:63032 isolated_anon:0
[ 1168.537206]  active_file:50462 inactive_file:723892 isolated_file:0
[ 1168.537206]  unevictable:11516 dirty:1 writeback:2139
[ 1168.537206]  slab_reclaimable:22932 slab_unreclaimable:22675
[ 1168.537206]  mapped:34357 shmem:3448 pagetables:1870
[ 1168.537206]  sec_pagetables:0 bounce:0
[ 1168.537206]  kernel_misc_reclaimable:0
[ 1168.537206]  free:87499 free_pcp:1642 free_cma:0
[ 1168.537279] Node 0 active_anon:1288kB inactive_anon:252128kB active_file:201848kB inactive_file:2895568kB unevictable:46064kB isolated(anon):0kB isolated(file):0kB mapped:137428kB dirty:4kB writeback:8556kB shmem:13792kB writeback_tmp:0kB kernel_stack:5776kB pagetables:7480kB sec_pagetables:0kB all_unreclaimable? no
[ 1168.537332] Node 0 DMA free:15488kB boost:0kB min:32kB low:44kB high:56kB reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB active_file:84kB inactive_file:352kB unevictable:0kB writepending:84kB present:15996kB managed:15936kB mlocked:0kB bounce:0kB free_pcp:12kB local_pcp:0kB free_cma:0kB
[ 1168.537387] lowmem_reserve[]: 0 1728 3857 3857
[ 1168.537409] Node 0 DMA32 free:155300kB boost:0kB min:3552kB low:5320kB high:7088kB reserved_highatomic:0KB active_anon:16kB inactive_anon:3368kB active_file:5660kB inactive_file:1585120kB unevictable:0kB writepending:7576kB present:1924360kB managed:1803376kB mlocked:0kB bounce:0kB free_pcp:3184kB local_pcp:864kB free_cma:0kB
[ 1168.537464] lowmem_reserve[]: 0 0 2129 2129
[ 1168.537483] Node 0 Normal free:179208kB boost:0kB min:4376kB low:6556kB high:8736kB reserved_highatomic:2048KB active_anon:1272kB inactive_anon:248760kB active_file:196104kB inactive_file:1310096kB unevictable:46064kB writepending:900kB present:2253948kB managed:2163776kB mlocked:39920kB bounce:0kB free_pcp:3372kB local_pcp:632kB free_cma:0kB
[ 1168.537540] lowmem_reserve[]: 0 0 0 0
[ 1168.537557] Node 0 DMA: 4*4kB (UM) 4*8kB (UM) 3*16kB (UM) 3*32kB (U) 3*64kB (U) 2*128kB (UM) 0*256kB 1*512kB (M) 2*1024kB (UM) 0*2048kB 3*4096kB (M) = 15488kB
[ 1168.537624] Node 0 DMA32: 1945*4kB (UME) 1446*8kB (UME) 953*16kB (UME) 1410*32kB (UM) 297*64kB (UM) 162*128kB (UM) 60*256kB (UM) 22*512kB (UM) 7*1024kB (UM) 1*2048kB (U) 0*4096kB = 155300kB
[ 1168.537695] Node 0 Normal: 3146*4kB (UMEH) 2412*8kB (UMEH) 1444*16kB (UMEH) 1138*32kB (UMEH) 486*64kB (UME) 97*128kB (UM) 13*256kB (UM) 8*512kB (M) 2*1024kB (M) 5*2048kB (M) 6*4096kB (UM) = 179208kB
[ 1168.537767] 779973 total pagecache pages
[ 1168.537778] 3 pages in swap cache
[ 1168.537788] Free swap  = 4112124kB
[ 1168.537798] Total swap = 4112380kB
[ 1168.537807] 1048576 pages RAM
[ 1168.537817] 0 pages HighMem/MovableOnly
[ 1168.537827] 52804 pages reserved

Quoted 163 lines

Quoted 157 lines

Mikulas

Quoted 150 lines · Marek Marczykowski-Górecki

Hi,

Since updating from 6.4.13 to 6.5.5 occasionally I hit a storage subsystem freeze - any I/O ends up frozen. I'm not sure what exactly triggers the issue, but often it happens when doing some LVM operations (lvremove, lvrename etc) on a dm-thin volume together with bulk data copy to/from another LVM thin volume with ext4 fs.

The storage stack I use is:
nvme -> dm-crypt (LUKS) -> dm-thin (LVM thin pool) -> ext4

And this whole thing running in a (PV) dom0 under Xen, on Qubes OS 4.2 to be specific.

I can reproduce the issue on at least 3 different machines. I did tried also 6.5.6 and the issue is still there. I haven't checked newer versions, but briefly reviewed git log and haven't found anything suggesting a fix to similar issue.

I managed to bisect it down to this commit:

commit 5054e778fcd9cd29ddaa8109077cd235527e4f94
Author: Mikulas Patocka <[email protected]>
Date: Mon May 1 09:19:17 2023 -0400

dm crypt: allocate compound pages if possible

It was reported that allocating pages for the write buffer in dm-crypt causes measurable overhead [1].

Change dm-crypt to allocate compound pages if they are available. If not, fall back to the mempool.

[1] https://listman.redhat.com/archives/dm-devel/2023-February/053284.html

Suggested-by Matthew Wilcox <[email protected]>

Signed-off-by Mikulas Patocka <[email protected]>

Signed-off-by Mike Snitzer <[email protected]>

TBH, I'm not sure if the bug is in this commit, or maybe in some functions it uses (I don't see dm-crypt functions directly involved in the stack traces I collected). But reverting this commit on top of 6.5.6 seems to fix the issue.

I tried also CONFIG_PROVE_LOCKING, but it didn't show any issue.

I managed to collect "blocked tasks" dump via sysrq below. Few more can be found at https://github.com/QubesOS/qubes-issues/issues/8575

    [ 4246.558313] sysrq: Show Blocked State
    [ 4246.558388] task:journal-offline state:D stack:0     pid:8098  ppid:1      flags:0x00000002
    [ 4246.558407] Call Trace:
    [ 4246.558414]  <TASK>
    [ 4246.558422]  __schedule+0x23d/0x670
    [ 4246.558440]  schedule+0x5e/0xd0
    [ 4246.558450]  io_schedule+0x46/0x70
    [ 4246.558461]  folio_wait_bit_common+0x13d/0x350
    [ 4246.558475]  ? __pfx_wake_page_function+0x10/0x10
    [ 4246.558488]  folio_wait_writeback+0x2c/0x90
    [ 4246.558498]  mpage_prepare_extent_to_map+0x15c/0x4d0
    [ 4246.558512]  ext4_do_writepages+0x25f/0x770
    [ 4246.558523]  ext4_writepages+0xad/0x180
    [ 4246.558533]  do_writepages+0xcf/0x1e0
    [ 4246.558543]  ? __seccomp_filter+0x32a/0x4f0
    [ 4246.558554]  filemap_fdatawrite_wbc+0x63/0x90
    [ 4246.558567]  __filemap_fdatawrite_range+0x5c/0x80
    [ 4246.558578]  file_write_and_wait_range+0x4a/0xb0
    [ 4246.558588]  ext4_sync_file+0x88/0x380
    [ 4246.558598]  __x64_sys_fsync+0x3b/0x70
    [ 4246.558609]  do_syscall_64+0x5c/0x90
    [ 4246.558621]  ? exit_to_user_mode_prepare+0xb2/0xd0
    [ 4246.558632]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
    [ 4246.558644] RIP: 0033:0x7710cf124d0a
    [ 4246.558654] RSP: 002b:00007710ccdfda40 EFLAGS: 00000293 ORIG_RAX: 000000000000004a
    [ 4246.558668] RAX: ffffffffffffffda RBX: 000064bb92f67e60 RCX: 00007710cf124d0a
    [ 4246.558679] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000028
    [ 4246.558691] RBP: 000064bb92f72670 R08: 0000000000000000 R09: 00007710ccdfe6c0
    [ 4246.558702] R10: 00007710cf0adfee R11: 0000000000000293 R12: 000064bb92505940
    [ 4246.558713] R13: 0000000000000002 R14: 00007ffc05649500 R15: 00007710cc5fe000
    [ 4246.558728]  </TASK>
    [ 4246.558836] task:lvm             state:D stack:0     pid:7835  ppid:5665   flags:0x00004006
    [ 4246.558852] Call Trace:
    [ 4246.558857]  <TASK>
    [ 4246.558863]  __schedule+0x23d/0x670
    [ 4246.558874]  schedule+0x5e/0xd0
    [ 4246.558884]  io_schedule+0x46/0x70
    [ 4246.558894]  dm_wait_for_bios_completion+0xfc/0x110
    [ 4246.558909]  ? __pfx_autoremove_wake_function+0x10/0x10
    [ 4246.558922]  __dm_suspend+0x7e/0x1b0
    [ 4246.558932]  dm_internal_suspend_noflush+0x5c/0x80
    [ 4246.558946]  pool_presuspend+0xcc/0x130 [dm_thin_pool]
    [ 4246.558968]  dm_table_presuspend_targets+0x3f/0x60
    [ 4246.558980]  __dm_suspend+0x41/0x1b0
    [ 4246.558991]  dm_suspend+0xc0/0xe0
    [ 4246.559001]  dev_suspend+0xa5/0xd0
    [ 4246.559011]  ctl_ioctl+0x26e/0x350
    [ 4246.559020]  ? __pfx_dev_suspend+0x10/0x10
    [ 4246.559032]  dm_ctl_ioctl+0xe/0x20
    [ 4246.559041]  __x64_sys_ioctl+0x94/0xd0
    [ 4246.559052]  do_syscall_64+0x5c/0x90
    [ 4246.559062]  ? do_syscall_64+0x6b/0x90
    [ 4246.559072]  ? do_syscall_64+0x6b/0x90
    [ 4246.559081]  ? xen_pv_evtchn_do_upcall+0x54/0xb0
    [ 4246.559093]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
    [ 4246.559104] RIP: 0033:0x7f1cb77cfe0f
    [ 4246.559112] RSP: 002b:00007fff870f2560 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
    [ 4246.559141] RAX: ffffffffffffffda RBX: 00005b8d13c16580 RCX: 00007f1cb77cfe0f
    [ 4246.559152] RDX: 00005b8d144a2180 RSI: 00000000c138fd06 RDI: 0000000000000003
    [ 4246.559164] RBP: 00005b8d144a2180 R08: 00005b8d132b1190 R09: 00007fff870f2420
    [ 4246.559175] R10: 0000000000000000 R11: 0000000000000246 R12: 000000000000000c
    [ 4246.559186] R13: 00005b8d132aacf0 R14: 00005b8d1324414d R15: 00005b8d144a21b0
    [ 4246.559199]  </TASK>
    [ 4246.559207] task:kworker/u8:3    state:D stack:0     pid:8033  ppid:2      flags:0x00004000
    [ 4246.559222] Workqueue: writeback wb_workfn (flush-253:4)
    [ 4246.559238] Call Trace:
    [ 4246.559244]  <TASK>
    [ 4246.559249]  __schedule+0x23d/0x670
    [ 4246.559260]  schedule+0x5e/0xd0
    [ 4246.559270]  io_schedule+0x46/0x70
    [ 4246.559280]  folio_wait_bit_common+0x13d/0x350
    [ 4246.559290]  ? __pfx_wake_page_function+0x10/0x10
    [ 4246.559302]  mpage_prepare_extent_to_map+0x309/0x4d0
    [ 4246.559314]  ext4_do_writepages+0x25f/0x770
    [ 4246.559324]  ext4_writepages+0xad/0x180
    [ 4246.559334]  do_writepages+0xcf/0x1e0
    [ 4246.559344]  ? find_busiest_group+0x42/0x1a0
    [ 4246.559354]  __writeback_single_inode+0x3d/0x280
    [ 4246.559368]  writeback_sb_inodes+0x1ed/0x4a0
    [ 4246.559381]  __writeback_inodes_wb+0x4c/0xf0
    [ 4246.559393]  wb_writeback+0x298/0x310
    [ 4246.559403]  wb_do_writeback+0x230/0x2b0
    [ 4246.559414]  wb_workfn+0x5f/0x260
    [ 4246.559424]  ? _raw_spin_unlock+0xe/0x30
    [ 4246.559434]  ? finish_task_switch.isra.0+0x95/0x2b0
    [ 4246.559447]  ? __schedule+0x245/0x670
    [ 4246.559457]  process_one_work+0x1df/0x3e0
    [ 4246.559466]  worker_thread+0x51/0x390
    [ 4246.559475]  ? __pfx_worker_thread+0x10/0x10
    [ 4246.559484]  kthread+0xe5/0x120
    [ 4246.559495]  ? __pfx_kthread+0x10/0x10
    [ 4246.559504]  ret_from_fork+0x31/0x50
    [ 4246.559514]  ? __pfx_kthread+0x10/0x10
    [ 4246.559523]  ret_from_fork_asm+0x1b/0x30
    [ 4246.559536]  </TASK>

Signature · 3 lines

Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

Signature · 3 lines

Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

Signature · 3 lines

Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

So, we got no reponse from the MM maintainers. Marek - please try this

patch on all the machines where you hit the bug and if you still hit the bug with this patch, report it.

Mikulas

From: Mikulas Patocka <[email protected]>
Subject: [PATCH] dm-crypt: don't allocate large compound pages

It was reported that the patch 5054e778fcd9cd29ddaa8109077cd235527e4f94 ("dm crypt: allocate compound pages if possible") causes intermittent freezes [1].

So far, it is not clear what is the root cause. It was reported that with the allocation order 3 or lower it works [1], so we restrict the order to 3 (that is PAGE_ALLOC_COSTLY_ORDER).

[1] https://www.spinics.net/lists/dm-devel/msg56048.html

Signed-off-by Mikulas Patocka <[email protected]>

Reported-by Marek Marczykowski-Górecki <[email protected]>

Tested-by Marek Marczykowski-Górecki <[email protected]>

Cc [email protected] # v6.5+

Fixes 5054e778fcd9 ("dm crypt: allocate compound pages if possible")

---
 drivers/md/dm-crypt.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

Index: linux-2.6/drivers/md/dm-crypt.c
===================================================================

drivers/md/dm-crypt.c +1 -1

@@ -1679,7 +1679,7 @@ static struct bio *crypt_alloc_buffer(st
 	unsigned int nr_iovecs = (size + PAGE_SIZE - 1) >> PAGE_SHIFT;
 	gfp_t gfp_mask = GFP_NOWAIT | __GFP_HIGHMEM;
 	unsigned int remaining_size;
-	unsigned int order = MAX_ORDER - 1;
+	unsigned int order = PAGE_ALLOC_COSTLY_ORDER;
 
 retry:
 	if (unlikely(gfp_mask & __GFP_DIRECT_RECLAIM))

Quoted 1 line · Mikulas Patocka

So, we got no reponse from the MM maintainers. Marek - please try this

yes, how dare i go on holiday. i'll look at this when i'm back. probably.

So, we got no reponse from the MM maintainers. Marek - please try this patch on all the machines where you hit the bug and if you still hit the bug with this patch, report it.

Mikulas

From: Mikulas Patocka <[email protected]>
Subject: [PATCH] dm-crypt: don't allocate large compound pages

It was reported that the patch 5054e778fcd9cd29ddaa8109077cd235527e4f94 ("dm crypt: allocate compound pages if possible") causes intermittent freezes [1].

So far, it is not clear what is the root cause. It was reported that with the allocation order 3 or lower it works [1], so we restrict the order to 3 (that is PAGE_ALLOC_COSTLY_ORDER).

[1] https://www.spinics.net/lists/dm-devel/msg56048.html

Signed-off-by Mikulas Patocka <[email protected]>

Reported-by Marek Marczykowski-Górecki <[email protected]>

Tested-by Marek Marczykowski-Górecki <[email protected]>

Cc [email protected] # v6.5+

Fixes 5054e778fcd9 ("dm crypt: allocate compound pages if possible")

---
 drivers/md/dm-crypt.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

Index: linux-2.6/drivers/md/dm-crypt.c
===================================================================

drivers/md/dm-crypt.c +1 -1

@@ -1679,7 +1679,7 @@ static struct bio *crypt_alloc_buffer(st
 	unsigned int nr_iovecs = (size + PAGE_SIZE - 1) >> PAGE_SHIFT;
 	gfp_t gfp_mask = GFP_NOWAIT | __GFP_HIGHMEM;
 	unsigned int remaining_size;
-	unsigned int order = MAX_ORDER - 1;
+	unsigned int order = PAGE_ALLOC_COSTLY_ORDER;
 
 retry:
 	if (unlikely(gfp_mask & __GFP_DIRECT_RECLAIM))

So, I forward this to memory management maintainers.

What do you think? - We have a problem that if dm-crypt allocates pages with order > 3 (PAGE_ALLOC_COSTLY_ORDER), the system occasionally freezes waiting in writeback.

dm-crypt allocates the pages with GFP_NOWAIT | __GFP_HIGHMEM | __GFP_NOMEMALLOC | __GFP_NORETRY | __GFP_NOWARN | __GFP_COMP, so it shouldn't put any pressure on the system. If the allocations fails, it falls back to smaller order allocation or to mempool as a last resort.

When the freeze happens, there is "349264kB" free memory - so the system is not short on memory.

Should we restrict the dm-crypt allocation size to PAGE_ALLOC_COSTLY_ORDER? Or is it a bug somewhere in memory management system that needs to be fixes there?

static struct bio *crypt_alloc_buffer(struct dm_crypt_io *io, unsigned int size)

{
	struct crypt_config *cc = io->cc;
	struct bio *clone;
	unsigned int nr_iovecs = (size + PAGE_SIZE - 1) >> PAGE_SHIFT;
	gfp_t gfp_mask = GFP_NOWAIT | __GFP_HIGHMEM;
	unsigned int remaining_size;
	unsigned int order = MAX_ORDER - 1;

retry:

	if (unlikely(gfp_mask & __GFP_DIRECT_RECLAIM))
		mutex_lock(&cc->bio_alloc_lock);

	clone = bio_alloc_bioset(cc->dev->bdev, nr_iovecs, io->base_bio->bi_opf,
				 GFP_NOIO, &cc->bs);
	clone->bi_private = io;
	clone->bi_end_io = crypt_endio;

	remaining_size = size;

	while (remaining_size) {
		struct page *pages;
		unsigned size_to_add;
		unsigned remaining_order = __fls((remaining_size + PAGE_SIZE - 1) >> PAGE_SHIFT);

		order = min(order, remaining_order);

		while (order > 0) {

			pages = alloc_pages(gfp_mask
				| __GFP_NOMEMALLOC | __GFP_NORETRY | __GFP_NOWARN | __GFP_COMP,
				order);
			if (likely(pages != NULL))
				goto have_pages;
			order--;
		}

		pages = mempool_alloc(&cc->page_pool, gfp_mask);
		if (!pages) {
			crypt_free_buffer_pages(cc, clone);
			bio_put(clone);
			gfp_mask |= __GFP_DIRECT_RECLAIM;
			order = 0;
			goto retry;
		}

have_pages:

		size_to_add = min((unsigned)PAGE_SIZE << order, remaining_size);
		__bio_add_page(clone, pages, size_to_add, 0);
		remaining_size -= size_to_add;
	}

	/* Allocate space for integrity tags */
	if (dm_crypt_integrity_io_alloc(io, clone)) {
		crypt_free_buffer_pages(cc, clone);
		bio_put(clone);
		clone = NULL;
	}

	if (unlikely(gfp_mask & __GFP_DIRECT_RECLAIM))
		mutex_unlock(&cc->bio_alloc_lock);

	return clone;
}

Haven't found any. However I'd like to point out some things I noticed in crypt_alloc_buffer(), although they are probably not related.

Quoted 9 lines

static struct bio *crypt_alloc_buffer(struct dm_crypt_io *io, unsigned int size)

{
	struct crypt_config *cc = io->cc;
	struct bio *clone;
	unsigned int nr_iovecs = (size + PAGE_SIZE - 1) >> PAGE_SHIFT;
	gfp_t gfp_mask = GFP_NOWAIT | __GFP_HIGHMEM;
	unsigned int remaining_size;
	unsigned int order = MAX_ORDER - 1;

Quoted 3 lines

retry:

	if (unlikely(gfp_mask & __GFP_DIRECT_RECLAIM))
		mutex_lock(&cc->bio_alloc_lock);

What if we end up in "goto retry" more than once? I don't see a matching

unlock. Yeah, very unlikely to happen that order-0 in page allocator which includes __GFP_DIRECT_RECLAIM would fail, but not impossible, and also I see crypt_page_alloc() for the mempool can fail for another reason, due to a counter being too high. Looks dangerous.

Quoted 6 lines

	clone = bio_alloc_bioset(cc->dev->bdev, nr_iovecs, io->base_bio->bi_opf,
				 GFP_NOIO, &cc->bs);
	clone->bi_private = io;
	clone->bi_end_io = crypt_endio;

Quoted 6 lines

	remaining_size = size;

	while (remaining_size) {
		struct page *pages;
		unsigned size_to_add;
		unsigned remaining_order = __fls((remaining_size + PAGE_SIZE - 1) >> PAGE_SHIFT);

Tip: you can use get_order(remaining_size) here.

Quoted 3 lines

		order = min(order, remaining_order);

		while (order > 0) {

Is this intentionally > 0 and not >= 0? We could still succeed avoiding mempool with order-0...

Quoted 30 lines

			pages = alloc_pages(gfp_mask
				| __GFP_NOMEMALLOC | __GFP_NORETRY | __GFP_NOWARN | __GFP_COMP,
				order);
			if (likely(pages != NULL))
				goto have_pages;
			order--;
		}

		pages = mempool_alloc(&cc->page_pool, gfp_mask);
		if (!pages) {
			crypt_free_buffer_pages(cc, clone);
			bio_put(clone);
			gfp_mask |= __GFP_DIRECT_RECLAIM;
			order = 0;
			goto retry;
		}

have_pages:

		size_to_add = min((unsigned)PAGE_SIZE << order, remaining_size);
		__bio_add_page(clone, pages, size_to_add, 0);
		remaining_size -= size_to_add;
	}

	/* Allocate space for integrity tags */
	if (dm_crypt_integrity_io_alloc(io, clone)) {
		crypt_free_buffer_pages(cc, clone);
		bio_put(clone);
		clone = NULL;
	}

Quoted 5 lines

	if (unlikely(gfp_mask & __GFP_DIRECT_RECLAIM))
		mutex_unlock(&cc->bio_alloc_lock);

	return clone;
}

Quoted 16 lines · Vlastimil Babka

Haven't found any. However I'd like to point out some things I noticed in crypt_alloc_buffer(), although they are probably not related.

Quoted 12 lines

static struct bio *crypt_alloc_buffer(struct dm_crypt_io *io, unsigned int size)

{
	struct crypt_config *cc = io->cc;
	struct bio *clone;
	unsigned int nr_iovecs = (size + PAGE_SIZE - 1) >> PAGE_SHIFT;
	gfp_t gfp_mask = GFP_NOWAIT | __GFP_HIGHMEM;
	unsigned int remaining_size;
	unsigned int order = MAX_ORDER - 1;

retry:

	if (unlikely(gfp_mask & __GFP_DIRECT_RECLAIM))
		mutex_lock(&cc->bio_alloc_lock);

Quoted 1 line

What if we end up in "goto retry" more than once? I don't see a matching

It is impossible. Before we jump to the retry label, we set __GFP_DIRECT_RECLAIM. mempool_alloc can't ever fail if __GFP_DIRECT_RECLAIM is present (it will just wait until some other task frees some objects into the mempool).

Ah, missed that. And the traces don't show that we would be waiting for that. I'm starting to think the allocation itself is really not the issue here. Also I don't think it deprives something else of large order pages, as per the sysrq listing they still existed.

What I rather suspect is what happens next to the allocated bio such that it works well with order-0 or up to costly_order pages, but there's some problem causing a deadlock if the bio contains larger pages than that?

Cc Honza. The thread starts here:
https://lore.kernel.org/all/ZTNH0qtmint%2FzLJZ@mail-itl/

The linked qubes reports has a number of blocked task listings that can be expanded:
https://github.com/QubesOS/qubes-issues/issues/8575

Quoted 5 lines · Vlastimil Babka

Ah, missed that. And the traces don't show that we would be waiting for that. I'm starting to think the allocation itself is really not the issue here. Also I don't think it deprives something else of large order pages, as per the sysrq listing they still existed.

Quoted 3 lines

What I rather suspect is what happens next to the allocated bio such that it works well with order-0 or up to costly_order pages, but there's some problem causing a deadlock if the bio contains larger pages than that?

Yes. There are many "if (order > PAGE_ALLOC_COSTLY_ORDER)" branches in the memory allocation code and I suppose that one of them does something bad and triggers this bug. But I don't know which one.

Quoted 6 lines

Cc Honza. The thread starts here:
https://lore.kernel.org/all/ZTNH0qtmint%2FzLJZ@mail-itl/

The linked qubes reports has a number of blocked task listings that can be expanded:
https://github.com/QubesOS/qubes-issues/issues/8575

Mikulas

Quoted 9 lines · Mikulas Patocka

Quoted 5 lines · Vlastimil Babka

Ah, missed that. And the traces don't show that we would be waiting for that. I'm starting to think the allocation itself is really not the issue here. Also I don't think it deprives something else of large order pages, as per the sysrq listing they still existed.

Quoted 7 lines

Quoted 3 lines

What I rather suspect is what happens next to the allocated bio such that it works well with order-0 or up to costly_order pages, but there's some problem causing a deadlock if the bio contains larger pages than that?

Yes. There are many "if (order > PAGE_ALLOC_COSTLY_ORDER)" branches in the memory allocation code and I suppose that one of them does something bad and triggers this bug. But I don't know which one.

It's not what I meant. All the interesting branches for costly order in page allocator/compaction only apply with __GFP_DIRECT_RECLAIM, so we can't be hitting those here.
The traces I've seen suggest the allocation of the bio suceeded, and problems arised only after it was submitted.

I wouldn't even be surprised if the threshold for hitting the bug was not exactly order > PAGE_ALLOC_COSTLY_ORDER but order > PAGE_ALLOC_COSTLY_ORDER
+ 1 or + 2 (has that been tested?) or rather that there's no exact threshold, but probability increases with order.

Quoted 7 lines · Mikulas Patocka

Quoted 5 lines · Vlastimil Babka

Ah, missed that. And the traces don't show that we would be waiting for that. I'm starting to think the allocation itself is really not the issue here. Also I don't think it deprives something else of large order pages, as per the sysrq listing they still existed.

Quoted 7 lines

Quoted 3 lines

What I rather suspect is what happens next to the allocated bio such that it works well with order-0 or up to costly_order pages, but there's some problem causing a deadlock if the bio contains larger pages than that?

Yes. There are many "if (order > PAGE_ALLOC_COSTLY_ORDER)" branches in the memory allocation code and I suppose that one of them does something bad and triggers this bug. But I don't know which one.

It's not what I meant. All the interesting branches for costly order in page allocator/compaction only apply with __GFP_DIRECT_RECLAIM, so we can't be hitting those here.
The traces I've seen suggest the allocation of the bio suceeded, and problems arised only after it was submitted.

I wouldn't even be surprised if the threshold for hitting the bug was not exactly order > PAGE_ALLOC_COSTLY_ORDER but order > PAGE_ALLOC_COSTLY_ORDER
+ 1 or + 2 (has that been tested?) or rather that there's no exact threshold, but probability increases with order.

Quoted 22 lines · Vlastimil Babka

Quoted 7 lines · Mikulas Patocka

Quoted 5 lines · Vlastimil Babka

Ah, missed that. And the traces don't show that we would be waiting for that. I'm starting to think the allocation itself is really not the issue here. Also I don't think it deprives something else of large order pages, as per the sysrq listing they still existed.

Quoted 7 lines

Quoted 3 lines

What I rather suspect is what happens next to the allocated bio such that it works well with order-0 or up to costly_order pages, but there's some problem causing a deadlock if the bio contains larger pages than that?

Yes. There are many "if (order > PAGE_ALLOC_COSTLY_ORDER)" branches in the memory allocation code and I suppose that one of them does something bad and triggers this bug. But I don't know which one.

It's not what I meant. All the interesting branches for costly order in page allocator/compaction only apply with __GFP_DIRECT_RECLAIM, so we can't be hitting those here.
The traces I've seen suggest the allocation of the bio suceeded, and problems arised only after it was submitted.

Quoted 4 lines

I wouldn't even be surprised if the threshold for hitting the bug was not exactly order > PAGE_ALLOC_COSTLY_ORDER but order > PAGE_ALLOC_COSTLY_ORDER
+ 1 or + 2 (has that been tested?) or rather that there's no exact threshold, but probability increases with order.

Well, it would be possible that larger pages in a bio would trip e.g. bio splitting due to maximum segment size the disk supports (which can be e.g. 0xffff) and that upsets something somewhere. But this is pure speculation. We definitely need more debug data to be able to tell more.

Quoted 4 lines

Well, it would be possible that larger pages in a bio would trip e.g. bio splitting due to maximum segment size the disk supports (which can be e.g. 0xffff) and that upsets something somewhere. But this is pure speculation. We definitely need more debug data to be able to tell more.

I can collect more info, but I need some guidance how :) Some patch adding extra debug messages?
Note I collect those via serial console (writing to disk doesn't work when it freezes), and that has some limits in the amount of data I can extract especially when printed quickly. For example sysrq-t is too much. Or maybe there is some trick to it, like increasing log_bug_len?

Quoted 11 lines · Marek Marczykowski-Górecki

Quoted 4 lines

Well, it would be possible that larger pages in a bio would trip e.g. bio splitting due to maximum segment size the disk supports (which can be e.g. 0xffff) and that upsets something somewhere. But this is pure speculation. We definitely need more debug data to be able to tell more.

I can collect more info, but I need some guidance how :) Some patch adding extra debug messages?
Note I collect those via serial console (writing to disk doesn't work when it freezes), and that has some limits in the amount of data I can extract especially when printed quickly. For example sysrq-t is too much. Or maybe there is some trick to it, like increasing log_bug_len?

If you can do more tests, I would suggest this:

We already know that it works with order 3 and doesn't work with order 4.

So, in the file include/linux/mmzone.h, change PAGE_ALLOC_COSTLY_ORDER from 3 to 4 and in the file drivers/md/dm-crypt.c leave "unsigned int order = PAGE_ALLOC_COSTLY_ORDER" there.

Does it deadlock or not?

So, that we can see whether the deadlock depends on PAGE_ALLOC_COSTLY_ORDER or whether it is just a coincidence.

Quoted 22 lines · Mikulas Patocka

Quoted 11 lines · Marek Marczykowski-Górecki

Quoted 4 lines

Well, it would be possible that larger pages in a bio would trip e.g. bio splitting due to maximum segment size the disk supports (which can be e.g. 0xffff) and that upsets something somewhere. But this is pure speculation. We definitely need more debug data to be able to tell more.

I can collect more info, but I need some guidance how :) Some patch adding extra debug messages?
Note I collect those via serial console (writing to disk doesn't work when it freezes), and that has some limits in the amount of data I can extract especially when printed quickly. For example sysrq-t is too much. Or maybe there is some trick to it, like increasing log_bug_len?

If you can do more tests, I would suggest this:

We already know that it works with order 3 and doesn't work with order 4.

So, in the file include/linux/mmzone.h, change PAGE_ALLOC_COSTLY_ORDER from 3 to 4 and in the file drivers/md/dm-crypt.c leave "unsigned int order = PAGE_ALLOC_COSTLY_ORDER" there.

Quoted 4 lines

Does it deadlock or not?

So, that we can see whether the deadlock depends on PAGE_ALLOC_COSTLY_ORDER or whether it is just a coincidence.

Good idea. Also if the kernel hangs, please find kcryptd processes. In what state are they? If they are sleeping, please send what's in /proc/<kcryptd-pid>/stack. Thanks!

Quoted 23 lines · Jan Kara

Quoted 22 lines · Mikulas Patocka

Quoted 11 lines · Marek Marczykowski-Górecki

Quoted 4 lines

Well, it would be possible that larger pages in a bio would trip e.g. bio splitting due to maximum segment size the disk supports (which can be e.g. 0xffff) and that upsets something somewhere. But this is pure speculation. We definitely need more debug data to be able to tell more.

I can collect more info, but I need some guidance how :) Some patch adding extra debug messages?
Note I collect those via serial console (writing to disk doesn't work when it freezes), and that has some limits in the amount of data I can extract especially when printed quickly. For example sysrq-t is too much. Or maybe there is some trick to it, like increasing log_bug_len?

If you can do more tests, I would suggest this:

We already know that it works with order 3 and doesn't work with order 4.

So, in the file include/linux/mmzone.h, change PAGE_ALLOC_COSTLY_ORDER from 3 to 4 and in the file drivers/md/dm-crypt.c leave "unsigned int order = PAGE_ALLOC_COSTLY_ORDER" there.

Quoted 8 lines

Quoted 4 lines

Does it deadlock or not?

So, that we can see whether the deadlock depends on PAGE_ALLOC_COSTLY_ORDER or whether it is just a coincidence.

Good idea. Also if the kernel hangs, please find kcryptd processes. In what state are they? If they are sleeping, please send what's in /proc/<kcryptd-pid>/stack. Thanks!

Will do.

In the meantime, while testing version with PAGE_ALLOC_COSTLY_ORDER=4, and order=PAGE_ALLOC_COSTLY_ORDER, I'm getting crash like this (see important note below both traces):

    [   92.668486] BUG: unable to handle page fault for address: ffff8880c7b64098
    [   92.668558] #PF: supervisor read access in kernel mode
    [   92.668574] #PF: error_code(0x0000) - not-present page
    [   92.668590] PGD 2a32067 P4D 2a32067 PUD 12868a067 PMD 0 
    [   92.668617] Oops: 0000 [#1] PREEMPT SMP NOPTI
    [   92.668637] CPU: 5 PID: 0 Comm: swapper/5 Tainted: G        W          6.5.6-dirty #354
    [   92.668658] Hardware name: Star Labs StarBook/StarBook, BIOS 8.97 10/03/2023
    [   92.668675] RIP: e030:__free_one_page+0x301/0x3e0
    [   92.668704] Code: 02 0f 85 c1 fe ff ff 49 c1 e6 04 49 8d 4c 24 08 4a 8d 94 36 c0 00 00 00 48 8d 34 80 48 8d 04 70 4c 01 fa 48 c1 e0 03 49 01 c6 <4b> 8b b4 37 c0 00 00 00 48 89 4e 08 49 89 74 24 08 49 89 54 24 10
    [   92.668738] RSP: e02b:ffffc90040154c60 EFLAGS: 00010006
    [   92.668754] RAX: 0000000000000058 RBX: 0000000000000001 RCX: ffff888075f66bc0
    [   92.668773] RDX: ffff8880c7b64098 RSI: 0000000000000005 RDI: 0000000000000000
    [   92.668789] RBP: fffffe7a01d7d9ae R08: ffff888075f66b38 R09: fffffe7a01d7d9ac
    [   92.668805] R10: ffffea0004b35bc8 R11: 0000000000000001 R12: ffff888075f66bb8
    [   92.668821] R13: 0000000000000000 R14: 0000000051bfd4d8 R15: ffff888075f66b00
    [   92.668854] FS:  0000000000000000(0000) GS:ffff888189740000(0000) knlGS:0000000000000000
    [   92.668874] CS:  10000e030 DS: 002b ES: 002b CR0: 0000000080050033
    [   92.668889] CR2: ffff8880c7b64098 CR3: 0000000133cf8000 CR4: 0000000000050660
    [   92.668912] Call Trace:
    [   92.668924]  <IRQ>
    [   92.668934]  ? __die+0x1e/0x60
    [   92.668955]  ? page_fault_oops+0x178/0x4a0
    [   92.668975]  ? exc_page_fault+0x14e/0x160
    [   92.668994]  ? asm_exc_page_fault+0x26/0x30
    [   92.669014]  ? __free_one_page+0x301/0x3e0
    [   92.669027]  free_pcppages_bulk+0x11c/0x2b0
    [   92.669042]  free_unref_page+0x10d/0x170
    [   92.669058]  crypt_free_buffer_pages+0x1f4/0x250
    [   92.669079]  crypt_endio+0x48/0x70
    [   92.669094]  blk_mq_end_request_batch+0xd0/0x400
    [   92.669114]  nvme_irq+0x6d/0x80
    [   92.669132]  ? __pfx_nvme_pci_complete_batch+0x10/0x10
    [   92.669148]  __handle_irq_event_percpu+0x42/0x1a0
    [   92.669166]  handle_irq_event+0x33/0x70
    [   92.669179]  handle_edge_irq+0x9e/0x240
    [   92.669197]  handle_irq_desc+0x36/0x50
    [   92.669215]  __evtchn_fifo_handle_events+0x1af/0x1d0
    [   92.669236]  __xen_evtchn_do_upcall+0x70/0xd0
    [   92.669255]  __xen_pv_evtchn_do_upcall+0x3d/0x70
    [   92.669275]  xen_pv_evtchn_do_upcall+0xd9/0x110
    [   92.669294]  </IRQ>
    [   92.669302]  <TASK>
    [   92.669310]  exc_xen_hypervisor_callback+0x8/0x20
    [   92.669330] RIP: e030:xen_hypercall_xen_version+0xa/0x20
    [   92.669348] Code: 51 41 53 b8 10 00 00 00 0f 05 41 5b 59 c3 cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc 51 41 53 b8 11 00 00 00 0f 05 <41> 5b 59 c3 cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc
    [   92.669380] RSP: e02b:ffffc900400c7e08 EFLAGS: 00000246
    [   92.669394] RAX: 0000000000040011 RBX: 0000000000000000 RCX: ffffffff81fc222a
    [   92.669411] RDX: 0000000000000002 RSI: 0000000000000000 RDI: 0000000000000000
    [   92.669426] RBP: ffffc900400c7eb0 R08: 0000000000000000 R09: 00000000000001ba
    [   92.669442] R10: 0000000000007ff0 R11: 0000000000000246 R12: ffff88818976c540
    [   92.669458] R13: ffff888101e10000 R14: 0000000000000000 R15: 0000000000000402
    [   92.669475]  ? xen_hypercall_xen_version+0xa/0x20
    [   92.669493]  ? pmu_msr_read+0x3c/0xd0
    [   92.669510]  ? xen_force_evtchn_callback+0xd/0x20
    [   92.669526]  ? check_events+0x16/0x30
    [   92.669540]  ? xen_irq_enable_direct+0x1d/0x30
    [   92.669556]  ? finish_task_switch.isra.0+0x8e/0x270
    [   92.669576]  ? __switch_to+0x165/0x3b0
    [   92.669590]  ? __schedule+0x316/0x8b0
    [   92.669609]  ? schedule_idle+0x25/0x40
    [   92.669626]  ? cpu_startup_entry+0x25/0x30
    [   92.669641]  ? cpu_bringup_and_idle+0x89/0xa0
    [   92.669660]  ? asm_cpu_bringup_and_idle+0x9/0x10
    [   92.669680]  </TASK>
    [   92.669688] Modules linked in: snd_hda_codec_hdmi snd_hda_codec_generic ledtrig_audio snd_sof_pci_intel_tgl snd_sof_intel_hda_common snd_soc_hdac_hda soundwire_intel soundwire_generic_allocation snd_sof_intel_hda_mlink soundwire_cadence snd_sof_intel_hda snd_sof_pci snd_sof snd_sof_utils snd_sof_xtensa_dsp snd_soc_acpi_intel_match snd_soc_acpi snd_hda_ext_core soundwire_bus snd_soc_core snd_compress snd_pcm_dmaengine ac97_bus snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi snd_hda_codec snd_hwdep hid_multitouch snd_hda_core snd_seq snd_seq_device idma64 snd_pcm i2c_designware_platform iwlwifi i2c_designware_core snd_timer snd soundcore i2c_i801 i2c_smbus efivarfs i2c_hid_acpi i2c_hid pinctrl_tigerlake pinctrl_intel xen_acpi_processor xen_pciback xen_blkback xen_gntalloc xen_gntdev xen_evtchn uinput
    [   92.669901] CR2: ffff8880c7b64098
    [   92.669915] ---[ end trace 0000000000000000 ]---
    [   92.669930] RIP: e030:__free_one_page+0x301/0x3e0
    [   92.669946] Code: 02 0f 85 c1 fe ff ff 49 c1 e6 04 49 8d 4c 24 08 4a 8d 94 36 c0 00 00 00 48 8d 34 80 48 8d 04 70 4c 01 fa 48 c1 e0 03 49 01 c6 <4b> 8b b4 37 c0 00 00 00 48 89 4e 08 49 89 74 24 08 49 89 54 24 10
    [   92.669977] RSP: e02b:ffffc90040154c60 EFLAGS: 00010006
    [   92.669992] RAX: 0000000000000058 RBX: 0000000000000001 RCX: ffff888075f66bc0
    [   92.670008] RDX: ffff8880c7b64098 RSI: 0000000000000005 RDI: 0000000000000000
    [   92.670024] RBP: fffffe7a01d7d9ae R08: ffff888075f66b38 R09: fffffe7a01d7d9ac
    [   92.670040] R10: ffffea0004b35bc8 R11: 0000000000000001 R12: ffff888075f66bb8
    [   92.670055] R13: 0000000000000000 R14: 0000000051bfd4d8 R15: ffff888075f66b00
    [   92.670083] FS:  0000000000000000(0000) GS:ffff888189740000(0000) knlGS:0000000000000000
    [   92.670101] CS:  10000e030 DS: 002b ES: 002b CR0: 0000000080050033
    [   92.670116] CR2: ffff8880c7b64098 CR3: 0000000133cf8000 CR4: 0000000000050660
    [   92.670148] Kernel panic - not syncing: Fatal exception in interrupt
    [   92.670177] ------------[ cut here ]------------
    [   92.670188] WARNING: CPU: 5 PID: 0 at kernel/smp.c:766 smp_call_function_many_cond+0x4db/0x560
    [   92.670219] Modules linked in: snd_hda_codec_hdmi snd_hda_codec_generic ledtrig_audio snd_sof_pci_intel_tgl snd_sof_intel_hda_common snd_soc_hdac_hda soundwire_intel soundwire_generic_allocation snd_sof_intel_hda_mlink soundwire_cadence snd_sof_intel_hda snd_sof_pci snd_sof snd_sof_utils snd_sof_xtensa_dsp snd_soc_acpi_intel_match snd_soc_acpi snd_hda_ext_core soundwire_bus snd_soc_core snd_compress snd_pcm_dmaengine ac97_bus snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi snd_hda_codec snd_hwdep hid_multitouch snd_hda_core snd_seq snd_seq_device idma64 snd_pcm i2c_designware_platform iwlwifi i2c_designware_core snd_timer snd soundcore i2c_i801 i2c_smbus efivarfs i2c_hid_acpi i2c_hid pinctrl_tigerlake pinctrl_intel xen_acpi_processor xen_pciback xen_blkback xen_gntalloc xen_gntdev xen_evtchn uinput
    [   92.670400] CPU: 5 PID: 0 Comm: swapper/5 Tainted: G      D W          6.5.6-dirty #354
    [   92.670419] Hardware name: Star Labs StarBook/StarBook, BIOS 8.97 10/03/2023
    [   92.670434] RIP: e030:smp_call_function_many_cond+0x4db/0x560
    [   92.670455] Code: f0 52 1b 81 48 89 74 24 08 e8 d1 c8 f6 ff 48 8b 74 24 08 65 ff 0d 5d 70 e7 7e 0f 85 bb fd ff ff 0f 1f 44 00 00 e9 b1 fd ff ff <0f> 0b e9 69 fb ff ff 8b 7c 24 38 e8 d5 4f f7 ff 84 c0 0f 84 a8 fd
    [   92.670486] RSP: e02b:ffffc900401549d0 EFLAGS: 00010006
    [   92.670500] RAX: 0000000080010007 RBX: 0000000000000000 RCX: 0000000000000000
    [   92.670516] RDX: 0000000000000000 RSI: ffffffff826f3c61 RDI: ffffffff82cbc1d0
    [   92.670531] RBP: 0000000000000005 R08: 0000000000000000 R09: 0000000000000001
    [   92.670546] R10: 00000000ffffdfff R11: ffffffff82a5ddc0 R12: 0000000000000005
    [   92.670562] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
    [   92.670588] FS:  0000000000000000(0000) GS:ffff888189740000(0000) knlGS:0000000000000000
    [   92.670606] CS:  10000e030 DS: 002b ES: 002b CR0: 0000000080050033
    [   92.670620] CR2: ffff8880c7b64098 CR3: 0000000133cf8000 CR4: 0000000000050660
    [   92.670642] Call Trace:
    [   92.670650]  <IRQ>
    [   92.670659]  ? smp_call_function_many_cond+0x4db/0x560
    [   92.670677]  ? __warn+0x7c/0x130
    [   92.670693]  ? smp_call_function_many_cond+0x4db/0x560
    [   92.670711]  ? report_bug+0x191/0x1c0
    [   92.670726]  ? handle_bug+0x3c/0x80
    [   92.670742]  ? exc_invalid_op+0x17/0x70
    [   92.670758]  ? asm_exc_invalid_op+0x1a/0x20
    [   92.670775]  ? smp_call_function_many_cond+0x4db/0x560
    [   92.670793]  ? __pfx_stop_self+0x10/0x10
    [   92.670811]  ? _printk+0x5f/0x80
    [   92.670823]  ? __pfx_stop_self+0x10/0x10
    [   92.670840]  smp_call_function+0x38/0x70
    [   92.670857]  panic+0x19c/0x320
    [   92.670873]  oops_end+0xd8/0xe0
    [   92.670887]  page_fault_oops+0x19c/0x4a0
    [   92.670905]  exc_page_fault+0x14e/0x160
    [   92.670921]  asm_exc_page_fault+0x26/0x30
    [   92.670937] RIP: e030:__free_one_page+0x301/0x3e0
    [   92.670952] Code: 02 0f 85 c1 fe ff ff 49 c1 e6 04 49 8d 4c 24 08 4a 8d 94 36 c0 00 00 00 48 8d 34 80 48 8d 04 70 4c 01 fa 48 c1 e0 03 49 01 c6 <4b> 8b b4 37 c0 00 00 00 48 89 4e 08 49 89 74 24 08 49 89 54 24 10
    [   92.670983] RSP: e02b:ffffc90040154c60 EFLAGS: 00010006
    [   92.670997] RAX: 0000000000000058 RBX: 0000000000000001 RCX: ffff888075f66bc0
    [   92.671013] RDX: ffff8880c7b64098 RSI: 0000000000000005 RDI: 0000000000000000
    [   92.671028] RBP: fffffe7a01d7d9ae R08: ffff888075f66b38 R09: fffffe7a01d7d9ac
    [   92.671044] R10: ffffea0004b35bc8 R11: 0000000000000001 R12: ffff888075f66bb8
    [   92.671059] R13: 0000000000000000 R14: 0000000051bfd4d8 R15: ffff888075f66b00
    [   92.671077]  free_pcppages_bulk+0x11c/0x2b0
    [   92.671091]  free_unref_page+0x10d/0x170
    [   92.671106]  crypt_free_buffer_pages+0x1f4/0x250
    [   92.671122]  crypt_endio+0x48/0x70
    [   92.671136]  blk_mq_end_request_batch+0xd0/0x400
    [   92.671152]  nvme_irq+0x6d/0x80
    [   92.671166]  ? __pfx_nvme_pci_complete_batch+0x10/0x10
    [   92.671181]  __handle_irq_event_percpu+0x42/0x1a0
    [   92.671196]  handle_irq_event+0x33/0x70
    [   92.671208]  handle_edge_irq+0x9e/0x240
    [   92.671224]  handle_irq_desc+0x36/0x50
    [   92.671241]  __evtchn_fifo_handle_events+0x1af/0x1d0
    [   92.671258]  __xen_evtchn_do_upcall+0x70/0xd0
    [   92.671275]  __xen_pv_evtchn_do_upcall+0x3d/0x70
    [   92.671292]  xen_pv_evtchn_do_upcall+0xd9/0x110
    [   92.671308]  </IRQ>
    [   92.671316]  <TASK>
    [   92.671324]  exc_xen_hypervisor_callback+0x8/0x20
    [   92.671342] RIP: e030:xen_hypercall_xen_version+0xa/0x20
    [   92.671360] Code: 51 41 53 b8 10 00 00 00 0f 05 41 5b 59 c3 cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc 51 41 53 b8 11 00 00 00 0f 05 <41> 5b 59 c3 cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc
    [   92.671390] RSP: e02b:ffffc900400c7e08 EFLAGS: 00000246
    [   92.671403] RAX: 0000000000040011 RBX: 0000000000000000 RCX: ffffffff81fc222a
    [   92.671419] RDX: 0000000000000002 RSI: 0000000000000000 RDI: 0000000000000000
    [   92.671434] RBP: ffffc900400c7eb0 R08: 0000000000000000 R09: 00000000000001ba
    [   92.671449] R10: 0000000000007ff0 R11: 0000000000000246 R12: ffff88818976c540
    [   92.671465] R13: ffff888101e10000 R14: 0000000000000000 R15: 0000000000000402
    [   92.671481]  ? xen_hypercall_xen_version+0xa/0x20
    [   92.671499]  ? pmu_msr_read+0x3c/0xd0
    [   92.671514]  ? xen_force_evtchn_callback+0xd/0x20
    [   92.671529]  ? check_events+0x16/0x30
    [   92.671543]  ? xen_irq_enable_direct+0x1d/0x30
    [   92.671560]  ? finish_task_switch.isra.0+0x8e/0x270
    [   92.671579]  ? __switch_to+0x165/0x3b0
    [   92.671593]  ? __schedule+0x316/0x8b0
    [   92.671611]  ? schedule_idle+0x25/0x40
    [   92.671631]  ? cpu_startup_entry+0x25/0x30
    [   92.671644]  ? cpu_bringup_and_idle+0x89/0xa0
    [   92.671663]  ? asm_cpu_bringup_and_idle+0x9/0x10
    [   92.671683]  </TASK>
    [   92.671691] ---[ end trace 0000000000000000 ]---
    [   92.671782] Kernel Offset: disabled
    (XEN) Hardware Dom0 crashed: rebooting machine in 5 seconds.

If I change order=PAGE_ALLOC_COSTLY_ORDER+1, then this:

    [ 2205.112802] BUG: unable to handle page fault for address: ffffffff89630301
    [ 2205.112866] #PF: supervisor write access in kernel mode
    [ 2205.112882] #PF: error_code(0x0002) - not-present page
    [ 2205.112899] PGD 2a35067 P4D 2a35067 PUD 2a36067 PMD 0 
    [ 2205.112921] Oops: 0002 [#1] PREEMPT SMP NOPTI
    [ 2205.112946] CPU: 0 PID: 12609 Comm: kworker/u12:9 Tainted: G        W          6.5.6-dirty #355
    [ 2205.112979] Hardware name: Star Labs StarBook/StarBook, BIOS 8.97 10/03/2023
    [ 2205.112997] Workqueue: kcryptd/252:0 kcryptd_crypt
    [ 2205.113022] RIP: e030:get_page_from_freelist+0x281/0x10c0
    [ 2205.113044] Code: 6c 05 18 49 89 df 8b 5c 24 34 49 8b 47 18 48 39 c5 0f 84 85 02 00 00 49 8b 47 18 48 8b 48 08 48 8b 30 48 8d 50 f8 48 89 4e 08 <48> 89 31 48 b9 00 01 00 00 00 00 ad de 48 89 08 48 83 c1 22 48 89
    [ 2205.113079] RSP: e02b:ffffc90041ea7c48 EFLAGS: 00010283
    [ 2205.113096] RAX: ffffea00059b9248 RBX: 0000000000000001 RCX: ffffffff89630301
    [ 2205.113117] RDX: ffffea00059b9240 RSI: ffffea00059b9201 RDI: 0000000000000001
    [ 2205.113134] RBP: ffff888189631718 R08: 000000000000c000 R09: 000000000003cb07
    [ 2205.113153] R10: 0000000000000001 R11: fefefefefefefeff R12: ffff888075f66b00
    [ 2205.113171] R13: ffff888189631700 R14: 0000000000000000 R15: ffff888189631700
    [ 2205.113208] FS:  0000000000000000(0000) GS:ffff888189600000(0000) knlGS:0000000000000000
    [ 2205.113229] CS:  e030 DS: 0000 ES: 0000 CR0: 0000000080050033
    [ 2205.113245] CR2: ffffffff89630301 CR3: 00000001049d0000 CR4: 0000000000050660
    [ 2205.113272] Call Trace:
    [ 2205.113285]  <TASK>
    [ 2205.113295]  ? __die+0x1e/0x60
    [ 2205.113312]  ? page_fault_oops+0x178/0x4a0
    [ 2205.113330]  ? exc_page_fault+0x14e/0x160
    [ 2205.113346]  ? asm_exc_page_fault+0x26/0x30
    [ 2205.113363]  ? get_page_from_freelist+0x281/0x10c0
    [ 2205.113379]  ? get_page_from_freelist+0x227/0x10c0
    [ 2205.113396]  __alloc_pages+0x1dd/0x300
    [ 2205.113412]  crypt_page_alloc+0x29/0x60
    [ 2205.113425]  mempool_alloc+0x81/0x1b0
    [ 2205.113443]  kcryptd_crypt+0x293/0x4b0
    [ 2205.113458]  process_one_work+0x1e0/0x3e0
    [ 2205.113476]  worker_thread+0x49/0x3b0
    [ 2205.113490]  ? _raw_spin_lock_irqsave+0x22/0x50
    [ 2205.113510]  ? __pfx_worker_thread+0x10/0x10
    [ 2205.113527]  kthread+0xef/0x120
    [ 2205.113541]  ? __pfx_kthread+0x10/0x10
    [ 2205.113554]  ret_from_fork+0x2c/0x50
    [ 2205.113568]  ? __pfx_kthread+0x10/0x10
    [ 2205.113581]  ret_from_fork_asm+0x1b/0x30
    [ 2205.113598]  </TASK>
    [ 2205.113606] Modules linked in: snd_hda_codec_hdmi snd_sof_pci_intel_tgl snd_sof_intel_hda_common snd_soc_hdac_hda soundwire_intel soundwire_generic_allocation snd_sof_intel_hda_mlink soundwire_cadence snd_sof_intel_hda snd_sof_pci snd_hda_codec_generic snd_sof ledtrig_audio snd_sof_utils snd_sof_xtensa_dsp snd_soc_acpi_intel_match snd_soc_acpi snd_hda_ext_core soundwire_bus snd_soc_core snd_compress snd_pcm_dmaengine ac97_bus snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi snd_hda_codec snd_hwdep snd_hda_core snd_seq snd_seq_device snd_pcm hid_multitouch snd_timer snd i2c_designware_platform i2c_designware_core i2c_i801 soundcore iwlwifi idma64 i2c_smbus i2c_hid_acpi i2c_hid pinctrl_tigerlake pinctrl_intel xen_acpi_processor xen_pciback xen_blkback xen_gntalloc xen_gntdev xen_evtchn uinput efivarfs
    [ 2205.113795] CR2: ffffffff89630301
    [ 2205.113808] ---[ end trace 0000000000000000 ]---
    [ 2205.113822] RIP: e030:get_page_from_freelist+0x281/0x10c0
    [ 2205.113839] Code: 6c 05 18 49 89 df 8b 5c 24 34 49 8b 47 18 48 39 c5 0f 84 85 02 00 00 49 8b 47 18 48 8b 48 08 48 8b 30 48 8d 50 f8 48 89 4e 08 <48> 89 31 48 b9 00 01 00 00 00 00 ad de 48 89 08 48 83 c1 22 48 89
    [ 2205.113873] RSP: e02b:ffffc90041ea7c48 EFLAGS: 00010283
    [ 2205.113887] RAX: ffffea00059b9248 RBX: 0000000000000001 RCX: ffffffff89630301
    [ 2205.113903] RDX: ffffea00059b9240 RSI: ffffea00059b9201 RDI: 0000000000000001
    [ 2205.113919] RBP: ffff888189631718 R08: 000000000000c000 R09: 000000000003cb07
    [ 2205.113935] R10: 0000000000000001 R11: fefefefefefefeff R12: ffff888075f66b00
    [ 2205.113950] R13: ffff888189631700 R14: 0000000000000000 R15: ffff888189631700
    [ 2205.113980] FS:  0000000000000000(0000) GS:ffff888189600000(0000) knlGS:0000000000000000
    [ 2205.113998] CS:  e030 DS: 0000 ES: 0000 CR0: 0000000080050033
    [ 2205.114012] CR2: ffffffff89630301 CR3: 00000001049d0000 CR4: 0000000000050660
    [ 2205.114038] note: kworker/u12:9[12609] exited with irqs disabled
    [ 2205.114100] note: kworker/u12:9[12609] exited with preempt_count 2

Then retried with order=PAGE_ALLOC_COSTLY_ORDER and PAGE_ALLOC_COSTLY_ORDER back at 3, and also got similar crash.

Both happened only after logging into X session (lightdm -> Xfce) and starting xfce4-terminal. If I use text console/ssh/serial and leave lightdm at login screen, then it does not crash (this is in fact how I did most previous tests). I have no idea if it's related to some other bug somewhere else (graphics driver?), or simply higher memory usage due to the whole Xfce session running.
It could be also a coincidence, the sample size is rather small... But could be also some memory corruption that depending on memory layout sometimes results in a crash and sometimes in "just" storage freeze.

Note this all is still on top of 6.5.6 with changes we discuss here. If you believe it's another issue that got fixed in the meantime, I can switch to another version, but otherwise I'd like to limit changes.

Signature · 3 lines

Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

Quoted 2 lines · Marek Marczykowski-Górecki

Then retried with order=PAGE_ALLOC_COSTLY_ORDER and PAGE_ALLOC_COSTLY_ORDER back at 3, and also got similar crash.

So, does it mean that even allocating with order=PAGE_ALLOC_COSTLY_ORDER isn't safe?

Try enabling CONFIG_DEBUG_VM (it also needs CONFIG_DEBUG_KERNEL) and try to provoke a similar crash. Let's see if it crashes on one of the VM_BUG_ON statements.

Quoted 6 lines · Mikulas Patocka

Quoted 2 lines · Marek Marczykowski-Górecki

Then retried with order=PAGE_ALLOC_COSTLY_ORDER and PAGE_ALLOC_COSTLY_ORDER back at 3, and also got similar crash.

So, does it mean that even allocating with order=PAGE_ALLOC_COSTLY_ORDER isn't safe?

That seems to be another bug, see below.

Quoted 3 lines

Try enabling CONFIG_DEBUG_VM (it also needs CONFIG_DEBUG_KERNEL) and try to provoke a similar crash. Let's see if it crashes on one of the VM_BUG_ON statements.

This was very interesting idea. With this, immediately after login I get the crash like below. Which makes sense, as this is when pulseaudio starts and opens /dev/snd/*. I then tried with the dm-crypt commit reverted and still got the crash! But, after blacklisting snd_pcm, there is no BUG splat, but the storage freeze still happens on vanilla 6.5.6.

Plain 6.5.6 (so order = MAX_ORDER - 1, and PAGE_ALLOC_COSTLY_ORDER=3), in frozen state:

[  143.196106] task:blkdiscard      state:D stack:13672 pid:4884  ppid:2025   flags:0x00000002
[  143.196130] Call Trace:
[  143.196139]  <TASK>
[  143.196147]  __schedule+0x30e/0x8b0
[  143.196162]  schedule+0x59/0xb0
[  143.196175]  schedule_timeout+0x14c/0x160
[  143.196193]  io_schedule_timeout+0x4b/0x70
[  143.196207]  wait_for_completion_io+0x81/0x130
[  143.196226]  submit_bio_wait+0x5c/0x90
[  143.196241]  blkdev_issue_discard+0x94/0xe0
[  143.196260]  blkdev_common_ioctl+0x79e/0x9c0
[  143.196279]  blkdev_ioctl+0xc7/0x270
[  143.196293]  __x64_sys_ioctl+0x8f/0xd0
[  143.196310]  do_syscall_64+0x3c/0x90

for f in $(grep -l crypt /proc/*/comm); do head $f ${f/comm/stack}; done

Then tried:
- PAGE_ALLOC_COSTLY_ORDER=4, order=4 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=5 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=6 - freeze rather quickly

I've retried the PAGE_ALLOC_COSTLY_ORDER=4,order=5 case several times and I can't reproduce the issue there. I'm confused...

Quoted 7 lines · Marek Marczykowski-Górecki

Then tried:
- PAGE_ALLOC_COSTLY_ORDER=4, order=4 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=5 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=6 - freeze rather quickly

I've retried the PAGE_ALLOC_COSTLY_ORDER=4,order=5 case several times and I can't reproduce the issue there. I'm confused...

And this kind of confirms that allocations > PAGE_ALLOC_COSTLY_ORDER causing hangs is most likely just a coincidence. Rather something either in the block layer or in the storage driver has problems with handling bios with sufficiently high order pages attached. This is going to be a bit painful to debug I'm afraid. How long does it take for you trigger the hang? I'm asking to get rough estimate how heavy tracing we can afford so that we don't overwhelm the system...

Quoted 9 lines · Jan Kara

Quoted 7 lines · Marek Marczykowski-Górecki

Then tried:
- PAGE_ALLOC_COSTLY_ORDER=4, order=4 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=5 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=6 - freeze rather quickly

I've retried the PAGE_ALLOC_COSTLY_ORDER=4,order=5 case several times and I can't reproduce the issue there. I'm confused...

Quoted 7 lines

And this kind of confirms that allocations > PAGE_ALLOC_COSTLY_ORDER causing hangs is most likely just a coincidence. Rather something either in the block layer or in the storage driver has problems with handling bios with sufficiently high order pages attached. This is going to be a bit painful to debug I'm afraid. How long does it take for you trigger the hang? I'm asking to get rough estimate how heavy tracing we can afford so that we don't overwhelm the system...

Sometimes it freezes just after logging in, but in worst case it takes me about 10min of more or less tar xz + dd.

Quoted 18 lines · Marek Marczykowski-Górecki

Quoted 9 lines · Jan Kara

Quoted 7 lines · Marek Marczykowski-Górecki

Then tried:
- PAGE_ALLOC_COSTLY_ORDER=4, order=4 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=5 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=6 - freeze rather quickly

I've retried the PAGE_ALLOC_COSTLY_ORDER=4,order=5 case several times and I can't reproduce the issue there. I'm confused...

Quoted 7 lines

And this kind of confirms that allocations > PAGE_ALLOC_COSTLY_ORDER causing hangs is most likely just a coincidence. Rather something either in the block layer or in the storage driver has problems with handling bios with sufficiently high order pages attached. This is going to be a bit painful to debug I'm afraid. How long does it take for you trigger the hang? I'm asking to get rough estimate how heavy tracing we can afford so that we don't overwhelm the system...

Quoted 2 lines

Sometimes it freezes just after logging in, but in worst case it takes me about 10min of more or less tar xz + dd.

Hi

I would like to ask you to try this patch. Revert the changes to "order" and "PAGE_ALLOC_COSTLY_ORDER" back to normal and apply this patch on a clean upstream kernel.

Does it deadlock?

There is a bug in dm-crypt that it doesn't account large pages in cc->n_allocated_pages, this patch fixes the bug.

Mikulas

Quoted 27 lines · Mikulas Patocka

Quoted 18 lines · Marek Marczykowski-Górecki

Quoted 9 lines · Jan Kara

Quoted 7 lines · Marek Marczykowski-Górecki

Then tried:
- PAGE_ALLOC_COSTLY_ORDER=4, order=4 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=5 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=6 - freeze rather quickly

I've retried the PAGE_ALLOC_COSTLY_ORDER=4,order=5 case several times and I can't reproduce the issue there. I'm confused...

Quoted 7 lines

And this kind of confirms that allocations > PAGE_ALLOC_COSTLY_ORDER causing hangs is most likely just a coincidence. Rather something either in the block layer or in the storage driver has problems with handling bios with sufficiently high order pages attached. This is going to be a bit painful to debug I'm afraid. How long does it take for you trigger the hang? I'm asking to get rough estimate how heavy tracing we can afford so that we don't overwhelm the system...

Quoted 2 lines

Sometimes it freezes just after logging in, but in worst case it takes me about 10min of more or less tar xz + dd.

Hi

Quoted 8 lines

I would like to ask you to try this patch. Revert the changes to "order" and "PAGE_ALLOC_COSTLY_ORDER" back to normal and apply this patch on a clean upstream kernel.

Does it deadlock?

There is a bug in dm-crypt that it doesn't account large pages in cc->n_allocated_pages, this patch fixes the bug.

If the previous patch didn't fix it, try this patch (on a clean upstream kernel).

This patch allocates large pages, but it breaks them up into single-page entries when adding them to the bio.

If this patch deadlocks, it is a sign that allocating large pages causes the problem.

If this patch doesn't deadlock, it is a sign that processing a bio with large pages is the problem.

Mikulas

---
 drivers/md/dm-crypt.c |   26 ++++++++++++++++++++++----
 1 file changed, 22 insertions(+), 4 deletions(-)

Index: linux-stable/drivers/md/dm-crypt.c
===================================================================

drivers/md/dm-crypt.c +22 -4

@@ -1700,11 +1700,16 @@ retry:
 		order = min(order, remaining_order);
 
 		while (order > 0) {
+			if (unlikely(percpu_counter_read_positive(&cc->n_allocated_pages) + (1 << order) > dm_crypt_pages_per_client))
+				goto decrease_order;
 			pages = alloc_pages(gfp_mask
 				| __GFP_NOMEMALLOC | __GFP_NORETRY | __GFP_NOWARN | __GFP_COMP,
 				order);
-			if (likely(pages != NULL))
+			if (likely(pages != NULL)) {
+				percpu_counter_add(&cc->n_allocated_pages, 1 << order);
 				goto have_pages;
+			}
+decrease_order:
 			order--;
 		}
 

@@ -1719,8 +1724,13 @@ retry:
 
 have_pages:
 		size_to_add = min((unsigned)PAGE_SIZE << order, remaining_size);
-		__bio_add_page(clone, pages, size_to_add, 0);
 		remaining_size -= size_to_add;
+		while (size_to_add) {
+			unsigned this_step = min(size_to_add, (unsigned)PAGE_SIZE);
+			__bio_add_page(clone, pages, this_step, 0);
+			size_to_add -= this_step;
+			pages++;
+		}
 	}
 
 	/* Allocate space for integrity tags */

@@ -1739,13 +1749,21 @@ have_pages:
 static void crypt_free_buffer_pages(struct crypt_config *cc, struct bio *clone)
 {
 	struct folio_iter fi;
+	unsigned skip = 0;
 
 	if (clone->bi_vcnt > 0) { /* bio_for_each_folio_all crashes with an empty bio */
 		bio_for_each_folio_all(fi, clone) {
-			if (folio_test_large(fi.folio))
+			if (skip) {
+				skip--;
+				continue;
+			}
+			if (folio_test_large(fi.folio)) {
+				skip = (1 << folio_order(fi.folio)) - 1;
+				percpu_counter_sub(&cc->n_allocated_pages, 1 << folio_order(fi.folio));
 				folio_put(fi.folio);
-			else
+			} else {
 				mempool_free(&fi.folio->page, &cc->page_pool);
+			}
 		}
 	}
 }

Quoted 10 lines · Mikulas Patocka

Quoted 10 lines

Hi

I would like to ask you to try this patch. Revert the changes to "order" and "PAGE_ALLOC_COSTLY_ORDER" back to normal and apply this patch on a clean upstream kernel.

Does it deadlock?

There is a bug in dm-crypt that it doesn't account large pages in cc->n_allocated_pages, this patch fixes the bug.

This patch did not help.

Quoted 5 lines

If the previous patch didn't fix it, try this patch (on a clean upstream kernel).

This patch allocates large pages, but it breaks them up into single-page entries when adding them to the bio.

But this does help.

Quoted 15 lines · Marek Marczykowski-Górecki

Quoted 10 lines · Mikulas Patocka

Quoted 10 lines

Hi

I would like to ask you to try this patch. Revert the changes to "order" and "PAGE_ALLOC_COSTLY_ORDER" back to normal and apply this patch on a clean upstream kernel.

Does it deadlock?

There is a bug in dm-crypt that it doesn't account large pages in cc->n_allocated_pages, this patch fixes the bug.

This patch did not help.

Quoted 7 lines

Quoted 5 lines

If the previous patch didn't fix it, try this patch (on a clean upstream kernel).

This patch allocates large pages, but it breaks them up into single-page entries when adding them to the bio.

But this does help.

Thanks. So we can stop blaming the memory allocator and start blaming the NVMe subsystem.

I added NVMe maintainers to this thread - the summary of the problem is:
In dm-crypt, we allocate a large compound page and add this compound page to the bio as a single big vector entry. Marek reports that on his system it causes deadlocks, the deadlocks look like a lost bio that was never completed. When I chop the large compound page to individual pages in dm-crypt and add bio vector for each of them, Marek reports that there are no longer any deadlocks. So, we have a problem (either hardware or software) that the NVMe subsystem doesn't like bio vectors with large bv_len. This is the original bug report:
https://lore.kernel.org/stable/ZTNH0qtmint%2FzLJZ@mail-itl/

Marek, what NVMe devices do you use? Do you use the same device on all 3 machines where you hit this bug?

In the directory /sys/block/nvme0n1/queue: what is the value of dma_alignment, max_hw_sectors_kb, max_sectors_kb, max_segment_size, max_segments, virt_boundary_mask?

Try lowring /sys/block/nvme0n1/queue/max_sectors_kb to some small value (for example 64) and test if it helps.

Quoted 2 lines · Mikulas Patocka

Try lowring /sys/block/nvme0n1/queue/max_sectors_kb to some small value (for example 64) and test if it helps.

Yes, this helps too.

Quoted 5 lines · Marek Marczykowski-Górecki

Quoted 2 lines · Mikulas Patocka

Try lowring /sys/block/nvme0n1/queue/max_sectors_kb to some small value (for example 64) and test if it helps.

Quoted 1 line

Yes, this helps too.

On a plain upstream kernel with no other modifications (and with default max_sectors_kb), set the value /sys/module/nvme/parameters/sgl_threshold to "0" and test it if it deadlocks. Then, set this value to "1" and test it again.

Revert sgl_threshold back to the default (32768). Boot the kernel with the option "iommu=panic". Reproduce the deadlock and if you get a kernel panic, send us the panic log.

Then, try this patch (without "iommu=panic"), reproduce the deadlock and tell us which one of the "printk" statements is triggered during the deadlock.

Quoted 7 lines · Mikulas Patocka

Quoted 5 lines · Marek Marczykowski-G'orecki

Quoted 2 lines · Mikulas Patocka

Try lowring /sys/block/nvme0n1/queue/max_sectors_kb to some small value (for example 64) and test if it helps.

Quoted 6 lines

Quoted 1 line

Yes, this helps too.

On a plain upstream kernel with no other modifications (and with default max_sectors_kb), set the value /sys/module/nvme/parameters/sgl_threshold to "0" and test it if it deadlocks. Then, set this value to "1" and test it again.

Got deadlock wit both values.

Quoted 3 lines

Revert sgl_threshold back to the default (32768). Boot the kernel with the option "iommu=panic". Reproduce the deadlock and if you get a kernel panic, send us the panic log.

This is a Xen PV, so Linux is not in charge of IOMMU here. And there is SWIOTLB involved (64MB of it), I'm not sure if for every DMA, but definitely for some.

Quoted 3 lines

Then, try this patch (without "iommu=panic"), reproduce the deadlock and tell us which one of the "printk" statements is triggered during the deadlock.

I'll try this next.

Then, try this patch (without "iommu=panic"), reproduce the deadlock and tell us which one of the "printk" statements is triggered during the deadlock.

Mikulas

---
 drivers/nvme/host/core.c |    8 ++++++--
 drivers/nvme/host/pci.c  |   27 ++++++++++++++++++++++-----
 2 files changed, 28 insertions(+), 7 deletions(-)

Index: linux-stable/drivers/nvme/host/pci.c
===================================================================

drivers/nvme/host/pci.c +17 -4

@@ -622,6 +622,10 @@ static blk_status_t nvme_pci_setup_prps(
 	prp_list = dma_pool_alloc(pool, GFP_ATOMIC, &prp_dma);
 	if (!prp_list) {
 		iod->nr_allocations = -1;
+		if (nprps <= (256 / 8))
+			printk("allocation failure at %d\n", __LINE__);
+		else
+			printk("allocation failure at %d\n", __LINE__);
 		return BLK_STS_RESOURCE;
 	}
 	iod->list[0].prp_list = prp_list;

@@ -631,8 +635,10 @@ static blk_status_t nvme_pci_setup_prps(
 		if (i == NVME_CTRL_PAGE_SIZE >> 3) {
 			__le64 *old_prp_list = prp_list;
 			prp_list = dma_pool_alloc(pool, GFP_ATOMIC, &prp_dma);
-			if (!prp_list)
+			if (!prp_list) {
+				printk("allocation failure at %d\n", __LINE__);
 				goto free_prps;
+			}
 			iod->list[iod->nr_allocations++].prp_list = prp_list;
 			prp_list[0] = old_prp_list[i - 1];
 			old_prp_list[i - 1] = cpu_to_le64(prp_dma);

@@ -712,6 +718,7 @@ static blk_status_t nvme_pci_setup_sgls(
 	sg_list = dma_pool_alloc(pool, GFP_ATOMIC, &sgl_dma);
 	if (!sg_list) {
 		iod->nr_allocations = -1;
+		printk("allocation failure at %d\n", __LINE__);
 		return BLK_STS_RESOURCE;
 	}
 

@@ -736,8 +743,10 @@ static blk_status_t nvme_setup_prp_simpl
 	unsigned int first_prp_len = NVME_CTRL_PAGE_SIZE - offset;
 
 	iod->first_dma = dma_map_bvec(dev->dev, bv, rq_dma_dir(req), 0);
-	if (dma_mapping_error(dev->dev, iod->first_dma))
+	if (dma_mapping_error(dev->dev, iod->first_dma)) {
+		printk("allocation failure at %d\n", __LINE__);
 		return BLK_STS_RESOURCE;
+	}
 	iod->dma_len = bv->bv_len;
 
 	cmnd->dptr.prp1 = cpu_to_le64(iod->first_dma);

@@ -755,8 +764,10 @@ static blk_status_t nvme_setup_sgl_simpl
 	struct nvme_iod *iod = blk_mq_rq_to_pdu(req);
 
 	iod->first_dma = dma_map_bvec(dev->dev, bv, rq_dma_dir(req), 0);
-	if (dma_mapping_error(dev->dev, iod->first_dma))
+	if (dma_mapping_error(dev->dev, iod->first_dma)) {
+		printk("allocation failure at %d\n", __LINE__);
 		return BLK_STS_RESOURCE;
+	}
 	iod->dma_len = bv->bv_len;
 
 	cmnd->flags = NVME_CMD_SGL_METABUF;

@@ -791,8 +802,10 @@ static blk_status_t nvme_map_data(struct
 
 	iod->dma_len = 0;
 	iod->sgt.sgl = mempool_alloc(dev->iod_mempool, GFP_ATOMIC);
-	if (!iod->sgt.sgl)
+	if (!iod->sgt.sgl) {
+		printk("allocation failure at %d\n", __LINE__);
 		return BLK_STS_RESOURCE;
+	}
 	sg_init_table(iod->sgt.sgl, blk_rq_nr_phys_segments(req));
 	iod->sgt.orig_nents = blk_rq_map_sg(req->q, req, iod->sgt.sgl);
 	if (!iod->sgt.orig_nents)

drivers/nvme/host/pci.c +1 -0

+		}
 		goto out_free_sg;
 	}
 

Index: linux-stable/drivers/nvme/host/core.c
===================================================================

drivers/nvme/host/core.c +6 -2

@@ -708,8 +708,10 @@ blk_status_t nvme_fail_nonready_command(
 	    ctrl->state != NVME_CTRL_DELETING &&
 	    ctrl->state != NVME_CTRL_DEAD &&
 	    !test_bit(NVME_CTRL_FAILFAST_EXPIRED, &ctrl->flags) &&
-	    !blk_noretry_request(rq) && !(rq->cmd_flags & REQ_NVME_MPATH))
+	    !blk_noretry_request(rq) && !(rq->cmd_flags & REQ_NVME_MPATH)) {
+		printk("allocation failure at %d\n", __LINE__);
 		return BLK_STS_RESOURCE;
+	}
 	return nvme_host_path_error(rq);
 }
 EXPORT_SYMBOL_GPL(nvme_fail_nonready_command);

@@ -784,8 +786,10 @@ static blk_status_t nvme_setup_discard(s
 		 * discard page. If that's also busy, it's safe to return
 		 * busy, as we know we can make progress once that's freed.
 		 */
-		if (test_and_set_bit_lock(0, &ns->ctrl->discard_page_busy))
+		if (test_and_set_bit_lock(0, &ns->ctrl->discard_page_busy)) {
+			printk("allocation failure at %d\n", __LINE__);
 			return BLK_STS_RESOURCE;
+		}
 
 		range = page_address(ns->ctrl->discard_page);
 	}

Quoted 3 lines · Mikulas Patocka

Then, try this patch (without "iommu=panic"), reproduce the deadlock and tell us which one of the "printk" statements is triggered during the deadlock.

The "821" one - see below.

Quoted 6 lines · Marek Marczykowski-G'orecki

Quoted 3 lines · Mikulas Patocka

Then, try this patch (without "iommu=panic"), reproduce the deadlock and tell us which one of the "printk" statements is triggered during the deadlock.

The "821" one - see below.

Thanks for confirming!

Could you try this patch?

Quoted 6 lines · Keith Busch

Quoted 5 lines · Marek Marczykowski-G'orecki

Quoted 3 lines · Mikulas Patocka

Then, try this patch (without "iommu=panic"), reproduce the deadlock and tell us which one of the "printk" statements is triggered during the deadlock.

Quoted 5 lines

Quoted 1 line

The "821" one - see below.

Thanks for confirming!

Could you try this patch?

Besides min3() being unhappy about types, it works.

Quoted 7 lines · Marek Marczykowski-G'orecki

Quoted 6 lines · Keith Busch

Quoted 5 lines · Marek Marczykowski-G'orecki

Quoted 3 lines · Mikulas Patocka

Then, try this patch (without "iommu=panic"), reproduce the deadlock and tell us which one of the "printk" statements is triggered during the deadlock.

Quoted 7 lines

Quoted 5 lines

Quoted 1 line

The "821" one - see below.

Thanks for confirming!

Could you try this patch?

Besides min3() being unhappy about types, it works.

Oops, should have changed the constant to "ul" instead of just "u".

Anyway, the overall idea makes sense to me, but I don't know the swiotlb stuff well.

Christoph, does that patch make sense? For reference:

   https://lore.kernel.org/linux-mm/[email protected]/T/#m8d34245e0eef43f8e9fe6cba6038d77ed2a93ad6

Quoted 21 lines · Keith Busch

Quoted 7 lines · Marek Marczykowski-G'orecki

Quoted 6 lines · Keith Busch

Quoted 5 lines · Marek Marczykowski-G'orecki

Quoted 3 lines · Mikulas Patocka

Then, try this patch (without "iommu=panic"), reproduce the deadlock and tell us which one of the "printk" statements is triggered during the deadlock.

Quoted 7 lines

Quoted 5 lines

Quoted 1 line

The "821" one - see below.

Thanks for confirming!

Could you try this patch?

Besides min3() being unhappy about types, it works.

Oops, should have changed the constant to "ul" instead of just "u".

Anyway, the overall idea makes sense to me, but I don't know the swiotlb stuff well.

Quoted 3 lines

Christoph, does that patch make sense? For reference:

   https://lore.kernel.org/linux-mm/[email protected]/T/#m8d34245e0eef43f8e9fe6cba6038d77ed2a93ad6

dma_opt_mapping_size returns "min(dma_max_mapping_size(dev), size)". So you don't have to call dma_max_mapping_size explicitly, you can leave the file drivers/nvme/host/pci.c as it is.

What about the other block device drivers (AHCI, SCSI...)? Should there be some generic framework that restricts max_hw_sectors according to dma_opt_mapping_size?

Quoted 3 lines

dma_opt_mapping_size returns "min(dma_max_mapping_size(dev), size)". So you don't have to call dma_max_mapping_size explicitly, you can leave the file drivers/nvme/host/pci.c as it is.

Indeed.

Quoted 3 lines

What about the other block device drivers (AHCI, SCSI...)? Should there be some generic framework that restricts max_hw_sectors according to dma_opt_mapping_size?

I think it's just like any other request_queue limits and the individual drivers have to set up these.

Thinking on this again, this feels more like a max_segment_size limit rather than a max_hw_sectors.

There's a bug that when using the XEN hypervisor with dm-crypt on NVMe, the kernel deadlocks [1].

The deadlocks are caused by inability to map a large bio vector - dma_map_sgtable always returns an error, this gets propagated to the block layer as BLK_STS_RESOURCE and the block layer retries the request indefinitely.

XEN uses the swiotlb framework to map discontiguous pages into contiguous runs that are submitted to the PCIe device. The swiotlb framework has a limitation on the length of a mapping - this needs to be announced with the max_mapping_size method to make sure that the hardware drivers do not create larger mappings.

Without max_mapping_size, the NVMe block driver would create large mappings that overrun the maximum mapping size.

[1] https://lore.kernel.org/stable/ZTNH0qtmint%2FzLJZ@mail-itl/

Signed-off-by Mikulas Patocka <[email protected]>

Reported-by Marek Marczykowski-G'orecki <[email protected]>

Tested-by Marek Marczykowski-G'orecki <[email protected]>

Suggested-by Keith Busch <[email protected]>

Suggested-by Christoph Hellwig <[email protected]>

Cc [email protected]

---
 drivers/xen/swiotlb-xen.c |    1 +
 1 file changed, 1 insertion(+)

Index: linux-stable/drivers/xen/swiotlb-xen.c
===================================================================

drivers/xen/swiotlb-xen.c +1 -0

@@ -405,4 +405,5 @@ const struct dma_map_ops xen_swiotlb_dma
 	.get_sgtable = dma_common_get_sgtable,
 	.alloc_pages = dma_common_alloc_pages,
 	.free_pages = dma_common_free_pages,
+	.max_mapping_size = swiotlb_max_mapping_size,
 };

Quoted 14 lines · Mikulas Patocka

There's a bug that when using the XEN hypervisor with dm-crypt on NVMe, the kernel deadlocks [1].

The deadlocks are caused by inability to map a large bio vector - dma_map_sgtable always returns an error, this gets propagated to the block layer as BLK_STS_RESOURCE and the block layer retries the request indefinitely.

XEN uses the swiotlb framework to map discontiguous pages into contiguous runs that are submitted to the PCIe device. The swiotlb framework has a limitation on the length of a mapping - this needs to be announced with the max_mapping_size method to make sure that the hardware drivers do not create larger mappings.

Quoted 4 lines

Without max_mapping_size, the NVMe block driver would create large mappings that overrun the maximum mapping size.

[1] https://lore.kernel.org/stable/ZTNH0qtmint%2FzLJZ@mail-itl/

This should be a "Link:" tag.

Quoted 4 lines

Signed-off-by Mikulas Patocka <[email protected]>

Reported-by Marek Marczykowski-G'orecki <[email protected]>

Tested-by Marek Marczykowski-G'orecki <[email protected]>

Suggested-by Keith Busch <[email protected]>

I was about to send the same thing. I did a little more than suggest
this: it's is the very patch I wrote for testing, minus the redundant nvme bits! But since you already have a commit message for it...

Acked-by Keith Busch <[email protected]>

Quoted 18 lines

Suggested-by Christoph Hellwig <[email protected]>

Cc [email protected]

---
 drivers/xen/swiotlb-xen.c |    1 +
 1 file changed, 1 insertion(+)

Index: linux-stable/drivers/xen/swiotlb-xen.c
===================================================================

drivers/xen/swiotlb-xen.c +1 -0

@@ -405,4 +405,5 @@ const struct dma_map_ops xen_swiotlb_dma
 	.get_sgtable = dma_common_get_sgtable,
 	.alloc_pages = dma_common_alloc_pages,
 	.free_pages = dma_common_free_pages,
+	.max_mapping_size = swiotlb_max_mapping_size,
 };

From: Keith Busch <[email protected]>

There's a bug that when using the XEN hypervisor with bios with large multi-page bio vectors on NVMe, the kernel deadlocks [1].

The deadlocks are caused by inability to map a large bio vector - dma_map_sgtable always returns an error, this gets propagated to the block layer as BLK_STS_RESOURCE and the block layer retries the request indefinitely.

XEN uses the swiotlb framework to map discontiguous pages into contiguous runs that are submitted to the PCIe device. The swiotlb framework has a limitation on the length of a mapping - this needs to be announced with the max_mapping_size method to make sure that the hardware drivers do not create larger mappings.

Without max_mapping_size, the NVMe block driver would create large mappings that overrun the maximum mapping size.

Reported-by Marek Marczykowski-Górecki <[email protected]>

Link https://lore.kernel.org/stable/ZTNH0qtmint%2FzLJZ@mail-itl/ [1] open here

Tested-by Marek Marczykowski-Górecki <[email protected]>

Suggested-by Christoph Hellwig <[email protected]>

Cc [email protected]

Signed-off-by Keith Busch <[email protected]>

Signed-off-by Mikulas Patocka <[email protected]>

---
 drivers/xen/swiotlb-xen.c |    1 +
 1 file changed, 1 insertion(+)

Index: linux-stable/drivers/xen/swiotlb-xen.c
===================================================================

drivers/xen/swiotlb-xen.c +1 -0

@@ -405,4 +405,5 @@ const struct dma_map_ops xen_swiotlb_dma
 	.get_sgtable = dma_common_get_sgtable,
 	.alloc_pages = dma_common_alloc_pages,
 	.free_pages = dma_common_free_pages,
+	.max_mapping_size = swiotlb_max_mapping_size,
 };

drivers/nvme/host/pci.c +0 -0

 	dev->ctrl.max_segments = NVME_MAX_SEGS;
 
 	/*

drivers/xen/swiotlb-xen.c +0 -0

index 946bd56f0ac53..0e6c6c25d154f 100644

Quoted 18 lines · Marek Marczykowski-Górecki

Quoted 10 lines · Mikulas Patocka

Quoted 10 lines

Hi

I would like to ask you to try this patch. Revert the changes to "order" and "PAGE_ALLOC_COSTLY_ORDER" back to normal and apply this patch on a clean upstream kernel.

Does it deadlock?

There is a bug in dm-crypt that it doesn't account large pages in cc->n_allocated_pages, this patch fixes the bug.

This patch did not help.

Quoted 3 lines

If the previous patch didn't fix it, try this patch (on a clean upstream kernel).

Quoted 4 lines

Quoted 2 lines

This patch allocates large pages, but it breaks them up into single-page entries when adding them to the bio.

But this does help.

Thanks. So we can stop blaming the memory allocator and start blaming the NVMe subsystem.

I added NVMe maintainers to this thread - the summary of the problem is:
In dm-crypt, we allocate a large compound page and add this compound page to the bio as a single big vector entry. Marek reports that on his system it causes deadlocks, the deadlocks look like a lost bio that was never completed. When I chop the large compound page to individual pages in dm-crypt and add bio vector for each of them, Marek reports that there are no longer any deadlocks. So, we have a problem (either hardware or software) that the NVMe subsystem doesn't like bio vectors with large bv_len. This is the original bug report:
https://lore.kernel.org/stable/ZTNH0qtmint%2FzLJZ@mail-itl/

Quoted 9 lines · Jan Kara

Quoted 7 lines · Marek Marczykowski-Górecki

Then tried:
- PAGE_ALLOC_COSTLY_ORDER=4, order=4 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=5 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=6 - freeze rather quickly

I've retried the PAGE_ALLOC_COSTLY_ORDER=4,order=5 case several times and I can't reproduce the issue there. I'm confused...

Quoted 7 lines

And this kind of confirms that allocations > PAGE_ALLOC_COSTLY_ORDER causing hangs is most likely just a coincidence. Rather something either in the block layer or in the storage driver has problems with handling bios with sufficiently high order pages attached. This is going to be a bit painful to debug I'm afraid. How long does it take for you trigger the hang? I'm asking to get rough estimate how heavy tracing we can afford so that we don't overwhelm the system...

Sometimes it freezes just after logging in, but in worst case it takes me about 10min of more or less tar xz + dd.

Quoted 19 lines · Marek Marczykowski-Górecki

Quoted 9 lines · Jan Kara

Quoted 7 lines · Marek Marczykowski-Górecki

Then tried:
- PAGE_ALLOC_COSTLY_ORDER=4, order=4 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=5 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=6 - freeze rather quickly

I've retried the PAGE_ALLOC_COSTLY_ORDER=4,order=5 case several times and I can't reproduce the issue there. I'm confused...

Quoted 7 lines

And this kind of confirms that allocations > PAGE_ALLOC_COSTLY_ORDER causing hangs is most likely just a coincidence. Rather something either in the block layer or in the storage driver has problems with handling bios with sufficiently high order pages attached. This is going to be a bit painful to debug I'm afraid. How long does it take for you trigger the hang? I'm asking to get rough estimate how heavy tracing we can afford so that we don't overwhelm the system...

Quoted 2 lines

Sometimes it freezes just after logging in, but in worst case it takes me about 10min of more or less tar xz + dd.

blk-mq debugfs is usually helpful for hang issue in block layer or underlying drivers:

(cd /sys/kernel/debug/block && find . -type f -exec grep -aH . {} \;)

BTW, you can just collect logs of the exact disks if you know what are behind dm-crypt,
which can be figured out by lsblk, and it has to be collected after the hang is triggered.

Quoted 27 lines · Ming Lei

Quoted 19 lines · Marek Marczykowski-Górecki

Quoted 9 lines · Jan Kara

Quoted 7 lines · Marek Marczykowski-Górecki

Then tried:
- PAGE_ALLOC_COSTLY_ORDER=4, order=4 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=5 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=6 - freeze rather quickly

I've retried the PAGE_ALLOC_COSTLY_ORDER=4,order=5 case several times and I can't reproduce the issue there. I'm confused...

Quoted 7 lines

And this kind of confirms that allocations > PAGE_ALLOC_COSTLY_ORDER causing hangs is most likely just a coincidence. Rather something either in the block layer or in the storage driver has problems with handling bios with sufficiently high order pages attached. This is going to be a bit painful to debug I'm afraid. How long does it take for you trigger the hang? I'm asking to get rough estimate how heavy tracing we can afford so that we don't overwhelm the system...

Quoted 2 lines

Sometimes it freezes just after logging in, but in worst case it takes me about 10min of more or less tar xz + dd.

blk-mq debugfs is usually helpful for hang issue in block layer or underlying drivers:

Quoted 6 lines

(cd /sys/kernel/debug/block && find . -type f -exec grep -aH . {} \;)

BTW, you can just collect logs of the exact disks if you know what are behind dm-crypt,
which can be figured out by lsblk, and it has to be collected after the hang is triggered.

dm-crypt lives on the nvme disk, this is what I collected when it hanged:

nvme0n1/hctx5/type:default
nvme0n1/hctx5/dispatch_busy:0
nvme0n1/hctx5/active:0
nvme0n1/hctx5/run:273
nvme0n1/hctx5/tags_bitmap:00000000: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx5/tags_bitmap:00000010: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx5/tags_bitmap:00000020: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx5/tags_bitmap:00000030: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx5/tags_bitmap:00000040: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx5/tags_bitmap:00000050: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx5/tags_bitmap:00000060: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx5/tags_bitmap:00000070: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx5/tags:nr_tags=1023
nvme0n1/hctx5/tags:nr_reserved_tags=0
nvme0n1/hctx5/tags:active_queues=0
nvme0n1/hctx5/tags:bitmap_tags:
nvme0n1/hctx5/tags:depth=1023
nvme0n1/hctx5/tags:busy=0
nvme0n1/hctx5/tags:cleared=7
nvme0n1/hctx5/tags:bits_per_word=64
nvme0n1/hctx5/tags:map_nr=16
nvme0n1/hctx5/tags:alloc_hint={633, 450, 354, 913, 651, 645}
nvme0n1/hctx5/tags:wake_batch=8
nvme0n1/hctx5/tags:wake_index=0
nvme0n1/hctx5/tags:ws_active=0
nvme0n1/hctx5/tags:ws={
nvme0n1/hctx5/tags: {.wait=inactive},
nvme0n1/hctx5/tags: {.wait=inactive},
nvme0n1/hctx5/tags: {.wait=inactive},
nvme0n1/hctx5/tags: {.wait=inactive},
nvme0n1/hctx5/tags: {.wait=inactive},
nvme0n1/hctx5/tags: {.wait=inactive},
nvme0n1/hctx5/tags: {.wait=inactive},
nvme0n1/hctx5/tags: {.wait=inactive},
nvme0n1/hctx5/tags:}
nvme0n1/hctx5/tags:round_robin=0
nvme0n1/hctx5/tags:min_shallow_depth=4294967295
nvme0n1/hctx5/ctx_map:00000000: 00
nvme0n1/hctx5/flags:alloc_policy=FIFO SHOULD_MERGE
nvme0n1/hctx4/cpu4/default_rq_list:000000000d41998f {.op=READ, .cmd_flags=, .rq_flags=IO_STAT, .state=idle, .tag=65, .internal_tag=-1} nvme0n1/hctx4/cpu4/default_rq_list:00000000d0d04ed2 {.op=READ, .cmd_flags=, .rq_flags=IO_STAT, .state=idle, .tag=70, .internal_tag=-1} nvme0n1/hctx4/type:default
nvme0n1/hctx4/dispatch_busy:9
nvme0n1/hctx4/active:0
nvme0n1/hctx4/run:20290468
nvme0n1/hctx4/tags_bitmap:00000000: 0000 0000 0000 0000 4240 0000 0000 0000
nvme0n1/hctx4/tags_bitmap:00000010: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx4/tags_bitmap:00000020: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx4/tags_bitmap:00000030: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx4/tags_bitmap:00000040: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx4/tags_bitmap:00000050: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx4/tags_bitmap:00000060: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx4/tags_bitmap:00000070: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx4/tags:nr_tags=1023
nvme0n1/hctx4/tags:nr_reserved_tags=0
nvme0n1/hctx4/tags:active_queues=0
nvme0n1/hctx4/tags:bitmap_tags:
nvme0n1/hctx4/tags:depth=1023
nvme0n1/hctx4/tags:busy=3
nvme0n1/hctx4/tags:cleared=7
nvme0n1/hctx4/tags:bits_per_word=64
nvme0n1/hctx4/tags:map_nr=16
nvme0n1/hctx4/tags:alloc_hint={899, 846, 390, 472, 73, 439}
nvme0n1/hctx4/tags:wake_batch=8
nvme0n1/hctx4/tags:wake_index=0
nvme0n1/hctx4/tags:ws_active=0
nvme0n1/hctx4/tags:ws={
nvme0n1/hctx4/tags: {.wait=inactive},
nvme0n1/hctx4/tags: {.wait=inactive},
nvme0n1/hctx4/tags: {.wait=inactive},
nvme0n1/hctx4/tags: {.wait=inactive},
nvme0n1/hctx4/tags: {.wait=inactive},
nvme0n1/hctx4/tags: {.wait=inactive},
nvme0n1/hctx4/tags: {.wait=inactive},
nvme0n1/hctx4/tags: {.wait=inactive},
nvme0n1/hctx4/tags:}
nvme0n1/hctx4/tags:round_robin=0
nvme0n1/hctx4/tags:min_shallow_depth=4294967295
nvme0n1/hctx4/ctx_map:00000000: 01
nvme0n1/hctx4/dispatch:00000000b335fa89 {.op=WRITE, .cmd_flags=NOMERGE, .rq_flags=DONTPREP|IO_STAT, .state=idle, .tag=78, .internal_tag=-1} nvme0n1/hctx4/flags:alloc_policy=FIFO SHOULD_MERGE
nvme0n1/hctx4/state:SCHED_RESTART
nvme0n1/hctx3/type:default
nvme0n1/hctx3/dispatch_busy:0
nvme0n1/hctx3/active:0
nvme0n1/hctx3/run:296
nvme0n1/hctx3/tags_bitmap:00000000: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx3/tags_bitmap:00000010: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx3/tags_bitmap:00000020: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx3/tags_bitmap:00000030: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx3/tags_bitmap:00000040: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx3/tags_bitmap:00000050: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx3/tags_bitmap:00000060: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx3/tags_bitmap:00000070: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx3/tags:nr_tags=1023
nvme0n1/hctx3/tags:nr_reserved_tags=0
nvme0n1/hctx3/tags:active_queues=0
nvme0n1/hctx3/tags:bitmap_tags:
nvme0n1/hctx3/tags:depth=1023
nvme0n1/hctx3/tags:busy=0
nvme0n1/hctx3/tags:cleared=23
nvme0n1/hctx3/tags:bits_per_word=64
nvme0n1/hctx3/tags:map_nr=16
nvme0n1/hctx3/tags:alloc_hint={862, 557, 480, 24, 841, 23}
nvme0n1/hctx3/tags:wake_batch=8
nvme0n1/hctx3/tags:wake_index=0
nvme0n1/hctx3/tags:ws_active=0
nvme0n1/hctx3/tags:ws={
nvme0n1/hctx3/tags: {.wait=inactive},
nvme0n1/hctx3/tags: {.wait=inactive},
nvme0n1/hctx3/tags: {.wait=inactive},
nvme0n1/hctx3/tags: {.wait=inactive},
nvme0n1/hctx3/tags: {.wait=inactive},
nvme0n1/hctx3/tags: {.wait=inactive},
nvme0n1/hctx3/tags: {.wait=inactive},
nvme0n1/hctx3/tags: {.wait=inactive},
nvme0n1/hctx3/tags:}
nvme0n1/hctx3/tags:round_robin=0
nvme0n1/hctx3/tags:min_shallow_depth=4294967295
nvme0n1/hctx3/ctx_map:00000000: 00
nvme0n1/hctx3/flags:alloc_policy=FIFO SHOULD_MERGE
nvme0n1/hctx2/type:default
nvme0n1/hctx2/dispatch_busy:0
nvme0n1/hctx2/active:0
nvme0n1/hctx2/run:279
nvme0n1/hctx2/tags_bitmap:00000000: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx2/tags_bitmap:00000010: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx2/tags_bitmap:00000020: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx2/tags_bitmap:00000030: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx2/tags_bitmap:00000040: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx2/tags_bitmap:00000050: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx2/tags_bitmap:00000060: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx2/tags_bitmap:00000070: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx2/tags:nr_tags=1023
nvme0n1/hctx2/tags:nr_reserved_tags=0
nvme0n1/hctx2/tags:active_queues=0
nvme0n1/hctx2/tags:bitmap_tags:
nvme0n1/hctx2/tags:depth=1023
nvme0n1/hctx2/tags:busy=0
nvme0n1/hctx2/tags:cleared=16
nvme0n1/hctx2/tags:bits_per_word=64
nvme0n1/hctx2/tags:map_nr=16
nvme0n1/hctx2/tags:alloc_hint={960, 528, 145, 730, 447, 1002}
nvme0n1/hctx2/tags:wake_batch=8
nvme0n1/hctx2/tags:wake_index=0
nvme0n1/hctx2/tags:ws_active=0
nvme0n1/hctx2/tags:ws={
nvme0n1/hctx2/tags: {.wait=inactive},
nvme0n1/hctx2/tags: {.wait=inactive},
nvme0n1/hctx2/tags: {.wait=inactive},
nvme0n1/hctx2/tags: {.wait=inactive},
nvme0n1/hctx2/tags: {.wait=inactive},
nvme0n1/hctx2/tags: {.wait=inactive},
nvme0n1/hctx2/tags: {.wait=inactive},
nvme0n1/hctx2/tags: {.wait=inactive},
nvme0n1/hctx2/tags:}
nvme0n1/hctx2/tags:round_robin=0
nvme0n1/hctx2/tags:min_shallow_depth=4294967295
nvme0n1/hctx2/ctx_map:00000000: 00
nvme0n1/hctx2/flags:alloc_policy=FIFO SHOULD_MERGE
nvme0n1/hctx1/type:default
nvme0n1/hctx1/dispatch_busy:0
nvme0n1/hctx1/active:0
nvme0n1/hctx1/run:458
nvme0n1/hctx1/tags_bitmap:00000000: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx1/tags_bitmap:00000010: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx1/tags_bitmap:00000020: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx1/tags_bitmap:00000030: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx1/tags_bitmap:00000040: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx1/tags_bitmap:00000050: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx1/tags_bitmap:00000060: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx1/tags_bitmap:00000070: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx1/tags:nr_tags=1023
nvme0n1/hctx1/tags:nr_reserved_tags=0
nvme0n1/hctx1/tags:active_queues=0
nvme0n1/hctx1/tags:bitmap_tags:
nvme0n1/hctx1/tags:depth=1023
nvme0n1/hctx1/tags:busy=0
nvme0n1/hctx1/tags:cleared=31
nvme0n1/hctx1/tags:bits_per_word=64
nvme0n1/hctx1/tags:map_nr=16
nvme0n1/hctx1/tags:alloc_hint={689, 284, 498, 188, 808, 610}
nvme0n1/hctx1/tags:wake_batch=8
nvme0n1/hctx1/tags:wake_index=0
nvme0n1/hctx1/tags:ws_active=0
nvme0n1/hctx1/tags:ws={
nvme0n1/hctx1/tags: {.wait=inactive},
nvme0n1/hctx1/tags: {.wait=inactive},
nvme0n1/hctx1/tags: {.wait=inactive},
nvme0n1/hctx1/tags: {.wait=inactive},
nvme0n1/hctx1/tags: {.wait=inactive},
nvme0n1/hctx1/tags: {.wait=inactive},
nvme0n1/hctx1/tags: {.wait=inactive},
nvme0n1/hctx1/tags: {.wait=inactive},
nvme0n1/hctx1/tags:}
nvme0n1/hctx1/tags:round_robin=0
nvme0n1/hctx1/tags:min_shallow_depth=4294967295
nvme0n1/hctx1/ctx_map:00000000: 00
nvme0n1/hctx1/flags:alloc_policy=FIFO SHOULD_MERGE
nvme0n1/hctx0/type:default
nvme0n1/hctx0/dispatch_busy:0
nvme0n1/hctx0/active:0
nvme0n1/hctx0/run:375
nvme0n1/hctx0/tags_bitmap:00000000: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx0/tags_bitmap:00000010: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx0/tags_bitmap:00000020: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx0/tags_bitmap:00000030: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx0/tags_bitmap:00000040: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx0/tags_bitmap:00000050: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx0/tags_bitmap:00000060: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx0/tags_bitmap:00000070: 0000 0000 0000 0000 0000 0000 0000 0000
nvme0n1/hctx0/tags:nr_tags=1023
nvme0n1/hctx0/tags:nr_reserved_tags=0
nvme0n1/hctx0/tags:active_queues=0
nvme0n1/hctx0/tags:bitmap_tags:
nvme0n1/hctx0/tags:depth=1023
nvme0n1/hctx0/tags:busy=0
nvme0n1/hctx0/tags:cleared=6
nvme0n1/hctx0/tags:bits_per_word=64
nvme0n1/hctx0/tags:map_nr=16
nvme0n1/hctx0/tags:alloc_hint={5, 18, 320, 448, 728, 9}
nvme0n1/hctx0/tags:wake_batch=8
nvme0n1/hctx0/tags:wake_index=0
nvme0n1/hctx0/tags:ws_active=0
nvme0n1/hctx0/tags:ws={
nvme0n1/hctx0/tags: {.wait=inactive},
nvme0n1/hctx0/tags: {.wait=inactive},
nvme0n1/hctx0/tags: {.wait=inactive},
nvme0n1/hctx0/tags: {.wait=inactive},
nvme0n1/hctx0/tags: {.wait=inactive},
nvme0n1/hctx0/tags: {.wait=inactive},
nvme0n1/hctx0/tags: {.wait=inactive},
nvme0n1/hctx0/tags: {.wait=inactive},
nvme0n1/hctx0/tags:}
nvme0n1/hctx0/tags:round_robin=0
nvme0n1/hctx0/tags:min_shallow_depth=4294967295
nvme0n1/hctx0/ctx_map:00000000: 00
nvme0n1/hctx0/flags:alloc_policy=FIFO SHOULD_MERGE nvme0n1/state:SAME_COMP|NONROT|IO_STAT|INIT_DONE|WC|FUA|REGISTERED|NOWAIT
nvme0n1/pm_only:0

This is without any of the patches Mikulas proposed.

And BTW, an attempt to access another partition on the same disk (not covered with dm-crypt) hangs too.

Quoted 27 lines · Ming Lei

Quoted 19 lines · Marek Marczykowski-Górecki

Quoted 9 lines · Jan Kara

Quoted 7 lines · Marek Marczykowski-Górecki

Then tried:
- PAGE_ALLOC_COSTLY_ORDER=4, order=4 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=5 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=6 - freeze rather quickly

I've retried the PAGE_ALLOC_COSTLY_ORDER=4,order=5 case several times and I can't reproduce the issue there. I'm confused...

Quoted 7 lines

And this kind of confirms that allocations > PAGE_ALLOC_COSTLY_ORDER causing hangs is most likely just a coincidence. Rather something either in the block layer or in the storage driver has problems with handling bios with sufficiently high order pages attached. This is going to be a bit painful to debug I'm afraid. How long does it take for you trigger the hang? I'm asking to get rough estimate how heavy tracing we can afford so that we don't overwhelm the system...

Quoted 2 lines

Sometimes it freezes just after logging in, but in worst case it takes me about 10min of more or less tar xz + dd.

blk-mq debugfs is usually helpful for hang issue in block layer or underlying drivers:

Quoted 6 lines

(cd /sys/kernel/debug/block && find . -type f -exec grep -aH . {} \;)

BTW, you can just collect logs of the exact disks if you know what are behind dm-crypt,
which can be figured out by lsblk, and it has to be collected after the hang is triggered.

dm-crypt lives on the nvme disk, this is what I collected when it hanged:

nvme0n1/hctx4/cpu4/default_rq_list:000000000d41998f {.op=READ, .cmd_flags=, .rq_flags=IO_STAT, .state=idle, .tag=65, .internal_tag=-1} nvme0n1/hctx4/cpu4/default_rq_list:00000000d0d04ed2 {.op=READ, .cmd_flags=, .rq_flags=IO_STAT, .state=idle, .tag=70, .internal_tag=-1}

nvme0n1/hctx4/type:default
nvme0n1/hctx4/dispatch_busy:9

nvme0n1/hctx4/active:0
nvme0n1/hctx4/run:20290468

nvme0n1/hctx4/tags:nr_tags=1023
nvme0n1/hctx4/tags:nr_reserved_tags=0
nvme0n1/hctx4/tags:active_queues=0
nvme0n1/hctx4/tags:bitmap_tags:
nvme0n1/hctx4/tags:depth=1023
nvme0n1/hctx4/tags:busy=3

nvme0n1/hctx4/dispatch:00000000b335fa89 {.op=WRITE, .cmd_flags=NOMERGE, .rq_flags=DONTPREP|IO_STAT, .state=idle, .tag=78, .internal_tag=-1} nvme0n1/hctx4/flags:alloc_policy=FIFO SHOULD_MERGE
nvme0n1/hctx4/state:SCHED_RESTART

Quoted 38 lines · Marek Marczykowski-Górecki

Quoted 27 lines · Ming Lei

Quoted 19 lines · Marek Marczykowski-Górecki

Quoted 9 lines · Jan Kara

Quoted 7 lines · Marek Marczykowski-Górecki

Then tried:
- PAGE_ALLOC_COSTLY_ORDER=4, order=4 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=5 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=6 - freeze rather quickly

I've retried the PAGE_ALLOC_COSTLY_ORDER=4,order=5 case several times and I can't reproduce the issue there. I'm confused...

Quoted 7 lines

And this kind of confirms that allocations > PAGE_ALLOC_COSTLY_ORDER causing hangs is most likely just a coincidence. Rather something either in the block layer or in the storage driver has problems with handling bios with sufficiently high order pages attached. This is going to be a bit painful to debug I'm afraid. How long does it take for you trigger the hang? I'm asking to get rough estimate how heavy tracing we can afford so that we don't overwhelm the system...

Quoted 2 lines

Sometimes it freezes just after logging in, but in worst case it takes me about 10min of more or less tar xz + dd.

blk-mq debugfs is usually helpful for hang issue in block layer or underlying drivers:

Quoted 6 lines

(cd /sys/kernel/debug/block && find . -type f -exec grep -aH . {} \;)

BTW, you can just collect logs of the exact disks if you know what are behind dm-crypt,
which can be figured out by lsblk, and it has to be collected after the hang is triggered.

dm-crypt lives on the nvme disk, this is what I collected when it hanged:

...

Quoted 2 lines

nvme0n1/hctx4/cpu4/default_rq_list:000000000d41998f {.op=READ, .cmd_flags=, .rq_flags=IO_STAT, .state=idle, .tag=65, .internal_tag=-1} nvme0n1/hctx4/cpu4/default_rq_list:00000000d0d04ed2 {.op=READ, .cmd_flags=, .rq_flags=IO_STAT, .state=idle, .tag=70, .internal_tag=-1}

Two requests stays in sw queue, but not related with this issue.

Quoted 2 lines

nvme0n1/hctx4/type:default
nvme0n1/hctx4/dispatch_busy:9

non-zero dispatch_busy means BLK_STS_RESOURCE is returned from nvme_queue_rq() recently and mostly.

Quoted 2 lines

nvme0n1/hctx4/active:0
nvme0n1/hctx4/run:20290468

...

Quoted 6 lines

nvme0n1/hctx4/tags:nr_tags=1023
nvme0n1/hctx4/tags:nr_reserved_tags=0
nvme0n1/hctx4/tags:active_queues=0
nvme0n1/hctx4/tags:bitmap_tags:
nvme0n1/hctx4/tags:depth=1023
nvme0n1/hctx4/tags:busy=3

Just three requests in-flight, two are in sw queue, another is in hctx->dispatch.

...

Quoted 3 lines

nvme0n1/hctx4/dispatch:00000000b335fa89 {.op=WRITE, .cmd_flags=NOMERGE, .rq_flags=DONTPREP|IO_STAT, .state=idle, .tag=78, .internal_tag=-1} nvme0n1/hctx4/flags:alloc_policy=FIFO SHOULD_MERGE
nvme0n1/hctx4/state:SCHED_RESTART

The request staying in hctx->dispatch can't move on, and nvme_queue_rq() returns -BLK_STS_RESOURCE constantly, and you can verify with the following bpftrace when the hang is triggered:

bpftrace -e 'kretfunc:nvme_queue_rq { @[retval, kstack]=count() }'

It is very likely that memory allocation inside nvme_queue_rq() can't be done successfully, then blk-mq just have to retry by calling nvme_queue_rq() on the above request.

Quoted 75 lines · Ming Lei

Quoted 38 lines · Marek Marczykowski-Górecki

Quoted 27 lines · Ming Lei

Quoted 19 lines · Marek Marczykowski-Górecki

Quoted 9 lines · Jan Kara

Quoted 7 lines · Marek Marczykowski-Górecki

Then tried:
- PAGE_ALLOC_COSTLY_ORDER=4, order=4 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=5 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=6 - freeze rather quickly

I've retried the PAGE_ALLOC_COSTLY_ORDER=4,order=5 case several times and I can't reproduce the issue there. I'm confused...

Quoted 7 lines

And this kind of confirms that allocations > PAGE_ALLOC_COSTLY_ORDER causing hangs is most likely just a coincidence. Rather something either in the block layer or in the storage driver has problems with handling bios with sufficiently high order pages attached. This is going to be a bit painful to debug I'm afraid. How long does it take for you trigger the hang? I'm asking to get rough estimate how heavy tracing we can afford so that we don't overwhelm the system...

Quoted 2 lines

Sometimes it freezes just after logging in, but in worst case it takes me about 10min of more or less tar xz + dd.

blk-mq debugfs is usually helpful for hang issue in block layer or underlying drivers:

Quoted 6 lines

(cd /sys/kernel/debug/block && find . -type f -exec grep -aH . {} \;)

BTW, you can just collect logs of the exact disks if you know what are behind dm-crypt,
which can be figured out by lsblk, and it has to be collected after the hang is triggered.

dm-crypt lives on the nvme disk, this is what I collected when it hanged:

...

Quoted 2 lines

nvme0n1/hctx4/cpu4/default_rq_list:000000000d41998f {.op=READ, .cmd_flags=, .rq_flags=IO_STAT, .state=idle, .tag=65, .internal_tag=-1} nvme0n1/hctx4/cpu4/default_rq_list:00000000d0d04ed2 {.op=READ, .cmd_flags=, .rq_flags=IO_STAT, .state=idle, .tag=70, .internal_tag=-1}

Two requests stays in sw queue, but not related with this issue.

Quoted 2 lines

nvme0n1/hctx4/type:default
nvme0n1/hctx4/dispatch_busy:9

non-zero dispatch_busy means BLK_STS_RESOURCE is returned from nvme_queue_rq() recently and mostly.

Quoted 2 lines

nvme0n1/hctx4/active:0
nvme0n1/hctx4/run:20290468

...

Quoted 6 lines

nvme0n1/hctx4/tags:nr_tags=1023
nvme0n1/hctx4/tags:nr_reserved_tags=0
nvme0n1/hctx4/tags:active_queues=0
nvme0n1/hctx4/tags:bitmap_tags:
nvme0n1/hctx4/tags:depth=1023
nvme0n1/hctx4/tags:busy=3

Just three requests in-flight, two are in sw queue, another is in hctx->dispatch.

...

Quoted 3 lines

nvme0n1/hctx4/dispatch:00000000b335fa89 {.op=WRITE, .cmd_flags=NOMERGE, .rq_flags=DONTPREP|IO_STAT, .state=idle, .tag=78, .internal_tag=-1} nvme0n1/hctx4/flags:alloc_policy=FIFO SHOULD_MERGE
nvme0n1/hctx4/state:SCHED_RESTART

The request staying in hctx->dispatch can't move on, and nvme_queue_rq() returns -BLK_STS_RESOURCE constantly, and you can verify with the following bpftrace when the hang is triggered:

Quoted 6 lines

bpftrace -e 'kretfunc:nvme_queue_rq { @[retval, kstack]=count() }'

It is very likely that memory allocation inside nvme_queue_rq() can't be done successfully, then blk-mq just have to retry by calling nvme_queue_rq() on the above request.

And that is something I've been wondering (for quite some time now):
What _is_ the appropriate error handling for -ENOMEM?
At this time, we assume it to be a retryable error and re-run the queue in the hope that things will sort itself out.
But if they don't we're stuck.
Can we somehow figure out if we make progress during submission, and (at least) issue a warning once we detect a stall?

Quoted 75 lines · Ming Lei

Quoted 38 lines · Marek Marczykowski-Górecki

Quoted 27 lines · Ming Lei

Quoted 19 lines · Marek Marczykowski-Górecki

Quoted 9 lines · Jan Kara

Quoted 7 lines · Marek Marczykowski-Górecki

Then tried:
- PAGE_ALLOC_COSTLY_ORDER=4, order=4 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=5 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=6 - freeze rather quickly

I've retried the PAGE_ALLOC_COSTLY_ORDER=4,order=5 case several times and I can't reproduce the issue there. I'm confused...

Quoted 7 lines

And this kind of confirms that allocations > PAGE_ALLOC_COSTLY_ORDER causing hangs is most likely just a coincidence. Rather something either in the block layer or in the storage driver has problems with handling bios with sufficiently high order pages attached. This is going to be a bit painful to debug I'm afraid. How long does it take for you trigger the hang? I'm asking to get rough estimate how heavy tracing we can afford so that we don't overwhelm the system...

Quoted 2 lines

Sometimes it freezes just after logging in, but in worst case it takes me about 10min of more or less tar xz + dd.

blk-mq debugfs is usually helpful for hang issue in block layer or underlying drivers:

Quoted 6 lines

(cd /sys/kernel/debug/block && find . -type f -exec grep -aH . {} \;)

BTW, you can just collect logs of the exact disks if you know what are behind dm-crypt,
which can be figured out by lsblk, and it has to be collected after the hang is triggered.

dm-crypt lives on the nvme disk, this is what I collected when it hanged:

...

Quoted 2 lines

nvme0n1/hctx4/cpu4/default_rq_list:000000000d41998f {.op=READ, .cmd_flags=, .rq_flags=IO_STAT, .state=idle, .tag=65, .internal_tag=-1} nvme0n1/hctx4/cpu4/default_rq_list:00000000d0d04ed2 {.op=READ, .cmd_flags=, .rq_flags=IO_STAT, .state=idle, .tag=70, .internal_tag=-1}

Two requests stays in sw queue, but not related with this issue.

Quoted 2 lines

nvme0n1/hctx4/type:default
nvme0n1/hctx4/dispatch_busy:9

non-zero dispatch_busy means BLK_STS_RESOURCE is returned from nvme_queue_rq() recently and mostly.

Quoted 2 lines

nvme0n1/hctx4/active:0
nvme0n1/hctx4/run:20290468

...

Quoted 6 lines

nvme0n1/hctx4/tags:nr_tags=1023
nvme0n1/hctx4/tags:nr_reserved_tags=0
nvme0n1/hctx4/tags:active_queues=0
nvme0n1/hctx4/tags:bitmap_tags:
nvme0n1/hctx4/tags:depth=1023
nvme0n1/hctx4/tags:busy=3

Just three requests in-flight, two are in sw queue, another is in hctx->dispatch.

...

Quoted 3 lines

nvme0n1/hctx4/dispatch:00000000b335fa89 {.op=WRITE, .cmd_flags=NOMERGE, .rq_flags=DONTPREP|IO_STAT, .state=idle, .tag=78, .internal_tag=-1} nvme0n1/hctx4/flags:alloc_policy=FIFO SHOULD_MERGE
nvme0n1/hctx4/state:SCHED_RESTART

The request staying in hctx->dispatch can't move on, and nvme_queue_rq() returns -BLK_STS_RESOURCE constantly, and you can verify with the following bpftrace when the hang is triggered:

Quoted 6 lines

bpftrace -e 'kretfunc:nvme_queue_rq { @[retval, kstack]=count() }'

It is very likely that memory allocation inside nvme_queue_rq() can't be done successfully, then blk-mq just have to retry by calling nvme_queue_rq() on the above request.

And that is something I've been wondering (for quite some time now):
What _is_ the appropriate error handling for -ENOMEM?

At this time, we assume it to be a retryable error and re-run the queue in the hope that things will sort itself out.

But if they don't we're stuck.
Can we somehow figure out if we make progress during submission, and (at least) issue a warning once we detect a stall?

Quoted 4 lines · Hannes Reinecke

Quoted 2 lines

nvme_queue_rq() on the above request.

And that is something I've been wondering (for quite some time now):
What _is_ the appropriate error handling for -ENOMEM?

It is just my guess.

Actually it shouldn't fail since the sgl allocation is backed with memory pool, but there is also dma pool allocation and dma mapping.

Quoted 2 lines

At this time, we assume it to be a retryable error and re-run the queue in the hope that things will sort itself out.

It should not be hard to figure out why nvme_queue_rq() can't move on.

And that is something I've been wondering (for quite some time now):
What _is_ the appropriate error handling for -ENOMEM?
At this time, we assume it to be a retryable error and re-run the queue in the hope that things will sort itself out.
But if they don't we're stuck.
Can we somehow figure out if we make progress during submission, and (at least) issue a warning once we detect a stall?

Quoted 18 lines · Mikulas Patocka

Quoted 16 lines · Vlastimil Babka

Haven't found any. However I'd like to point out some things I noticed in crypt_alloc_buffer(), although they are probably not related.

Quoted 12 lines

static struct bio *crypt_alloc_buffer(struct dm_crypt_io *io, unsigned int size)

{
	struct crypt_config *cc = io->cc;
	struct bio *clone;
	unsigned int nr_iovecs = (size + PAGE_SIZE - 1) >> PAGE_SHIFT;
	gfp_t gfp_mask = GFP_NOWAIT | __GFP_HIGHMEM;
	unsigned int remaining_size;
	unsigned int order = MAX_ORDER - 1;

retry:

	if (unlikely(gfp_mask & __GFP_DIRECT_RECLAIM))
		mutex_lock(&cc->bio_alloc_lock);

Quoted 6 lines

Quoted 1 line

What if we end up in "goto retry" more than once? I don't see a matching

It is impossible. Before we jump to the retry label, we set __GFP_DIRECT_RECLAIM. mempool_alloc can't ever fail if __GFP_DIRECT_RECLAIM is present (it will just wait until some other task frees some objects into the mempool).

Ah, missed that. And the traces don't show that we would be waiting for that. I'm starting to think the allocation itself is really not the issue here. Also I don't think it deprives something else of large order pages, as per the sysrq listing they still existed.

What I rather suspect is what happens next to the allocated bio such that it works well with order-0 or up to costly_order pages, but there's some problem causing a deadlock if the bio contains larger pages than that?

Quoted 7 lines

Quoted 6 lines

Quoted 1 line

What if we end up in "goto retry" more than once? I don't see a matching

It is impossible. Before we jump to the retry label, we set __GFP_DIRECT_RECLAIM. mempool_alloc can't ever fail if __GFP_DIRECT_RECLAIM is present (it will just wait until some other task frees some objects into the mempool).

Quoted 8 lines

Ah, missed that. And the traces don't show that we would be waiting for that. I'm starting to think the allocation itself is really not the issue here. Also I don't think it deprives something else of large order pages, as per the sysrq listing they still existed.

What I rather suspect is what happens next to the allocated bio such that it works well with order-0 or up to costly_order pages, but there's some problem causing a deadlock if the bio contains larger pages than that?

Hum, so in all the backtraces presented we see that we are waiting for page writeback to complete but I don't see anything that would be preventing the bios from completing. Page writeback can submit quite large bios so it kind of makes sense that it trips up some odd behavior. Looking at the code I can see one possible problem in crypt_alloc_buffer() but it doesn't explain why reducing initial page order would help. Anyway: Are we guaranteed mempool has enough pages for arbitrarily large bio that can enter crypt_alloc_buffer()? I can see crypt_page_alloc() does limit the number of pages in the mempool to dm_crypt_pages_per_client plus I assume the percpu counter bias in cc->n_allocated_pages can limit the really available number of pages even further. So if a single bio is large enough to trip percpu_counter_read_positive(&cc->n_allocated_pages) >= dm_crypt_pages_per_client condition in crypt_page_alloc(), we can loop forever? But maybe this cannot happen for some reason...

If this is not it, I think we need to find out why the writeback bios are not completeting. Probably I'd start with checking what is kcryptd, presumably responsible for processing these bios, doing.

Honza

Quoted 31 lines · Jan Kara

Quoted 7 lines

Quoted 6 lines

Quoted 1 line

What if we end up in "goto retry" more than once? I don't see a matching

It is impossible. Before we jump to the retry label, we set __GFP_DIRECT_RECLAIM. mempool_alloc can't ever fail if __GFP_DIRECT_RECLAIM is present (it will just wait until some other task frees some objects into the mempool).

Quoted 8 lines

Ah, missed that. And the traces don't show that we would be waiting for that. I'm starting to think the allocation itself is really not the issue here. Also I don't think it deprives something else of large order pages, as per the sysrq listing they still existed.

What I rather suspect is what happens next to the allocated bio such that it works well with order-0 or up to costly_order pages, but there's some problem causing a deadlock if the bio contains larger pages than that?

Hum, so in all the backtraces presented we see that we are waiting for page writeback to complete but I don't see anything that would be preventing the bios from completing. Page writeback can submit quite large bios so it kind of makes sense that it trips up some odd behavior. Looking at the code I can see one possible problem in crypt_alloc_buffer() but it doesn't explain why reducing initial page order would help. Anyway: Are we guaranteed mempool has enough pages for arbitrarily large bio that can enter crypt_alloc_buffer()? I can see crypt_page_alloc() does limit the number of pages in the mempool to dm_crypt_pages_per_client plus I assume the percpu counter bias in cc->n_allocated_pages can limit the really available number of pages even further. So if a single bio is large enough to trip percpu_counter_read_positive(&cc->n_allocated_pages) >= dm_crypt_pages_per_client condition in crypt_page_alloc(), we can loop forever? But maybe this cannot happen for some reason...

Quoted 5 lines

If this is not it, I think we need to find out why the writeback bios are not completeting. Probably I'd start with checking what is kcryptd, presumably responsible for processing these bios, doing.

Honza

cc->page_pool is initialized to hold BIO_MAX_VECS pages. crypt_map will restrict the bio size to BIO_MAX_VECS (see dm_accept_partial_bio being called from crypt_map).

When we allocate a buffer in crypt_alloc_buffer, we try first allocation without waiting, then we grab the mutex and we try allocation with waiting.

The mutex should prevent a deadlock when two processes allocate 128 pages concurrently and wait for each other to free some pages.

The limit to dm_crypt_pages_per_client only applies to pages allocated from the kernel - when this limit is reached, we can still allocate from the mempool, so it shoudn't cause deadlocks.