On Wed, Oct 27, 2021 at 11:48 PM Jens Axboe <axboe@xxxxxxxxx> wrote: > > On 10/26/21 11:45 PM, Yi Zhang wrote: > > Bisecting shows it was introduced from below commit: > > > > commit 2ff0682da6e09c1e0db63a2d2abcd4efb531c8db > > Author: Jens Axboe <axboe@xxxxxxxxx> > > Date: Fri Oct 15 09:44:38 2021 -0600 > > > > block: store elevator state in request > > > > Add an rq private RQF_ELV flag, which tells the block layer that this > > request was initialized on a queue that has an IO scheduler attached. > > This allows for faster checking in the fast path, rather than having to > > deference rq->q later on. > > > > Elevator switching does full quiesce of the queue before detaching an > > IO scheduler, so it's safe to cache this in the request itself. > > > > > > > > Here is another log[2] triggered by scsi-debug fio tests[1] > > [1] > > https://gitlab.com/cki-project/kernel-tests/-/blob/main/storage/block/fs_fio/runtest.sh > > [2] > > [ 1112.348295] scsi_debug:sdebug_driver_probe: scsi_debug: trim > > poll_queues to 0. poll_q/nr_hw = (0/1) > > [ 1112.348339] scsi host1: scsi_debug: version 0190 [20200710] > > dev_size_mb=6144, opts=0x0, submit_queues=1, statistics=0 > > [ 1112.349234] scsi 1:0:0:0: Direct-Access Linux scsi_debug > > 0190 PQ: 0 ANSI: 7 > > [ 1112.349580] sd 1:0:0:0: Power-on or device reset occurred > > [ 1112.349637] sd 1:0:0:0: Attached scsi generic sg2 type 0 > > [ 1112.369756] sd 1:0:0:0: [sdb] 12582912 512-byte logical blocks: > > (6.44 GB/6.00 GiB) > > [ 1112.379864] sd 1:0:0:0: [sdb] Write Protect is off > > [ 1112.379880] sd 1:0:0:0: [sdb] Mode Sense: 73 00 10 08 > > [ 1112.400332] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: > > enabled, supports DPO and FUA > > [ 1112.430438] sd 1:0:0:0: [sdb] Optimal transfer size 524288 bytes > > [ 1112.793383] sd 1:0:0:0: [sdb] Attached SCSI disk > > [ 1120.056278] HOST:host1 ,DISK:/dev/sdb ,I/O SCHED:mq-deadline ,FSTYPE:ext2 > > [ 1121.916590] EXT4-fs (sdb): mounting ext2 file system using the ext4 subsystem > > [ 1121.959726] EXT4-fs (sdb): mounted filesystem without journal. > > Opts: (null). Quota mode: none. > > [ 1122.174428] hrtimer: interrupt took 8900 ns > > [ 1182.447526] HOST:host1 ,DISK:/dev/sdb ,I/O SCHED:mq-deadline ,FSTYPE:ext3 > > [ 1359.486446] EXT4-fs (sdb): mounting ext3 file system using the ext4 subsystem > > [ 1359.712286] EXT4-fs (sdb): mounted filesystem with ordered data > > mode. Opts: (null). Quota mode: none. > > [ 1420.376102] HOST:host1 ,DISK:/dev/sdb ,I/O SCHED:mq-deadline ,FSTYPE:ext4 > > [ 1421.653574] EXT4-fs (sdb): mounted filesystem with ordered data > > mode. Opts: (null). Quota mode: none. > > [ 1482.381289] HOST:host1 ,DISK:/dev/sdb ,I/O SCHED:mq-deadline ,FSTYPE:xfs > > [ 1483.717398] XFS (sdb): Mounting V5 Filesystem > > [ 1484.082012] XFS (sdb): Ending clean mount > > [ 1484.242791] xfs filesystem being mounted at /mnt/test supports > > timestamps until 2038 (0x7fffffff) > > [ 1544.757546] XFS (sdb): Unmounting Filesystem > > [ 1545.121423] ------------[ cut here ]------------ > > [ 1545.121445] statistics for priority 1: i 67042 m 0 d 67048 c 67038 > > [ 1545.121497] WARNING: CPU: 44 PID: 110967 at block/mq-deadline.c:597 > > dd_exit_sched+0x198/0x1d0 > > [ 1545.121526] Modules linked in: scsi_debug loop rfkill sunrpc at24 > > ses enclosure scsi_transport_sas regmap_i2c joydev i40e ipmi_powernv > > tpm_i2c_nuvoton ofpart ipmi_devintf crct10dif_vpmsum ipmi_msghandler > > opal_prd rtc_opal powernv_flash mtd i2c_opal fuse zram ip_tables xfs > > ast i2c_algo_bit drm_vram_helper drm_kms_helper syscopyarea > > sysfillrect sysimgblt fb_sys_fops cec drm_ttm_helper ttm drm > > vmx_crypto crc32c_vpmsum i2c_core aacraid drm_panel_orientation_quirks > > [last unloaded: nvme_core] > > [ 1545.121668] CPU: 44 PID: 110967 Comm: bash Tainted: G W > > 5.15.0-rc6 #1 > > [ 1545.121687] NIP: c000000000973ab8 LR: c000000000973ab4 CTR: c0000000000cd680 > > [ 1545.121705] REGS: c00000005a92f720 TRAP: 0700 Tainted: G W > > (5.15.0-rc6) > > [ 1545.121723] MSR: 900000000282b033 > > <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE> CR: 48428282 XER: 20040006 > > [ 1545.121759] CFAR: c000000000152b34 IRQMASK: 0 > > GPR00: c000000000973ab4 c00000005a92f9c0 > > c0000000028a9a00 0000000000000036 > > GPR04: 00000000ffff7fff c00000005a92f678 > > c00000005a92f670 0000000000000027 > > GPR08: 0000000000000001 c0000007fed87f90 > > 0000000000000023 0000000000000001 > > GPR12: 0000000028428282 c0000007fffafe00 > > 0000000000000000 0000000000000000 > > GPR16: 0000000131fb87b8 0000000131fb94d4 > > 0000000020000000 0000000131ecae80 > > GPR20: c00020002178f0bc 00000000000105e2 > > 00000000000105de 0000000000000001 > > GPR24: c00000000152b4a8 0000000000000000 > > c0000000027e2094 0000000000000000 > > GPR28: c00020002178f148 c00020002178f000 > > 0000000000000001 c00020002178f080 > > [ 1545.121919] NIP [c000000000973ab8] dd_exit_sched+0x198/0x1d0 > > [ 1545.121937] LR [c000000000973ab4] dd_exit_sched+0x194/0x1d0 > > [ 1545.121953] Call Trace: > > [ 1545.121961] [c00000005a92f9c0] [c000000000973ab4] > > dd_exit_sched+0x194/0x1d0 (unreliable) > > [ 1545.121983] [c00000005a92fa80] [c000000000947628] > > blk_mq_exit_sched+0xe8/0x120 > > [ 1545.122005] [c00000005a92fad0] [c000000000925504] > > elevator_switch_mq+0x84/0x210 > > [ 1545.122026] [c00000005a92fb50] [c000000000925d8c] > > elv_iosched_store+0x47c/0x5d0 > > [ 1545.122046] [c00000005a92fbb0] [c00000000092ce78] queue_attr_store+0x78/0xc0 > > [ 1545.122068] [c00000005a92fc00] [c000000000644a44] sysfs_kf_write+0x64/0x80 > > [ 1545.122087] [c00000005a92fc20] [c000000000643f0c] > > kernfs_fop_write_iter+0x1bc/0x2b0 > > [ 1545.122107] [c00000005a92fc70] [c000000000521494] new_sync_write+0x124/0x1b0 > > [ 1545.122129] [c00000005a92fd10] [c000000000524794] vfs_write+0x2c4/0x390 > > [ 1545.122148] [c00000005a92fd60] [c000000000524b08] ksys_write+0x78/0x130 > > [ 1545.122166] [c00000005a92fdb0] [c00000000002d648] > > system_call_exception+0x188/0x360 > > [ 1545.122189] [c00000005a92fe10] [c00000000000c1e8] > > system_call_vectored_common+0xe8/0x278 > > [ 1545.122212] --- interrupt: 3000 at 0x7fff8982fee4 > > [ 1545.122226] NIP: 00007fff8982fee4 LR: 0000000000000000 CTR: 0000000000000000 > > [ 1545.122243] REGS: c00000005a92fe80 TRAP: 3000 Tainted: G W > > (5.15.0-rc6) > > [ 1545.122261] MSR: 900000000280f033 > > <SF,HV,VEC,VSX,EE,PR,FP,ME,IR,DR,RI,LE> CR: 48422488 XER: 00000000 > > [ 1545.122296] IRQMASK: 0 > > GPR00: 0000000000000004 00007fffca9f8230 > > 00007fff89927000 0000000000000001 > > GPR04: 00000001719f58b0 0000000000000006 > > 0000000000000010 0000000171ce2863 > > GPR08: 0000000000000000 0000000000000000 > > 0000000000000000 0000000000000000 > > GPR12: 0000000000000000 00007fff89a6afa0 > > 0000000000000000 0000000000000000 > > GPR16: 0000000131fb87b8 0000000131fb94d4 > > 0000000020000000 0000000131ecae80 > > GPR20: 0000000000000000 00007fffca9f8454 > > 0000000131f63128 0000000131fb89bc > > GPR24: 0000000131fb8a50 0000000000000000 > > 00000001719f58b0 0000000000000006 > > GPR28: 0000000000000006 00007fff899216d8 > > 00000001719f58b0 0000000000000006 > > [ 1545.124405] NIP [00007fff8982fee4] 0x7fff8982fee4 > > [ 1545.128567] LR [0000000000000000] 0x0 > > [ 1545.132725] --- interrupt: 3000 > > [ 1545.135501] Instruction dump: > > [ 1545.138275] 2c090000 4082ff7c 9afa0000 81140000 80ff0038 80df0034 > > 80bf0030 7d0807b4 > > [ 1545.146594] 7fc4f378 7f03c378 4b7df01d 60000000 <0fe00000> 60420000 > > 0fe00000 60000000 > > [ 1545.154914] ---[ end trace a32220e1437afcc2 ]--- > > What kernel are you running? The linux-block/for-next, and it still can be reproduced with the latest update: 8cfa4097726f (HEAD -> for-next, origin/for-next) Merge branch 'for-5.16/block' into for-next > > > -- > Jens Axboe > -- Best Regards, Yi Zhang
