[bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[Changhui Zhong]

Hello,

repo:https://git.kernel.org/pub/scm/linux/kernel/git/axboe/linux-block.git
branch:for-next
commit HEAD:f2738f2440eb573094ef6f09cca915ae37f2f8bc

hit this issue on recent upstream，reproduced with ubdsrv, trigger this
issue on "running generic/005" and "running generic/006",

# cd ubdsrv
# make test T=generic

[  993.347470] WARNING: CPU: 13 PID: 4628 at io_uring/io_uring.c:2835
io_ring_exit_work+0x2b6/0x2e0
[  993.357304] Modules linked in: ext4 mbcache jbd2 rfkill sunrpc
dm_multipath intel_rapl_msr intel_rapl_common intel_uncore_frequency
intel_uncore_frequency_common i10nm_edac nfit libnvdimm
x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm ipmi_ssif
rapl intel_cstate mgag200 iTCO_wdt dax_hmem iTCO_vendor_support
cxl_acpi mei_me i2c_algo_bit cxl_core i2c_i801 drm_shmem_helper
isst_if_mmio isst_if_mbox_pci drm_kms_helper intel_uncore mei einj
ioatdma pcspkr i2c_smbus isst_if_common intel_vsec intel_pch_thermal
ipmi_si dca ipmi_devintf ipmi_msghandler acpi_pad acpi_power_meter drm
fuse xfs libcrc32c sd_mod t10_pi sg ahci crct10dif_pclmul libahci
crc32_pclmul crc32c_intel libata tg3 ghash_clmulni_intel wmi dm_mirror
dm_region_hash dm_log dm_mod
[  993.431516] CPU: 13 PID: 4628 Comm: kworker/u96:2 Not tainted 6.9.0-rc3+ #1
[  993.439297] Hardware name: Lenovo ThinkSystem SR650 V2/7Z73CTO1WW,
BIOS AFE120G-1.40 09/20/2022
[  993.449015] Workqueue: iou_exit io_ring_exit_work
[  993.454275] RIP: 0010:io_ring_exit_work+0x2b6/0x2e0
[  993.459729] Code: 89 e7 e8 6d de ff ff 48 8b 44 24 58 65 48 2b 04
25 28 00 00 00 75 2e 48 8d 65 d8 5b 41 5c 41 5d 41 5e 41 5f 5d c3 cc
cc cc cc <0f> 0b 41 be 60 ea 00 00 e9 45 fe ff ff 0f 0b e9 1d ff ff ff
e8 c1
[  993.480695] RSP: 0018:ff70b0c247657dd0 EFLAGS: 00010287
[  993.486533] RAX: 00000001000a94c0 RBX: ff26a781c5b48448 RCX: 0000000000000000
[  993.494506] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ff26a781c5b48040
[  993.502475] RBP: ff70b0c247657e60 R08: 0000000000000000 R09: ffffffffbb254ca0
[  993.510445] R10: 0000000000000000 R11: 0000000000000000 R12: ff26a781c5b48000
[  993.518415] R13: ff26a781c5b48040 R14: 0000000000000032 R15: 0000000000000000
[  993.526387] FS:  0000000000000000(0000) GS:ff26a784efa80000(0000)
knlGS:0000000000000000
[  993.535427] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  993.541848] CR2: 00007ff5a794f004 CR3: 000000003ea20006 CR4: 0000000000771ef0
[  993.549820] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  993.557790] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  993.565761] PKRU: 55555554
[  993.568787] Call Trace:
[  993.571523]  <TASK>
[  993.573871]  ? __warn+0x7f/0x130
[  993.577486]  ? io_ring_exit_work+0x2b6/0x2e0
[  993.582259]  ? report_bug+0x18a/0x1a0
[  993.586358]  ? handle_bug+0x3c/0x70
[  993.590262]  ? exc_invalid_op+0x14/0x70
[  993.594551]  ? asm_exc_invalid_op+0x16/0x20
[  993.599234]  ? io_ring_exit_work+0x2b6/0x2e0
[  993.604006]  ? try_to_wake_up+0x21e/0x600
[  993.608490]  process_one_work+0x193/0x3d0
[  993.612969]  worker_thread+0x2fc/0x410
[  993.617161]  ? __pfx_worker_thread+0x10/0x10
[  993.621934]  kthread+0xdc/0x110
[  993.625448]  ? __pfx_kthread+0x10/0x10
[  993.629640]  ret_from_fork+0x2d/0x50
[  993.633640]  ? __pfx_kthread+0x10/0x10
[  993.637830]  ret_from_fork_asm+0x1a/0x30
[  993.642219]  </TASK>
[  993.644661] ---[ end trace 0000000000000000 ]---

Thanks,

