Re: [PATCH 4/5] block: move queue enter logic into blk_mq_submit_bio()

From: Michael Schmitz
Date: Sat Nov 13 2021 - 17:11:42 EST


Hi Geert, Martin,

On 12/11/21 20:37, Geert Uytterhoeven wrote:
Hi Michael,

On Thu, Nov 11, 2021 at 10:35 PM Michael Schmitz <schmitzmic@xxxxxxxxx> wrote:
how easy is that to reproduce?

Fairly easy: it happens either on mounting, or after a few seconds booting
into my old Debian userspace.

sd_setup_read_write_cmnd() does not validate the request's FUA flag
against sdkp->DPOFUA (not suggesting that it should ...). I'd like to
try and trace when such a mismatch happens.

Thanks!

Also happens with the pata-falcon driver (which stats it doesnt support DPO or FUA).

Seen twice, once on boot, once on reboot (FUA bit not set in the SCSI command descriptor when the disk doesn't support that, to avoid a panic, otherwise still 5833291ab6de). Each time when a remount operation happens:

EXT4-fs (sda1): re-mounted. Opts: . Quota mode: disabled.
------------[ cut here ]------------
WARNING: CPU: 0 PID: 695 at drivers/scsi/sd.c:1271 sd_init_command+0x6aa/0x886
Modules linked in:
CPU: 0 PID: 695 Comm: mount Not tainted 5.15.0-atari-fpuemu-clean-signalfixes-remove-set_fs-ataflopfix4+ #88
Stack from 00be1c10:
00be1c10 0035cc02 0035cc02 002cac7a 00379b57 000004f7 00000009 00ad80a4
002cacd4 00379b57 000004f7 0020ac5e 00000009 00000000 00000000 00209d00
00000008 00000000 00000001 00000000 00000001 00ab6400 0020ac5e 00379b57
000004f7 00000009 00000000 00adc800 00add9d0 00ab6400 00000001 001269c4
00003a98 00ad8000 00adc800 00ad80a4 00ab6400 00adc800 00000008 00020801
00000000 00000008 00000000 00000001 00000001 00201876 00ad80a4 00ad80a4
Call Trace: [<002cac7a>] __warn+0x9e/0xb6
[<002cacd4>] warn_slowpath_fmt+0x42/0x62
[<0020ac5e>] sd_init_command+0x6aa/0x886
[<00209d00>] max_write_same_blocks_store+0x6c/0x88
[<0020ac5e>] sd_init_command+0x6aa/0x886
[<001269c4>] ext4_get_group_desc+0x0/0xb0
[<00003a98>] setup_frame+0xba/0x20a
[<00020801>] _I_CALL_TOP+0xf21/0x1900
[<00201876>] scsi_queue_rq+0x4f8/0x67e
[<00194aaa>] __blk_mq_try_issue_directly+0x8a/0xf8
[<00194adc>] __blk_mq_try_issue_directly+0xbc/0xf8
[<00194fd0>] blk_mq_try_issue_directly+0x28/0x7a
[<0019584c>] blk_mq_submit_bio+0x3fc/0x422
[<0018c6f6>] __submit_bio+0x0/0x78
[<0018b5cc>] bio_list_pop+0x0/0x1a
[<00092800>] btf_check_type_match+0x274/0x2e4
[<00020801>] _I_CALL_TOP+0xf21/0x1900
[<00002000>] _start+0x0/0x8
[<0018c7dc>] submit_bio_noacct+0x6e/0x152
[<00020801>] _I_CALL_TOP+0xf21/0x1900
[<000f21fc>] test_bit+0x0/0x12
[<00051f68>] ktime_get_real_seconds+0x0/0x30
[<000f21fc>] test_bit+0x0/0x12
[<00051f68>] ktime_get_real_seconds+0x0/0x30
[<000f329c>] submit_bh_wbc.isra.54+0x178/0x182
[<000f21fc>] test_bit+0x0/0x12
[<000f32b8>] submit_bh+0x12/0x18
[<00020800>] _I_CALL_TOP+0xf20/0x1900
[<000f362e>] __sync_dirty_buffer+0x78/0xaa
[<00020800>] _I_CALL_TOP+0xf20/0x1900
[<00158684>] test_bit+0x0/0x12
[<0015a508>] ext4_commit_super+0xa8/0xf8
[<00020800>] _I_CALL_TOP+0xf20/0x1900
[<0015be82>] ext4_setup_super+0x132/0x1ac
[<0015c970>] ext4_remount+0x49c/0x57e
[<00004003>] do_rt_sigreturn+0xe1/0x1b8
[<000dbe3e>] dentry_lru_isolate_shrink+0x0/0x1c
[<000efaf0>] legacy_reconfigure+0x30/0x42
[<000ce664>] reconfigure_super+0xae/0x178
[<000e4a38>] path_mount+0x274/0x61c
[<000e4e20>] do_mount+0x40/0x5c
[<000e50c4>] sys_mount+0xf8/0x10e
[<00002922>] syscall+0x8/0xc
[<0018c00c>] blk_cleanup_queue+0x5a/0xc6

---[ end trace b0cd975622ec08c4 ]---
EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro. Quota mode: disabled.
ext4 filesystem being remounted at / supports timestamps until 2038 (0x7fffffff)

------------[ cut here ]------------
WARNING: CPU: 0 PID: 1174 at drivers/scsi/sd.c:1271 sd_init_command+0x6aa/0x886
Modules linked in:
CPU: 0 PID: 1174 Comm: umount Tainted: G W 5.15.0-atari-fpuemu-clean-signalfixes-remove-set_fs-ataflopfix4+ #88
Stack from 00b6dc70:
00b6dc70 0035cc02 0035cc02 002cac7a 00379b57 000004f7 00000009 00ad80a4
002cacd4 00379b57 000004f7 0020ac5e 00000009 00000000 00000000 00209d00
00000008 00000000 00000001 00000000 00000001 00ab6400 0020ac5e 00379b57
000004f7 00000009 00000000 00adc800 00add9d0 00ab6400 00000001 00000000
00003a98 00ad8000 00adc800 00ad80a4 00ab6400 00adc800 00000008 00023801
00000000 00000008 00000000 00000001 00000001 00201876 00ad80a4 00ad80a4
Call Trace: [<002cac7a>] __warn+0x9e/0xb6
[<002cacd4>] warn_slowpath_fmt+0x42/0x62
[<0020ac5e>] sd_init_command+0x6aa/0x886
[<00209d00>] max_write_same_blocks_store+0x6c/0x88
[<0020ac5e>] sd_init_command+0x6aa/0x886
[<00003a98>] setup_frame+0xba/0x20a
[<00023801>] fp_fadd+0x1d5/0x1e4
[<00201876>] scsi_queue_rq+0x4f8/0x67e
[<00194aaa>] __blk_mq_try_issue_directly+0x8a/0xf8
[<00194adc>] __blk_mq_try_issue_directly+0xbc/0xf8
[<00194fd0>] blk_mq_try_issue_directly+0x28/0x7a
[<0019584c>] blk_mq_submit_bio+0x3fc/0x422
[<0018c6f6>] __submit_bio+0x0/0x78
[<0018b5cc>] bio_list_pop+0x0/0x1a
[<00092800>] btf_check_type_match+0x274/0x2e4
[<00023801>] fp_fadd+0x1d5/0x1e4
[<00002000>] _start+0x0/0x8
[<0018c7dc>] submit_bio_noacct+0x6e/0x152
[<00023801>] fp_fadd+0x1d5/0x1e4
[<000f21fc>] test_bit+0x0/0x12
[<000f21fc>] test_bit+0x0/0x12
[<000f329c>] submit_bh_wbc.isra.54+0x178/0x182
[<00158684>] test_bit+0x0/0x12
[<000f21fc>] test_bit+0x0/0x12
[<000f32b8>] submit_bh+0x12/0x18
[<00020800>] _I_CALL_TOP+0xf20/0x1900
[<000f362e>] __sync_dirty_buffer+0x78/0xaa
[<00020800>] _I_CALL_TOP+0xf20/0x1900
[<00158684>] test_bit+0x0/0x12
[<00158684>] test_bit+0x0/0x12
[<0015a508>] ext4_commit_super+0xa8/0xf8
[<00020800>] _I_CALL_TOP+0xf20/0x1900
[<00158684>] test_bit+0x0/0x12
[<0015c80e>] ext4_remount+0x33a/0x57e
[<00004003>] do_rt_sigreturn+0xe1/0x1b8
[<000dbe3e>] dentry_lru_isolate_shrink+0x0/0x1c
[<000efaf0>] legacy_reconfigure+0x30/0x42
[<000ce664>] reconfigure_super+0xae/0x178
[<000e3ab0>] path_umount+0x17c/0x2e8
[<000e3c62>] ksys_umount+0x46/0x54
[<000e3c8a>] sys_oldumount+0xa/0xe
[<00002922>] syscall+0x8/0xc
[<0018c00c>] blk_cleanup_queue+0x5a/0xc6

---[ end trace b0cd975622ec08c5 ]---
EXT4-fs (sda1): re-mounted. Opts: (null). Quota mode: disabled.
EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro. Quota mode: disabled.

Not sure this helps much.

Cheers,

Michael


On 12/11/21 03:48, Geert Uytterhoeven wrote:
On Thu, Nov 11, 2021 at 2:19 PM Martin K. Petersen
<martin.petersen@xxxxxxxxxx> wrote:
sd 0:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=0s
sd 0:0:0:0: [sda] tag#0 Sense Key : Illegal Request [current]
sd 0:0:0:0: [sda] tag#0 Add. Sense: Invalid field in cdb
sd 0:0:0:0: [sda] tag#0 CDB: Write(10) 2a 08 00 00 00 01 00 00 08 00
critical target error, dev sda, sector 1 op 0x1:(WRITE) flags 0x20800 phys_seg 1 prio class 0
Buffer I/O error on dev sda1, logical block 0, lost sync page write

Peculiar. That write command looks OK to me. I wonder if it's the FUA
bit that trips it?

What does:

# dmesg | grep FUA

say?

sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't
support DPO or FUA

Gr{oetje,eeting}s,

Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@xxxxxxxxxxxxxx

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
-- Linus Torvalds