Re: [bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[Jens Axboe]

On 4/15/24 3:14 AM, Changhui Zhong wrote:
> Hello,
> 
> repo:https://git.kernel.org/pub/scm/linux/kernel/git/axboe/linux-block.git
> branch:for-next
> commit HEAD:f2738f2440eb573094ef6f09cca915ae37f2f8bc
> 
> hit this issue on recent upstream，reproduced with ubdsrv, trigger this
> issue on "running generic/005" and "running generic/006",
> 
> # cd ubdsrv
> # make test T=generic
> 
> [  993.347470] WARNING: CPU: 13 PID: 4628 at io_uring/io_uring.c:2835
> io_ring_exit_work+0x2b6/0x2e0
> [  993.357304] Modules linked in: ext4 mbcache jbd2 rfkill sunrpc
> dm_multipath intel_rapl_msr intel_rapl_common intel_uncore_frequency
> intel_uncore_frequency_common i10nm_edac nfit libnvdimm
> x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm ipmi_ssif
> rapl intel_cstate mgag200 iTCO_wdt dax_hmem iTCO_vendor_support
> cxl_acpi mei_me i2c_algo_bit cxl_core i2c_i801 drm_shmem_helper
> isst_if_mmio isst_if_mbox_pci drm_kms_helper intel_uncore mei einj
> ioatdma pcspkr i2c_smbus isst_if_common intel_vsec intel_pch_thermal
> ipmi_si dca ipmi_devintf ipmi_msghandler acpi_pad acpi_power_meter drm
> fuse xfs libcrc32c sd_mod t10_pi sg ahci crct10dif_pclmul libahci
> crc32_pclmul crc32c_intel libata tg3 ghash_clmulni_intel wmi dm_mirror
> dm_region_hash dm_log dm_mod
> [  993.431516] CPU: 13 PID: 4628 Comm: kworker/u96:2 Not tainted 6.9.0-rc3+ #1
> [  993.439297] Hardware name: Lenovo ThinkSystem SR650 V2/7Z73CTO1WW,
> BIOS AFE120G-1.40 09/20/2022
> [  993.449015] Workqueue: iou_exit io_ring_exit_work
> [  993.454275] RIP: 0010:io_ring_exit_work+0x2b6/0x2e0
> [  993.459729] Code: 89 e7 e8 6d de ff ff 48 8b 44 24 58 65 48 2b 04
> 25 28 00 00 00 75 2e 48 8d 65 d8 5b 41 5c 41 5d 41 5e 41 5f 5d c3 cc
> cc cc cc <0f> 0b 41 be 60 ea 00 00 e9 45 fe ff ff 0f 0b e9 1d ff ff ff
> e8 c1
> [  993.480695] RSP: 0018:ff70b0c247657dd0 EFLAGS: 00010287
> [  993.486533] RAX: 00000001000a94c0 RBX: ff26a781c5b48448 RCX: 0000000000000000
> [  993.494506] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ff26a781c5b48040
> [  993.502475] RBP: ff70b0c247657e60 R08: 0000000000000000 R09: ffffffffbb254ca0
> [  993.510445] R10: 0000000000000000 R11: 0000000000000000 R12: ff26a781c5b48000
> [  993.518415] R13: ff26a781c5b48040 R14: 0000000000000032 R15: 0000000000000000
> [  993.526387] FS:  0000000000000000(0000) GS:ff26a784efa80000(0000)
> knlGS:0000000000000000
> [  993.535427] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [  993.541848] CR2: 00007ff5a794f004 CR3: 000000003ea20006 CR4: 0000000000771ef0
> [  993.549820] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [  993.557790] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [  993.565761] PKRU: 55555554
> [  993.568787] Call Trace:
> [  993.571523]  <TASK>
> [  993.573871]  ? __warn+0x7f/0x130
> [  993.577486]  ? io_ring_exit_work+0x2b6/0x2e0
> [  993.582259]  ? report_bug+0x18a/0x1a0
> [  993.586358]  ? handle_bug+0x3c/0x70
> [  993.590262]  ? exc_invalid_op+0x14/0x70
> [  993.594551]  ? asm_exc_invalid_op+0x16/0x20
> [  993.599234]  ? io_ring_exit_work+0x2b6/0x2e0
> [  993.604006]  ? try_to_wake_up+0x21e/0x600
> [  993.608490]  process_one_work+0x193/0x3d0
> [  993.612969]  worker_thread+0x2fc/0x410
> [  993.617161]  ? __pfx_worker_thread+0x10/0x10
> [  993.621934]  kthread+0xdc/0x110
> [  993.625448]  ? __pfx_kthread+0x10/0x10
> [  993.629640]  ret_from_fork+0x2d/0x50
> [  993.633640]  ? __pfx_kthread+0x10/0x10
> [  993.637830]  ret_from_fork_asm+0x1a/0x30
> [  993.642219]  </TASK>
> [  993.644661] ---[ end trace 0000000000000000 ]---

I can't reproduce this here, fwiw. Ming, something you've seen?

-- 
Jens Axboe

Re: [bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[Ming Lei]

On Mon, Apr 15, 2024 at 08:28:05AM -0600, Jens Axboe wrote:
> On 4/15/24 3:14 AM, Changhui Zhong wrote:
> > Hello,
> > 
> > repo:https://git.kernel.org/pub/scm/linux/kernel/git/axboe/linux-block.git
> > branch:for-next
> > commit HEAD:f2738f2440eb573094ef6f09cca915ae37f2f8bc
> > 
> > hit this issue on recent upstream，reproduced with ubdsrv, trigger this
> > issue on "running generic/005" and "running generic/006",
> > 
> > # cd ubdsrv
> > # make test T=generic
> > 
> > [  993.347470] WARNING: CPU: 13 PID: 4628 at io_uring/io_uring.c:2835
> > io_ring_exit_work+0x2b6/0x2e0
> > [  993.357304] Modules linked in: ext4 mbcache jbd2 rfkill sunrpc
> > dm_multipath intel_rapl_msr intel_rapl_common intel_uncore_frequency
> > intel_uncore_frequency_common i10nm_edac nfit libnvdimm
> > x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm ipmi_ssif
> > rapl intel_cstate mgag200 iTCO_wdt dax_hmem iTCO_vendor_support
> > cxl_acpi mei_me i2c_algo_bit cxl_core i2c_i801 drm_shmem_helper
> > isst_if_mmio isst_if_mbox_pci drm_kms_helper intel_uncore mei einj
> > ioatdma pcspkr i2c_smbus isst_if_common intel_vsec intel_pch_thermal
> > ipmi_si dca ipmi_devintf ipmi_msghandler acpi_pad acpi_power_meter drm
> > fuse xfs libcrc32c sd_mod t10_pi sg ahci crct10dif_pclmul libahci
> > crc32_pclmul crc32c_intel libata tg3 ghash_clmulni_intel wmi dm_mirror
> > dm_region_hash dm_log dm_mod
> > [  993.431516] CPU: 13 PID: 4628 Comm: kworker/u96:2 Not tainted 6.9.0-rc3+ #1
> > [  993.439297] Hardware name: Lenovo ThinkSystem SR650 V2/7Z73CTO1WW,
> > BIOS AFE120G-1.40 09/20/2022
> > [  993.449015] Workqueue: iou_exit io_ring_exit_work
> > [  993.454275] RIP: 0010:io_ring_exit_work+0x2b6/0x2e0
> > [  993.459729] Code: 89 e7 e8 6d de ff ff 48 8b 44 24 58 65 48 2b 04
> > 25 28 00 00 00 75 2e 48 8d 65 d8 5b 41 5c 41 5d 41 5e 41 5f 5d c3 cc
> > cc cc cc <0f> 0b 41 be 60 ea 00 00 e9 45 fe ff ff 0f 0b e9 1d ff ff ff
> > e8 c1
> > [  993.480695] RSP: 0018:ff70b0c247657dd0 EFLAGS: 00010287
> > [  993.486533] RAX: 00000001000a94c0 RBX: ff26a781c5b48448 RCX: 0000000000000000
> > [  993.494506] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ff26a781c5b48040
> > [  993.502475] RBP: ff70b0c247657e60 R08: 0000000000000000 R09: ffffffffbb254ca0
> > [  993.510445] R10: 0000000000000000 R11: 0000000000000000 R12: ff26a781c5b48000
> > [  993.518415] R13: ff26a781c5b48040 R14: 0000000000000032 R15: 0000000000000000
> > [  993.526387] FS:  0000000000000000(0000) GS:ff26a784efa80000(0000)
> > knlGS:0000000000000000
> > [  993.535427] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [  993.541848] CR2: 00007ff5a794f004 CR3: 000000003ea20006 CR4: 0000000000771ef0
> > [  993.549820] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > [  993.557790] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> > [  993.565761] PKRU: 55555554
> > [  993.568787] Call Trace:
> > [  993.571523]  <TASK>
> > [  993.573871]  ? __warn+0x7f/0x130
> > [  993.577486]  ? io_ring_exit_work+0x2b6/0x2e0
> > [  993.582259]  ? report_bug+0x18a/0x1a0
> > [  993.586358]  ? handle_bug+0x3c/0x70
> > [  993.590262]  ? exc_invalid_op+0x14/0x70
> > [  993.594551]  ? asm_exc_invalid_op+0x16/0x20
> > [  993.599234]  ? io_ring_exit_work+0x2b6/0x2e0
> > [  993.604006]  ? try_to_wake_up+0x21e/0x600
> > [  993.608490]  process_one_work+0x193/0x3d0
> > [  993.612969]  worker_thread+0x2fc/0x410
> > [  993.617161]  ? __pfx_worker_thread+0x10/0x10
> > [  993.621934]  kthread+0xdc/0x110
> > [  993.625448]  ? __pfx_kthread+0x10/0x10
> > [  993.629640]  ret_from_fork+0x2d/0x50
> > [  993.633640]  ? __pfx_kthread+0x10/0x10
> > [  993.637830]  ret_from_fork_asm+0x1a/0x30
> > [  993.642219]  </TASK>
> > [  993.644661] ---[ end trace 0000000000000000 ]---
> 
> I can't reproduce this here, fwiw. Ming, something you've seen?

I just test against the latest for-next/block(-rc4 based), and still can't
reproduce it. There was such RH internal report before, and maybe not
ublk related.

Changhui, if the issue can be reproduced in your machine, care to share
your machine for me to investigate a bit?

Thanks,
Ming

Re: [bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[Changhui Zhong]

> >
> > I can't reproduce this here, fwiw. Ming, something you've seen?
>
> I just test against the latest for-next/block(-rc4 based), and still can't
> reproduce it. There was such RH internal report before, and maybe not
> ublk related.
>
> Changhui, if the issue can be reproduced in your machine, care to share
> your machine for me to investigate a bit?
>
> Thanks,
> Ming
>

I still can reproduce this issue on my machine，
and I shared machine to Ming，he can do more investigation for this issue，

[ 1244.207092] running generic/006
[ 1246.456896] blk_print_req_error: 77 callbacks suppressed
[ 1246.456907] I/O error, dev ublkb1, sector 2395864 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1246.465887] I/O error, dev ublkb1, sector 2551168 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1246.473176] I/O error, dev ublkb1, sector 2395928 op 0x1:(WRITE)
flags 0x8800 phys_seg 4 prio class 0
[ 1246.473185] I/O error, dev ublkb1, sector 2395888 op 0x1:(WRITE)
flags 0x8800 phys_seg 2 prio class 0
[ 1246.483487] I/O error, dev ublkb1, sector 2550936 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1246.493775] I/O error, dev ublkb1, sector 2395984 op 0x1:(WRITE)
flags 0x8800 phys_seg 3 prio class 0
[ 1246.493778] I/O error, dev ublkb1, sector 2395960 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1246.504071] I/O error, dev ublkb1, sector 2221344 op 0x0:(READ)
flags 0x0 phys_seg 1 prio class 0
[ 1246.514367] I/O error, dev ublkb1, sector 2408312 op 0x1:(WRITE)
flags 0x8800 phys_seg 2 prio class 0
[ 1246.524665] I/O error, dev ublkb1, sector 2223680 op 0x1:(WRITE)
flags 0x8800 phys_seg 2 prio class 0
[ 1258.012089] blk_print_req_error: 214 callbacks suppressed
[ 1258.012097] I/O error, dev ublkb1, sector 2191768 op 0x0:(READ)
flags 0x0 phys_seg 2 prio class 0
[ 1258.019007] I/O error, dev ublkb1, sector 2123752 op 0x0:(READ)
flags 0x0 phys_seg 5 prio class 0
[ 1258.028079] I/O error, dev ublkb1, sector 2195728 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1258.037993] I/O error, dev ublkb1, sector 2127424 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1258.048276] I/O error, dev ublkb1, sector 2191920 op 0x0:(READ)
flags 0x0 phys_seg 2 prio class 0
[ 1258.058567] I/O error, dev ublkb1, sector 2127384 op 0x1:(WRITE)
flags 0x8800 phys_seg 2 prio class 0
[ 1258.068467] I/O error, dev ublkb1, sector 2200624 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1258.078763] I/O error, dev ublkb1, sector 2127656 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1258.089058] I/O error, dev ublkb1, sector 2195360 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1258.089061] I/O error, dev ublkb1, sector 2191784 op 0x0:(READ)
flags 0x0 phys_seg 1 prio class 0
[ 1269.576153] blk_print_req_error: 237 callbacks suppressed
[ 1269.576161] I/O error, dev ublkb1, sector 2061112 op 0x0:(READ)
flags 0x0 phys_seg 2 prio class 0
[ 1269.592138] I/O error, dev ublkb1, sector 2177016 op 0x0:(READ)
flags 0x0 phys_seg 1 prio class 0
[ 1269.602051] I/O error, dev ublkb1, sector 2184568 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1269.612347] I/O error, dev ublkb1, sector 2061304 op 0x0:(READ)
flags 0x0 phys_seg 2 prio class 0
[ 1269.622258] I/O error, dev ublkb1, sector 2059360 op 0x1:(WRITE)
flags 0x8800 phys_seg 2 prio class 0
[ 1269.632556] I/O error, dev ublkb1, sector 2061320 op 0x0:(READ)
flags 0x0 phys_seg 1 prio class 0
[ 1269.642466] I/O error, dev ublkb1, sector 2059080 op 0x1:(WRITE)
flags 0x8800 phys_seg 2 prio class 0
[ 1269.652763] I/O error, dev ublkb1, sector 2061128 op 0x0:(READ)
flags 0x0 phys_seg 1 prio class 0
[ 1269.662672] I/O error, dev ublkb1, sector 2059112 op 0x1:(WRITE)
flags 0x8800 phys_seg 2 prio class 0
[ 1269.672969] I/O error, dev ublkb1, sector 2061136 op 0x0:(READ)
flags 0x0 phys_seg 1 prio class 0
[ 1299.615464] blk_print_req_error: 74 callbacks suppressed
[ 1299.615472] I/O error, dev ublkb1, sector 2023992 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1299.631730] I/O error, dev ublkb1, sector 2387840 op 0x0:(READ)
flags 0x0 phys_seg 1 prio class 0
[ 1299.641647] I/O error, dev ublkb1, sector 2017904 op 0x0:(READ)
flags 0x0 phys_seg 2 prio class 0
[ 1299.651551] I/O error, dev ublkb1, sector 2386584 op 0x1:(WRITE)
flags 0x8800 phys_seg 2 prio class 0
[ 1299.661852] I/O error, dev ublkb1, sector 2017872 op 0x0:(READ)
flags 0x0 phys_seg 3 prio class 0
[ 1299.671769] I/O error, dev ublkb1, sector 2387944 op 0x0:(READ)
flags 0x0 phys_seg 3 prio class 0
[ 1299.681689] I/O error, dev ublkb1, sector 2386672 op 0x1:(WRITE)
flags 0x8800 phys_seg 2 prio class 0
[ 1299.691991] I/O error, dev ublkb1, sector 2023968 op 0x1:(WRITE)
flags 0x8800 phys_seg 3 prio class 0
[ 1299.702289] I/O error, dev ublkb1, sector 2386864 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1299.712586] I/O error, dev ublkb1, sector 2018072 op 0x0:(READ)
flags 0x0 phys_seg 2 prio class 0
[ 1310.309570] blk_print_req_error: 118 callbacks suppressed
[ 1310.309579] I/O error, dev ublkb1, sector 1939168 op 0x0:(READ)
flags 0x0 phys_seg 2 prio class 0
[ 1310.310554] I/O error, dev ublkb1, sector 2575992 op 0x0:(READ)
flags 0x0 phys_seg 1 prio class 0
[ 1310.315649] I/O error, dev ublkb1, sector 1939704 op 0x1:(WRITE)
flags 0x8800 phys_seg 2 prio class 0
[ 1310.325550] I/O error, dev ublkb1, sector 2582152 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1310.335456] I/O error, dev ublkb1, sector 1939776 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1310.345751] I/O error, dev ublkb1, sector 2576008 op 0x0:(READ)
flags 0x0 phys_seg 4 prio class 0
[ 1310.356048] I/O error, dev ublkb1, sector 1939456 op 0x1:(WRITE)
flags 0x8800 phys_seg 2 prio class 0
[ 1310.356051] I/O error, dev ublkb1, sector 1939424 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1310.356054] I/O error, dev ublkb1, sector 1939272 op 0x0:(READ)
flags 0x0 phys_seg 1 prio class 0
[ 1310.356057] I/O error, dev ublkb1, sector 1939440 op 0x1:(WRITE)
flags 0x8800 phys_seg 1 prio class 0
[ 1321.569744] ------------[ cut here ]------------
[ 1321.574931] WARNING: CPU: 15 PID: 679 at io_uring/io_uring.c:2835
io_ring_exit_work+0x2b6/0x2e0
[ 1321.584673] Modules linked in: ext4 mbcache jbd2 rpcsec_gss_krb5
auth_rpcgss nfsv4 dns_resolver nfs lockd grace netfs rfkill sunrpc
dm_multipath intel_rapl_msr intel_rapl_common intel_uncore_frequency
intel_uncore_frequency_common i10nm_edac nfit libnvdimm
x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm ipmi_ssif
rapl intel_cstate mgag200 i2c_algo_bit dax_hmem iTCO_wdt cxl_acpi
drm_shmem_helper iTCO_vendor_support cxl_core mei_me drm_kms_helper
ioatdma i2c_i801 isst_if_mmio intel_uncore isst_if_mbox_pci mei einj
isst_if_common pcspkr intel_pch_thermal i2c_smbus intel_vsec ipmi_si
dca ipmi_devintf ipmi_msghandler acpi_power_meter acpi_pad drm fuse
xfs libcrc32c sd_mod t10_pi sg crct10dif_pclmul crc32_pclmul
crc32c_intel ahci libahci libata tg3 ghash_clmulni_intel wmi dm_mirror
dm_region_hash dm_log dm_mod
[ 1321.665566] CPU: 15 PID: 679 Comm: kworker/u96:9 Not tainted 6.9.0-rc3+ #1
[ 1321.673251] Hardware name: Lenovo ThinkSystem SR650 V2/7Z73CTO1WW,
BIOS AFE120G-1.40 09/20/2022
[ 1321.682970] Workqueue: iou_exit io_ring_exit_work
[ 1321.688235] RIP: 0010:io_ring_exit_work+0x2b6/0x2e0
[ 1321.693689] Code: 89 e7 e8 6d de ff ff 48 8b 44 24 58 65 48 2b 04
25 28 00 00 00 75 2e 48 8d 65 d8 5b 41 5c 41 5d 41 5e 41 5f 5d c3 cc
cc cc cc <0f> 0b 41 be 60 ea 00 00 e9 45 fe ff ff 0f 0b e9 1d ff ff ff
e8 c1
[ 1321.714654] RSP: 0018:ff37e1e101257dd0 EFLAGS: 00010293
[ 1321.720494] RAX: 00000001000f97d6 RBX: ff3771afdd8bec48 RCX: 0000000000000000
[ 1321.728468] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ff3771afdd8be840
[ 1321.736437] RBP: ff37e1e101257e60 R08: 0000000000000000 R09: ffffffffa6c54ca0
[ 1321.744406] R10: 0000000000000000 R11: 0000000000000000 R12: ff3771afdd8be800
[ 1321.752376] R13: ff3771afdd8be840 R14: 0000000000000032 R15: 0000000000000000
[ 1321.760354] FS:  0000000000000000(0000) GS:ff3771b2efb80000(0000)
knlGS:0000000000000000
[ 1321.769396] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1321.775808] CR2: 00007f5334002088 CR3: 00000003ba220001 CR4: 0000000000771ef0
[ 1321.783783] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1321.791757] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 1321.799733] PKRU: 55555554
[ 1321.802760] Call Trace:
[ 1321.805498]  <TASK>
[ 1321.807847]  ? __warn+0x7f/0x130
[ 1321.811460]  ? io_ring_exit_work+0x2b6/0x2e0
[ 1321.816238]  ? report_bug+0x18a/0x1a0
[ 1321.820340]  ? handle_bug+0x3c/0x70
[ 1321.824247]  ? exc_invalid_op+0x14/0x70
[ 1321.828537]  ? asm_exc_invalid_op+0x16/0x20
[ 1321.833222]  ? io_ring_exit_work+0x2b6/0x2e0
[ 1321.837998]  ? finish_task_switch.isra.0+0x8e/0x2a0
[ 1321.843457]  process_one_work+0x193/0x3d0
[ 1321.847945]  worker_thread+0x2fc/0x410
[ 1321.852140]  ? __pfx_worker_thread+0x10/0x10
[ 1321.856907]  kthread+0xdc/0x110
[ 1321.860421]  ? __pfx_kthread+0x10/0x10
[ 1321.864617]  ret_from_fork+0x2d/0x50
[ 1321.868622]  ? __pfx_kthread+0x10/0x10
[ 1321.872812]  ret_from_fork_asm+0x1a/0x30
[ 1321.877208]  </TASK>
[ 1321.879655] ---[ end trace 0000000000000000 ]---

Re: [bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[Ming Lei]

On Tue, Apr 16, 2024 at 10:26:16AM +0800, Changhui Zhong wrote:
> > >
> > > I can't reproduce this here, fwiw. Ming, something you've seen?
> >
> > I just test against the latest for-next/block(-rc4 based), and still can't
> > reproduce it. There was such RH internal report before, and maybe not
> > ublk related.
> >
> > Changhui, if the issue can be reproduced in your machine, care to share
> > your machine for me to investigate a bit?
> >
> > Thanks,
> > Ming
> >
> 
> I still can reproduce this issue on my machine，
> and I shared machine to Ming，he can do more investigation for this issue，
> 
> [ 1244.207092] running generic/006
> [ 1246.456896] blk_print_req_error: 77 callbacks suppressed
> [ 1246.456907] I/O error, dev ublkb1, sector 2395864 op 0x1:(WRITE)
> flags 0x8800 phys_seg 1 prio class 0

The failure is actually triggered in recovering qcow2 target in generic/005,
since ublkb0 isn't removed successfully in generic/005.

git-bisect shows that the 1st bad commit is cca6571381a0 ("io_uring/rw:
cleanup retry path").

And not see any issue in uring command side, so the trouble seems
in normal io_uring rw side over XFS file, and not related with block
device.


Thanks,
Ming

Re: [bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[Jens Axboe]

On 4/16/24 4:00 AM, Ming Lei wrote:
> On Tue, Apr 16, 2024 at 10:26:16AM +0800, Changhui Zhong wrote:
>>>>
>>>> I can't reproduce this here, fwiw. Ming, something you've seen?
>>>
>>> I just test against the latest for-next/block(-rc4 based), and still can't
>>> reproduce it. There was such RH internal report before, and maybe not
>>> ublk related.
>>>
>>> Changhui, if the issue can be reproduced in your machine, care to share
>>> your machine for me to investigate a bit?
>>>
>>> Thanks,
>>> Ming
>>>
>>
>> I still can reproduce this issue on my machine?
>> and I shared machine to Ming?he can do more investigation for this issue?
>>
>> [ 1244.207092] running generic/006
>> [ 1246.456896] blk_print_req_error: 77 callbacks suppressed
>> [ 1246.456907] I/O error, dev ublkb1, sector 2395864 op 0x1:(WRITE)
>> flags 0x8800 phys_seg 1 prio class 0
> 
> The failure is actually triggered in recovering qcow2 target in generic/005,
> since ublkb0 isn't removed successfully in generic/005.
> 
> git-bisect shows that the 1st bad commit is cca6571381a0 ("io_uring/rw:
> cleanup retry path").
> 
> And not see any issue in uring command side, so the trouble seems
> in normal io_uring rw side over XFS file, and not related with block
> device.

Indeed, I can reproduce it on XFS as well. I'll take a look.

-- 
Jens Axboe

Re: [bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[Pavel Begunkov]

On 4/16/24 12:38, Jens Axboe wrote:
> On 4/16/24 4:00 AM, Ming Lei wrote:
>> On Tue, Apr 16, 2024 at 10:26:16AM +0800, Changhui Zhong wrote:
>>>>>
>>>>> I can't reproduce this here, fwiw. Ming, something you've seen?
>>>>
>>>> I just test against the latest for-next/block(-rc4 based), and still can't
>>>> reproduce it. There was such RH internal report before, and maybe not
>>>> ublk related.
>>>>
>>>> Changhui, if the issue can be reproduced in your machine, care to share
>>>> your machine for me to investigate a bit?
>>>>
>>>> Thanks,
>>>> Ming
>>>>
>>>
>>> I still can reproduce this issue on my machine?
>>> and I shared machine to Ming?he can do more investigation for this issue?
>>>
>>> [ 1244.207092] running generic/006
>>> [ 1246.456896] blk_print_req_error: 77 callbacks suppressed
>>> [ 1246.456907] I/O error, dev ublkb1, sector 2395864 op 0x1:(WRITE)
>>> flags 0x8800 phys_seg 1 prio class 0
>>
>> The failure is actually triggered in recovering qcow2 target in generic/005,
>> since ublkb0 isn't removed successfully in generic/005.
>>
>> git-bisect shows that the 1st bad commit is cca6571381a0 ("io_uring/rw:
>> cleanup retry path").
>>
>> And not see any issue in uring command side, so the trouble seems
>> in normal io_uring rw side over XFS file, and not related with block
>> device.
> 
> Indeed, I can reproduce it on XFS as well. I'll take a look.

Looking at this patch, that io_rw_should_reissue() path is for when
we failed via the kiocb callback but came there off of the submission
path, so when we unwind back it finds the flag, preps and resubmits
the req. If it's not the case but we still return "true", it'd leaks
the request, which would explains why exit_work gets stuck.

-- 
Pavel Begunkov

Re: [bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[Jens Axboe]

On 4/16/24 6:14 AM, Pavel Begunkov wrote:
> On 4/16/24 12:38, Jens Axboe wrote:
>> On 4/16/24 4:00 AM, Ming Lei wrote:
>>> On Tue, Apr 16, 2024 at 10:26:16AM +0800, Changhui Zhong wrote:
>>>>>>
>>>>>> I can't reproduce this here, fwiw. Ming, something you've seen?
>>>>>
>>>>> I just test against the latest for-next/block(-rc4 based), and still can't
>>>>> reproduce it. There was such RH internal report before, and maybe not
>>>>> ublk related.
>>>>>
>>>>> Changhui, if the issue can be reproduced in your machine, care to share
>>>>> your machine for me to investigate a bit?
>>>>>
>>>>> Thanks,
>>>>> Ming
>>>>>
>>>>
>>>> I still can reproduce this issue on my machine?
>>>> and I shared machine to Ming?he can do more investigation for this issue?
>>>>
>>>> [ 1244.207092] running generic/006
>>>> [ 1246.456896] blk_print_req_error: 77 callbacks suppressed
>>>> [ 1246.456907] I/O error, dev ublkb1, sector 2395864 op 0x1:(WRITE)
>>>> flags 0x8800 phys_seg 1 prio class 0
>>>
>>> The failure is actually triggered in recovering qcow2 target in generic/005,
>>> since ublkb0 isn't removed successfully in generic/005.
>>>
>>> git-bisect shows that the 1st bad commit is cca6571381a0 ("io_uring/rw:
>>> cleanup retry path").
>>>
>>> And not see any issue in uring command side, so the trouble seems
>>> in normal io_uring rw side over XFS file, and not related with block
>>> device.
>>
>> Indeed, I can reproduce it on XFS as well. I'll take a look.
> 
> Looking at this patch, that io_rw_should_reissue() path is for when
> we failed via the kiocb callback but came there off of the submission
> path, so when we unwind back it finds the flag, preps and resubmits
> the req. If it's not the case but we still return "true", it'd leaks
> the request, which would explains why exit_work gets stuck.

Yep, this is what happens. I have a test patch that just punts any
reissue to task_work, it'll insert to iowq from there. Before we would
fail it, even though we didn't have to, but that check was killed and
then it just lingers for this case and it's lost.

-- 
Jens Axboe

Re: [bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[Jens Axboe]

On 4/16/24 5:38 AM, Jens Axboe wrote:
> On 4/16/24 4:00 AM, Ming Lei wrote:
>> On Tue, Apr 16, 2024 at 10:26:16AM +0800, Changhui Zhong wrote:
>>>>>
>>>>> I can't reproduce this here, fwiw. Ming, something you've seen?
>>>>
>>>> I just test against the latest for-next/block(-rc4 based), and still can't
>>>> reproduce it. There was such RH internal report before, and maybe not
>>>> ublk related.
>>>>
>>>> Changhui, if the issue can be reproduced in your machine, care to share
>>>> your machine for me to investigate a bit?
>>>>
>>>> Thanks,
>>>> Ming
>>>>
>>>
>>> I still can reproduce this issue on my machine?
>>> and I shared machine to Ming?he can do more investigation for this issue?
>>>
>>> [ 1244.207092] running generic/006
>>> [ 1246.456896] blk_print_req_error: 77 callbacks suppressed
>>> [ 1246.456907] I/O error, dev ublkb1, sector 2395864 op 0x1:(WRITE)
>>> flags 0x8800 phys_seg 1 prio class 0
>>
>> The failure is actually triggered in recovering qcow2 target in generic/005,
>> since ublkb0 isn't removed successfully in generic/005.
>>
>> git-bisect shows that the 1st bad commit is cca6571381a0 ("io_uring/rw:
>> cleanup retry path").
>>
>> And not see any issue in uring command side, so the trouble seems
>> in normal io_uring rw side over XFS file, and not related with block
>> device.
> 
> Indeed, I can reproduce it on XFS as well. I'll take a look.

Can you try this one?


diff --git a/io_uring/io_uring.c b/io_uring/io_uring.c
index 3c9087f37c43..c67ae6e36c4f 100644
--- a/io_uring/io_uring.c
+++ b/io_uring/io_uring.c
@@ -527,6 +527,19 @@ static void io_queue_iowq(struct io_kiocb *req)
 		io_queue_linked_timeout(link);
 }
 
+static void io_tw_requeue_iowq(struct io_kiocb *req, struct io_tw_state *ts)
+{
+	req->flags &= ~REQ_F_REISSUE;
+	io_queue_iowq(req);
+}
+
+void io_tw_queue_iowq(struct io_kiocb *req)
+{
+	req->flags |= REQ_F_REISSUE | REQ_F_BL_NO_RECYCLE;
+	req->io_task_work.func = io_tw_requeue_iowq;
+	io_req_task_work_add(req);
+}
+
 static __cold void io_queue_deferred(struct io_ring_ctx *ctx)
 {
 	while (!list_empty(&ctx->defer_list)) {
diff --git a/io_uring/io_uring.h b/io_uring/io_uring.h
index 624ca9076a50..b83a719c5443 100644
--- a/io_uring/io_uring.h
+++ b/io_uring/io_uring.h
@@ -75,6 +75,7 @@ struct file *io_file_get_fixed(struct io_kiocb *req, int fd,
 void __io_req_task_work_add(struct io_kiocb *req, unsigned flags);
 bool io_alloc_async_data(struct io_kiocb *req);
 void io_req_task_queue(struct io_kiocb *req);
+void io_tw_queue_iowq(struct io_kiocb *req);
 void io_req_task_complete(struct io_kiocb *req, struct io_tw_state *ts);
 void io_req_task_queue_fail(struct io_kiocb *req, int ret);
 void io_req_task_submit(struct io_kiocb *req, struct io_tw_state *ts);
diff --git a/io_uring/rw.c b/io_uring/rw.c
index 3134a6ece1be..4fed829fe97c 100644
--- a/io_uring/rw.c
+++ b/io_uring/rw.c
@@ -455,7 +455,7 @@ static bool __io_complete_rw_common(struct io_kiocb *req, long res)
 			 * current cycle.
 			 */
 			io_req_io_end(req);
-			req->flags |= REQ_F_REISSUE | REQ_F_BL_NO_RECYCLE;
+			io_tw_queue_iowq(req);
 			return true;
 		}
 		req_set_fail(req);
@@ -521,7 +521,7 @@ static void io_complete_rw_iopoll(struct kiocb *kiocb, long res)
 		io_req_end_write(req);
 	if (unlikely(res != req->cqe.res)) {
 		if (res == -EAGAIN && io_rw_should_reissue(req)) {
-			req->flags |= REQ_F_REISSUE | REQ_F_BL_NO_RECYCLE;
+			io_tw_queue_iowq(req);
 			return;
 		}
 		req->cqe.res = res;
@@ -839,7 +839,8 @@ static int __io_read(struct io_kiocb *req, unsigned int issue_flags)
 	ret = io_iter_do_read(rw, &io->iter);
 
 	if (ret == -EAGAIN || (req->flags & REQ_F_REISSUE)) {
-		req->flags &= ~REQ_F_REISSUE;
+		if (req->flags & REQ_F_REISSUE)
+			return IOU_ISSUE_SKIP_COMPLETE;
 		/* If we can poll, just do that. */
 		if (io_file_can_poll(req))
 			return -EAGAIN;
@@ -1034,10 +1035,8 @@ int io_write(struct io_kiocb *req, unsigned int issue_flags)
 	else
 		ret2 = -EINVAL;
 
-	if (req->flags & REQ_F_REISSUE) {
-		req->flags &= ~REQ_F_REISSUE;
-		ret2 = -EAGAIN;
-	}
+	if (req->flags & REQ_F_REISSUE)
+		return IOU_ISSUE_SKIP_COMPLETE;
 
 	/*
 	 * Raw bdev writes will return -EOPNOTSUPP for IOCB_NOWAIT. Just

-- 
Jens Axboe

Re: [bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[Pavel Begunkov]

On 4/16/24 13:24, Jens Axboe wrote:
> On 4/16/24 6:14 AM, Pavel Begunkov wrote:
>> On 4/16/24 12:38, Jens Axboe wrote:
>>> On 4/16/24 4:00 AM, Ming Lei wrote:
>>>> On Tue, Apr 16, 2024 at 10:26:16AM +0800, Changhui Zhong wrote:
>>>>>>>
>>>>>>> I can't reproduce this here, fwiw. Ming, something you've seen?
>>>>>>
>>>>>> I just test against the latest for-next/block(-rc4 based), and still can't
>>>>>> reproduce it. There was such RH internal report before, and maybe not
>>>>>> ublk related.
>>>>>>
>>>>>> Changhui, if the issue can be reproduced in your machine, care to share
>>>>>> your machine for me to investigate a bit?
>>>>>>
>>>>>> Thanks,
>>>>>> Ming
>>>>>>
>>>>>
>>>>> I still can reproduce this issue on my machine?
>>>>> and I shared machine to Ming?he can do more investigation for this issue?
>>>>>
>>>>> [ 1244.207092] running generic/006
>>>>> [ 1246.456896] blk_print_req_error: 77 callbacks suppressed
>>>>> [ 1246.456907] I/O error, dev ublkb1, sector 2395864 op 0x1:(WRITE)
>>>>> flags 0x8800 phys_seg 1 prio class 0
>>>>
>>>> The failure is actually triggered in recovering qcow2 target in generic/005,
>>>> since ublkb0 isn't removed successfully in generic/005.
>>>>
>>>> git-bisect shows that the 1st bad commit is cca6571381a0 ("io_uring/rw:
>>>> cleanup retry path").
>>>>
>>>> And not see any issue in uring command side, so the trouble seems
>>>> in normal io_uring rw side over XFS file, and not related with block
>>>> device.
>>>
>>> Indeed, I can reproduce it on XFS as well. I'll take a look.
>>
>> Looking at this patch, that io_rw_should_reissue() path is for when
>> we failed via the kiocb callback but came there off of the submission
>> path, so when we unwind back it finds the flag, preps and resubmits
>> the req. If it's not the case but we still return "true", it'd leaks
>> the request, which would explains why exit_work gets stuck.
> 
> Yep, this is what happens. I have a test patch that just punts any
> reissue to task_work, it'll insert to iowq from there. Before we would
> fail it, even though we didn't have to, but that check was killed and
> then it just lingers for this case and it's lost.

Sounds good, but let me note that while unwinding, block/fs/etc
could try to revert the iter, so it might not be safe to initiate
async IO from the callback as is

-- 
Pavel Begunkov

Re: [bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[Jens Axboe]

On 4/16/24 6:40 AM, Pavel Begunkov wrote:
> On 4/16/24 13:24, Jens Axboe wrote:
>> On 4/16/24 6:14 AM, Pavel Begunkov wrote:
>>> On 4/16/24 12:38, Jens Axboe wrote:
>>>> On 4/16/24 4:00 AM, Ming Lei wrote:
>>>>> On Tue, Apr 16, 2024 at 10:26:16AM +0800, Changhui Zhong wrote:
>>>>>>>>
>>>>>>>> I can't reproduce this here, fwiw. Ming, something you've seen?
>>>>>>>
>>>>>>> I just test against the latest for-next/block(-rc4 based), and still can't
>>>>>>> reproduce it. There was such RH internal report before, and maybe not
>>>>>>> ublk related.
>>>>>>>
>>>>>>> Changhui, if the issue can be reproduced in your machine, care to share
>>>>>>> your machine for me to investigate a bit?
>>>>>>>
>>>>>>> Thanks,
>>>>>>> Ming
>>>>>>>
>>>>>>
>>>>>> I still can reproduce this issue on my machine?
>>>>>> and I shared machine to Ming?he can do more investigation for this issue?
>>>>>>
>>>>>> [ 1244.207092] running generic/006
>>>>>> [ 1246.456896] blk_print_req_error: 77 callbacks suppressed
>>>>>> [ 1246.456907] I/O error, dev ublkb1, sector 2395864 op 0x1:(WRITE)
>>>>>> flags 0x8800 phys_seg 1 prio class 0
>>>>>
>>>>> The failure is actually triggered in recovering qcow2 target in generic/005,
>>>>> since ublkb0 isn't removed successfully in generic/005.
>>>>>
>>>>> git-bisect shows that the 1st bad commit is cca6571381a0 ("io_uring/rw:
>>>>> cleanup retry path").
>>>>>
>>>>> And not see any issue in uring command side, so the trouble seems
>>>>> in normal io_uring rw side over XFS file, and not related with block
>>>>> device.
>>>>
>>>> Indeed, I can reproduce it on XFS as well. I'll take a look.
>>>
>>> Looking at this patch, that io_rw_should_reissue() path is for when
>>> we failed via the kiocb callback but came there off of the submission
>>> path, so when we unwind back it finds the flag, preps and resubmits
>>> the req. If it's not the case but we still return "true", it'd leaks
>>> the request, which would explains why exit_work gets stuck.
>>
>> Yep, this is what happens. I have a test patch that just punts any
>> reissue to task_work, it'll insert to iowq from there. Before we would
>> fail it, even though we didn't have to, but that check was killed and
>> then it just lingers for this case and it's lost.
> 
> Sounds good, but let me note that while unwinding, block/fs/etc
> could try to revert the iter, so it might not be safe to initiate
> async IO from the callback as is

Good point, we may just want to do the iov iter revert before sending it
to io-wq for retry. Seems prudent, and can't hurt.

-- 
Jens Axboe

Re: [bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[Ming Lei]

On Tue, Apr 16, 2024 at 06:35:14AM -0600, Jens Axboe wrote:
> On 4/16/24 5:38 AM, Jens Axboe wrote:
> > On 4/16/24 4:00 AM, Ming Lei wrote:
> >> On Tue, Apr 16, 2024 at 10:26:16AM +0800, Changhui Zhong wrote:
> >>>>>
> >>>>> I can't reproduce this here, fwiw. Ming, something you've seen?
> >>>>
> >>>> I just test against the latest for-next/block(-rc4 based), and still can't
> >>>> reproduce it. There was such RH internal report before, and maybe not
> >>>> ublk related.
> >>>>
> >>>> Changhui, if the issue can be reproduced in your machine, care to share
> >>>> your machine for me to investigate a bit?
> >>>>
> >>>> Thanks,
> >>>> Ming
> >>>>
> >>>
> >>> I still can reproduce this issue on my machine?
> >>> and I shared machine to Ming?he can do more investigation for this issue?
> >>>
> >>> [ 1244.207092] running generic/006
> >>> [ 1246.456896] blk_print_req_error: 77 callbacks suppressed
> >>> [ 1246.456907] I/O error, dev ublkb1, sector 2395864 op 0x1:(WRITE)
> >>> flags 0x8800 phys_seg 1 prio class 0
> >>
> >> The failure is actually triggered in recovering qcow2 target in generic/005,
> >> since ublkb0 isn't removed successfully in generic/005.
> >>
> >> git-bisect shows that the 1st bad commit is cca6571381a0 ("io_uring/rw:
> >> cleanup retry path").
> >>
> >> And not see any issue in uring command side, so the trouble seems
> >> in normal io_uring rw side over XFS file, and not related with block
> >> device.
> > 
> > Indeed, I can reproduce it on XFS as well. I'll take a look.
> 
> Can you try this one?
> 
> 
> diff --git a/io_uring/io_uring.c b/io_uring/io_uring.c
> index 3c9087f37c43..c67ae6e36c4f 100644
> --- a/io_uring/io_uring.c
> +++ b/io_uring/io_uring.c
> @@ -527,6 +527,19 @@ static void io_queue_iowq(struct io_kiocb *req)
>  		io_queue_linked_timeout(link);
>  }
>  
> +static void io_tw_requeue_iowq(struct io_kiocb *req, struct io_tw_state *ts)
> +{
> +	req->flags &= ~REQ_F_REISSUE;
> +	io_queue_iowq(req);
> +}
> +
> +void io_tw_queue_iowq(struct io_kiocb *req)
> +{
> +	req->flags |= REQ_F_REISSUE | REQ_F_BL_NO_RECYCLE;
> +	req->io_task_work.func = io_tw_requeue_iowq;
> +	io_req_task_work_add(req);
> +}
> +
>  static __cold void io_queue_deferred(struct io_ring_ctx *ctx)
>  {
>  	while (!list_empty(&ctx->defer_list)) {
> diff --git a/io_uring/io_uring.h b/io_uring/io_uring.h
> index 624ca9076a50..b83a719c5443 100644
> --- a/io_uring/io_uring.h
> +++ b/io_uring/io_uring.h
> @@ -75,6 +75,7 @@ struct file *io_file_get_fixed(struct io_kiocb *req, int fd,
>  void __io_req_task_work_add(struct io_kiocb *req, unsigned flags);
>  bool io_alloc_async_data(struct io_kiocb *req);
>  void io_req_task_queue(struct io_kiocb *req);
> +void io_tw_queue_iowq(struct io_kiocb *req);
>  void io_req_task_complete(struct io_kiocb *req, struct io_tw_state *ts);
>  void io_req_task_queue_fail(struct io_kiocb *req, int ret);
>  void io_req_task_submit(struct io_kiocb *req, struct io_tw_state *ts);
> diff --git a/io_uring/rw.c b/io_uring/rw.c
> index 3134a6ece1be..4fed829fe97c 100644
> --- a/io_uring/rw.c
> +++ b/io_uring/rw.c
> @@ -455,7 +455,7 @@ static bool __io_complete_rw_common(struct io_kiocb *req, long res)
>  			 * current cycle.
>  			 */
>  			io_req_io_end(req);
> -			req->flags |= REQ_F_REISSUE | REQ_F_BL_NO_RECYCLE;
> +			io_tw_queue_iowq(req);
>  			return true;
>  		}
>  		req_set_fail(req);
> @@ -521,7 +521,7 @@ static void io_complete_rw_iopoll(struct kiocb *kiocb, long res)
>  		io_req_end_write(req);
>  	if (unlikely(res != req->cqe.res)) {
>  		if (res == -EAGAIN && io_rw_should_reissue(req)) {
> -			req->flags |= REQ_F_REISSUE | REQ_F_BL_NO_RECYCLE;
> +			io_tw_queue_iowq(req);
>  			return;
>  		}
>  		req->cqe.res = res;
> @@ -839,7 +839,8 @@ static int __io_read(struct io_kiocb *req, unsigned int issue_flags)
>  	ret = io_iter_do_read(rw, &io->iter);
>  
>  	if (ret == -EAGAIN || (req->flags & REQ_F_REISSUE)) {
> -		req->flags &= ~REQ_F_REISSUE;
> +		if (req->flags & REQ_F_REISSUE)
> +			return IOU_ISSUE_SKIP_COMPLETE;
>  		/* If we can poll, just do that. */
>  		if (io_file_can_poll(req))
>  			return -EAGAIN;
> @@ -1034,10 +1035,8 @@ int io_write(struct io_kiocb *req, unsigned int issue_flags)
>  	else
>  		ret2 = -EINVAL;
>  
> -	if (req->flags & REQ_F_REISSUE) {
> -		req->flags &= ~REQ_F_REISSUE;
> -		ret2 = -EAGAIN;
> -	}
> +	if (req->flags & REQ_F_REISSUE)
> +		return IOU_ISSUE_SKIP_COMPLETE;
>  
>  	/*
>  	 * Raw bdev writes will return -EOPNOTSUPP for IOCB_NOWAIT. Just
> 

With above patch against for-next of block tree, ublksrv 'make test T=generic/005'
can pass now, please feel free to add:

Tested-by: Ming Lei <ming.lei@redhat.com>


Thanks,
Ming

Re: [bug report] WARNING: CPU: 5 PID: 679 at io_uring/io_uring.c:2835 io_ring_exit_work+0x2b6/0x2e0

[Pavel Begunkov]

On 4/16/24 13:51, Jens Axboe wrote:
> On 4/16/24 6:40 AM, Pavel Begunkov wrote:
>> On 4/16/24 13:24, Jens Axboe wrote:
>>> On 4/16/24 6:14 AM, Pavel Begunkov wrote:
>>>> On 4/16/24 12:38, Jens Axboe wrote:
>>>>> On 4/16/24 4:00 AM, Ming Lei wrote:
>>>>>> On Tue, Apr 16, 2024 at 10:26:16AM +0800, Changhui Zhong wrote:
>>>>>>>>>
>>>>>>>>> I can't reproduce this here, fwiw. Ming, something you've seen?
>>>>>>>>
>>>>>>>> I just test against the latest for-next/block(-rc4 based), and still can't
>>>>>>>> reproduce it. There was such RH internal report before, and maybe not
>>>>>>>> ublk related.
>>>>>>>>
>>>>>>>> Changhui, if the issue can be reproduced in your machine, care to share
>>>>>>>> your machine for me to investigate a bit?
>>>>>>>>
>>>>>>>> Thanks,
>>>>>>>> Ming
>>>>>>>>
>>>>>>>
>>>>>>> I still can reproduce this issue on my machine?
>>>>>>> and I shared machine to Ming?he can do more investigation for this issue?
>>>>>>>
>>>>>>> [ 1244.207092] running generic/006
>>>>>>> [ 1246.456896] blk_print_req_error: 77 callbacks suppressed
>>>>>>> [ 1246.456907] I/O error, dev ublkb1, sector 2395864 op 0x1:(WRITE)
>>>>>>> flags 0x8800 phys_seg 1 prio class 0
>>>>>>
>>>>>> The failure is actually triggered in recovering qcow2 target in generic/005,
>>>>>> since ublkb0 isn't removed successfully in generic/005.
>>>>>>
>>>>>> git-bisect shows that the 1st bad commit is cca6571381a0 ("io_uring/rw:
>>>>>> cleanup retry path").
>>>>>>
>>>>>> And not see any issue in uring command side, so the trouble seems
>>>>>> in normal io_uring rw side over XFS file, and not related with block
>>>>>> device.
>>>>>
>>>>> Indeed, I can reproduce it on XFS as well. I'll take a look.
>>>>
>>>> Looking at this patch, that io_rw_should_reissue() path is for when
>>>> we failed via the kiocb callback but came there off of the submission
>>>> path, so when we unwind back it finds the flag, preps and resubmits
>>>> the req. If it's not the case but we still return "true", it'd leaks
>>>> the request, which would explains why exit_work gets stuck.
>>>
>>> Yep, this is what happens. I have a test patch that just punts any
>>> reissue to task_work, it'll insert to iowq from there. Before we would
>>> fail it, even though we didn't have to, but that check was killed and
>>> then it just lingers for this case and it's lost.
>>
>> Sounds good, but let me note that while unwinding, block/fs/etc
>> could try to revert the iter, so it might not be safe to initiate
>> async IO from the callback as is
> 
> Good point, we may just want to do the iov iter revert before sending it
> to io-wq for retry. Seems prudent, and can't hurt.

To be more precise, the case I worry about is like this:

{fs,block}_read_iter()          |
-> iter_truncate();             |
-> kiocb->callback();           |
--> restore iter                |
--> queue async IO              |
                                 | start IO async()
                                 | -> or restore iter here
                                 | -> iter_truncate() / etc.
-> iter_reexpand() // unwind    |

At the iter_reexpand(), it's already re-initialised, and
re-expanding it would likely corrupt it.

-- 
Pavel Begunkov