[bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Yi Zhang]

Hello

The following WARNING was triggered by blktests nvme/fc nvme/012,
please help check and let me know if you need any info/test, thanks.

commit: linux-block: 38f4878b9463 (HEAD, origin/for-next) Merge branch
'block-6.16' into for-next

[ 2679.835074] run blktests nvme/012 at 2025-06-05 19:50:45
[ 2681.492049] loop0: detected capacity change from 0 to 2097152
[ 2681.678145] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
[ 2682.883261] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 2682.895317] (NULL device *): {0:0} Association created
[ 2682.902895] nvmet: Created nvm controller 1 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 2682.970869] nvme nvme0: NVME-FC{0}: controller connect complete
[ 2682.970996] nvme nvme0: NVME-FC{0}: new ctrl: NQN
"blktests-subsystem-1", hostnqn:
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349
[ 2685.498124] XFS (nvme0n1): Mounting V5 Filesystem
3f19217c-d3fd-42af-9dbe-aa5dce6bb607
[ 2685.567936] XFS (nvme0n1): Ending clean mount
[ 2746.161840] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 0 fctype 1
(I/O Cmd) w10/11: x00000000/x00000000
[ 2746.163061] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0010007a/x00000000
[ 2746.163126] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001000ba/x00000000
[ 2746.163175] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001000fa/x00000000
[ 2746.163220] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0010013a/x00000000
[ 2746.163265] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0010017a/x00000000
[ 2746.163308] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001001ba/x00000000
[ 2746.163352] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001001fa/x00000000
[ 2746.163396] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001d8618/x00000000
[ 2746.163441] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000d9d88/x00000000
[ 2746.163486] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00014be0/x00000000
[ 2746.163531] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001bb168/x00000000
[ 2746.163585] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0006b620/x00000000
[ 2746.163639] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000b6688/x00000000
[ 2746.164885] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000581c0/x00000000
[ 2746.166593] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001468c0/x00000000
[ 2746.166681] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00080780/x00000000
[ 2746.166732] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00147338/x00000000
[ 2746.166780] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000acee8/x00000000
[ 2746.166826] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00016e20/x00000000
[ 2746.166872] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0019add0/x00000000
[ 2746.166916] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001bdab8/x00000000
[ 2746.166960] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000ea0f8/x00000000
[ 2746.167005] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00006328/x00000000
[ 2746.170320] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 2746.173629] nvme nvme0: NVME-FC{0}: resetting controller
[ 2746.175966] block nvme0n1: no usable path - requeuing I/O
[ 2746.177234] block nvme0n1: no usable path - requeuing I/O
[ 2746.177571] block nvme0n1: no usable path - requeuing I/O
[ 2746.177916] block nvme0n1: no usable path - requeuing I/O
[ 2746.178228] block nvme0n1: no usable path - requeuing I/O
[ 2746.178576] block nvme0n1: no usable path - requeuing I/O
[ 2746.179173] block nvme0n1: no usable path - requeuing I/O
[ 2746.179476] block nvme0n1: no usable path - requeuing I/O
[ 2746.179807] block nvme0n1: no usable path - requeuing I/O
[ 2746.180146] block nvme0n1: no usable path - requeuing I/O
[ 2746.232899] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 2746.238446] (NULL device *): {0:1} Association created
[ 2746.239620] nvmet: Created nvm controller 2 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 2746.259174] (NULL device *): {0:0} Association deleted
[ 2746.296717] nvme nvme0: NVME-FC{0}: controller connect complete
[ 2755.870750] nvmet: ctrl 1 keep-alive timer (5 seconds) expired!
[ 2755.873263] nvmet: ctrl 1 fatal error occurred!
[ 2769.422990] (NULL device *): Disconnect LS failed: No Association
[ 2769.424288] (NULL device *): {0:0} Association freed
[ 2801.582208] perf: interrupt took too long (2527 > 2500), lowering
kernel.perf_event_max_sample_rate to 79000
[ 2830.657742] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000a06a8/x00000000
[ 2830.657865] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000994d0/x00000000
[ 2830.657916] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000263b8/x00000000
[ 2830.657965] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000ecf10/x00000000
[ 2830.658010] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00054418/x00000000
[ 2830.658071] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001f42f0/x00000000
[ 2830.658088] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 2830.658119] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000bb588/x00000000
[ 2830.659087] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000fd620/x00000000
[ 2830.659134] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000d66b0/x00000000
[ 2830.659189] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00188488/x00000000
[ 2830.659233] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00086fd0/x00000000
[ 2830.659276] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001a0950/x00000000
[ 2830.659345] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00136340/x00000000
[ 2830.659390] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0013dc60/x00000000
[ 2830.659433] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00193530/x00000000
[ 2830.659500] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001d3ff0/x00000000
[ 2830.659545] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00101455/x00000000
[ 2830.659589] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00101495/x00000000
[ 2830.659650] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001014d5/x00000000
[ 2830.659758] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00101515/x00000000
[ 2830.659842] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00101555/x00000000
[ 2830.659889] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00101595/x00000000
[ 2830.659904] nvme nvme0: NVME-FC{0}: resetting controller
[ 2830.659941] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001015d5/x00000000
[ 2830.660321] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 0 fctype 1
(I/O Cmd) w10/11: x00000000/x00000000
[ 2830.660348] nvme_ns_head_submit_bio: 81 callbacks suppressed
[ 2830.660362] block nvme0n1: no usable path - requeuing I/O
[ 2830.661765] block nvme0n1: no usable path - requeuing I/O
[ 2830.662070] block nvme0n1: no usable path - requeuing I/O
[ 2830.662367] block nvme0n1: no usable path - requeuing I/O
[ 2830.662660] block nvme0n1: no usable path - requeuing I/O
[ 2830.663046] block nvme0n1: no usable path - requeuing I/O
[ 2830.663337] block nvme0n1: no usable path - requeuing I/O
[ 2830.663627] block nvme0n1: no usable path - requeuing I/O
[ 2830.663976] block nvme0n1: no usable path - requeuing I/O
[ 2830.664288] block nvme0n1: no usable path - requeuing I/O
[ 2830.700704] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 2830.706376] (NULL device *): {0:0} Association created
[ 2830.707571] nvmet: Created nvm controller 1 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 2830.725113] (NULL device *): {0:1} Association deleted
[ 2830.745872] ------------[ cut here ]------------
[ 2830.746780] WARNING: CPU: 49 PID: 1020 at block/genhd.c:146
bdev_count_inflight_rw+0x2a6/0x410
[ 2830.747730] Modules linked in: nvme_fcloop nvmet_fc nvmet nvme_fc
nvme_fabrics nvme_core nvme_keyring nvme_auth rfkill sunrpc
intel_rapl_msr intel_rapl_common intel_uncore_frequency
intel_uncore_frequency_common sb_edac x86_pkg_temp_thermal
intel_powerclamp coretemp kvm_intel vfat
[ 2830.748536] nvme nvme0: NVME-FC{0}: controller connect complete
[ 2830.749958]  fat kvm irqbypass iTCO_wdt rapl iTCO_vendor_support
intel_cstate intel_uncore pcspkr bnx2x mgag200 i2c_i801 tg3 i2c_smbus
lpc_ich i2c_algo_bit hpilo ioatdma mdio dca ipmi_ssif ipmi_si acpi_tad
acpi_power_meter acpi_ipmi ipmi_devintf ipmi_msghandler dax_pmem sg
fuse loop nfnetlink xfs nd_pmem sr_mod sd_mod cdrom
ghash_clmulni_intel hpsa scsi_transport_sas hpwdt ahci libahci libata
wmi nfit libnvdimm dm_mirror dm_region_hash dm_log dm_mod [last
unloaded: nvmet]
[ 2830.752807] CPU: 49 UID: 0 PID: 1020 Comm: kworker/49:1H Not
tainted 6.15.0+ #2 PREEMPT(lazy)
[ 2830.753650] Hardware name: HP ProLiant DL380 Gen9/ProLiant DL380
Gen9, BIOS P89 10/05/2016
[ 2830.754291] Workqueue: kblockd nvme_requeue_work [nvme_core]
[ 2830.755188] RIP: 0010:bdev_count_inflight_rw+0x2a6/0x410
[ 2830.755503] Code: fa 48 c1 ea 03 0f b6 14 02 4c 89 f8 83 e0 07 83
c0 03 38 d0 7c 08 84 d2 0f 85 59 01 00 00 41 c7 07 00 00 00 00 e9 75
ff ff ff <0f> 0b 48 b8 00 00 00 00 00 fc ff df 4c 89 f2 48 c1 ea 03 0f
b6 14
[ 2830.756887] RSP: 0018:ffffc9000ad973e8 EFLAGS: 00010286
[ 2830.757221] RAX: 00000000ffffffff RBX: 0000000000000048 RCX: ffffffffa9b9ee56
[ 2830.758007] RDX: 0000000000000000 RSI: 0000000000000048 RDI: ffffffffac36b380
[ 2830.758831] RBP: ffffe8ffffa33758 R08: 0000000000000000 R09: fffff91ffff466fd
[ 2830.759609] R10: ffffe8ffffa337ef R11: 0000000000000001 R12: ffff888121d16200
[ 2830.760405] R13: dffffc0000000000 R14: ffffc9000ad97474 R15: ffffc9000ad97470
[ 2830.761226] FS:  0000000000000000(0000) GS:ffff888440550000(0000)
knlGS:0000000000000000
[ 2830.761724] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2830.762472] CR2: 000055aa8905b038 CR3: 0000000bfae7a001 CR4: 00000000003726f0
[ 2830.763293] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 2830.764124] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 2830.764921] Call Trace:
[ 2830.765087]  <TASK>
[ 2830.765625]  bdev_count_inflight+0x6d/0xa0
[ 2830.765921]  ? __pfx_bdev_count_inflight+0x10/0x10
[ 2830.766604]  update_io_ticks+0x1bd/0x210
[ 2830.789758]  ? __pfx_update_io_ticks+0x10/0x10
[ 2830.823941]  ? nvme_fc_map_data+0x1d0/0x860 [nvme_fc]
[ 2830.861999]  bdev_start_io_acct+0x31/0xe0
[ 2830.893416]  nvme_mpath_start_request+0x222/0x390 [nvme_core]
[ 2830.934768]  nvme_fc_start_fcp_op+0xc4c/0xfe0 [nvme_fc]
[ 2830.973158]  ? trace_nvme_setup_cmd+0x149/0x1b0 [nvme_core]
[ 2831.011196]  ? __pfx_nvme_fc_start_fcp_op+0x10/0x10 [nvme_fc]
[ 2831.050102]  ? nvme_fc_queue_rq+0x1b6/0x4c0 [nvme_fc]
[ 2831.085274]  __blk_mq_issue_directly+0xe1/0x1c0
[ 2831.117939]  ? __pfx___blk_mq_issue_directly+0x10/0x10
[ 2831.153586]  ? blk_mq_request_issue_directly+0xc6/0x190
[ 2831.189705]  blk_mq_issue_direct+0x16b/0x690
[ 2831.220964]  ? lock_acquire+0x10b/0x150
[ 2831.249564]  blk_mq_dispatch_queue_requests+0x31c/0x640
[ 2831.267274]  blk_mq_flush_plug_list+0x187/0x6a0
[ 2831.267940]  ? trace_block_plug+0x15e/0x1e0
[ 2831.268164]  ? blk_add_rq_to_plug+0x2cf/0x460
[ 2831.268799]  ? rcu_is_watching+0x15/0xb0
[ 2831.269033]  ? __pfx_blk_mq_flush_plug_list+0x10/0x10
[ 2831.269316]  ? blk_mq_submit_bio+0x10cc/0x1bc0
[ 2831.269969]  __blk_flush_plug+0x27b/0x4d0
[ 2831.270200]  ? find_held_lock+0x32/0x90
[ 2831.270426]  ? __pfx___blk_flush_plug+0x10/0x10
[ 2831.271079]  ? percpu_ref_put_many.constprop.0+0x7a/0x1b0
[ 2831.271380]  __submit_bio+0x49b/0x600
[ 2831.271594]  ? __pfx___submit_bio+0x10/0x10
[ 2831.271843]  ? raw_spin_rq_lock_nested+0x2e/0x130
[ 2831.272506]  ? __submit_bio_noacct+0x16d/0x5b0
[ 2831.273157]  __submit_bio_noacct+0x16d/0x5b0
[ 2831.273805]  ? find_held_lock+0x32/0x90
[ 2831.274035]  ? local_clock_noinstr+0xd/0xe0
[ 2831.274251]  ? __pfx___submit_bio_noacct+0x10/0x10
[ 2831.274901]  ? ktime_get+0x164/0x200
[ 2831.275127]  ? lockdep_hardirqs_on+0x78/0x100
[ 2831.275777]  ? ktime_get+0xb0/0x200
[ 2831.276382]  submit_bio_noacct_nocheck+0x4e1/0x630
[ 2831.302650]  ? __pfx___might_resched+0x10/0x10
[ 2831.334528]  ? __pfx_submit_bio_noacct_nocheck+0x10/0x10
[ 2831.371424]  ? should_fail_bio+0xb5/0x150
[ 2831.400963]  ? submit_bio_noacct+0x9ba/0x1b30
[ 2831.432384]  nvme_requeue_work+0xa6/0xd0 [nvme_core]
[ 2831.467097]  process_one_work+0xd8b/0x1320
[ 2831.497417]  ? __pfx_process_one_work+0x10/0x10
[ 2831.529776]  ? assign_work+0x16c/0x240
[ 2831.557932]  worker_thread+0x5f3/0xfe0
[ 2831.586080]  ? __kthread_parkme+0xb4/0x200
[ 2831.616411]  ? __pfx_worker_thread+0x10/0x10
[ 2831.647363]  kthread+0x3b4/0x770
[ 2831.672690]  ? local_clock_noinstr+0xd/0xe0
[ 2831.703340]  ? __pfx_kthread+0x10/0x10
[ 2831.732902]  ? __lock_release.isra.0+0x1a4/0x2c0
[ 2831.766864]  ? rcu_is_watching+0x15/0xb0
[ 2831.796921]  ? __pfx_kthread+0x10/0x10
[ 2831.826375]  ret_from_fork+0x393/0x480
[ 2831.855873]  ? __pfx_kthread+0x10/0x10
[ 2831.885038]  ? __pfx_kthread+0x10/0x10
[ 2831.914099]  ret_from_fork_asm+0x1a/0x30
[ 2831.944085]  </TASK>
[ 2831.964399] irq event stamp: 55415
[ 2831.991755] hardirqs last  enabled at (55425): [<ffffffffa8cd533e>]
__up_console_sem+0x5e/0x80
[ 2832.047850] hardirqs last disabled at (55440): [<ffffffffa8cd5323>]
__up_console_sem+0x43/0x80
[ 2832.104417] softirqs last  enabled at (55438): [<ffffffffa8afce0b>]
handle_softirqs+0x62b/0x890
[ 2832.161018] softirqs last disabled at (55459): [<ffffffffa8afd1fd>]
__irq_exit_rcu+0xfd/0x250
[ 2832.216709] ---[ end trace 0000000000000000 ]---
[ 2840.350778] nvmet: ctrl 2 keep-alive timer (5 seconds) expired!
[ 2840.351593] nvmet: ctrl 2 fatal error occurred!
[ 2851.548112] (NULL device *): {0:1} Association freed
[ 2851.548216] (NULL device *): Disconnect LS failed: No Association
[ 2912.554772] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001e2628/x00000000
[ 2912.554869] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001f66b8/x00000000
[ 2912.554920] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001dcbe0/x00000000
[ 2912.554997] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001b3b88/x00000000
[ 2912.555105] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001efe68/x00000000
[ 2912.555121] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 2912.555196] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000f31d0/x00000000
[ 2912.556040] nvme nvme0: NVME-FC{0}: resetting controller
[ 2912.557078] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000c39c8/x00000000
[ 2912.557173] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000998e0/x00000000
[ 2912.557257] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000dd468/x00000000
[ 2912.557304] nvme_ns_head_submit_bio: 66 callbacks suppressed
[ 2912.557321] block nvme0n1: no usable path - requeuing I/O
[ 2912.557348] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00061990/x00000000
[ 2912.558132] block nvme0n1: no usable path - requeuing I/O
[ 2912.558501] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000ee800/x00000000
[ 2912.558732] block nvme0n1: no usable path - requeuing I/O
[ 2912.558755] block nvme0n1: no usable path - requeuing I/O
[ 2912.559093] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0000dff0/x00000000
[ 2912.559310] block nvme0n1: no usable path - requeuing I/O
[ 2912.559374] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000fba20/x00000000
[ 2912.559622] block nvme0n1: no usable path - requeuing I/O
[ 2912.559722] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000ce700/x00000000
[ 2912.559938] block nvme0n1: no usable path - requeuing I/O
[ 2912.559989] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00066cc0/x00000000
[ 2912.560240] block nvme0n1: no usable path - requeuing I/O
[ 2912.560309] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00080e00/x00000000
[ 2912.560543] block nvme0n1: no usable path - requeuing I/O
[ 2912.560603] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00102d93/x00000000
[ 2912.560920] block nvme0n1: no usable path - requeuing I/O
[ 2912.560973] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00102dd3/x00000000
[ 2912.561286] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00102e13/x00000000
[ 2912.561384] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00102e53/x00000000
[ 2912.561489] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00102e93/x00000000
[ 2912.561573] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 0 fctype 1
(I/O Cmd) w10/11: x00000000/x00000000
[ 2912.590374] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 2912.595940] (NULL device *): {0:1} Association created
[ 2912.597107] nvmet: Created nvm controller 2 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 2912.623269] (NULL device *): {0:0} Association deleted
[ 2912.636244] nvme nvme0: NVME-FC{0}: controller connect complete
[ 2919.293060] perf: interrupt took too long (3266 > 3158), lowering
kernel.perf_event_max_sample_rate to 61000
[ 2922.270774] nvmet: ctrl 1 keep-alive timer (5 seconds) expired!
[ 2922.271738] nvmet: ctrl 1 fatal error occurred!
[ 2934.302272] (NULL device *): {0:0} Association freed
[ 2934.302378] (NULL device *): Disconnect LS failed: No Association
[ 2995.509865] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 0 fctype 1
(I/O Cmd) w10/11: x00000000/x00000000
[ 2995.509964] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00104d98/x00000000
[ 2995.510013] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00104dd8/x00000000
[ 2995.510062] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00104e18/x00000000
[ 2995.510108] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0019b148/x00000000
[ 2995.510154] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000e1688/x00000000
[ 2995.510213] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001941f8/x00000000
[ 2995.510243] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 2995.510264] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00057bd8/x00000000
[ 2995.511324] nvme nvme0: NVME-FC{0}: resetting controller
[ 2995.511353] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001d6a18/x00000000
[ 2995.511672] nvme_ns_head_submit_bio: 137 callbacks suppressed
[ 2995.511736] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001c8c50/x00000000
[ 2995.512440] block nvme0n1: no usable path - requeuing I/O
[ 2995.512453] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001f8ae8/x00000000
[ 2995.512809] block nvme0n1: no usable path - requeuing I/O
[ 2995.512829] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00185638/x00000000
[ 2995.513122] block nvme0n1: no usable path - requeuing I/O
[ 2995.513152] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000be958/x00000000
[ 2995.513426] block nvme0n1: no usable path - requeuing I/O
[ 2995.513456] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00072188/x00000000
[ 2995.513766] block nvme0n1: no usable path - requeuing I/O
[ 2995.513797] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0006cfa0/x00000000
[ 2995.514076] block nvme0n1: no usable path - requeuing I/O
[ 2995.514101] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001b8d68/x00000000
[ 2995.514368] block nvme0n1: no usable path - requeuing I/O
[ 2995.514399] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000bbf70/x00000000
[ 2995.514648] block nvme0n1: no usable path - requeuing I/O
[ 2995.514679] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00049d80/x00000000
[ 2995.514990] block nvme0n1: no usable path - requeuing I/O
[ 2995.515005] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001ab7b8/x00000000
[ 2995.515291] block nvme0n1: no usable path - requeuing I/O
[ 2995.515323] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000aa258/x00000000
[ 2995.581458] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 2995.587043] (NULL device *): {0:0} Association created
[ 2995.588238] nvmet: Created nvm controller 1 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 2995.598095] (NULL device *): {0:1} Association deleted
[ 2995.629543] nvme nvme0: NVME-FC{0}: controller connect complete
[ 3006.238795] nvmet: ctrl 2 keep-alive timer (5 seconds) expired!
[ 3006.239676] nvmet: ctrl 2 fatal error occurred!
[ 3016.812134] (NULL device *): {0:1} Association freed
[ 3016.812234] (NULL device *): Disconnect LS failed: No Association
[ 3077.954779] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 0 fctype 1
(I/O Cmd) w10/11: x00000000/x00000000
[ 3077.954930] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00107368/x00000000
[ 3077.956502] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 3077.956501] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001073a8/x00000000
[ 3077.957556] nvme nvme0: NVME-FC{0}: resetting controller
[ 3077.957592] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001d98b8/x00000000
[ 3077.957995] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00013600/x00000000
[ 3077.958084] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000111f0/x00000000
[ 3077.958143] nvme_ns_head_submit_bio: 50 callbacks suppressed
[ 3077.958159] block nvme0n1: no usable path - requeuing I/O
[ 3077.958182] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000bae28/x00000000
[ 3077.959136] block nvme0n1: no usable path - requeuing I/O
[ 3077.959529] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001d8c98/x00000000
[ 3077.959764] block nvme0n1: no usable path - requeuing I/O
[ 3077.959837] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0008cf40/x00000000
[ 3077.960077] block nvme0n1: no usable path - requeuing I/O
[ 3077.960143] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001d3578/x00000000
[ 3077.960453] block nvme0n1: no usable path - requeuing I/O
[ 3077.960518] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00064990/x00000000
[ 3077.960773] block nvme0n1: no usable path - requeuing I/O
[ 3077.960853] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000b4710/x00000000
[ 3077.961078] block nvme0n1: no usable path - requeuing I/O
[ 3077.961139] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00085db8/x00000000
[ 3077.961368] block nvme0n1: no usable path - requeuing I/O
[ 3077.961435] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00069120/x00000000
[ 3077.961655] block nvme0n1: no usable path - requeuing I/O
[ 3077.961753] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0013bf18/x00000000
[ 3077.961974] block nvme0n1: no usable path - requeuing I/O
[ 3077.962012] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0014fa40/x00000000
[ 3077.962334] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000521c8/x00000000
[ 3077.962423] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00015478/x00000000
[ 3077.962519] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00006610/x00000000
[ 3078.007378] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 3078.013515] (NULL device *): {0:1} Association created
[ 3078.014685] nvmet: Created nvm controller 2 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 3078.023212] (NULL device *): {0:0} Association deleted
[ 3078.054495] nvme nvme0: NVME-FC{0}: controller connect complete
[ 3087.646802] nvmet: ctrl 1 keep-alive timer (5 seconds) expired!
[ 3087.647785] nvmet: ctrl 1 fatal error occurred!
[ 3100.716095] (NULL device *): {0:0} Association freed
[ 3100.716200] (NULL device *): Disconnect LS failed: No Association
[ 3161.908938] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001f2700/x00000000
[ 3161.909035] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00037618/x00000000
[ 3161.909088] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001df730/x00000000
[ 3161.909137] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000bca30/x00000000
[ 3161.909200] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001e35c8/x00000000
[ 3161.909245] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001bd010/x00000000
[ 3161.909299] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00127fb0/x00000000
[ 3161.909334] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 3161.909350] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0016d498/x00000000
[ 3161.909418] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0008a318/x00000000
[ 3161.910296] nvme nvme0: NVME-FC{0}: resetting controller
[ 3161.910498] nvme_ns_head_submit_bio: 84 callbacks suppressed
[ 3161.910520] block nvme0n1: no usable path - requeuing I/O
[ 3161.910760] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000b5568/x00000000
[ 3161.911637] block nvme0n1: no usable path - requeuing I/O
[ 3161.911940] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001cb018/x00000000
[ 3161.912197] block nvme0n1: no usable path - requeuing I/O
[ 3161.912224] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001babe0/x00000000
[ 3161.912541] block nvme0n1: no usable path - requeuing I/O
[ 3161.912562] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000fad88/x00000000
[ 3161.912874] block nvme0n1: no usable path - requeuing I/O
[ 3161.912902] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00188490/x00000000
[ 3161.913200] block nvme0n1: no usable path - requeuing I/O
[ 3161.913229] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000d5000/x00000000
[ 3161.913530] block nvme0n1: no usable path - requeuing I/O
[ 3161.913559] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000c6df8/x00000000
[ 3161.913850] block nvme0n1: no usable path - requeuing I/O
[ 3161.913927] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 0 fctype 1
(I/O Cmd) w10/11: x00000000/x00000000
[ 3161.914195] block nvme0n1: no usable path - requeuing I/O
[ 3161.914232] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00109ad8/x00000000
[ 3161.914675] block nvme0n1: no usable path - requeuing I/O
[ 3161.914696] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00109b18/x00000000
[ 3161.915023] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00109b58/x00000000
[ 3161.915068] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00109b98/x00000000
[ 3161.915112] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00109bd8/x00000000
[ 3161.956466] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 3161.962211] (NULL device *): {0:0} Association created
[ 3161.963374] nvmet: Created nvm controller 1 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 3161.975270] (NULL device *): {0:1} Association deleted
[ 3162.006074] nvme nvme0: NVME-FC{0}: controller connect complete
[ 3172.126859] nvmet: ctrl 2 keep-alive timer (5 seconds) expired!
[ 3172.127623] nvmet: ctrl 2 fatal error occurred!
[ 3184.377203] (NULL device *): {0:1} Association freed
[ 3184.377314] (NULL device *): Disconnect LS failed: No Association
[ 3245.358575] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000b4340/x00000000
[ 3245.358682] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0000a050/x00000000
[ 3245.358821] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0002b1e8/x00000000
[ 3245.358881] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00033980/x00000000
[ 3245.358933] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00051468/x00000000
[ 3245.359006] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001f3dc0/x00000000
[ 3245.359032] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 3245.359057] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000d1f18/x00000000
[ 3245.359972] nvme nvme0: NVME-FC{0}: resetting controller
[ 3245.360010] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000915c0/x00000000
[ 3245.360351] nvme_ns_head_submit_bio: 82 callbacks suppressed
[ 3245.360374] block nvme0n1: no usable path - requeuing I/O
[ 3245.360400] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00081080/x00000000
[ 3245.361245] block nvme0n1: no usable path - requeuing I/O
[ 3245.361264] block nvme0n1: no usable path - requeuing I/O
[ 3245.361652] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001d41e8/x00000000
[ 3245.361914] block nvme0n1: no usable path - requeuing I/O
[ 3245.361937] block nvme0n1: no usable path - requeuing I/O
[ 3245.361950] block nvme0n1: no usable path - requeuing I/O
[ 3245.361964] block nvme0n1: no usable path - requeuing I/O
[ 3245.361977] block nvme0n1: no usable path - requeuing I/O
[ 3245.364224] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00089910/x00000000
[ 3245.364281] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001938d0/x00000000
[ 3245.364332] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00146ae0/x00000000
[ 3245.364383] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001692d0/x00000000
[ 3245.364435] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001f23b0/x00000000
[ 3245.364488] block nvme0n1: no usable path - requeuing I/O
[ 3245.364497] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0009ec68/x00000000
[ 3245.364545] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0010c6f2/x00000000
[ 3245.364874] block nvme0n1: no usable path - requeuing I/O
[ 3245.365277] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0010c732/x00000000
[ 3245.365322] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0010c772/x00000000
[ 3245.365350] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0010c7b2/x00000000
[ 3245.365377] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0010c7f2/x00000000
[ 3245.365406] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 0 fctype 1
(I/O Cmd) w10/11: x00000000/x00000000
[ 3245.399397] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 3245.404662] (NULL device *): {0:1} Association created
[ 3245.405845] nvmet: Created nvm controller 2 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 3245.414713] (NULL device *): {0:0} Association deleted
[ 3245.439156] nvme nvme0: NVME-FC{0}: controller connect complete
[ 3255.070828] nvmet: ctrl 1 keep-alive timer (5 seconds) expired!
[ 3255.071589] nvmet: ctrl 1 fatal error occurred!
[ 3270.991000] (NULL device *): {0:0} Association freed
[ 3270.991124] (NULL device *): Disconnect LS failed: No Association
[ 3287.286065] perf: interrupt took too long (4088 > 4082), lowering
kernel.perf_event_max_sample_rate to 48000
[ 3331.891056] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000bda00/x00000000
[ 3331.891152] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001543d8/x00000000
[ 3331.891202] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00074e10/x00000000
[ 3331.891252] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0001a388/x00000000
[ 3331.891319] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001b2360/x00000000
[ 3331.891376] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00169330/x00000000
[ 3331.891421] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001d0e70/x00000000
[ 3331.891431] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 3331.891473] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000d1d28/x00000000
[ 3331.892414] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x001cfc50/x00000000
[ 3331.892497] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000abb28/x00000000
[ 3331.892581] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0002ee28/x00000000
[ 3331.892673] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0008a438/x00000000
[ 3331.892801] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0015e2d8/x00000000
[ 3331.892901] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x000d12b8/x00000000
[ 3331.893010] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00159e58/x00000000
[ 3331.893096] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x00097190/x00000000
[ 3331.893115] nvme nvme0: NVME-FC{0}: resetting controller
[ 3331.893158] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 0 fctype 1
(I/O Cmd) w10/11: x00000000/x00000000
[ 3331.893514] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0010f20c/x00000000
[ 3331.893558] nvme_ns_head_submit_bio: 93 callbacks suppressed
[ 3331.893572] block nvme0n1: no usable path - requeuing I/O
[ 3331.893575] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0010f24c/x00000000
[ 3331.893617] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0010f28c/x00000000
[ 3331.894339] block nvme0n1: no usable path - requeuing I/O
[ 3331.894678] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(I/O Cmd) w10/11: x0010f2cc/x00000000
[ 3331.894982] block nvme0n1: no usable path - requeuing I/O
[ 3331.895321] block nvme0n1: no usable path - requeuing I/O
[ 3331.895611] block nvme0n1: no usable path - requeuing I/O
[ 3331.895933] block nvme0n1: no usable path - requeuing I/O
[ 3331.896290] block nvme0n1: no usable path - requeuing I/O
[ 3331.896594] block nvme0n1: no usable path - requeuing I/O
[ 3331.896913] block nvme0n1: no usable path - requeuing I/O
[ 3331.897251] block nvme0n1: no usable path - requeuing I/O
[ 3331.937837] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 3331.943499] (NULL device *): {0:0} Association created
[ 3331.944725] nvmet: Created nvm controller 1 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 3331.976229] (NULL device *): {0:1} Association deleted
[ 3331.984385] nvme nvme0: NVME-FC{0}: controller connect complete
[ 3341.015948] ------------[ cut here ]------------
[ 3341.017039] WARNING: CPU: 3 PID: 522 at block/genhd.c:144
bdev_count_inflight_rw+0x26e/0x410
[ 3341.018176] Modules linked in: nvme_fcloop nvmet_fc nvmet nvme_fc
nvme_fabrics nvme_core nvme_keyring nvme_auth rfkill sunrpc
intel_rapl_msr intel_rapl_common intel_uncore_frequency
intel_uncore_frequency_common sb_edac x86_pkg_temp_thermal
intel_powerclamp coretemp kvm_intel vfat fat kvm irqbypass iTCO_wdt
rapl iTCO_vendor_support intel_cstate intel_uncore pcspkr bnx2x
mgag200 i2c_i801 tg3 i2c_smbus lpc_ich i2c_algo_bit hpilo ioatdma mdio
dca ipmi_ssif ipmi_si acpi_tad acpi_power_meter acpi_ipmi ipmi_devintf
ipmi_msghandler dax_pmem sg fuse loop nfnetlink xfs nd_pmem sr_mod
sd_mod cdrom ghash_clmulni_intel hpsa scsi_transport_sas hpwdt ahci
libahci libata wmi nfit libnvdimm dm_mirror dm_region_hash dm_log
dm_mod [last unloaded: nvmet]
[ 3341.022670] CPU: 3 UID: 0 PID: 522 Comm: kworker/u289:34 Tainted: G
       W           6.15.0+ #2 PREEMPT(lazy)
[ 3341.023677] Tainted: [W]=WARN
[ 3341.024351] Hardware name: HP ProLiant DL380 Gen9/ProLiant DL380
Gen9, BIOS P89 10/05/2016
[ 3341.024868] Workqueue: loop0 loop_rootcg_workfn [loop]
[ 3341.025232] RIP: 0010:bdev_count_inflight_rw+0x26e/0x410
[ 3341.025556] Code: 00 41 8b 47 04 85 c0 78 59 48 83 c4 30 5b 5d 41
5c 41 5d 41 5e 41 5f c3 cc cc cc cc e8 5b d4 fd ff 4d 8d 77 04 e9 7c
ff ff ff <0f> 0b 48 b8 00 00 00 00 00 fc ff df 4c 89 fa 48 c1 ea 03 0f
b6 14
[ 3341.027096] RSP: 0018:ffffc900058d6c90 EFLAGS: 00010286
[ 3341.027466] RAX: 0000000000000003 RBX: 0000000000000048 RCX: ffffffffa9b9ee56
[ 3341.028304] RDX: 00000000ffffffff RSI: 0000000000000048 RDI: ffffffffac36b380
[ 3341.029153] RBP: ffffe8ffffa0c600 R08: 0000000000000000 R09: fffff91ffff418d2
[ 3341.030067] R10: ffffe8ffffa0c697 R11: 0000000000000001 R12: ffff8881e2be9880
[ 3341.030975] R13: dffffc0000000000 R14: ffffc900058d6d1c R15: ffffc900058d6d18
[ 3341.031845] FS:  0000000000000000(0000) GS:ffff888439550000(0000)
knlGS:0000000000000000
[ 3341.032328] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 3341.033131] CR2: 000055aa896e5068 CR3: 0000000bfae7a006 CR4: 00000000003726f0
[ 3341.033996] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 3341.034915] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 3341.035805] Call Trace:
[ 3341.035991]  <TASK>
[ 3341.036585]  bdev_count_inflight+0x6d/0xa0
[ 3341.036918]  ? __pfx_bdev_count_inflight+0x10/0x10
[ 3341.037658]  update_io_ticks+0x1bd/0x210
[ 3341.037997]  ? __pfx_update_io_ticks+0x10/0x10
[ 3341.038854]  ? find_held_lock+0x32/0x90
[ 3341.039131]  ? local_clock_noinstr+0xd/0xe0
[ 3341.039437]  bdev_start_io_acct+0x31/0xe0
[ 3341.039720]  dm_io_acct+0x101/0x510 [dm_mod]
[ 3341.040570]  ? bio_associate_blkg+0xf9/0x1e0
[ 3341.041666]  dm_submit_bio_remap+0x52/0x380 [dm_mod]
[ 3341.042205]  dm_split_and_process_bio+0x369/0x1520 [dm_mod]
[ 3341.042666]  ? __lock_acquire+0x57c/0xbd0
[ 3341.042993]  ? __pfx_dm_split_and_process_bio+0x10/0x10 [dm_mod]
[ 3341.054346]  dm_submit_bio+0x130/0x460 [dm_mod]
[ 3341.088843]  ? local_clock_noinstr+0xd/0xe0
[ 3341.121535]  ? __pfx_dm_submit_bio+0x10/0x10 [dm_mod]
[ 3341.158880]  ? __lock_release.isra.0+0x1a4/0x2c0
[ 3341.193695]  ? __submit_bio_noacct+0x16d/0x5b0
[ 3341.227517]  __submit_bio+0x3bd/0x600
[ 3341.255891]  ? __pfx___submit_bio+0x10/0x10
[ 3341.286439]  ? rcu_is_watching+0x15/0xb0
[ 3341.315563]  ? __submit_bio_noacct+0x16d/0x5b0
[ 3341.347325]  __submit_bio_noacct+0x16d/0x5b0
[ 3341.378388]  ? find_held_lock+0x32/0x90
[ 3341.406774]  ? local_clock_noinstr+0xd/0xe0
[ 3341.437031]  ? __pfx___submit_bio_noacct+0x10/0x10
[ 3341.470525]  ? ktime_get+0x164/0x200
[ 3341.497850]  ? lockdep_hardirqs_on+0x78/0x100
[ 3341.529043]  ? rcu_is_watching+0x15/0xb0
[ 3341.557891]  submit_bio_noacct_nocheck+0x4e1/0x630
[ 3341.591401]  ? __pfx_submit_bio_noacct_nocheck+0x10/0x10
[ 3341.628047]  ? should_fail_bio+0xb5/0x150
[ 3341.657364]  ? submit_bio_noacct+0x9ba/0x1b30
[ 3341.688554]  xfs_submit_ioend+0x181/0x3e0 [xfs]
[ 3341.721154]  iomap_submit_ioend+0x97/0x240
[ 3341.751291]  ? __pfx_xfs_map_blocks+0x10/0x10 [xfs]
[ 3341.785620]  iomap_add_to_ioend+0x30b/0xa90
[ 3341.815876]  ? __pfx___folio_start_writeback+0x10/0x10
[ 3341.851253]  iomap_writepage_map_blocks+0x34d/0x4b0
[ 3341.885587]  ? rcu_is_watching+0x15/0xb0
[ 3341.914441]  iomap_writepage_map+0x502/0x1130
[ 3341.945625]  ? rcu_is_watching+0x15/0xb0
[ 3341.974472]  ? __pfx_iomap_writepage_map+0x10/0x10
[ 3342.008342]  ? writeback_iter+0x136/0x720
[ 3342.037668]  iomap_writepages+0xf2/0x190
[ 3342.044509]  ? local_clock_noinstr+0xd/0xe0
[ 3342.044762]  ? __pfx_iomap_writepages+0x10/0x10
[ 3342.045412]  ? __lock_release.isra.0+0x1a4/0x2c0
[ 3342.046072]  ? xfs_vm_writepages+0xc0/0x140 [xfs]
[ 3342.047168]  xfs_vm_writepages+0xe6/0x140 [xfs]
[ 3342.048224]  ? __pfx_xfs_vm_writepages+0x10/0x10 [xfs]
[ 3342.048946]  ? lock_acquire.part.0+0xbd/0x260
[ 3342.049598]  ? find_held_lock+0x32/0x90
[ 3342.049834]  ? local_clock_noinstr+0xd/0xe0
[ 3342.050063]  do_writepages+0x21f/0x560
[ 3342.050281]  ? __pfx_do_writepages+0x10/0x10
[ 3342.050936]  ? _raw_spin_unlock+0x2d/0x50
[ 3342.051176]  ? wbc_attach_and_unlock_inode.part.0+0x389/0x720
[ 3342.051943]  filemap_fdatawrite_wbc+0xcf/0x120
[ 3342.052596]  __filemap_fdatawrite_range+0xa7/0xe0
[ 3342.053262]  ? __pfx___filemap_fdatawrite_range+0x10/0x10
[ 3342.053568]  ? __up_write+0x1b3/0x4f0
[ 3342.053850]  ? __lock_acquire+0x57c/0xbd0
[ 3342.054093]  file_write_and_wait_range+0x95/0x110
[ 3342.072359]  xfs_file_fsync+0x15d/0x870 [xfs]
[ 3342.105328]  ? local_clock_noinstr+0xd/0xe0
[ 3342.110862] nvmet: ctrl 2 keep-alive timer (5 seconds) expired!
[ 3342.137782]  ? __pfx_xfs_file_fsync+0x10/0x10 [xfs]
[ 3342.179648] nvmet: ctrl 2 fatal error occurred!
[ 3342.215534]  ? mark_held_locks+0x40/0x70
[ 3342.215553]  loop_process_work+0x68b/0xf70 [loop]
[ 3342.314888]  process_one_work+0xd8b/0x1320
[ 3342.346102]  ? __pfx_process_one_work+0x10/0x10
[ 3342.380018]  ? assign_work+0x16c/0x240
[ 3342.409265]  worker_thread+0x5f3/0xfe0
[ 3342.438574]  ? __pfx_worker_thread+0x10/0x10
[ 3342.470813]  kthread+0x3b4/0x770
[ 3342.497590]  ? local_clock_noinstr+0x45/0xe0
[ 3342.529996]  ? __pfx_kthread+0x10/0x10
[ 3342.554641]  ? __lock_release.isra.0+0x1a4/0x2c0
[ 3342.555303]  ? rcu_is_watching+0x15/0xb0
[ 3342.555539]  ? __pfx_kthread+0x10/0x10
[ 3342.555780]  ret_from_fork+0x393/0x480
[ 3342.556006]  ? __pfx_kthread+0x10/0x10
[ 3342.556218]  ? __pfx_kthread+0x10/0x10
[ 3342.556496]  ret_from_fork_asm+0x1a/0x30
[ 3342.556775]  </TASK>
[ 3342.556944] irq event stamp: 15317467
[ 3342.557159] hardirqs last  enabled at (15317475):
[<ffffffffa8cd533e>] __up_console_sem+0x5e/0x80
[ 3342.558026] hardirqs last disabled at (15317490):
[<ffffffffa8cd5323>] __up_console_sem+0x43/0x80
[ 3342.558921] softirqs last  enabled at (15317504):
[<ffffffffa8afce0b>] handle_softirqs+0x62b/0x890
[ 3342.559800] softirqs last disabled at (15317515):
[<ffffffffa8afd1fd>] __irq_exit_rcu+0xfd/0x250
[ 3342.560684] ---[ end trace 0000000000000000 ]-----
Best Regards,
  Yi Zhang

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Breno Leitao]

On Fri, Jun 06, 2025 at 11:31:06AM +0800, Yi Zhang wrote:
> Hello
> 
> The following WARNING was triggered by blktests nvme/fc nvme/012,
> please help check and let me know if you need any info/test, thanks.
> 
> commit: linux-block: 38f4878b9463 (HEAD, origin/for-next) Merge branch
> 'block-6.16' into for-next

I am seeing a similar issue on Linus' recent tree as e271ed52b344
("Merge tag 'pm-6.16-rc1-3' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm").
CCing Jens.

This is my stack, in case it is useful.

           WARNING: CPU: 33 PID: 1865 at block/genhd.c:146 bdev_count_inflight_rw+0x334/0x3b0
           Modules linked in: sch_fq(E) tls(E) act_gact(E) tcp_diag(E) inet_diag(E) cls_bpf(E) intel_uncore_frequency(E) intel_uncore_frequency_common(E) skx_edac(E) skx_edac_common(E) nfit(E) libnvdimm(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) coretemp(E) kvm_intel(E) kvm(E) mlx5_ib(E) iTCO_wdt(E) iTCO_vendor_support(E) xhci_pci(E) evdev(E) irqbypass(E) acpi_cpufreq(E) ib_uverbs(E) ipmi_si(E) i2c_i801(E) xhci_hcd(E) i2c_smbus(E) ipmi_devintf(E) wmi(E) ipmi_msghandler(E) button(E) sch_fq_codel(E) vhost_net(E) tun(E) vhost(E) vhost_iotlb(E) tap(E) mpls_gso(E) mpls_iptunnel(E) mpls_router(E) fou(E) loop(E) drm(E) backlight(E) drm_panel_orientation_quirks(E) autofs4(E) efivarfs(E)
           CPU: 33 UID: 0 PID: 1865 Comm: kworker/u144:14 Kdump: loaded Tainted: G S          E    N  6.15.0-0_fbk701_debugnightly_rc0_upstream_12426_ge271ed52b344 #1 PREEMPT(undef) 
           Tainted: [S]=CPU_OUT_OF_SPEC, [E]=UNSIGNED_MODULE, [N]=TEST
           Hardware name: Quanta Twin Lakes MP/Twin Lakes Passive MP, BIOS F09_3A23 12/08/2020
           Workqueue: writeback wb_workfn (flush-btrfs-1)
           RIP: 0010:bdev_count_inflight_rw+0x334/0x3b0
           Code: 75 5c 41 83 3f 00 78 22 48 83 c4 40 5b 41 5c 41 5d 41 5e 41 5f 5d c3 0f 0b 41 0f b6 06 84 c0 75 54 41 c7 07 00 00 00 00 eb bb <0f> 0b 48 b8 00 00 00 00 00 fc ff df 0f b6 04 03 84 c0 75 4e 41 c7
           RSP: 0018:ffff8882ed786f20 EFLAGS: 00010286
           RAX: 0000000000000000 RBX: 1ffff1105daf0df3 RCX: ffffffff829739f7
           RDX: 0000000000000024 RSI: 0000000000000024 RDI: ffffffff853f79f8
           RBP: 0000606f9ff42610 R08: ffffe8ffffd866a7 R09: 1ffffd1ffffb0cd4
           R10: dffffc0000000000 R11: fffff91ffffb0cd5 R12: 0000000000000024
           R13: 1ffffffff0dd0120 R14: ffffed105daf0df3 R15: ffff8882ed786f9c
           FS:  0000000000000000(0000) GS:ffff88905fd44000(0000) knlGS:0000000000000000
           CR2: 00007f904bc6d008 CR3: 0000001075c2b001 CR4: 00000000007726f0
           PKRU: 55555554
           Call Trace:
            <TASK>
            bdev_count_inflight+0x28/0x50
            update_io_ticks+0x10f/0x1b0
            blk_account_io_start+0x3a0/0x690
            blk_mq_submit_bio+0xc7e/0x1940
            __submit_bio+0x125/0x3c0
            ? lock_release+0x4a/0x3c0
            submit_bio_noacct_nocheck+0x3cf/0xa30
            btree_write_cache_pages+0x5eb/0x870
            do_writepages+0x307/0x4d0
            ? rcu_is_watching+0xf/0xa0
            __writeback_single_inode+0x106/0xd10
            writeback_sb_inodes+0x53d/0xd60
            wb_writeback+0x368/0x8d0
            wb_workfn+0x3aa/0xcf0
            ? rcu_is_watching+0xf/0xa0
            ? trace_irq_enable+0x64/0x190
            ? process_scheduled_works+0x959/0x1450
            process_scheduled_works+0x9fe/0x1450
            worker_thread+0x8fd/0xd10
            kthread+0x50c/0x630
            ? rcu_is_watching+0xf/0xa0
            </TASK>
           irq event stamp: 0
           hardirqs last disabled at (0): [<ffffffff81401f85>] copy_process+0x655/0x32d0
           softirqs last  enabled at (0): [<ffffffff81401f85>] copy_process+0x655/0x32d0

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Jens Axboe]

On 6/9/25 3:14 AM, Breno Leitao wrote:
> On Fri, Jun 06, 2025 at 11:31:06AM +0800, Yi Zhang wrote:
>> Hello
>>
>> The following WARNING was triggered by blktests nvme/fc nvme/012,
>> please help check and let me know if you need any info/test, thanks.
>>
>> commit: linux-block: 38f4878b9463 (HEAD, origin/for-next) Merge branch
>> 'block-6.16' into for-next
> 
> I am seeing a similar issue on Linus' recent tree as e271ed52b344
> ("Merge tag 'pm-6.16-rc1-3' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm").
> CCing Jens.
> 
> This is my stack, in case it is useful.

What does your storage setup look like? Likely not a new issue, only
change is that we now report/warn if these counters ever hit < 0. Adding
Yu to the CC as he recently worked in this area, and added the patch
that triggers the warning now.


-- 
Jens Axboe

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Breno Leitao]

Hello Jens,

On Mon, Jun 09, 2025 at 08:22:35AM -0600, Jens Axboe wrote:
> On 6/9/25 3:14 AM, Breno Leitao wrote:
> > On Fri, Jun 06, 2025 at 11:31:06AM +0800, Yi Zhang wrote:
> >> Hello
> >>
> >> The following WARNING was triggered by blktests nvme/fc nvme/012,
> >> please help check and let me know if you need any info/test, thanks.
> >>
> >> commit: linux-block: 38f4878b9463 (HEAD, origin/for-next) Merge branch
> >> 'block-6.16' into for-next
> > 
> > I am seeing a similar issue on Linus' recent tree as e271ed52b344
> > ("Merge tag 'pm-6.16-rc1-3' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm").
> > CCing Jens.
> > 
> > This is my stack, in case it is useful.
> 
> What does your storage setup look like? Likely not a new issue, only
> change is that we now report/warn if these counters ever hit < 0. Adding
> Yu to the CC as he recently worked in this area, and added the patch
> that triggers the warning now.

Basically a host with a bunch of nvme:

	# lsblk
	NAME        MAJ:MIN RM   SIZE RO TYPE MOUNTPOINTS
	nvme1n1     259:0    0 238.5G  0 disk
	├─nvme1n1p1 259:2    0   243M  0 part /boot/efi
	├─nvme1n1p2 259:3    0   488M  0 part /boot
	├─nvme1n1p3 259:4    0   1.9G  0 part [SWAP]
	└─nvme1n1p4 259:5    0 235.8G  0 part /
	nvme0n1     259:1    0   1.6T  0 disk
	├─nvme0n1p1 259:6    0 838.4G  0 part
	└─nvme0n1p2 259:7    0 838.4G  0 part

	# dmesg | grep nvme
	[  435.301782] nvme nvme0: pci function 0000:b4:00.0
	[  435.412268] nvme nvme1: pci function 0000:64:00.0
	[  435.459601] nvme nvme0: D3 entry latency set to 8 seconds
	[  435.848628] nvme nvme1: 32/0/0 default/read/poll queues
	[  435.944582] nvme nvme0: 52/0/0 default/read/poll queues
	[  436.135123]  nvme1n1: p1 p2 p3 p4
	[  436.316921]  nvme0n1: p1 p2
	[  500.912739] BTRFS: device label / devid 1 transid 2052 /dev/nvme1n1p4 (259:5) scanned by mount (837)
	[  501.583187] BTRFS info (device nvme1n1p4): first mount of filesystem 0568aa14-1bee-4c76-b409-662d748eefad
	[  501.602891] BTRFS info (device nvme1n1p4): using crc32c (crc32c-x86) checksum algorithm
	[  501.618986] BTRFS info (device nvme1n1p4): using free-space-tree
	[  562.737848] systemd[1]: Expecting device dev-nvme0n1p3.device - /dev/nvme0n1p3...
	[  567.865384] BTRFS info (device nvme1n1p4 state M): force zstd compression, level 3
	[  603.745650] EXT4-fs (nvme1n1p2): mounted filesystem 57120c82-6f1a-4e1f-a8c3-6aa17bffb1f2 r/w with ordered data mode. Quota mode: none.
	[  604.103672] FAT-fs (nvme1n1p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
	[  658.986835]        nvme_alloc_ns+0x204/0x2ee0
	[  658.986842]        nvme_scan_ns+0x53f/0x8b0
	[  660.888749] nvme nvme0: using unchecked data buffer
	[  859.589752] Adding 2000892k swap on /dev/nvme1n1p3.  Priority:5 extents:1 across:2000892k SS
	[ 1698.294280] block nvme1n1: No UUID available providing old NGUID
	[ 1698.356183] block nvme1n1: the capability attribute has been deprecated.
	[ 1807.416851] Adding 2000892k swap on /dev/nvme1n1p3.  Priority:5 extents:1 across:2000892k SS

This was happening while a HTTP server was being executed.

Does it answer your question?

Thanks for the reply,
--breno

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Yu Kuai]

Hi,

在 2025/06/09 17:14, Breno Leitao 写道:
> On Fri, Jun 06, 2025 at 11:31:06AM +0800, Yi Zhang wrote:
>> Hello
>>
>> The following WARNING was triggered by blktests nvme/fc nvme/012,
>> please help check and let me know if you need any info/test, thanks.
>>
>> commit: linux-block: 38f4878b9463 (HEAD, origin/for-next) Merge branch
>> 'block-6.16' into for-next
> 
> I am seeing a similar issue on Linus' recent tree as e271ed52b344
> ("Merge tag 'pm-6.16-rc1-3' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm").
> CCing Jens.
> 
> This is my stack, in case it is useful.
> 
>             WARNING: CPU: 33 PID: 1865 at block/genhd.c:146 bdev_count_inflight_rw+0x334/0x3b0
>             Modules linked in: sch_fq(E) tls(E) act_gact(E) tcp_diag(E) inet_diag(E) cls_bpf(E) intel_uncore_frequency(E) intel_uncore_frequency_common(E) skx_edac(E) skx_edac_common(E) nfit(E) libnvdimm(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) coretemp(E) kvm_intel(E) kvm(E) mlx5_ib(E) iTCO_wdt(E) iTCO_vendor_support(E) xhci_pci(E) evdev(E) irqbypass(E) acpi_cpufreq(E) ib_uverbs(E) ipmi_si(E) i2c_i801(E) xhci_hcd(E) i2c_smbus(E) ipmi_devintf(E) wmi(E) ipmi_msghandler(E) button(E) sch_fq_codel(E) vhost_net(E) tun(E) vhost(E) vhost_iotlb(E) tap(E) mpls_gso(E) mpls_iptunnel(E) mpls_router(E) fou(E) loop(E) drm(E) backlight(E) drm_panel_orientation_quirks(E) autofs4(E) efivarfs(E)
>             CPU: 33 UID: 0 PID: 1865 Comm: kworker/u144:14 Kdump: loaded Tainted: G S          E    N  6.15.0-0_fbk701_debugnightly_rc0_upstream_12426_ge271ed52b344 #1 PREEMPT(undef)
>             Tainted: [S]=CPU_OUT_OF_SPEC, [E]=UNSIGNED_MODULE, [N]=TEST
>             Hardware name: Quanta Twin Lakes MP/Twin Lakes Passive MP, BIOS F09_3A23 12/08/2020
>             Workqueue: writeback wb_workfn (flush-btrfs-1)
>             RIP: 0010:bdev_count_inflight_rw+0x334/0x3b0
>             Code: 75 5c 41 83 3f 00 78 22 48 83 c4 40 5b 41 5c 41 5d 41 5e 41 5f 5d c3 0f 0b 41 0f b6 06 84 c0 75 54 41 c7 07 00 00 00 00 eb bb <0f> 0b 48 b8 00 00 00 00 00 fc ff df 0f b6 04 03 84 c0 75 4e 41 c7
>             RSP: 0018:ffff8882ed786f20 EFLAGS: 00010286
>             RAX: 0000000000000000 RBX: 1ffff1105daf0df3 RCX: ffffffff829739f7
>             RDX: 0000000000000024 RSI: 0000000000000024 RDI: ffffffff853f79f8
>             RBP: 0000606f9ff42610 R08: ffffe8ffffd866a7 R09: 1ffffd1ffffb0cd4
>             R10: dffffc0000000000 R11: fffff91ffffb0cd5 R12: 0000000000000024
>             R13: 1ffffffff0dd0120 R14: ffffed105daf0df3 R15: ffff8882ed786f9c
>             FS:  0000000000000000(0000) GS:ffff88905fd44000(0000) knlGS:0000000000000000
>             CR2: 00007f904bc6d008 CR3: 0000001075c2b001 CR4: 00000000007726f0
>             PKRU: 55555554
>             Call Trace:
>              <TASK>
>              bdev_count_inflight+0x28/0x50
>              update_io_ticks+0x10f/0x1b0
>              blk_account_io_start+0x3a0/0x690
>              blk_mq_submit_bio+0xc7e/0x1940

So, this is blk-mq IO accounting, a different problem than nvme mpath.

What kind of test you're running, can you reporduce ths problem? I don't
have a clue yet after a quick code review.

Thanks,
Kuai

>              __submit_bio+0x125/0x3c0
>              ? lock_release+0x4a/0x3c0
>              submit_bio_noacct_nocheck+0x3cf/0xa30
>              btree_write_cache_pages+0x5eb/0x870
>              do_writepages+0x307/0x4d0
>              ? rcu_is_watching+0xf/0xa0
>              __writeback_single_inode+0x106/0xd10
>              writeback_sb_inodes+0x53d/0xd60
>              wb_writeback+0x368/0x8d0
>              wb_workfn+0x3aa/0xcf0
>              ? rcu_is_watching+0xf/0xa0
>              ? trace_irq_enable+0x64/0x190
>              ? process_scheduled_works+0x959/0x1450
>              process_scheduled_works+0x9fe/0x1450
>              worker_thread+0x8fd/0xd10
>              kthread+0x50c/0x630
>              ? rcu_is_watching+0xf/0xa0
>              </TASK>
>             irq event stamp: 0
>             hardirqs last disabled at (0): [<ffffffff81401f85>] copy_process+0x655/0x32d0
>             softirqs last  enabled at (0): [<ffffffff81401f85>] copy_process+0x655/0x32d0
> 
> .
> 

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Breno Leitao]

On Tue, Jun 10, 2025 at 10:07:47AM +0800, Yu Kuai wrote:
> Hi,
> 
> 在 2025/06/09 17:14, Breno Leitao 写道:
> > On Fri, Jun 06, 2025 at 11:31:06AM +0800, Yi Zhang wrote:
> > > Hello
> > > 
> > > The following WARNING was triggered by blktests nvme/fc nvme/012,
> > > please help check and let me know if you need any info/test, thanks.
> > > 
> > > commit: linux-block: 38f4878b9463 (HEAD, origin/for-next) Merge branch
> > > 'block-6.16' into for-next
> > 
> > I am seeing a similar issue on Linus' recent tree as e271ed52b344
> > ("Merge tag 'pm-6.16-rc1-3' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm").
> > CCing Jens.
> > 
> > This is my stack, in case it is useful.
> > 
> >             WARNING: CPU: 33 PID: 1865 at block/genhd.c:146 bdev_count_inflight_rw+0x334/0x3b0
> >             Modules linked in: sch_fq(E) tls(E) act_gact(E) tcp_diag(E) inet_diag(E) cls_bpf(E) intel_uncore_frequency(E) intel_uncore_frequency_common(E) skx_edac(E) skx_edac_common(E) nfit(E) libnvdimm(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) coretemp(E) kvm_intel(E) kvm(E) mlx5_ib(E) iTCO_wdt(E) iTCO_vendor_support(E) xhci_pci(E) evdev(E) irqbypass(E) acpi_cpufreq(E) ib_uverbs(E) ipmi_si(E) i2c_i801(E) xhci_hcd(E) i2c_smbus(E) ipmi_devintf(E) wmi(E) ipmi_msghandler(E) button(E) sch_fq_codel(E) vhost_net(E) tun(E) vhost(E) vhost_iotlb(E) tap(E) mpls_gso(E) mpls_iptunnel(E) mpls_router(E) fou(E) loop(E) drm(E) backlight(E) drm_panel_orientation_quirks(E) autofs4(E) efivarfs(E)
> >             CPU: 33 UID: 0 PID: 1865 Comm: kworker/u144:14 Kdump: loaded Tainted: G S          E    N  6.15.0-0_fbk701_debugnightly_rc0_upstream_12426_ge271ed52b344 #1 PREEMPT(undef)
> >             Tainted: [S]=CPU_OUT_OF_SPEC, [E]=UNSIGNED_MODULE, [N]=TEST
> >             Hardware name: Quanta Twin Lakes MP/Twin Lakes Passive MP, BIOS F09_3A23 12/08/2020
> >             Workqueue: writeback wb_workfn (flush-btrfs-1)
> >             RIP: 0010:bdev_count_inflight_rw+0x334/0x3b0
> >             Code: 75 5c 41 83 3f 00 78 22 48 83 c4 40 5b 41 5c 41 5d 41 5e 41 5f 5d c3 0f 0b 41 0f b6 06 84 c0 75 54 41 c7 07 00 00 00 00 eb bb <0f> 0b 48 b8 00 00 00 00 00 fc ff df 0f b6 04 03 84 c0 75 4e 41 c7
> >             RSP: 0018:ffff8882ed786f20 EFLAGS: 00010286
> >             RAX: 0000000000000000 RBX: 1ffff1105daf0df3 RCX: ffffffff829739f7
> >             RDX: 0000000000000024 RSI: 0000000000000024 RDI: ffffffff853f79f8
> >             RBP: 0000606f9ff42610 R08: ffffe8ffffd866a7 R09: 1ffffd1ffffb0cd4
> >             R10: dffffc0000000000 R11: fffff91ffffb0cd5 R12: 0000000000000024
> >             R13: 1ffffffff0dd0120 R14: ffffed105daf0df3 R15: ffff8882ed786f9c
> >             FS:  0000000000000000(0000) GS:ffff88905fd44000(0000) knlGS:0000000000000000
> >             CR2: 00007f904bc6d008 CR3: 0000001075c2b001 CR4: 00000000007726f0
> >             PKRU: 55555554
> >             Call Trace:
> >              <TASK>
> >              bdev_count_inflight+0x28/0x50
> >              update_io_ticks+0x10f/0x1b0
> >              blk_account_io_start+0x3a0/0x690
> >              blk_mq_submit_bio+0xc7e/0x1940
> 
> So, this is blk-mq IO accounting, a different problem than nvme mpath.
> 
> What kind of test you're running, can you reporduce ths problem? I don't
> have a clue yet after a quick code review.

I have a bunch of machines running some Meta prod workloads on them,
and this one was running a webserver.

Unfortunately I don't have a reproducer.

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Calvin Owens]

On Tuesday 06/10 at 10:07 +0800, Yu Kuai wrote:
> So, this is blk-mq IO accounting, a different problem than nvme mpath.
>
> What kind of test you're running, can you reporduce ths problem? I don't
> have a clue yet after a quick code review.
>
> Thanks,
> Kuai

Hi all,

I've also been hitting this warning, I can reproduce it pretty
consistently within a few hours of running large Yocto builds. If I can
help test any patches, let me know.

A close approximation to what I'm doing is to clone Poky and build
core-image-weston: https://github.com/yoctoproject/poky

Using a higher than reasonable concurrency seems to help: I'm setting
BB_NUMBER_THREADS and PARALLEL_MAKE to 2x - 4x the number of CPUs. I'm
trying to narrow it down to a simpler reproducer, but haven't had any
luck yet.

I see this on three machines. One is btrfs/luks/nvme, the other two are
btrfs/luks/mdraid1/nvme*2. All three have a very large swapfile on the
rootfs. This is from the machine without mdraid:

    ------------[ cut here ]------------
    WARNING: CPU: 6 PID: 1768274 at block/genhd.c:144 bdev_count_inflight_rw+0x8a/0xc0
    CPU: 6 UID: 1000 PID: 1768274 Comm: cc1plus Not tainted 6.16.0-rc2-gcc-slubdebug-lockdep-00071-g74b4cc9b8780 #1 PREEMPT
    Hardware name: Gigabyte Technology Co., Ltd. A620I AX/A620I AX, BIOS F3 07/10/2023
    RIP: 0010:bdev_count_inflight_rw+0x8a/0xc0
    Code: 00 01 d7 89 3e 49 8b 50 20 4a 03 14 d5 c0 4b 76 82 48 8b 92 90 00 00 00 01 d1 48 63 d0 89 4e 04 48 83 fa 1f 76 92 85 ff 79 a7 <0f> 0b c7 06 00 00 00 00 85 c9 79 9f 0f 0b c7 46 04 00 00 00 00 48
    RSP: 0000:ffffc9002b027ab8 EFLAGS: 00010282
    RAX: 0000000000000020 RBX: ffff88810dec0000 RCX: 000000000000000a
    RDX: 0000000000000020 RSI: ffffc9002b027ac8 RDI: 00000000fffffffe
    RBP: ffff88810dec0000 R08: ffff888100660b40 R09: ffffffffffffffff
    R10: 000000000000001f R11: ffff888f3a30e9a8 R12: ffff8881098855d0
    R13: ffffc9002b027b90 R14: 0000000000000001 R15: ffffc9002b027e18
    FS:  00007fb394b48400(0000) GS:ffff888ccc9b9000(0000) knlGS:0000000000000000
    CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
    CR2: 00007fb3884a81c8 CR3: 00000013db708000 CR4: 0000000000350ef0
    Call Trace:
     <TASK>
     bdev_count_inflight+0x16/0x30
     update_io_ticks+0xb7/0xd0
     blk_account_io_start+0xe8/0x200
     blk_mq_submit_bio+0x34c/0x910
     __submit_bio+0x95/0x5a0
     ? submit_bio_noacct_nocheck+0x169/0x400
     submit_bio_noacct_nocheck+0x169/0x400
     swapin_readahead+0x18a/0x550
     ? __filemap_get_folio+0x26/0x400
     ? get_swap_device+0xe8/0x210
     ? lock_release+0xc3/0x2a0
     do_swap_page+0x1fa/0x1850
     ? __lock_acquire+0x46d/0x25c0
     ? wake_up_state+0x10/0x10
     __handle_mm_fault+0x5e5/0x880
     handle_mm_fault+0x70/0x2e0
     exc_page_fault+0x374/0x8a0
     asm_exc_page_fault+0x22/0x30
    RIP: 0033:0x915570
    Code: ff 01 0f 86 c4 05 00 00 41 56 41 55 41 54 55 48 89 fd 53 48 89 fb 0f 1f 40 00 48 89 df e8 98 c8 0b 00 84 c0 0f 85 90 05 00 00 <0f> b7 03 48 c1 e0 06 80 b8 99 24 d1 02 00 48 8d 90 80 24 d1 02 0f
    RSP: 002b:00007ffc9327dfd0 EFLAGS: 00010246
    RAX: 0000000000000000 RBX: 00007fb3884a81c8 RCX: 0000000000000008
    RDX: 0000000000000006 RSI: 0000000005dba008 RDI: 0000000000000000
    RBP: 00007fb3884a81c8 R08: 000000000000000c R09: 00000007fb3884a8
    R10: 0000000000000007 R11: 0000000000000206 R12: 0000000000000000
    R13: 0000000000000002 R14: 00007ffc9329cb90 R15: 00007fb36e5d2700
     </TASK>
    irq event stamp: 36649373
    hardirqs last  enabled at (36649387): [<ffffffff813cea2d>] __up_console_sem+0x4d/0x50
    hardirqs last disabled at (36649398): [<ffffffff813cea12>] __up_console_sem+0x32/0x50
    softirqs last  enabled at (36648786): [<ffffffff8136017f>] __irq_exit_rcu+0x8f/0xb0
    softirqs last disabled at (36648617): [<ffffffff8136017f>] __irq_exit_rcu+0x8f/0xb0
    ---[ end trace 0000000000000000 ]---

I dumped all the similar WARNs I've seen here (blk-warn-%d.txt):

    https://github.com/jcalvinowens/lkml-debug-616/tree/master

I don't have any evidence it's related, but I'm also hitting a rare OOPS
in futex with this same Yocto build workload. Sebastian has done some
analysis here:

    https://lore.kernel.org/lkml/20250618160333.PdGB89yt@linutronix.de/

I get this warning most of the time I get the oops, but not all of the
time. Curious if anyone else is seeing the oops?

Thanks,
Calvin

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Yu Kuai]

Hi,

在 2025/06/20 12:10, Calvin Owens 写道:
> I dumped all the similar WARNs I've seen here (blk-warn-%d.txt):
> 
>      https://github.com/jcalvinowens/lkml-debug-616/tree/master

These reports also contain both request-based and bio-based disk, I
think perhaps following concurrent scenario is possible:

While bdev_count_inflight is interating all cpu, some IOs are issued
from traversed cpu and then completed from the cpu that is not traversed
yet.

cpu0
		cpu1
		bdev_count_inflight
		 //for_each_possible_cpu
		 // cpu0 is 0
		 infliht += 0
// issue a io
blk_account_io_start
// cpu0 inflight ++

				cpu2
				// the io is done
				blk_account_io_done
				// cpu2 inflight --
		 // cpu 1 is 0
		 inflight += 0
		 // cpu2 is -1
		 inflight += -1
		 ...

In this case, the total inflight will be -1.

Yi and Calvin,

Can you please help testing the following patch, it add a WARN_ON_ONCE()
using atomic operations, if the new warning is not reporduced while
the old warning is reporduced, I think it can be confirmed the above
analyze is correct, and I will send a revert for the WARN_ON_ONCE()
change in bdev_count_inflight().

Thanks,
Kuai

diff --git a/block/blk-core.c b/block/blk-core.c
index b862c66018f2..2b033caa74e8 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -1035,6 +1035,8 @@ unsigned long bdev_start_io_acct(struct 
block_device *bdev, enum req_op op,
         part_stat_local_inc(bdev, in_flight[op_is_write(op)]);
         part_stat_unlock();

+       atomic_inc(&bdev->inflight[op_is_write(op)]);
+
         return start_time;
  }
  EXPORT_SYMBOL(bdev_start_io_acct);
@@ -1065,6 +1067,8 @@ void bdev_end_io_acct(struct block_device *bdev, 
enum req_op op,
         part_stat_add(bdev, nsecs[sgrp], jiffies_to_nsecs(duration));
         part_stat_local_dec(bdev, in_flight[op_is_write(op)]);
         part_stat_unlock();
+
+       WARN_ON_ONCE(atomic_dec_return(&bdev->inflight[op_is_write(op)]) 
< 0);
  }
  EXPORT_SYMBOL(bdev_end_io_acct);

diff --git a/block/blk-merge.c b/block/blk-merge.c
index 70d704615be5..ff15276d277f 100644
--- a/block/blk-merge.c
+++ b/block/blk-merge.c
@@ -658,6 +658,8 @@ static void blk_account_io_merge_request(struct 
request *req)
                 part_stat_local_dec(req->part,
                                     in_flight[op_is_write(req_op(req))]);
                 part_stat_unlock();
+
+ 
WARN_ON_ONCE(atomic_dec_return(&req->part->inflight[op_is_write(req_op(req))]) 
< 0);
         }
  }

diff --git a/block/blk-mq.c b/block/blk-mq.c
index 4806b867e37d..94e728ff8bb6 100644
--- a/block/blk-mq.c
+++ b/block/blk-mq.c
@@ -1056,6 +1056,8 @@ static inline void blk_account_io_done(struct 
request *req, u64 now)
                 part_stat_local_dec(req->part,
                                     in_flight[op_is_write(req_op(req))]);
                 part_stat_unlock();
+
+ 
WARN_ON_ONCE(atomic_dec_return(&req->part->inflight[op_is_write(req_op(req))]) 
< 0);
         }
  }

@@ -1116,6 +1118,8 @@ static inline void blk_account_io_start(struct 
request *req)
         update_io_ticks(req->part, jiffies, false);
         part_stat_local_inc(req->part, 
in_flight[op_is_write(req_op(req))]);
         part_stat_unlock();
+
+       atomic_inc(&req->part->inflight[op_is_write(req_op(req))]);
  }

  static inline void __blk_mq_end_request_acct(struct request *rq, u64 now)
diff --git a/include/linux/blk_types.h b/include/linux/blk_types.h
index 3d1577f07c1c..a81110c07426 100644
--- a/include/linux/blk_types.h
+++ b/include/linux/blk_types.h
@@ -43,6 +43,7 @@ struct block_device {
         sector_t                bd_nr_sectors;
         struct gendisk *        bd_disk;
         struct request_queue *  bd_queue;
+       atomic_t                inflight[2];
         struct disk_stats __percpu *bd_stats;
         unsigned long           bd_stamp;
         atomic_t                __bd_flags;     // partition number + flags

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Calvin Owens]

On Friday 06/20 at 14:47 +0800, Yu Kuai wrote:
> Hi,
> 
> 在 2025/06/20 12:10, Calvin Owens 写道:
> > I dumped all the similar WARNs I've seen here (blk-warn-%d.txt):
> > 
> >      https://github.com/jcalvinowens/lkml-debug-616/tree/master
> 
> These reports also contain both request-based and bio-based disk, I
> think perhaps following concurrent scenario is possible:
> 
> While bdev_count_inflight is interating all cpu, some IOs are issued
> from traversed cpu and then completed from the cpu that is not traversed
> yet.
> 
> cpu0
> 		cpu1
> 		bdev_count_inflight
> 		 //for_each_possible_cpu
> 		 // cpu0 is 0
> 		 infliht += 0
> // issue a io
> blk_account_io_start
> // cpu0 inflight ++
> 
> 				cpu2
> 				// the io is done
> 				blk_account_io_done
> 				// cpu2 inflight --
> 		 // cpu 1 is 0
> 		 inflight += 0
> 		 // cpu2 is -1
> 		 inflight += -1
> 		 ...
> 
> In this case, the total inflight will be -1.
> 
> Yi and Calvin,
> 
> Can you please help testing the following patch, it add a WARN_ON_ONCE()
> using atomic operations, if the new warning is not reporduced while
> the old warning is reporduced, I think it can be confirmed the above
> analyze is correct, and I will send a revert for the WARN_ON_ONCE()
> change in bdev_count_inflight().

Hi Kuai,

I can confirm it's what you expected, I've reproduced the original
warning with your patch while not seeing any of the new ones.

If you like, for the revert:

Tested-By: Calvin Owens <calvin@wbinvd.org>

Thanks,
Calvin

> Thanks,
> Kuai
> 
> diff --git a/block/blk-core.c b/block/blk-core.c
> index b862c66018f2..2b033caa74e8 100644
> --- a/block/blk-core.c
> +++ b/block/blk-core.c
> @@ -1035,6 +1035,8 @@ unsigned long bdev_start_io_acct(struct block_device
> *bdev, enum req_op op,
>         part_stat_local_inc(bdev, in_flight[op_is_write(op)]);
>         part_stat_unlock();
> 
> +       atomic_inc(&bdev->inflight[op_is_write(op)]);
> +
>         return start_time;
>  }
>  EXPORT_SYMBOL(bdev_start_io_acct);
> @@ -1065,6 +1067,8 @@ void bdev_end_io_acct(struct block_device *bdev, enum
> req_op op,
>         part_stat_add(bdev, nsecs[sgrp], jiffies_to_nsecs(duration));
>         part_stat_local_dec(bdev, in_flight[op_is_write(op)]);
>         part_stat_unlock();
> +
> +       WARN_ON_ONCE(atomic_dec_return(&bdev->inflight[op_is_write(op)]) <
> 0);
>  }
>  EXPORT_SYMBOL(bdev_end_io_acct);
> 
> diff --git a/block/blk-merge.c b/block/blk-merge.c
> index 70d704615be5..ff15276d277f 100644
> --- a/block/blk-merge.c
> +++ b/block/blk-merge.c
> @@ -658,6 +658,8 @@ static void blk_account_io_merge_request(struct request
> *req)
>                 part_stat_local_dec(req->part,
>                                     in_flight[op_is_write(req_op(req))]);
>                 part_stat_unlock();
> +
> + WARN_ON_ONCE(atomic_dec_return(&req->part->inflight[op_is_write(req_op(req))])
> < 0);
>         }
>  }
> 
> diff --git a/block/blk-mq.c b/block/blk-mq.c
> index 4806b867e37d..94e728ff8bb6 100644
> --- a/block/blk-mq.c
> +++ b/block/blk-mq.c
> @@ -1056,6 +1056,8 @@ static inline void blk_account_io_done(struct request
> *req, u64 now)
>                 part_stat_local_dec(req->part,
>                                     in_flight[op_is_write(req_op(req))]);
>                 part_stat_unlock();
> +
> + WARN_ON_ONCE(atomic_dec_return(&req->part->inflight[op_is_write(req_op(req))])
> < 0);
>         }
>  }
> 
> @@ -1116,6 +1118,8 @@ static inline void blk_account_io_start(struct request
> *req)
>         update_io_ticks(req->part, jiffies, false);
>         part_stat_local_inc(req->part, in_flight[op_is_write(req_op(req))]);
>         part_stat_unlock();
> +
> +       atomic_inc(&req->part->inflight[op_is_write(req_op(req))]);
>  }
> 
>  static inline void __blk_mq_end_request_acct(struct request *rq, u64 now)
> diff --git a/include/linux/blk_types.h b/include/linux/blk_types.h
> index 3d1577f07c1c..a81110c07426 100644
> --- a/include/linux/blk_types.h
> +++ b/include/linux/blk_types.h
> @@ -43,6 +43,7 @@ struct block_device {
>         sector_t                bd_nr_sectors;
>         struct gendisk *        bd_disk;
>         struct request_queue *  bd_queue;
> +       atomic_t                inflight[2];
>         struct disk_stats __percpu *bd_stats;
>         unsigned long           bd_stamp;
>         atomic_t                __bd_flags;     // partition number + flags
> 

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Yu Kuai]

Hi,

在 2025/06/25 9:43, Calvin Owens 写道:
> I can confirm it's what you expected, I've reproduced the original
> warning with your patch while not seeing any of the new ones.
> 
> If you like, for the revert:
> 
> Tested-By: Calvin Owens<calvin@wbinvd.org>

Thanks for the test, I'll send the revert with your tag.

Kuai

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Yi Zhang]

Hi Yu

Seems both the original and new warning are triggered, here is the full log:

[  957.877438] run blktests nvme/012 at 2025-06-25 23:58:12
[  958.533643] loop0: detected capacity change from 0 to 2097152
[  958.642850] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
[  959.512306] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[  959.519831] (NULL device *): {0:0} Association created
[  959.523618] nvmet: Created nvm controller 1 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[  959.582072] nvme nvme0: NVME-FC{0}: controller connect complete
[  959.582621] nvme nvme0: NVME-FC{0}: new ctrl: NQN
"blktests-subsystem-1", hostnqn:
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349
[  960.197452] nvme nvme1: NVME-FC{1}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"nqn.2014-08.org.nvmexpress.discovery"
[  960.204257] (NULL device *): {0:1} Association created
[  960.205846] nvmet: Created discovery controller 2 for subsystem
nqn.2014-08.org.nvmexpress.discovery for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[  960.218038] nvme nvme1: NVME-FC{1}: controller connect complete
[  960.218468] nvme nvme1: NVME-FC{1}: new ctrl: NQN
"nqn.2014-08.org.nvmexpress.discovery", hostnqn:
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349
[  960.249003] nvme nvme1: Removing ctrl: NQN
"nqn.2014-08.org.nvmexpress.discovery"
[  960.672600] (NULL device *): {0:1} Association deleted
[  960.690869] XFS (nvme0n1): Mounting V5 Filesystem
4cf8fd97-5f8e-48ea-b8d3-450aac8dc021
[  960.755721] XFS (nvme0n1): Ending clean mount
[  960.893903] (NULL device *): {0:1} Association freed
[  960.894140] (NULL device *): Disconnect LS failed: No Association
[ 1021.580164] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000d60a0/x00000000
[ 1021.580790] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001bcae8/x00000000
[ 1021.580868] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0001af68/x00000000
[ 1021.580941] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000c2200/x00000000
[ 1021.581011] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00005838/x00000000
[ 1021.581163] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00131fa0/x00000000
[ 1021.581260] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00144de0/x00000000
[ 1021.581327] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001f8408/x00000000
[ 1021.581343] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 1021.581393] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00076308/x00000000
[ 1021.590801] nvme nvme0: NVME-FC{0}: resetting controller
[ 1021.590861] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0003be10/x00000000
[ 1021.596242] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001cbf78/x00000000
[ 1021.596427] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0004d428/x00000000
[ 1021.596472] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001d1700/x00000000
[ 1021.596506] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0015de58/x00000000
[ 1021.596536] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000008c0/x00000000
[ 1021.596567] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001f22a0/x00000000
[ 1021.596615] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00100072/x00000000
[ 1021.596672] block nvme0n1: no usable path - requeuing I/O
[ 1021.596674] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001000b2/x00000000
[ 1021.602131] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001000f2/x00000000
[ 1021.602141] block nvme0n1: no usable path - requeuing I/O
[ 1021.602157] block nvme0n1: no usable path - requeuing I/O
[ 1021.607588] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00100132/x00000000
[ 1021.613050] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00100172/x00000000
[ 1021.613084] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001001b2/x00000000
[ 1021.613119] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001001f2/x00000000
[ 1021.613151] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 0 fctype 1
(Flush) w10/11: x00000000/x00000000
[ 1021.613198] block nvme0n1: no usable path - requeuing I/O
[ 1021.618681] block nvme0n1: no usable path - requeuing I/O
[ 1021.624099] block nvme0n1: no usable path - requeuing I/O
[ 1021.629514] block nvme0n1: no usable path - requeuing I/O
[ 1021.634935] block nvme0n1: no usable path - requeuing I/O
[ 1021.640351] block nvme0n1: no usable path - requeuing I/O
[ 1021.645775] block nvme0n1: no usable path - requeuing I/O
[ 1022.169519] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 1022.169566] ------------[ cut here ]------------
[ 1022.174594] WARNING: CPU: 12 PID: 466 at block/blk-core.c:1071
bdev_end_io_acct+0x494/0x5c0
[ 1022.176221] (NULL device *): {0:1} Association created
[ 1022.183010] Modules linked in: loop nvme_fcloop nvmet_fc nvmet
nvme_fc nvme_fabrics nvme_core nvme_keyring nvme_auth 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 skx_edac skx_edac_common
x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm mgag200
irqbypass iTCO_wdt i2c_algo_bit rapl cdc_ether iTCO_vendor_support
drm_client_lib mei_me drm_shmem_helper dell_smbios usbnet intel_cstate
platform_profile dcdbas intel_uncore dell_wmi_descriptor wmi_bmof
pcspkr mii ipmi_ssif drm_kms_helper i2c_i801 mei lpc_ich i2c_smbus
intel_pch_thermal ipmi_si acpi_power_meter acpi_ipmi dax_pmem
ipmi_devintf ipmi_msghandler drm fuse xfs sd_mod sg nd_pmem nd_btt
ahci libahci ghash_clmulni_intel bnxt_en libata tg3 megaraid_sas wmi
nfit libnvdimm dm_mirror dm_region_hash dm_log dm_mod
[ 1022.183834] nvmet: Created nvm controller 2 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 1022.223500] ------------[ cut here ]------------
[ 1022.223572] WARNING: CPU: 42 PID: 2014 at block/genhd.c:146
bdev_count_inflight_rw+0x2a6/0x410
[ 1022.223596] Modules linked in: loop nvme_fcloop nvmet_fc nvmet
nvme_fc nvme_fabrics nvme_core nvme_keyring nvme_auth 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 skx_edac skx_edac_common
x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm mgag200
irqbypass iTCO_wdt i2c_algo_bit rapl cdc_ether iTCO_vendor_support
drm_client_lib mei_me drm_shmem_helper dell_smbios usbnet intel_cstate
platform_profile dcdbas intel_uncore dell_wmi_descriptor wmi_bmof
pcspkr mii ipmi_ssif drm_kms_helper i2c_i801 mei lpc_ich i2c_smbus
intel_pch_thermal ipmi_si acpi_power_meter acpi_ipmi dax_pmem
ipmi_devintf ipmi_msghandler drm fuse xfs sd_mod sg nd_pmem nd_btt
ahci libahci ghash_clmulni_intel bnxt_en libata tg3 megaraid_sas wmi
nfit libnvdimm dm_mirror dm_region_hash dm_log dm_mod
[ 1022.224168] CPU: 42 UID: 0 PID: 2014 Comm: fio Not tainted
6.16.0-rc3.yu+ #2 PREEMPT(voluntary)
[ 1022.224185] Hardware name: Dell Inc. PowerEdge R640/08HT8T, BIOS
2.22.2 09/12/2024
[ 1022.224194] RIP: 0010:bdev_count_inflight_rw+0x2a6/0x410
[ 1022.224207] Code: fa 48 c1 ea 03 0f b6 14 02 4c 89 f8 83 e0 07 83
c0 03 38 d0 7c 08 84 d2 0f 85 59 01 00 00 41 c7 07 00 00 00 00 e9 75
ff ff ff <0f> 0b 48 b8 00 00 00 00 00 fc ff df 4c 89 f2 48 c1 ea 03 0f
b6 14
[ 1022.224219] RSP: 0018:ffffc9000e2578c8 EFLAGS: 00010286
[ 1022.224234] RAX: 00000000ffffffff RBX: 0000000000000030 RCX: ffffffffb0090a46
[ 1022.224243] RDX: 0000000000000000 RSI: 0000000000000030 RDI: ffffffffb26e42c0
[ 1022.224252] RBP: ffffe8ffffa4e440 R08: 0000000000000000 R09: fffff91ffff49c9a
[ 1022.224262] R10: ffffe8ffffa4e4d7 R11: 0000000000000000 R12: ffff88a922776e40
[ 1022.224270] R13: dffffc0000000000 R14: ffffc9000e257984 R15: ffffc9000e257980
[ 1022.224280] FS:  00007feaa0b15640(0000) GS:ffff889c401a7000(0000)
knlGS:0000000000000000
[ 1022.224291] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1022.224300] CR2: 0000562e119e6018 CR3: 00000005a21ca003 CR4: 00000000007726f0
[ 1022.224309] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1022.224318] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 1022.224326] PKRU: 55555554
[ 1022.224333] Call Trace:
[ 1022.224342]  <TASK>
[ 1022.224383]  part_stat_show+0x9e/0x290
[ 1022.224401]  ? rcu_is_watching+0x11/0xb0
[ 1022.224422]  ? trace_contention_end+0x150/0x1c0
[ 1022.224447]  ? __pfx_part_stat_show+0x10/0x10
[ 1022.224478]  ? __lock_acquire+0x6f1/0xc00
[ 1022.224528]  ? find_held_lock+0x32/0x90
[ 1022.224541]  ? local_clock_noinstr+0x9/0xc0
[ 1022.224565]  ? __lock_release+0x1a2/0x2c0
[ 1022.224619]  dev_attr_show+0x3f/0xc0
[ 1022.224636]  ? __asan_memset+0x20/0x50
[ 1022.224656]  sysfs_kf_seq_show+0x1a4/0x3b0
[ 1022.224693]  seq_read_iter+0x40b/0x1090
[ 1022.224747]  ? rw_verify_area+0x2fd/0x520
[ 1022.224777]  vfs_read+0x74e/0xc30
[ 1022.224798]  ? __pfx___mutex_lock+0x10/0x10
[ 1022.224816]  ? find_held_lock+0x32/0x90
[ 1022.224838]  ? __pfx_vfs_read+0x10/0x10
[ 1022.224866]  ? __fget_files+0x195/0x2e0
[ 1022.224885]  ? __fget_files+0x195/0x2e0
[ 1022.224954]  ksys_read+0xf3/0x1d0
[ 1022.224975]  ? __pfx_ksys_read+0x10/0x10
[ 1022.225064]  do_syscall_64+0x8c/0x3d0
[ 1022.225108]  ? __x64_sys_openat+0x11e/0x1e0
[ 1022.225134]  ? __pfx___x64_sys_openat+0x10/0x10
[ 1022.225178]  ? entry_SYSCALL_64_after_hwframe+0x76/0x7e
[ 1022.225193]  ? lockdep_hardirqs_on+0x78/0x100
[ 1022.225211]  ? do_syscall_64+0x16e/0x3d0
[ 1022.225223]  ? lockdep_hardirqs_on+0x78/0x100
[ 1022.225241]  ? do_syscall_64+0x16e/0x3d0
[ 1022.225256]  ? do_syscall_64+0x16e/0x3d0
[ 1022.225285]  entry_SYSCALL_64_after_hwframe+0x76/0x7e
[ 1022.225297] RIP: 0033:0x7feac08fe30c
[ 1022.225312] Code: ec 28 48 89 54 24 18 48 89 74 24 10 89 7c 24 08
e8 19 8b f8 ff 48 8b 54 24 18 48 8b 74 24 10 41 89 c0 8b 7c 24 08 31
c0 0f 05 <48> 3d 00 f0 ff ff 77 34 44 89 c7 48 89 44 24 08 e8 6f 8b f8
ff 48
[ 1022.225322] RSP: 002b:00007feaa0b148a0 EFLAGS: 00000246 ORIG_RAX:
0000000000000000
[ 1022.225338] RAX: ffffffffffffffda RBX: 00007feab4000b60 RCX: 00007feac08fe30c
[ 1022.225347] RDX: 0000000000001000 RSI: 00007feab4001280 RDI: 0000000000000007
[ 1022.225356] RBP: 00007feac09f65e0 R08: 0000000000000000 R09: 0000000000000077
[ 1022.225364] R10: 0000000000000063 R11: 0000000000000246 R12: 00007feab4000b60
[ 1022.225373] R13: 0000000000000d68 R14: 00007feac09f59e0 R15: 0000000000000d68
[ 1022.225441]  </TASK>
[ 1022.225449] irq event stamp: 64865
[ 1022.225456] hardirqs last  enabled at (64871): [<ffffffffaf1f6ee1>]
console_trylock_spinning+0x221/0x260
[ 1022.225473] hardirqs last disabled at (64876): [<ffffffffaf1f6e91>]
console_trylock_spinning+0x1d1/0x260
[ 1022.225486] softirqs last  enabled at (63932): [<ffffffffaf01f7c8>]
handle_softirqs+0x5f8/0x920
[ 1022.225502] softirqs last disabled at (63923): [<ffffffffaf01fc9b>]
__irq_exit_rcu+0x11b/0x270
[ 1022.225513] ---[ end trace 0000000000000000 ]---
[ 1022.263295] CPU: 12 UID: 0 PID: 466 Comm: kworker/12:1H Tainted: G
      W           6.16.0-rc3.yu+ #2 PREEMPT(voluntary)
[ 1022.291560] nvme nvme0: NVME-FC{0}: controller connect complete
[ 1022.356344] Tainted: [W]=WARN
[ 1022.356348] Hardware name: Dell Inc. PowerEdge R640/08HT8T, BIOS
2.22.2 09/12/2024
[ 1022.356352] Workqueue: kblockd blk_mq_run_work_fn
[ 1022.744652] RIP: 0010:bdev_end_io_acct+0x494/0x5c0
[ 1022.749466] Code: 22 fd ff ff 48 c7 44 24 08 10 00 00 00 41 be 30
00 00 00 48 c7 04 24 50 00 00 00 e9 c3 fb ff ff 0f 1f 44 00 00 e9 f5
fd ff ff <0f> 0b 48 83 c4 28 5b 5d 41 5c 41 5d 41 5e 41 5f c3 cc cc cc
cc 48
[ 1022.768235] RSP: 0018:ffffc9000f9f78e8 EFLAGS: 00010297
[ 1022.773484] RAX: 00000000ffffffff RBX: ffff88a922776e64 RCX: ffffffffb003853f
[ 1022.780632] RDX: ffffed15244eedcd RSI: 0000000000000004 RDI: ffff88a922776e64
[ 1022.787784] RBP: ffffe8d448a4e440 R08: 0000000000000001 R09: ffffed15244eedcc
[ 1022.794934] R10: ffff88a922776e67 R11: 0000000000000000 R12: ffff88a922776e68
[ 1022.802101] R13: 0000000000000001 R14: 0000000000000028 R15: 0000000000007e42
[ 1022.809251] FS:  0000000000000000(0000) GS:ffff889c3c5a7000(0000)
knlGS:0000000000000000
[ 1022.817352] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1022.823114] CR2: 0000562e119bd048 CR3: 0000003661478001 CR4: 00000000007726f0
[ 1022.830265] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1022.837418] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 1022.844561] PKRU: 55555554
[ 1022.847293] Call Trace:
[ 1022.849762]  <TASK>
[ 1022.851898]  nvme_end_req+0x4d/0x70 [nvme_core]
[ 1022.856494]  nvme_failover_req+0x3bd/0x530 [nvme_core]
[ 1022.861692]  nvme_fail_nonready_command+0x12c/0x170 [nvme_core]
[ 1022.867666]  nvme_fc_queue_rq+0x463/0x720 [nvme_fc]
[ 1022.872573]  ? flush_busy_ctx+0x2bd/0x410
[ 1022.876612]  ? __pfx_nvme_fc_queue_rq+0x10/0x10 [nvme_fc]
[ 1022.882040]  ? _raw_spin_unlock+0x29/0x50
[ 1022.886075]  ? flush_busy_ctx+0x2bd/0x410
[ 1022.890112]  blk_mq_dispatch_rq_list+0x358/0x1260
[ 1022.894846]  ? __pfx_blk_mq_flush_busy_ctxs+0x10/0x10
[ 1022.899914]  ? __pfx_blk_mq_dispatch_rq_list+0x10/0x10
[ 1022.905077]  ? __lock_acquire+0x6f1/0xc00
[ 1022.909119]  __blk_mq_sched_dispatch_requests+0x2dd/0x480
[ 1022.914543]  ? __pfx___blk_mq_sched_dispatch_requests+0x10/0x10
[ 1022.920484]  ? rcu_is_watching+0x11/0xb0
[ 1022.924437]  blk_mq_sched_dispatch_requests+0xa6/0x140
[ 1022.929597]  blk_mq_run_work_fn+0x1bb/0x2a0
[ 1022.933803]  process_one_work+0x8ca/0x1950
[ 1022.937956]  ? __pfx_process_one_work+0x10/0x10
[ 1022.942517]  ? assign_work+0x16c/0x240
[ 1022.946292]  worker_thread+0x58d/0xcf0
[ 1022.950080]  ? __pfx_worker_thread+0x10/0x10
[ 1022.954376]  kthread+0x3d5/0x7a0
[ 1022.957632]  ? __pfx_kthread+0x10/0x10
[ 1022.961411]  ? rcu_is_watching+0x11/0xb0
[ 1022.965362]  ? __pfx_kthread+0x10/0x10
[ 1022.969144]  ret_from_fork+0x403/0x510
[ 1022.972932]  ? __pfx_kthread+0x10/0x10
[ 1022.976701]  ret_from_fork_asm+0x1a/0x30
[ 1022.980671]  </TASK>
[ 1022.982879] irq event stamp: 4185
[ 1022.986216] hardirqs last  enabled at (4195): [<ffffffffaf1f438b>]
__up_console_sem+0x6b/0x80
[ 1022.994753] hardirqs last disabled at (4204): [<ffffffffaf1f4370>]
__up_console_sem+0x50/0x80
[ 1023.003288] softirqs last  enabled at (4140): [<ffffffffaf01f7c8>]
handle_softirqs+0x5f8/0x920
[ 1023.011932] softirqs last disabled at (4135): [<ffffffffaf01fc9b>]
__irq_exit_rcu+0x11b/0x270
[ 1023.020463] ---[ end trace 0000000000000000 ]---
[ 1023.042643] (NULL device *): {0:0} Association deleted
[ 1031.553369] nvmet: ctrl 1 keep-alive timer (5 seconds) expired!
[ 1031.560460] nvmet: ctrl 1 fatal error occurred!
[ 1032.690809] (NULL device *): {0:0} Association freed
[ 1032.690915] (NULL device *): Disconnect LS failed: No Association
[ 1092.492635] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 0 fctype 1
(Flush) w10/11: x00000000/x00000000
[ 1092.492757] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001615e0/x00000000
[ 1092.492833] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001ee528/x00000000
[ 1092.492903] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000d9608/x00000000
[ 1092.492971] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001e6fc0/x00000000
[ 1092.493078] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001ce330/x00000000
[ 1092.493113] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 1092.493278] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00194c58/x00000000
[ 1092.501618] nvme nvme0: NVME-FC{0}: resetting controller
[ 1092.501646] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00036808/x00000000
[ 1092.507031] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00098858/x00000000
[ 1092.507083] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001d6af0/x00000000
[ 1092.507143] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00037110/x00000000
[ 1092.507211] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00028738/x00000000
[ 1092.507256] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000cb2f8/x00000000
[ 1092.507294] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001db548/x00000000
[ 1092.507294] nvme_ns_head_submit_bio: 53 callbacks suppressed
[ 1092.507319] block nvme0n1: no usable path - requeuing I/O
[ 1092.507332] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00164e88/x00000000
[ 1092.507370] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000c6a58/x00000000
[ 1092.513146] block nvme0n1: no usable path - requeuing I/O
[ 1092.518453] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00063908/x00000000
[ 1092.518473] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00101de4/x00000000
[ 1092.523917] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00101e24/x00000000
[ 1092.523927] block nvme0n1: no usable path - requeuing I/O
[ 1092.523939] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00101e64/x00000000
[ 1092.529353] block nvme0n1: no usable path - requeuing I/O
[ 1092.529362] block nvme0n1: no usable path - requeuing I/O
[ 1092.529370] block nvme0n1: no usable path - requeuing I/O
[ 1092.529379] block nvme0n1: no usable path - requeuing I/O
[ 1092.529387] block nvme0n1: no usable path - requeuing I/O
[ 1092.529395] block nvme0n1: no usable path - requeuing I/O
[ 1092.529407] block nvme0n1: no usable path - requeuing I/O
[ 1092.567521] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00101ea4/x00000000
[ 1092.567544] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00101ee4/x00000000
[ 1092.567565] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00101f24/x00000000
[ 1092.567586] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00101f64/x00000000
[ 1092.586616] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 1092.589236] (NULL device *): {0:0} Association created
[ 1092.590346] nvmet: Created nvm controller 1 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 1092.617739] (NULL device *): {0:1} Association deleted
[ 1092.618501] nvme nvme0: NVME-FC{0}: controller connect complete
[ 1101.692537] nvmet: ctrl 2 keep-alive timer (5 seconds) expired!
[ 1101.698582] nvmet: ctrl 2 fatal error occurred!
[ 1108.581555] (NULL device *): {0:1} Association freed
[ 1108.581673] (NULL device *): Disconnect LS failed: No Association
[ 1169.292656] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000ac410/x00000000
[ 1169.292773] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00022280/x00000000
[ 1169.292902] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00165558/x00000000
[ 1169.292975] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001e6be8/x00000000
[ 1169.293045] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00075aa0/x00000000
[ 1169.293121] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00096d28/x00000000
[ 1169.293190] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0016a1c8/x00000000
[ 1169.293210] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 1169.293285] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0018cc08/x00000000
[ 1169.301731] nvme nvme0: NVME-FC{0}: resetting controller
[ 1169.301750] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000e80b0/x00000000
[ 1169.307114] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001f0150/x00000000
[ 1169.307162] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0013c950/x00000000
[ 1169.307201] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001bcb50/x00000000
[ 1169.307245] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000ab668/x00000000
[ 1169.307290] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000f07f8/x00000000
[ 1169.307332] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00158748/x00000000
[ 1169.307371] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0002aea8/x00000000
[ 1169.307413] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 0 fctype 1
(Flush) w10/11: x00000000/x00000000
[ 1169.307479] nvme_ns_head_submit_bio: 73 callbacks suppressed
[ 1169.307498] block nvme0n1: no usable path - requeuing I/O
[ 1169.318700] block nvme0n1: no usable path - requeuing I/O
[ 1169.324148] block nvme0n1: no usable path - requeuing I/O
[ 1169.329577] block nvme0n1: no usable path - requeuing I/O
[ 1169.335085] block nvme0n1: no usable path - requeuing I/O
[ 1169.340499] block nvme0n1: no usable path - requeuing I/O
[ 1169.345913] block nvme0n1: no usable path - requeuing I/O
[ 1169.351327] block nvme0n1: no usable path - requeuing I/O
[ 1169.356747] block nvme0n1: no usable path - requeuing I/O
[ 1169.362161] block nvme0n1: no usable path - requeuing I/O
[ 1169.388582] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 1169.395335] (NULL device *): {0:1} Association created
[ 1169.396654] nvmet: Created nvm controller 2 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 1169.404023] (NULL device *): {0:0} Association deleted
[ 1169.424767] nvme nvme0: NVME-FC{0}: controller connect complete
[ 1178.485216] nvmet: ctrl 1 keep-alive timer (5 seconds) expired!
[ 1178.491269] nvmet: ctrl 1 fatal error occurred!
[ 1199.495733] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00165558/x00000000
[ 1199.495846] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00022280/x00000000
[ 1199.495921] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001e6be8/x00000000
[ 1199.495992] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00075aa0/x00000000
[ 1199.496059] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00096d28/x00000000
[ 1199.496141] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0016a1c8/x00000000
[ 1199.496217] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0018cc08/x00000000
[ 1199.496229] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 1199.496285] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001bcb50/x00000000
[ 1199.504778] nvme nvme0: NVME-FC{0}: resetting controller
[ 1199.505035] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000ab668/x00000000
[ 1199.510168] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000f07f8/x00000000
[ 1199.510209] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00158748/x00000000
[ 1199.510245] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0002aea8/x00000000
[ 1199.510287] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000e80b0/x00000000
[ 1199.510341] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001f0150/x00000000
[ 1199.510378] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0013c950/x00000000
[ 1199.510416] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000ac410/x00000000
[ 1199.510453] nvme nvme0: NVME-FC{0.2}: io timeout: opcode 0 fctype 1
(Flush) w10/11: x00000000/x00000000
[ 1199.548601] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 1199.550025] nvme_ns_head_submit_bio: 31 callbacks suppressed
[ 1199.550033] block nvme0n1: no usable path - requeuing I/O
[ 1199.555063] (NULL device *): {0:2} Association created
[ 1199.562849] nvmet: Created nvm controller 3 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 1199.568924] block nvme0n1: no usable path - requeuing I/O
[ 1199.570148] (NULL device *): {0:1} Association deleted
[ 1199.574360] block nvme0n1: no usable path - requeuing I/O
[ 1199.574369] block nvme0n1: no usable path - requeuing I/O
[ 1199.574376] block nvme0n1: no usable path - requeuing I/O
[ 1199.574383] block nvme0n1: no usable path - requeuing I/O
[ 1199.574393] block nvme0n1: no usable path - requeuing I/O
[ 1199.574402] block nvme0n1: no usable path - requeuing I/O
[ 1199.574412] block nvme0n1: no usable path - requeuing I/O
[ 1199.574422] block nvme0n1: no usable path - requeuing I/O
[ 1199.606289] nvme nvme0: NVME-FC{0}: controller connect complete
[ 1199.851981] (NULL device *): {0:1} Association freed
[ 1199.852095] (NULL device *): Disconnect LS failed: No Association
[ 1199.865367] (NULL device *): {0:0} Association freed
[ 1199.865419] (NULL device *): Disconnect LS failed: No Association
[ 1260.424514] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001b5a00/x00000000
[ 1260.424632] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0014b5c0/x00000000
[ 1260.424708] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00122cf8/x00000000
[ 1260.424778] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000ac538/x00000000
[ 1260.424846] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000b6890/x00000000
[ 1260.424933] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001ddb68/x00000000
[ 1260.425009] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0006e720/x00000000
[ 1260.425021] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 1260.425076] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000c8948/x00000000
[ 1260.433557] nvme nvme0: NVME-FC{0}: resetting controller
[ 1260.438935] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00038560/x00000000
[ 1260.438966] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000c0480/x00000000
[ 1260.438995] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000e2948/x00000000
[ 1260.439025] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001ceff8/x00000000
[ 1260.439061] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0000de28/x00000000
[ 1260.439091] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000a3530/x00000000
[ 1260.439120] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000a9450/x00000000
[ 1260.439149] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0019be38/x00000000
[ 1260.439168] nvme_ns_head_submit_bio: 25 callbacks suppressed
[ 1260.439185] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 0 fctype 1
(Flush) w10/11: x00000000/x00000000
[ 1260.439185] block nvme0n1: no usable path - requeuing I/O
[ 1260.444904] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00103fb5/x00000000
[ 1260.444933] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00103ff5/x00000000
[ 1260.450361] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00104035/x00000000
[ 1260.450382] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00103eb5/x00000000
[ 1260.450403] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00103ef5/x00000000
[ 1260.450423] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00103f35/x00000000
[ 1260.450445] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00103f75/x00000000
[ 1260.450515] block nvme0n1: no usable path - requeuing I/O
[ 1260.456040] block nvme0n1: no usable path - requeuing I/O
[ 1260.461481] block nvme0n1: no usable path - requeuing I/O
[ 1260.466899] block nvme0n1: no usable path - requeuing I/O
[ 1260.472327] block nvme0n1: no usable path - requeuing I/O
[ 1260.477737] block nvme0n1: no usable path - requeuing I/O
[ 1260.483157] block nvme0n1: no usable path - requeuing I/O
[ 1260.488570] block nvme0n1: no usable path - requeuing I/O
[ 1260.493987] block nvme0n1: no usable path - requeuing I/O
[ 1260.502057] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 1260.509561] (NULL device *): {0:0} Association created
[ 1260.511108] nvmet: Created nvm controller 1 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 1260.516897] (NULL device *): {0:2} Association deleted
[ 1260.552786] nvme nvme0: NVME-FC{0}: controller connect complete
[ 1270.637574] nvmet: ctrl 3 keep-alive timer (5 seconds) expired!
[ 1270.643622] nvmet: ctrl 3 fatal error occurred!
[ 1286.221388] (NULL device *): {0:2} Association freed
[ 1286.221515] (NULL device *): Disconnect LS failed: No Association
[ 1346.424230] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 0 fctype 1
(Flush) w10/11: x00000000/x00000000
[ 1346.424294] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001d1d40/x00000000
[ 1346.424344] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001868b0/x00000000
[ 1346.424377] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001c6038/x00000000
[ 1346.424409] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000e5e20/x00000000
[ 1346.424441] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x001df538/x00000000
[ 1346.424483] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000103b8/x00000000
[ 1346.424516] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0018bb20/x00000000
[ 1346.424547] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0002de48/x00000000
[ 1346.424597] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000759d0/x00000000
[ 1346.424652] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x0012e340/x00000000
[ 1346.424685] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00055a20/x00000000
[ 1346.424719] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00074eb8/x00000000
[ 1346.424753] nvme nvme0: NVME-FC{0}: transport association event:
transport detected io error
[ 1346.424764] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00168cb0/x00000000
[ 1346.424867] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00045f98/x00000000
[ 1346.433288] nvme nvme0: NVME-FC{0}: resetting controller
[ 1346.433319] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x000fe478/x00000000
[ 1346.438737] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
(Write) w10/11: x00153c98/x00000000
[ 1346.438905] nvme_ns_head_submit_bio: 49 callbacks suppressed
[ 1346.438922] block nvme0n1: no usable path - requeuing I/O
[ 1346.450290] block nvme0n1: no usable path - requeuing I/O
[ 1346.455823] block nvme0n1: no usable path - requeuing I/O
[ 1346.461263] block nvme0n1: no usable path - requeuing I/O
[ 1346.466683] block nvme0n1: no usable path - requeuing I/O
[ 1346.472095] block nvme0n1: no usable path - requeuing I/O
[ 1346.477510] block nvme0n1: no usable path - requeuing I/O
[ 1346.482926] block nvme0n1: no usable path - requeuing I/O
[ 1346.488343] block nvme0n1: no usable path - requeuing I/O
[ 1346.493759] block nvme0n1: no usable path - requeuing I/O
[ 1346.512987] nvme nvme0: NVME-FC{0}: create association : host wwpn
0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
"blktests-subsystem-1"
[ 1346.519457] (NULL device *): {0:1} Association created
[ 1346.520786] nvmet: Created nvm controller 2 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
[ 1346.534750] (NULL device *): {0:0} Association deleted
[ 1346.550214] nvme nvme0: NVME-FC{0}: controller connect complete
[ 1356.646385] nvmet: ctrl 1 keep-alive timer (5 seconds) expired!
[ 1356.652430] nvmet: ctrl 1 fatal error occurred!
[ 1359.532517] (NULL device *): {0:0} Association freed
[ 1359.532642] (NULL device *): Disconnect LS failed: No Association
[ 1419.047820] XFS (nvme0n1): Unmounting Filesystem
4cf8fd97-5f8e-48ea-b8d3-450aac8dc021
[ 1419.259166] nvme nvme0: Removing ctrl: NQN "blktests-subsystem-1"
[ 1419.452477] (NULL device *): {0:1} Association deleted
[ 1419.608635] (NULL device *): {0:1} Association freed
[ 1419.608751] (NULL device *): Disconnect LS failed: No Association
[ 1420.231038] nvme_fc: nvme_fc_create_ctrl:
nn-0x10001100ab000001:pn-0x20001100ab000001 -
nn-0x10001100aa000001:pn-0x20001100aa000001 combination not found
[ 1426.441719] Key type psk unregistered
[ 1429.557488] Key type psk registered

On Fri, Jun 20, 2025 at 2:47 PM Yu Kuai <yukuai1@huaweicloud.com> wrote:
>
> Hi,
>
> 在 2025/06/20 12:10, Calvin Owens 写道:
> > I dumped all the similar WARNs I've seen here (blk-warn-%d.txt):
> >
> >      https://github.com/jcalvinowens/lkml-debug-616/tree/master
>
> These reports also contain both request-based and bio-based disk, I
> think perhaps following concurrent scenario is possible:
>
> While bdev_count_inflight is interating all cpu, some IOs are issued
> from traversed cpu and then completed from the cpu that is not traversed
> yet.
>
> cpu0
>                 cpu1
>                 bdev_count_inflight
>                  //for_each_possible_cpu
>                  // cpu0 is 0
>                  infliht += 0
> // issue a io
> blk_account_io_start
> // cpu0 inflight ++
>
>                                 cpu2
>                                 // the io is done
>                                 blk_account_io_done
>                                 // cpu2 inflight --
>                  // cpu 1 is 0
>                  inflight += 0
>                  // cpu2 is -1
>                  inflight += -1
>                  ...
>
> In this case, the total inflight will be -1.
>
> Yi and Calvin,
>
> Can you please help testing the following patch, it add a WARN_ON_ONCE()
> using atomic operations, if the new warning is not reporduced while
> the old warning is reporduced, I think it can be confirmed the above
> analyze is correct, and I will send a revert for the WARN_ON_ONCE()
> change in bdev_count_inflight().
>
> Thanks,
> Kuai
>
> diff --git a/block/blk-core.c b/block/blk-core.c
> index b862c66018f2..2b033caa74e8 100644
> --- a/block/blk-core.c
> +++ b/block/blk-core.c
> @@ -1035,6 +1035,8 @@ unsigned long bdev_start_io_acct(struct
> block_device *bdev, enum req_op op,
>          part_stat_local_inc(bdev, in_flight[op_is_write(op)]);
>          part_stat_unlock();
>
> +       atomic_inc(&bdev->inflight[op_is_write(op)]);
> +
>          return start_time;
>   }
>   EXPORT_SYMBOL(bdev_start_io_acct);
> @@ -1065,6 +1067,8 @@ void bdev_end_io_acct(struct block_device *bdev,
> enum req_op op,
>          part_stat_add(bdev, nsecs[sgrp], jiffies_to_nsecs(duration));
>          part_stat_local_dec(bdev, in_flight[op_is_write(op)]);
>          part_stat_unlock();
> +
> +       WARN_ON_ONCE(atomic_dec_return(&bdev->inflight[op_is_write(op)])
> < 0);
>   }
>   EXPORT_SYMBOL(bdev_end_io_acct);
>
> diff --git a/block/blk-merge.c b/block/blk-merge.c
> index 70d704615be5..ff15276d277f 100644
> --- a/block/blk-merge.c
> +++ b/block/blk-merge.c
> @@ -658,6 +658,8 @@ static void blk_account_io_merge_request(struct
> request *req)
>                  part_stat_local_dec(req->part,
>                                      in_flight[op_is_write(req_op(req))]);
>                  part_stat_unlock();
> +
> +
> WARN_ON_ONCE(atomic_dec_return(&req->part->inflight[op_is_write(req_op(req))])
> < 0);
>          }
>   }
>
> diff --git a/block/blk-mq.c b/block/blk-mq.c
> index 4806b867e37d..94e728ff8bb6 100644
> --- a/block/blk-mq.c
> +++ b/block/blk-mq.c
> @@ -1056,6 +1056,8 @@ static inline void blk_account_io_done(struct
> request *req, u64 now)
>                  part_stat_local_dec(req->part,
>                                      in_flight[op_is_write(req_op(req))]);
>                  part_stat_unlock();
> +
> +
> WARN_ON_ONCE(atomic_dec_return(&req->part->inflight[op_is_write(req_op(req))])
> < 0);
>          }
>   }
>
> @@ -1116,6 +1118,8 @@ static inline void blk_account_io_start(struct
> request *req)
>          update_io_ticks(req->part, jiffies, false);
>          part_stat_local_inc(req->part,
> in_flight[op_is_write(req_op(req))]);
>          part_stat_unlock();
> +
> +       atomic_inc(&req->part->inflight[op_is_write(req_op(req))]);
>   }
>
>   static inline void __blk_mq_end_request_acct(struct request *rq, u64 now)
> diff --git a/include/linux/blk_types.h b/include/linux/blk_types.h
> index 3d1577f07c1c..a81110c07426 100644
> --- a/include/linux/blk_types.h
> +++ b/include/linux/blk_types.h
> @@ -43,6 +43,7 @@ struct block_device {
>          sector_t                bd_nr_sectors;
>          struct gendisk *        bd_disk;
>          struct request_queue *  bd_queue;
> +       atomic_t                inflight[2];
>          struct disk_stats __percpu *bd_stats;
>          unsigned long           bd_stamp;
>          atomic_t                __bd_flags;     // partition number + flags
>


-- 
Best Regards,
  Yi Zhang

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Yu Kuai]

Hi,

在 2025/06/26 12:41, Yi Zhang 写道:
> Seems both the original and new warning are triggered, here is the full log:
> 
[...]

> [ 1022.263295] CPU: 12 UID: 0 PID: 466 Comm: kworker/12:1H Tainted: G
>        W           6.16.0-rc3.yu+ #2 PREEMPT(voluntary)
> [ 1022.291560] nvme nvme0: NVME-FC{0}: controller connect complete
> [ 1022.356344] Tainted: [W]=WARN
> [ 1022.356348] Hardware name: Dell Inc. PowerEdge R640/08HT8T, BIOS
> 2.22.2 09/12/2024
> [ 1022.356352] Workqueue: kblockd blk_mq_run_work_fn
> [ 1022.744652] RIP: 0010:bdev_end_io_acct+0x494/0x5c0
> [ 1022.749466] Code: 22 fd ff ff 48 c7 44 24 08 10 00 00 00 41 be 30
> 00 00 00 48 c7 04 24 50 00 00 00 e9 c3 fb ff ff 0f 1f 44 00 00 e9 f5
> fd ff ff <0f> 0b 48 83 c4 28 5b 5d 41 5c 41 5d 41 5e 41 5f c3 cc cc cc
> cc 48
> [ 1022.768235] RSP: 0018:ffffc9000f9f78e8 EFLAGS: 00010297
> [ 1022.773484] RAX: 00000000ffffffff RBX: ffff88a922776e64 RCX: ffffffffb003853f
> [ 1022.780632] RDX: ffffed15244eedcd RSI: 0000000000000004 RDI: ffff88a922776e64
> [ 1022.787784] RBP: ffffe8d448a4e440 R08: 0000000000000001 R09: ffffed15244eedcc
> [ 1022.794934] R10: ffff88a922776e67 R11: 0000000000000000 R12: ffff88a922776e68
> [ 1022.802101] R13: 0000000000000001 R14: 0000000000000028 R15: 0000000000007e42
> [ 1022.809251] FS:  0000000000000000(0000) GS:ffff889c3c5a7000(0000)
> knlGS:0000000000000000
> [ 1022.817352] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 1022.823114] CR2: 0000562e119bd048 CR3: 0000003661478001 CR4: 00000000007726f0
> [ 1022.830265] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 1022.837418] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [ 1022.844561] PKRU: 55555554
> [ 1022.847293] Call Trace:
> [ 1022.849762]  <TASK>
> [ 1022.851898]  nvme_end_req+0x4d/0x70 [nvme_core]
> [ 1022.856494]  nvme_failover_req+0x3bd/0x530 [nvme_core]
> [ 1022.861692]  nvme_fail_nonready_command+0x12c/0x170 [nvme_core]
> [ 1022.867666]  nvme_fc_queue_rq+0x463/0x720 [nvme_fc]

Thanks for the test, so nvme-mpath do have real problems. However, it's
still not clear to me and I'll send the revert first, because lots of
false warning are reported.

Kuai

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Yu Kuai]

Hi, Christoph

在 2025/06/26 12:41, Yi Zhang 写道:
> [ 1022.225513] ---[ end trace 0000000000000000 ]---
> [ 1022.263295] CPU: 12 UID: 0 PID: 466 Comm: kworker/12:1H Tainted: G
>        W           6.16.0-rc3.yu+ #2 PREEMPT(voluntary)
> [ 1022.291560] nvme nvme0: NVME-FC{0}: controller connect complete
> [ 1022.356344] Tainted: [W]=WARN
> [ 1022.356348] Hardware name: Dell Inc. PowerEdge R640/08HT8T, BIOS
> 2.22.2 09/12/2024
> [ 1022.356352] Workqueue: kblockd blk_mq_run_work_fn
> [ 1022.744652] RIP: 0010:bdev_end_io_acct+0x494/0x5c0
> [ 1022.749466] Code: 22 fd ff ff 48 c7 44 24 08 10 00 00 00 41 be 30
> 00 00 00 48 c7 04 24 50 00 00 00 e9 c3 fb ff ff 0f 1f 44 00 00 e9 f5
> fd ff ff <0f> 0b 48 83 c4 28 5b 5d 41 5c 41 5d 41 5e 41 5f c3 cc cc cc
> cc 48
> [ 1022.768235] RSP: 0018:ffffc9000f9f78e8 EFLAGS: 00010297
> [ 1022.773484] RAX: 00000000ffffffff RBX: ffff88a922776e64 RCX: ffffffffb003853f
> [ 1022.780632] RDX: ffffed15244eedcd RSI: 0000000000000004 RDI: ffff88a922776e64
> [ 1022.787784] RBP: ffffe8d448a4e440 R08: 0000000000000001 R09: ffffed15244eedcc
> [ 1022.794934] R10: ffff88a922776e67 R11: 0000000000000000 R12: ffff88a922776e68
> [ 1022.802101] R13: 0000000000000001 R14: 0000000000000028 R15: 0000000000007e42
> [ 1022.809251] FS:  0000000000000000(0000) GS:ffff889c3c5a7000(0000)
> knlGS:0000000000000000
> [ 1022.817352] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 1022.823114] CR2: 0000562e119bd048 CR3: 0000003661478001 CR4: 00000000007726f0
> [ 1022.830265] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 1022.837418] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [ 1022.844561] PKRU: 55555554
> [ 1022.847293] Call Trace:
> [ 1022.849762]  <TASK>
> [ 1022.851898]  nvme_end_req+0x4d/0x70 [nvme_core]
> [ 1022.856494]  nvme_failover_req+0x3bd/0x530 [nvme_core]
> [ 1022.861692]  nvme_fail_nonready_command+0x12c/0x170 [nvme_core]
> [ 1022.867666]  nvme_fc_queue_rq+0x463/0x720 [nvme_fc]

Just a quick look, look like this stack has a problem that the request
nevert started, however it still goes to the bdev_end_io_acct().

nvme_fc_queue_rq
  if (...)
   // nvme_start_request never called.
   return nvme_fail_nonready_command

I'm not that familiar with nvme-fc, does the following fix make sense to
you?

Thanks,
Kuai

diff --git a/drivers/nvme/host/fc.c b/drivers/nvme/host/fc.c
index 014b387f1e8b..4b8f08be24a7 100644
--- a/drivers/nvme/host/fc.c
+++ b/drivers/nvme/host/fc.c
@@ -2765,8 +2765,10 @@ nvme_fc_queue_rq(struct blk_mq_hw_ctx *hctx,
         blk_status_t ret;

         if (ctrl->rport->remoteport.port_state != FC_OBJSTATE_ONLINE ||
-           !nvme_check_ready(&queue->ctrl->ctrl, rq, queue_ready))
+           !nvme_check_ready(&queue->ctrl->ctrl, rq, queue_ready)) {
+               nvme_clear_nvme_request(rq);
                 return nvme_fail_nonready_command(&queue->ctrl->ctrl, rq);
+       }

         ret = nvme_setup_cmd(ns, rq);
         if (ret)

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Yu Kuai]

在 2025/06/06 11:31, Yi Zhang 写道:
> Hello
> 
> The following WARNING was triggered by blktests nvme/fc nvme/012,
> please help check and let me know if you need any info/test, thanks.
> 
> commit: linux-block: 38f4878b9463 (HEAD, origin/for-next) Merge branch
> 'block-6.16' into for-next
> 
> [ 2679.835074] run blktests nvme/012 at 2025-06-05 19:50:45
> [ 2681.492049] loop0: detected capacity change from 0 to 2097152
> [ 2681.678145] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
> [ 2682.883261] nvme nvme0: NVME-FC{0}: create association : host wwpn
> 0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
> "blktests-subsystem-1"
> [ 2682.895317] (NULL device *): {0:0} Association created
> [ 2682.902895] nvmet: Created nvm controller 1 for subsystem
> blktests-subsystem-1 for NQN
> nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
> [ 2682.970869] nvme nvme0: NVME-FC{0}: controller connect complete
> [ 2682.970996] nvme nvme0: NVME-FC{0}: new ctrl: NQN
> "blktests-subsystem-1", hostnqn:
> nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349
> [ 2685.498124] XFS (nvme0n1): Mounting V5 Filesystem
> 3f19217c-d3fd-42af-9dbe-aa5dce6bb607
> [ 2685.567936] XFS (nvme0n1): Ending clean mount
> [ 2746.161840] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 0 fctype 1
> (I/O Cmd) w10/11: x00000000/x00000000
> [ 2746.163061] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0010007a/x00000000
> [ 2746.163126] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001000ba/x00000000
> [ 2746.163175] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001000fa/x00000000
> [ 2746.163220] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0010013a/x00000000
> [ 2746.163265] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0010017a/x00000000
> [ 2746.163308] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001001ba/x00000000
> [ 2746.163352] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001001fa/x00000000
> [ 2746.163396] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001d8618/x00000000
> [ 2746.163441] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000d9d88/x00000000
> [ 2746.163486] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00014be0/x00000000
> [ 2746.163531] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001bb168/x00000000
> [ 2746.163585] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0006b620/x00000000
> [ 2746.163639] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000b6688/x00000000
> [ 2746.164885] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000581c0/x00000000
> [ 2746.166593] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001468c0/x00000000
> [ 2746.166681] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00080780/x00000000
> [ 2746.166732] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00147338/x00000000
> [ 2746.166780] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000acee8/x00000000
> [ 2746.166826] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00016e20/x00000000
> [ 2746.166872] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0019add0/x00000000
> [ 2746.166916] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001bdab8/x00000000
> [ 2746.166960] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000ea0f8/x00000000
> [ 2746.167005] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00006328/x00000000
> [ 2746.170320] nvme nvme0: NVME-FC{0}: transport association event:
> transport detected io error
> [ 2746.173629] nvme nvme0: NVME-FC{0}: resetting controller
> [ 2746.175966] block nvme0n1: no usable path - requeuing I/O
> [ 2746.177234] block nvme0n1: no usable path - requeuing I/O
> [ 2746.177571] block nvme0n1: no usable path - requeuing I/O
> [ 2746.177916] block nvme0n1: no usable path - requeuing I/O
> [ 2746.178228] block nvme0n1: no usable path - requeuing I/O
> [ 2746.178576] block nvme0n1: no usable path - requeuing I/O
> [ 2746.179173] block nvme0n1: no usable path - requeuing I/O
> [ 2746.179476] block nvme0n1: no usable path - requeuing I/O
> [ 2746.179807] block nvme0n1: no usable path - requeuing I/O
> [ 2746.180146] block nvme0n1: no usable path - requeuing I/O
> [ 2746.232899] nvme nvme0: NVME-FC{0}: create association : host wwpn
> 0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
> "blktests-subsystem-1"
> [ 2746.238446] (NULL device *): {0:1} Association created
> [ 2746.239620] nvmet: Created nvm controller 2 for subsystem
> blktests-subsystem-1 for NQN
> nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
> [ 2746.259174] (NULL device *): {0:0} Association deleted
> [ 2746.296717] nvme nvme0: NVME-FC{0}: controller connect complete
> [ 2755.870750] nvmet: ctrl 1 keep-alive timer (5 seconds) expired!
> [ 2755.873263] nvmet: ctrl 1 fatal error occurred!
> [ 2769.422990] (NULL device *): Disconnect LS failed: No Association
> [ 2769.424288] (NULL device *): {0:0} Association freed
> [ 2801.582208] perf: interrupt took too long (2527 > 2500), lowering
> kernel.perf_event_max_sample_rate to 79000
> [ 2830.657742] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000a06a8/x00000000
> [ 2830.657865] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000994d0/x00000000
> [ 2830.657916] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000263b8/x00000000
> [ 2830.657965] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000ecf10/x00000000
> [ 2830.658010] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00054418/x00000000
> [ 2830.658071] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001f42f0/x00000000
> [ 2830.658088] nvme nvme0: NVME-FC{0}: transport association event:
> transport detected io error
> [ 2830.658119] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000bb588/x00000000
> [ 2830.659087] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000fd620/x00000000
> [ 2830.659134] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000d66b0/x00000000
> [ 2830.659189] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00188488/x00000000
> [ 2830.659233] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00086fd0/x00000000
> [ 2830.659276] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001a0950/x00000000
> [ 2830.659345] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00136340/x00000000
> [ 2830.659390] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0013dc60/x00000000
> [ 2830.659433] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00193530/x00000000
> [ 2830.659500] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001d3ff0/x00000000
> [ 2830.659545] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00101455/x00000000
> [ 2830.659589] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00101495/x00000000
> [ 2830.659650] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001014d5/x00000000
> [ 2830.659758] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00101515/x00000000
> [ 2830.659842] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00101555/x00000000
> [ 2830.659889] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00101595/x00000000
> [ 2830.659904] nvme nvme0: NVME-FC{0}: resetting controller
> [ 2830.659941] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001015d5/x00000000
> [ 2830.660321] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 0 fctype 1
> (I/O Cmd) w10/11: x00000000/x00000000
> [ 2830.660348] nvme_ns_head_submit_bio: 81 callbacks suppressed
> [ 2830.660362] block nvme0n1: no usable path - requeuing I/O
> [ 2830.661765] block nvme0n1: no usable path - requeuing I/O
> [ 2830.662070] block nvme0n1: no usable path - requeuing I/O
> [ 2830.662367] block nvme0n1: no usable path - requeuing I/O
> [ 2830.662660] block nvme0n1: no usable path - requeuing I/O
> [ 2830.663046] block nvme0n1: no usable path - requeuing I/O
> [ 2830.663337] block nvme0n1: no usable path - requeuing I/O
> [ 2830.663627] block nvme0n1: no usable path - requeuing I/O
> [ 2830.663976] block nvme0n1: no usable path - requeuing I/O
> [ 2830.664288] block nvme0n1: no usable path - requeuing I/O
> [ 2830.700704] nvme nvme0: NVME-FC{0}: create association : host wwpn
> 0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
> "blktests-subsystem-1"
> [ 2830.706376] (NULL device *): {0:0} Association created
> [ 2830.707571] nvmet: Created nvm controller 1 for subsystem
> blktests-subsystem-1 for NQN
> nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
> [ 2830.725113] (NULL device *): {0:1} Association deleted
> [ 2830.745872] ------------[ cut here ]------------
> [ 2830.746780] WARNING: CPU: 49 PID: 1020 at block/genhd.c:146
> bdev_count_inflight_rw+0x2a6/0x410
> [ 2830.747730] Modules linked in: nvme_fcloop nvmet_fc nvmet nvme_fc
> nvme_fabrics nvme_core nvme_keyring nvme_auth rfkill sunrpc
> intel_rapl_msr intel_rapl_common intel_uncore_frequency
> intel_uncore_frequency_common sb_edac x86_pkg_temp_thermal
> intel_powerclamp coretemp kvm_intel vfat
> [ 2830.748536] nvme nvme0: NVME-FC{0}: controller connect complete
> [ 2830.749958]  fat kvm irqbypass iTCO_wdt rapl iTCO_vendor_support
> intel_cstate intel_uncore pcspkr bnx2x mgag200 i2c_i801 tg3 i2c_smbus
> lpc_ich i2c_algo_bit hpilo ioatdma mdio dca ipmi_ssif ipmi_si acpi_tad
> acpi_power_meter acpi_ipmi ipmi_devintf ipmi_msghandler dax_pmem sg
> fuse loop nfnetlink xfs nd_pmem sr_mod sd_mod cdrom
> ghash_clmulni_intel hpsa scsi_transport_sas hpwdt ahci libahci libata
> wmi nfit libnvdimm dm_mirror dm_region_hash dm_log dm_mod [last
> unloaded: nvmet]
> [ 2830.752807] CPU: 49 UID: 0 PID: 1020 Comm: kworker/49:1H Not
> tainted 6.15.0+ #2 PREEMPT(lazy)
> [ 2830.753650] Hardware name: HP ProLiant DL380 Gen9/ProLiant DL380
> Gen9, BIOS P89 10/05/2016
> [ 2830.754291] Workqueue: kblockd nvme_requeue_work [nvme_core]
> [ 2830.755188] RIP: 0010:bdev_count_inflight_rw+0x2a6/0x410
> [ 2830.755503] Code: fa 48 c1 ea 03 0f b6 14 02 4c 89 f8 83 e0 07 83
> c0 03 38 d0 7c 08 84 d2 0f 85 59 01 00 00 41 c7 07 00 00 00 00 e9 75
> ff ff ff <0f> 0b 48 b8 00 00 00 00 00 fc ff df 4c 89 f2 48 c1 ea 03 0f
> b6 14
> [ 2830.756887] RSP: 0018:ffffc9000ad973e8 EFLAGS: 00010286
> [ 2830.757221] RAX: 00000000ffffffff RBX: 0000000000000048 RCX: ffffffffa9b9ee56
> [ 2830.758007] RDX: 0000000000000000 RSI: 0000000000000048 RDI: ffffffffac36b380
> [ 2830.758831] RBP: ffffe8ffffa33758 R08: 0000000000000000 R09: fffff91ffff466fd
> [ 2830.759609] R10: ffffe8ffffa337ef R11: 0000000000000001 R12: ffff888121d16200
> [ 2830.760405] R13: dffffc0000000000 R14: ffffc9000ad97474 R15: ffffc9000ad97470
> [ 2830.761226] FS:  0000000000000000(0000) GS:ffff888440550000(0000)
> knlGS:0000000000000000
> [ 2830.761724] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 2830.762472] CR2: 000055aa8905b038 CR3: 0000000bfae7a001 CR4: 00000000003726f0
> [ 2830.763293] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 2830.764124] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [ 2830.764921] Call Trace:
> [ 2830.765087]  <TASK>
> [ 2830.765625]  bdev_count_inflight+0x6d/0xa0
> [ 2830.765921]  ? __pfx_bdev_count_inflight+0x10/0x10
> [ 2830.766604]  update_io_ticks+0x1bd/0x210
> [ 2830.789758]  ? __pfx_update_io_ticks+0x10/0x10
> [ 2830.823941]  ? nvme_fc_map_data+0x1d0/0x860 [nvme_fc]
> [ 2830.861999]  bdev_start_io_acct+0x31/0xe0
> [ 2830.893416]  nvme_mpath_start_request+0x222/0x390 [nvme_core]
> [ 2830.934768]  nvme_fc_start_fcp_op+0xc4c/0xfe0 [nvme_fc]
> [ 2830.973158]  ? trace_nvme_setup_cmd+0x149/0x1b0 [nvme_core]
> [ 2831.011196]  ? __pfx_nvme_fc_start_fcp_op+0x10/0x10 [nvme_fc]
> [ 2831.050102]  ? nvme_fc_queue_rq+0x1b6/0x4c0 [nvme_fc]
> [ 2831.085274]  __blk_mq_issue_directly+0xe1/0x1c0
> [ 2831.117939]  ? __pfx___blk_mq_issue_directly+0x10/0x10
> [ 2831.153586]  ? blk_mq_request_issue_directly+0xc6/0x190
> [ 2831.189705]  blk_mq_issue_direct+0x16b/0x690
> [ 2831.220964]  ? lock_acquire+0x10b/0x150
> [ 2831.249564]  blk_mq_dispatch_queue_requests+0x31c/0x640
> [ 2831.267274]  blk_mq_flush_plug_list+0x187/0x6a0
> [ 2831.267940]  ? trace_block_plug+0x15e/0x1e0
> [ 2831.268164]  ? blk_add_rq_to_plug+0x2cf/0x460
> [ 2831.268799]  ? rcu_is_watching+0x15/0xb0
> [ 2831.269033]  ? __pfx_blk_mq_flush_plug_list+0x10/0x10
> [ 2831.269316]  ? blk_mq_submit_bio+0x10cc/0x1bc0
> [ 2831.269969]  __blk_flush_plug+0x27b/0x4d0
> [ 2831.270200]  ? find_held_lock+0x32/0x90
> [ 2831.270426]  ? __pfx___blk_flush_plug+0x10/0x10
> [ 2831.271079]  ? percpu_ref_put_many.constprop.0+0x7a/0x1b0
> [ 2831.271380]  __submit_bio+0x49b/0x600
> [ 2831.271594]  ? __pfx___submit_bio+0x10/0x10
> [ 2831.271843]  ? raw_spin_rq_lock_nested+0x2e/0x130
> [ 2831.272506]  ? __submit_bio_noacct+0x16d/0x5b0
> [ 2831.273157]  __submit_bio_noacct+0x16d/0x5b0
> [ 2831.273805]  ? find_held_lock+0x32/0x90
> [ 2831.274035]  ? local_clock_noinstr+0xd/0xe0
> [ 2831.274251]  ? __pfx___submit_bio_noacct+0x10/0x10
> [ 2831.274901]  ? ktime_get+0x164/0x200
> [ 2831.275127]  ? lockdep_hardirqs_on+0x78/0x100
> [ 2831.275777]  ? ktime_get+0xb0/0x200
> [ 2831.276382]  submit_bio_noacct_nocheck+0x4e1/0x630
> [ 2831.302650]  ? __pfx___might_resched+0x10/0x10
> [ 2831.334528]  ? __pfx_submit_bio_noacct_nocheck+0x10/0x10
> [ 2831.371424]  ? should_fail_bio+0xb5/0x150
> [ 2831.400963]  ? submit_bio_noacct+0x9ba/0x1b30
> [ 2831.432384]  nvme_requeue_work+0xa6/0xd0 [nvme_core]

Looks like this problem is related to nvme mpath, and it's using
bio based disk IO accounting. I'm not familiar with this driver,
however, can you try the following bpftrace script to check if
start request and end request are balanced? From the log I guess
it's related to mpath error handler, probably requeuing I/O.

k:nvme_mpath_start_request
{
         @rq[arg0] = 1;
}

k:nvme_mpath_end_request
{
         if (@rq[arg0]) {
                 delete(@rq[arg0]);
         } else {
                 printf("leak end request counter\n %s\n", kstack());
         }
}

And can you test the following patch?

diff --git a/drivers/nvme/host/multipath.c b/drivers/nvme/host/multipath.c
index 878ea8b1a0ac..ad366f0fd8cb 100644
--- a/drivers/nvme/host/multipath.c
+++ b/drivers/nvme/host/multipath.c
@@ -200,14 +200,17 @@ void nvme_mpath_end_request(struct request *rq)
  {
         struct nvme_ns *ns = rq->q->queuedata;

-       if (nvme_req(rq)->flags & NVME_MPATH_CNT_ACTIVE)
+       if (nvme_req(rq)->flags & NVME_MPATH_CNT_ACTIVE) {
                 atomic_dec_if_positive(&ns->ctrl->nr_active);
+               nvme_req(rq)->flags &= ~NVME_MPATH_CNT_ACTIVE;
+       }

-       if (!(nvme_req(rq)->flags & NVME_MPATH_IO_STATS))
-               return;
-       bdev_end_io_acct(ns->head->disk->part0, req_op(rq),
-                        blk_rq_bytes(rq) >> SECTOR_SHIFT,
-                        nvme_req(rq)->start_time);
+       if (nvme_req(rq)->flags & NVME_MPATH_IO_STATS) {
+               bdev_end_io_acct(ns->head->disk->part0, req_op(rq),
+                                blk_rq_bytes(rq) >> SECTOR_SHIFT,
+                                nvme_req(rq)->start_time);
+               nvme_req(rq)->flags &= ~NVME_MPATH_IO_STATS;
+       }
  }

  void nvme_kick_requeue_lists(struct nvme_ctrl *ctrl)


Thanks,
Kuai
> [ 2831.467097]  process_one_work+0xd8b/0x1320
> [ 2831.497417]  ? __pfx_process_one_work+0x10/0x10
> [ 2831.529776]  ? assign_work+0x16c/0x240
> [ 2831.557932]  worker_thread+0x5f3/0xfe0
> [ 2831.586080]  ? __kthread_parkme+0xb4/0x200
> [ 2831.616411]  ? __pfx_worker_thread+0x10/0x10
> [ 2831.647363]  kthread+0x3b4/0x770
> [ 2831.672690]  ? local_clock_noinstr+0xd/0xe0
> [ 2831.703340]  ? __pfx_kthread+0x10/0x10
> [ 2831.732902]  ? __lock_release.isra.0+0x1a4/0x2c0
> [ 2831.766864]  ? rcu_is_watching+0x15/0xb0
> [ 2831.796921]  ? __pfx_kthread+0x10/0x10
> [ 2831.826375]  ret_from_fork+0x393/0x480
> [ 2831.855873]  ? __pfx_kthread+0x10/0x10
> [ 2831.885038]  ? __pfx_kthread+0x10/0x10
> [ 2831.914099]  ret_from_fork_asm+0x1a/0x30
> [ 2831.944085]  </TASK>
> [ 2831.964399] irq event stamp: 55415
> [ 2831.991755] hardirqs last  enabled at (55425): [<ffffffffa8cd533e>]
> __up_console_sem+0x5e/0x80
> [ 2832.047850] hardirqs last disabled at (55440): [<ffffffffa8cd5323>]
> __up_console_sem+0x43/0x80
> [ 2832.104417] softirqs last  enabled at (55438): [<ffffffffa8afce0b>]
> handle_softirqs+0x62b/0x890
> [ 2832.161018] softirqs last disabled at (55459): [<ffffffffa8afd1fd>]
> __irq_exit_rcu+0xfd/0x250
> [ 2832.216709] ---[ end trace 0000000000000000 ]---
> [ 2840.350778] nvmet: ctrl 2 keep-alive timer (5 seconds) expired!
> [ 2840.351593] nvmet: ctrl 2 fatal error occurred!
> [ 2851.548112] (NULL device *): {0:1} Association freed
> [ 2851.548216] (NULL device *): Disconnect LS failed: No Association
> [ 2912.554772] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001e2628/x00000000
> [ 2912.554869] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001f66b8/x00000000
> [ 2912.554920] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001dcbe0/x00000000
> [ 2912.554997] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001b3b88/x00000000
> [ 2912.555105] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001efe68/x00000000
> [ 2912.555121] nvme nvme0: NVME-FC{0}: transport association event:
> transport detected io error
> [ 2912.555196] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000f31d0/x00000000
> [ 2912.556040] nvme nvme0: NVME-FC{0}: resetting controller
> [ 2912.557078] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000c39c8/x00000000
> [ 2912.557173] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000998e0/x00000000
> [ 2912.557257] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000dd468/x00000000
> [ 2912.557304] nvme_ns_head_submit_bio: 66 callbacks suppressed
> [ 2912.557321] block nvme0n1: no usable path - requeuing I/O
> [ 2912.557348] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00061990/x00000000
> [ 2912.558132] block nvme0n1: no usable path - requeuing I/O
> [ 2912.558501] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000ee800/x00000000
> [ 2912.558732] block nvme0n1: no usable path - requeuing I/O
> [ 2912.558755] block nvme0n1: no usable path - requeuing I/O
> [ 2912.559093] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0000dff0/x00000000
> [ 2912.559310] block nvme0n1: no usable path - requeuing I/O
> [ 2912.559374] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000fba20/x00000000
> [ 2912.559622] block nvme0n1: no usable path - requeuing I/O
> [ 2912.559722] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000ce700/x00000000
> [ 2912.559938] block nvme0n1: no usable path - requeuing I/O
> [ 2912.559989] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00066cc0/x00000000
> [ 2912.560240] block nvme0n1: no usable path - requeuing I/O
> [ 2912.560309] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00080e00/x00000000
> [ 2912.560543] block nvme0n1: no usable path - requeuing I/O
> [ 2912.560603] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00102d93/x00000000
> [ 2912.560920] block nvme0n1: no usable path - requeuing I/O
> [ 2912.560973] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00102dd3/x00000000
> [ 2912.561286] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00102e13/x00000000
> [ 2912.561384] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00102e53/x00000000
> [ 2912.561489] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00102e93/x00000000
> [ 2912.561573] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 0 fctype 1
> (I/O Cmd) w10/11: x00000000/x00000000
> [ 2912.590374] nvme nvme0: NVME-FC{0}: create association : host wwpn
> 0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
> "blktests-subsystem-1"
> [ 2912.595940] (NULL device *): {0:1} Association created
> [ 2912.597107] nvmet: Created nvm controller 2 for subsystem
> blktests-subsystem-1 for NQN
> nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
> [ 2912.623269] (NULL device *): {0:0} Association deleted
> [ 2912.636244] nvme nvme0: NVME-FC{0}: controller connect complete
> [ 2919.293060] perf: interrupt took too long (3266 > 3158), lowering
> kernel.perf_event_max_sample_rate to 61000
> [ 2922.270774] nvmet: ctrl 1 keep-alive timer (5 seconds) expired!
> [ 2922.271738] nvmet: ctrl 1 fatal error occurred!
> [ 2934.302272] (NULL device *): {0:0} Association freed
> [ 2934.302378] (NULL device *): Disconnect LS failed: No Association
> [ 2995.509865] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 0 fctype 1
> (I/O Cmd) w10/11: x00000000/x00000000
> [ 2995.509964] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00104d98/x00000000
> [ 2995.510013] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00104dd8/x00000000
> [ 2995.510062] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00104e18/x00000000
> [ 2995.510108] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0019b148/x00000000
> [ 2995.510154] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000e1688/x00000000
> [ 2995.510213] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001941f8/x00000000
> [ 2995.510243] nvme nvme0: NVME-FC{0}: transport association event:
> transport detected io error
> [ 2995.510264] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00057bd8/x00000000
> [ 2995.511324] nvme nvme0: NVME-FC{0}: resetting controller
> [ 2995.511353] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001d6a18/x00000000
> [ 2995.511672] nvme_ns_head_submit_bio: 137 callbacks suppressed
> [ 2995.511736] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001c8c50/x00000000
> [ 2995.512440] block nvme0n1: no usable path - requeuing I/O
> [ 2995.512453] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001f8ae8/x00000000
> [ 2995.512809] block nvme0n1: no usable path - requeuing I/O
> [ 2995.512829] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00185638/x00000000
> [ 2995.513122] block nvme0n1: no usable path - requeuing I/O
> [ 2995.513152] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000be958/x00000000
> [ 2995.513426] block nvme0n1: no usable path - requeuing I/O
> [ 2995.513456] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00072188/x00000000
> [ 2995.513766] block nvme0n1: no usable path - requeuing I/O
> [ 2995.513797] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0006cfa0/x00000000
> [ 2995.514076] block nvme0n1: no usable path - requeuing I/O
> [ 2995.514101] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001b8d68/x00000000
> [ 2995.514368] block nvme0n1: no usable path - requeuing I/O
> [ 2995.514399] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000bbf70/x00000000
> [ 2995.514648] block nvme0n1: no usable path - requeuing I/O
> [ 2995.514679] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00049d80/x00000000
> [ 2995.514990] block nvme0n1: no usable path - requeuing I/O
> [ 2995.515005] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001ab7b8/x00000000
> [ 2995.515291] block nvme0n1: no usable path - requeuing I/O
> [ 2995.515323] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000aa258/x00000000
> [ 2995.581458] nvme nvme0: NVME-FC{0}: create association : host wwpn
> 0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
> "blktests-subsystem-1"
> [ 2995.587043] (NULL device *): {0:0} Association created
> [ 2995.588238] nvmet: Created nvm controller 1 for subsystem
> blktests-subsystem-1 for NQN
> nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
> [ 2995.598095] (NULL device *): {0:1} Association deleted
> [ 2995.629543] nvme nvme0: NVME-FC{0}: controller connect complete
> [ 3006.238795] nvmet: ctrl 2 keep-alive timer (5 seconds) expired!
> [ 3006.239676] nvmet: ctrl 2 fatal error occurred!
> [ 3016.812134] (NULL device *): {0:1} Association freed
> [ 3016.812234] (NULL device *): Disconnect LS failed: No Association
> [ 3077.954779] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 0 fctype 1
> (I/O Cmd) w10/11: x00000000/x00000000
> [ 3077.954930] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00107368/x00000000
> [ 3077.956502] nvme nvme0: NVME-FC{0}: transport association event:
> transport detected io error
> [ 3077.956501] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001073a8/x00000000
> [ 3077.957556] nvme nvme0: NVME-FC{0}: resetting controller
> [ 3077.957592] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001d98b8/x00000000
> [ 3077.957995] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00013600/x00000000
> [ 3077.958084] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000111f0/x00000000
> [ 3077.958143] nvme_ns_head_submit_bio: 50 callbacks suppressed
> [ 3077.958159] block nvme0n1: no usable path - requeuing I/O
> [ 3077.958182] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000bae28/x00000000
> [ 3077.959136] block nvme0n1: no usable path - requeuing I/O
> [ 3077.959529] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001d8c98/x00000000
> [ 3077.959764] block nvme0n1: no usable path - requeuing I/O
> [ 3077.959837] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0008cf40/x00000000
> [ 3077.960077] block nvme0n1: no usable path - requeuing I/O
> [ 3077.960143] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001d3578/x00000000
> [ 3077.960453] block nvme0n1: no usable path - requeuing I/O
> [ 3077.960518] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00064990/x00000000
> [ 3077.960773] block nvme0n1: no usable path - requeuing I/O
> [ 3077.960853] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000b4710/x00000000
> [ 3077.961078] block nvme0n1: no usable path - requeuing I/O
> [ 3077.961139] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00085db8/x00000000
> [ 3077.961368] block nvme0n1: no usable path - requeuing I/O
> [ 3077.961435] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00069120/x00000000
> [ 3077.961655] block nvme0n1: no usable path - requeuing I/O
> [ 3077.961753] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0013bf18/x00000000
> [ 3077.961974] block nvme0n1: no usable path - requeuing I/O
> [ 3077.962012] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0014fa40/x00000000
> [ 3077.962334] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000521c8/x00000000
> [ 3077.962423] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00015478/x00000000
> [ 3077.962519] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00006610/x00000000
> [ 3078.007378] nvme nvme0: NVME-FC{0}: create association : host wwpn
> 0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
> "blktests-subsystem-1"
> [ 3078.013515] (NULL device *): {0:1} Association created
> [ 3078.014685] nvmet: Created nvm controller 2 for subsystem
> blktests-subsystem-1 for NQN
> nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
> [ 3078.023212] (NULL device *): {0:0} Association deleted
> [ 3078.054495] nvme nvme0: NVME-FC{0}: controller connect complete
> [ 3087.646802] nvmet: ctrl 1 keep-alive timer (5 seconds) expired!
> [ 3087.647785] nvmet: ctrl 1 fatal error occurred!
> [ 3100.716095] (NULL device *): {0:0} Association freed
> [ 3100.716200] (NULL device *): Disconnect LS failed: No Association
> [ 3161.908938] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001f2700/x00000000
> [ 3161.909035] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00037618/x00000000
> [ 3161.909088] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001df730/x00000000
> [ 3161.909137] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000bca30/x00000000
> [ 3161.909200] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001e35c8/x00000000
> [ 3161.909245] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001bd010/x00000000
> [ 3161.909299] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00127fb0/x00000000
> [ 3161.909334] nvme nvme0: NVME-FC{0}: transport association event:
> transport detected io error
> [ 3161.909350] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0016d498/x00000000
> [ 3161.909418] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0008a318/x00000000
> [ 3161.910296] nvme nvme0: NVME-FC{0}: resetting controller
> [ 3161.910498] nvme_ns_head_submit_bio: 84 callbacks suppressed
> [ 3161.910520] block nvme0n1: no usable path - requeuing I/O
> [ 3161.910760] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000b5568/x00000000
> [ 3161.911637] block nvme0n1: no usable path - requeuing I/O
> [ 3161.911940] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001cb018/x00000000
> [ 3161.912197] block nvme0n1: no usable path - requeuing I/O
> [ 3161.912224] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001babe0/x00000000
> [ 3161.912541] block nvme0n1: no usable path - requeuing I/O
> [ 3161.912562] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000fad88/x00000000
> [ 3161.912874] block nvme0n1: no usable path - requeuing I/O
> [ 3161.912902] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00188490/x00000000
> [ 3161.913200] block nvme0n1: no usable path - requeuing I/O
> [ 3161.913229] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000d5000/x00000000
> [ 3161.913530] block nvme0n1: no usable path - requeuing I/O
> [ 3161.913559] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000c6df8/x00000000
> [ 3161.913850] block nvme0n1: no usable path - requeuing I/O
> [ 3161.913927] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 0 fctype 1
> (I/O Cmd) w10/11: x00000000/x00000000
> [ 3161.914195] block nvme0n1: no usable path - requeuing I/O
> [ 3161.914232] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00109ad8/x00000000
> [ 3161.914675] block nvme0n1: no usable path - requeuing I/O
> [ 3161.914696] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00109b18/x00000000
> [ 3161.915023] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00109b58/x00000000
> [ 3161.915068] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00109b98/x00000000
> [ 3161.915112] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00109bd8/x00000000
> [ 3161.956466] nvme nvme0: NVME-FC{0}: create association : host wwpn
> 0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
> "blktests-subsystem-1"
> [ 3161.962211] (NULL device *): {0:0} Association created
> [ 3161.963374] nvmet: Created nvm controller 1 for subsystem
> blktests-subsystem-1 for NQN
> nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
> [ 3161.975270] (NULL device *): {0:1} Association deleted
> [ 3162.006074] nvme nvme0: NVME-FC{0}: controller connect complete
> [ 3172.126859] nvmet: ctrl 2 keep-alive timer (5 seconds) expired!
> [ 3172.127623] nvmet: ctrl 2 fatal error occurred!
> [ 3184.377203] (NULL device *): {0:1} Association freed
> [ 3184.377314] (NULL device *): Disconnect LS failed: No Association
> [ 3245.358575] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000b4340/x00000000
> [ 3245.358682] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0000a050/x00000000
> [ 3245.358821] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0002b1e8/x00000000
> [ 3245.358881] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00033980/x00000000
> [ 3245.358933] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00051468/x00000000
> [ 3245.359006] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001f3dc0/x00000000
> [ 3245.359032] nvme nvme0: NVME-FC{0}: transport association event:
> transport detected io error
> [ 3245.359057] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000d1f18/x00000000
> [ 3245.359972] nvme nvme0: NVME-FC{0}: resetting controller
> [ 3245.360010] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000915c0/x00000000
> [ 3245.360351] nvme_ns_head_submit_bio: 82 callbacks suppressed
> [ 3245.360374] block nvme0n1: no usable path - requeuing I/O
> [ 3245.360400] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00081080/x00000000
> [ 3245.361245] block nvme0n1: no usable path - requeuing I/O
> [ 3245.361264] block nvme0n1: no usable path - requeuing I/O
> [ 3245.361652] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001d41e8/x00000000
> [ 3245.361914] block nvme0n1: no usable path - requeuing I/O
> [ 3245.361937] block nvme0n1: no usable path - requeuing I/O
> [ 3245.361950] block nvme0n1: no usable path - requeuing I/O
> [ 3245.361964] block nvme0n1: no usable path - requeuing I/O
> [ 3245.361977] block nvme0n1: no usable path - requeuing I/O
> [ 3245.364224] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00089910/x00000000
> [ 3245.364281] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001938d0/x00000000
> [ 3245.364332] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00146ae0/x00000000
> [ 3245.364383] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001692d0/x00000000
> [ 3245.364435] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001f23b0/x00000000
> [ 3245.364488] block nvme0n1: no usable path - requeuing I/O
> [ 3245.364497] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0009ec68/x00000000
> [ 3245.364545] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0010c6f2/x00000000
> [ 3245.364874] block nvme0n1: no usable path - requeuing I/O
> [ 3245.365277] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0010c732/x00000000
> [ 3245.365322] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0010c772/x00000000
> [ 3245.365350] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0010c7b2/x00000000
> [ 3245.365377] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0010c7f2/x00000000
> [ 3245.365406] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 0 fctype 1
> (I/O Cmd) w10/11: x00000000/x00000000
> [ 3245.399397] nvme nvme0: NVME-FC{0}: create association : host wwpn
> 0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
> "blktests-subsystem-1"
> [ 3245.404662] (NULL device *): {0:1} Association created
> [ 3245.405845] nvmet: Created nvm controller 2 for subsystem
> blktests-subsystem-1 for NQN
> nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
> [ 3245.414713] (NULL device *): {0:0} Association deleted
> [ 3245.439156] nvme nvme0: NVME-FC{0}: controller connect complete
> [ 3255.070828] nvmet: ctrl 1 keep-alive timer (5 seconds) expired!
> [ 3255.071589] nvmet: ctrl 1 fatal error occurred!
> [ 3270.991000] (NULL device *): {0:0} Association freed
> [ 3270.991124] (NULL device *): Disconnect LS failed: No Association
> [ 3287.286065] perf: interrupt took too long (4088 > 4082), lowering
> kernel.perf_event_max_sample_rate to 48000
> [ 3331.891056] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000bda00/x00000000
> [ 3331.891152] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001543d8/x00000000
> [ 3331.891202] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00074e10/x00000000
> [ 3331.891252] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0001a388/x00000000
> [ 3331.891319] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001b2360/x00000000
> [ 3331.891376] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00169330/x00000000
> [ 3331.891421] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001d0e70/x00000000
> [ 3331.891431] nvme nvme0: NVME-FC{0}: transport association event:
> transport detected io error
> [ 3331.891473] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000d1d28/x00000000
> [ 3331.892414] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x001cfc50/x00000000
> [ 3331.892497] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000abb28/x00000000
> [ 3331.892581] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0002ee28/x00000000
> [ 3331.892673] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0008a438/x00000000
> [ 3331.892801] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0015e2d8/x00000000
> [ 3331.892901] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x000d12b8/x00000000
> [ 3331.893010] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00159e58/x00000000
> [ 3331.893096] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x00097190/x00000000
> [ 3331.893115] nvme nvme0: NVME-FC{0}: resetting controller
> [ 3331.893158] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 0 fctype 1
> (I/O Cmd) w10/11: x00000000/x00000000
> [ 3331.893514] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0010f20c/x00000000
> [ 3331.893558] nvme_ns_head_submit_bio: 93 callbacks suppressed
> [ 3331.893572] block nvme0n1: no usable path - requeuing I/O
> [ 3331.893575] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0010f24c/x00000000
> [ 3331.893617] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0010f28c/x00000000
> [ 3331.894339] block nvme0n1: no usable path - requeuing I/O
> [ 3331.894678] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> (I/O Cmd) w10/11: x0010f2cc/x00000000
> [ 3331.894982] block nvme0n1: no usable path - requeuing I/O
> [ 3331.895321] block nvme0n1: no usable path - requeuing I/O
> [ 3331.895611] block nvme0n1: no usable path - requeuing I/O
> [ 3331.895933] block nvme0n1: no usable path - requeuing I/O
> [ 3331.896290] block nvme0n1: no usable path - requeuing I/O
> [ 3331.896594] block nvme0n1: no usable path - requeuing I/O
> [ 3331.896913] block nvme0n1: no usable path - requeuing I/O
> [ 3331.897251] block nvme0n1: no usable path - requeuing I/O
> [ 3331.937837] nvme nvme0: NVME-FC{0}: create association : host wwpn
> 0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
> "blktests-subsystem-1"
> [ 3331.943499] (NULL device *): {0:0} Association created
> [ 3331.944725] nvmet: Created nvm controller 1 for subsystem
> blktests-subsystem-1 for NQN
> nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
> [ 3331.976229] (NULL device *): {0:1} Association deleted
> [ 3331.984385] nvme nvme0: NVME-FC{0}: controller connect complete
> [ 3341.015948] ------------[ cut here ]------------
> [ 3341.017039] WARNING: CPU: 3 PID: 522 at block/genhd.c:144
> bdev_count_inflight_rw+0x26e/0x410
> [ 3341.018176] Modules linked in: nvme_fcloop nvmet_fc nvmet nvme_fc
> nvme_fabrics nvme_core nvme_keyring nvme_auth rfkill sunrpc
> intel_rapl_msr intel_rapl_common intel_uncore_frequency
> intel_uncore_frequency_common sb_edac x86_pkg_temp_thermal
> intel_powerclamp coretemp kvm_intel vfat fat kvm irqbypass iTCO_wdt
> rapl iTCO_vendor_support intel_cstate intel_uncore pcspkr bnx2x
> mgag200 i2c_i801 tg3 i2c_smbus lpc_ich i2c_algo_bit hpilo ioatdma mdio
> dca ipmi_ssif ipmi_si acpi_tad acpi_power_meter acpi_ipmi ipmi_devintf
> ipmi_msghandler dax_pmem sg fuse loop nfnetlink xfs nd_pmem sr_mod
> sd_mod cdrom ghash_clmulni_intel hpsa scsi_transport_sas hpwdt ahci
> libahci libata wmi nfit libnvdimm dm_mirror dm_region_hash dm_log
> dm_mod [last unloaded: nvmet]
> [ 3341.022670] CPU: 3 UID: 0 PID: 522 Comm: kworker/u289:34 Tainted: G
>         W           6.15.0+ #2 PREEMPT(lazy)
> [ 3341.023677] Tainted: [W]=WARN
> [ 3341.024351] Hardware name: HP ProLiant DL380 Gen9/ProLiant DL380
> Gen9, BIOS P89 10/05/2016
> [ 3341.024868] Workqueue: loop0 loop_rootcg_workfn [loop]
> [ 3341.025232] RIP: 0010:bdev_count_inflight_rw+0x26e/0x410
> [ 3341.025556] Code: 00 41 8b 47 04 85 c0 78 59 48 83 c4 30 5b 5d 41
> 5c 41 5d 41 5e 41 5f c3 cc cc cc cc e8 5b d4 fd ff 4d 8d 77 04 e9 7c
> ff ff ff <0f> 0b 48 b8 00 00 00 00 00 fc ff df 4c 89 fa 48 c1 ea 03 0f
> b6 14
> [ 3341.027096] RSP: 0018:ffffc900058d6c90 EFLAGS: 00010286
> [ 3341.027466] RAX: 0000000000000003 RBX: 0000000000000048 RCX: ffffffffa9b9ee56
> [ 3341.028304] RDX: 00000000ffffffff RSI: 0000000000000048 RDI: ffffffffac36b380
> [ 3341.029153] RBP: ffffe8ffffa0c600 R08: 0000000000000000 R09: fffff91ffff418d2
> [ 3341.030067] R10: ffffe8ffffa0c697 R11: 0000000000000001 R12: ffff8881e2be9880
> [ 3341.030975] R13: dffffc0000000000 R14: ffffc900058d6d1c R15: ffffc900058d6d18
> [ 3341.031845] FS:  0000000000000000(0000) GS:ffff888439550000(0000)
> knlGS:0000000000000000
> [ 3341.032328] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 3341.033131] CR2: 000055aa896e5068 CR3: 0000000bfae7a006 CR4: 00000000003726f0
> [ 3341.033996] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 3341.034915] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [ 3341.035805] Call Trace:
> [ 3341.035991]  <TASK>
> [ 3341.036585]  bdev_count_inflight+0x6d/0xa0
> [ 3341.036918]  ? __pfx_bdev_count_inflight+0x10/0x10
> [ 3341.037658]  update_io_ticks+0x1bd/0x210
> [ 3341.037997]  ? __pfx_update_io_ticks+0x10/0x10
> [ 3341.038854]  ? find_held_lock+0x32/0x90
> [ 3341.039131]  ? local_clock_noinstr+0xd/0xe0
> [ 3341.039437]  bdev_start_io_acct+0x31/0xe0
> [ 3341.039720]  dm_io_acct+0x101/0x510 [dm_mod]
> [ 3341.040570]  ? bio_associate_blkg+0xf9/0x1e0
> [ 3341.041666]  dm_submit_bio_remap+0x52/0x380 [dm_mod]
> [ 3341.042205]  dm_split_and_process_bio+0x369/0x1520 [dm_mod]
> [ 3341.042666]  ? __lock_acquire+0x57c/0xbd0
> [ 3341.042993]  ? __pfx_dm_split_and_process_bio+0x10/0x10 [dm_mod]
> [ 3341.054346]  dm_submit_bio+0x130/0x460 [dm_mod]
> [ 3341.088843]  ? local_clock_noinstr+0xd/0xe0
> [ 3341.121535]  ? __pfx_dm_submit_bio+0x10/0x10 [dm_mod]
> [ 3341.158880]  ? __lock_release.isra.0+0x1a4/0x2c0
> [ 3341.193695]  ? __submit_bio_noacct+0x16d/0x5b0
> [ 3341.227517]  __submit_bio+0x3bd/0x600
> [ 3341.255891]  ? __pfx___submit_bio+0x10/0x10
> [ 3341.286439]  ? rcu_is_watching+0x15/0xb0
> [ 3341.315563]  ? __submit_bio_noacct+0x16d/0x5b0
> [ 3341.347325]  __submit_bio_noacct+0x16d/0x5b0
> [ 3341.378388]  ? find_held_lock+0x32/0x90
> [ 3341.406774]  ? local_clock_noinstr+0xd/0xe0
> [ 3341.437031]  ? __pfx___submit_bio_noacct+0x10/0x10
> [ 3341.470525]  ? ktime_get+0x164/0x200
> [ 3341.497850]  ? lockdep_hardirqs_on+0x78/0x100
> [ 3341.529043]  ? rcu_is_watching+0x15/0xb0
> [ 3341.557891]  submit_bio_noacct_nocheck+0x4e1/0x630
> [ 3341.591401]  ? __pfx_submit_bio_noacct_nocheck+0x10/0x10
> [ 3341.628047]  ? should_fail_bio+0xb5/0x150
> [ 3341.657364]  ? submit_bio_noacct+0x9ba/0x1b30
> [ 3341.688554]  xfs_submit_ioend+0x181/0x3e0 [xfs]
> [ 3341.721154]  iomap_submit_ioend+0x97/0x240
> [ 3341.751291]  ? __pfx_xfs_map_blocks+0x10/0x10 [xfs]
> [ 3341.785620]  iomap_add_to_ioend+0x30b/0xa90
> [ 3341.815876]  ? __pfx___folio_start_writeback+0x10/0x10
> [ 3341.851253]  iomap_writepage_map_blocks+0x34d/0x4b0
> [ 3341.885587]  ? rcu_is_watching+0x15/0xb0
> [ 3341.914441]  iomap_writepage_map+0x502/0x1130
> [ 3341.945625]  ? rcu_is_watching+0x15/0xb0
> [ 3341.974472]  ? __pfx_iomap_writepage_map+0x10/0x10
> [ 3342.008342]  ? writeback_iter+0x136/0x720
> [ 3342.037668]  iomap_writepages+0xf2/0x190
> [ 3342.044509]  ? local_clock_noinstr+0xd/0xe0
> [ 3342.044762]  ? __pfx_iomap_writepages+0x10/0x10
> [ 3342.045412]  ? __lock_release.isra.0+0x1a4/0x2c0
> [ 3342.046072]  ? xfs_vm_writepages+0xc0/0x140 [xfs]
> [ 3342.047168]  xfs_vm_writepages+0xe6/0x140 [xfs]
> [ 3342.048224]  ? __pfx_xfs_vm_writepages+0x10/0x10 [xfs]
> [ 3342.048946]  ? lock_acquire.part.0+0xbd/0x260
> [ 3342.049598]  ? find_held_lock+0x32/0x90
> [ 3342.049834]  ? local_clock_noinstr+0xd/0xe0
> [ 3342.050063]  do_writepages+0x21f/0x560
> [ 3342.050281]  ? __pfx_do_writepages+0x10/0x10
> [ 3342.050936]  ? _raw_spin_unlock+0x2d/0x50
> [ 3342.051176]  ? wbc_attach_and_unlock_inode.part.0+0x389/0x720
> [ 3342.051943]  filemap_fdatawrite_wbc+0xcf/0x120
> [ 3342.052596]  __filemap_fdatawrite_range+0xa7/0xe0
> [ 3342.053262]  ? __pfx___filemap_fdatawrite_range+0x10/0x10
> [ 3342.053568]  ? __up_write+0x1b3/0x4f0
> [ 3342.053850]  ? __lock_acquire+0x57c/0xbd0
> [ 3342.054093]  file_write_and_wait_range+0x95/0x110
> [ 3342.072359]  xfs_file_fsync+0x15d/0x870 [xfs]
> [ 3342.105328]  ? local_clock_noinstr+0xd/0xe0
> [ 3342.110862] nvmet: ctrl 2 keep-alive timer (5 seconds) expired!
> [ 3342.137782]  ? __pfx_xfs_file_fsync+0x10/0x10 [xfs]
> [ 3342.179648] nvmet: ctrl 2 fatal error occurred!
> [ 3342.215534]  ? mark_held_locks+0x40/0x70
> [ 3342.215553]  loop_process_work+0x68b/0xf70 [loop]
> [ 3342.314888]  process_one_work+0xd8b/0x1320
> [ 3342.346102]  ? __pfx_process_one_work+0x10/0x10
> [ 3342.380018]  ? assign_work+0x16c/0x240
> [ 3342.409265]  worker_thread+0x5f3/0xfe0
> [ 3342.438574]  ? __pfx_worker_thread+0x10/0x10
> [ 3342.470813]  kthread+0x3b4/0x770
> [ 3342.497590]  ? local_clock_noinstr+0x45/0xe0
> [ 3342.529996]  ? __pfx_kthread+0x10/0x10
> [ 3342.554641]  ? __lock_release.isra.0+0x1a4/0x2c0
> [ 3342.555303]  ? rcu_is_watching+0x15/0xb0
> [ 3342.555539]  ? __pfx_kthread+0x10/0x10
> [ 3342.555780]  ret_from_fork+0x393/0x480
> [ 3342.556006]  ? __pfx_kthread+0x10/0x10
> [ 3342.556218]  ? __pfx_kthread+0x10/0x10
> [ 3342.556496]  ret_from_fork_asm+0x1a/0x30
> [ 3342.556775]  </TASK>
> [ 3342.556944] irq event stamp: 15317467
> [ 3342.557159] hardirqs last  enabled at (15317475):
> [<ffffffffa8cd533e>] __up_console_sem+0x5e/0x80
> [ 3342.558026] hardirqs last disabled at (15317490):
> [<ffffffffa8cd5323>] __up_console_sem+0x43/0x80
> [ 3342.558921] softirqs last  enabled at (15317504):
> [<ffffffffa8afce0b>] handle_softirqs+0x62b/0x890
> [ 3342.559800] softirqs last disabled at (15317515):
> [<ffffffffa8afd1fd>] __irq_exit_rcu+0xfd/0x250
> [ 3342.560684] ---[ end trace 0000000000000000 ]-----
> Best Regards,
>    Yi Zhang
> 
> 
> .
> 

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Christoph Hellwig]

On Tue, Jun 10, 2025 at 10:02:19AM +0800, Yu Kuai wrote:
> Looks like this problem is related to nvme mpath, and it's using
> bio based disk IO accounting. I'm not familiar with this driver,
> however, can you try the following bpftrace script to check if
> start request and end request are balanced? From the log I guess
> it's related to mpath error handler, probably requeuing I/O.

nvme-mpath is a bio based driver.  It is a bit special in that
it passed down the bio it recived through to the lower-level
request based nvme transport driver, while most remapping drivers
always clone a bio.  I suspect that is messing up I/O accounting
here somehow.

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Yi Zhang]

On Tue, Jun 10, 2025 at 10:02 AM Yu Kuai <yukuai1@huaweicloud.com> wrote:
>
>
>
> 在 2025/06/06 11:31, Yi Zhang 写道:
> > Hello
> >
> > The following WARNING was triggered by blktests nvme/fc nvme/012,
> > please help check and let me know if you need any info/test, thanks.
> >
> > commit: linux-block: 38f4878b9463 (HEAD, origin/for-next) Merge branch
> > 'block-6.16' into for-next
> >
> > [ 2679.835074] run blktests nvme/012 at 2025-06-05 19:50:45
> > [ 2681.492049] loop0: detected capacity change from 0 to 2097152
> > [ 2681.678145] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
> > [ 2682.883261] nvme nvme0: NVME-FC{0}: create association : host wwpn
> > 0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
> > "blktests-subsystem-1"
> > [ 2682.895317] (NULL device *): {0:0} Association created
> > [ 2682.902895] nvmet: Created nvm controller 1 for subsystem
> > blktests-subsystem-1 for NQN
> > nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
> > [ 2682.970869] nvme nvme0: NVME-FC{0}: controller connect complete
> > [ 2682.970996] nvme nvme0: NVME-FC{0}: new ctrl: NQN
> > "blktests-subsystem-1", hostnqn:
> > nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349
> > [ 2685.498124] XFS (nvme0n1): Mounting V5 Filesystem
> > 3f19217c-d3fd-42af-9dbe-aa5dce6bb607
> > [ 2685.567936] XFS (nvme0n1): Ending clean mount
> > [ 2746.161840] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 0 fctype 1
> > (I/O Cmd) w10/11: x00000000/x00000000
> > [ 2746.163061] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x0010007a/x00000000
> > [ 2746.163126] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x001000ba/x00000000
> > [ 2746.163175] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x001000fa/x00000000
> > [ 2746.163220] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x0010013a/x00000000
> > [ 2746.163265] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x0010017a/x00000000
> > [ 2746.163308] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x001001ba/x00000000
> > [ 2746.163352] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x001001fa/x00000000
> > [ 2746.163396] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x001d8618/x00000000
> > [ 2746.163441] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x000d9d88/x00000000
> > [ 2746.163486] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00014be0/x00000000
> > [ 2746.163531] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x001bb168/x00000000
> > [ 2746.163585] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x0006b620/x00000000
> > [ 2746.163639] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x000b6688/x00000000
> > [ 2746.164885] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x000581c0/x00000000
> > [ 2746.166593] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x001468c0/x00000000
> > [ 2746.166681] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00080780/x00000000
> > [ 2746.166732] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00147338/x00000000
> > [ 2746.166780] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x000acee8/x00000000
> > [ 2746.166826] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00016e20/x00000000
> > [ 2746.166872] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x0019add0/x00000000
> > [ 2746.166916] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x001bdab8/x00000000
> > [ 2746.166960] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x000ea0f8/x00000000
> > [ 2746.167005] nvme nvme0: NVME-FC{0.3}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00006328/x00000000
> > [ 2746.170320] nvme nvme0: NVME-FC{0}: transport association event:
> > transport detected io error
> > [ 2746.173629] nvme nvme0: NVME-FC{0}: resetting controller
> > [ 2746.175966] block nvme0n1: no usable path - requeuing I/O
> > [ 2746.177234] block nvme0n1: no usable path - requeuing I/O
> > [ 2746.177571] block nvme0n1: no usable path - requeuing I/O
> > [ 2746.177916] block nvme0n1: no usable path - requeuing I/O
> > [ 2746.178228] block nvme0n1: no usable path - requeuing I/O
> > [ 2746.178576] block nvme0n1: no usable path - requeuing I/O
> > [ 2746.179173] block nvme0n1: no usable path - requeuing I/O
> > [ 2746.179476] block nvme0n1: no usable path - requeuing I/O
> > [ 2746.179807] block nvme0n1: no usable path - requeuing I/O
> > [ 2746.180146] block nvme0n1: no usable path - requeuing I/O
> > [ 2746.232899] nvme nvme0: NVME-FC{0}: create association : host wwpn
> > 0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
> > "blktests-subsystem-1"
> > [ 2746.238446] (NULL device *): {0:1} Association created
> > [ 2746.239620] nvmet: Created nvm controller 2 for subsystem
> > blktests-subsystem-1 for NQN
> > nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
> > [ 2746.259174] (NULL device *): {0:0} Association deleted
> > [ 2746.296717] nvme nvme0: NVME-FC{0}: controller connect complete
> > [ 2755.870750] nvmet: ctrl 1 keep-alive timer (5 seconds) expired!
> > [ 2755.873263] nvmet: ctrl 1 fatal error occurred!
> > [ 2769.422990] (NULL device *): Disconnect LS failed: No Association
> > [ 2769.424288] (NULL device *): {0:0} Association freed
> > [ 2801.582208] perf: interrupt took too long (2527 > 2500), lowering
> > kernel.perf_event_max_sample_rate to 79000
> > [ 2830.657742] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x000a06a8/x00000000
> > [ 2830.657865] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x000994d0/x00000000
> > [ 2830.657916] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x000263b8/x00000000
> > [ 2830.657965] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x000ecf10/x00000000
> > [ 2830.658010] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00054418/x00000000
> > [ 2830.658071] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x001f42f0/x00000000
> > [ 2830.658088] nvme nvme0: NVME-FC{0}: transport association event:
> > transport detected io error
> > [ 2830.658119] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x000bb588/x00000000
> > [ 2830.659087] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x000fd620/x00000000
> > [ 2830.659134] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x000d66b0/x00000000
> > [ 2830.659189] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00188488/x00000000
> > [ 2830.659233] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00086fd0/x00000000
> > [ 2830.659276] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x001a0950/x00000000
> > [ 2830.659345] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00136340/x00000000
> > [ 2830.659390] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x0013dc60/x00000000
> > [ 2830.659433] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00193530/x00000000
> > [ 2830.659500] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x001d3ff0/x00000000
> > [ 2830.659545] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00101455/x00000000
> > [ 2830.659589] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00101495/x00000000
> > [ 2830.659650] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x001014d5/x00000000
> > [ 2830.659758] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00101515/x00000000
> > [ 2830.659842] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00101555/x00000000
> > [ 2830.659889] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x00101595/x00000000
> > [ 2830.659904] nvme nvme0: NVME-FC{0}: resetting controller
> > [ 2830.659941] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 1 fctype 1
> > (I/O Cmd) w10/11: x001015d5/x00000000
> > [ 2830.660321] nvme nvme0: NVME-FC{0.4}: io timeout: opcode 0 fctype 1
> > (I/O Cmd) w10/11: x00000000/x00000000
> > [ 2830.660348] nvme_ns_head_submit_bio: 81 callbacks suppressed
> > [ 2830.660362] block nvme0n1: no usable path - requeuing I/O
> > [ 2830.661765] block nvme0n1: no usable path - requeuing I/O
> > [ 2830.662070] block nvme0n1: no usable path - requeuing I/O
> > [ 2830.662367] block nvme0n1: no usable path - requeuing I/O
> > [ 2830.662660] block nvme0n1: no usable path - requeuing I/O
> > [ 2830.663046] block nvme0n1: no usable path - requeuing I/O
> > [ 2830.663337] block nvme0n1: no usable path - requeuing I/O
> > [ 2830.663627] block nvme0n1: no usable path - requeuing I/O
> > [ 2830.663976] block nvme0n1: no usable path - requeuing I/O
> > [ 2830.664288] block nvme0n1: no usable path - requeuing I/O
> > [ 2830.700704] nvme nvme0: NVME-FC{0}: create association : host wwpn
> > 0x20001100aa000001  rport wwpn 0x20001100ab000001: NQN
> > "blktests-subsystem-1"
> > [ 2830.706376] (NULL device *): {0:0} Association created
> > [ 2830.707571] nvmet: Created nvm controller 1 for subsystem
> > blktests-subsystem-1 for NQN
> > nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
> > [ 2830.725113] (NULL device *): {0:1} Association deleted
> > [ 2830.745872] ------------[ cut here ]------------
> > [ 2830.746780] WARNING: CPU: 49 PID: 1020 at block/genhd.c:146
> > bdev_count_inflight_rw+0x2a6/0x410
> > [ 2830.747730] Modules linked in: nvme_fcloop nvmet_fc nvmet nvme_fc
> > nvme_fabrics nvme_core nvme_keyring nvme_auth rfkill sunrpc
> > intel_rapl_msr intel_rapl_common intel_uncore_frequency
> > intel_uncore_frequency_common sb_edac x86_pkg_temp_thermal
> > intel_powerclamp coretemp kvm_intel vfat
> > [ 2830.748536] nvme nvme0: NVME-FC{0}: controller connect complete
> > [ 2830.749958]  fat kvm irqbypass iTCO_wdt rapl iTCO_vendor_support
> > intel_cstate intel_uncore pcspkr bnx2x mgag200 i2c_i801 tg3 i2c_smbus
> > lpc_ich i2c_algo_bit hpilo ioatdma mdio dca ipmi_ssif ipmi_si acpi_tad
> > acpi_power_meter acpi_ipmi ipmi_devintf ipmi_msghandler dax_pmem sg
> > fuse loop nfnetlink xfs nd_pmem sr_mod sd_mod cdrom
> > ghash_clmulni_intel hpsa scsi_transport_sas hpwdt ahci libahci libata
> > wmi nfit libnvdimm dm_mirror dm_region_hash dm_log dm_mod [last
> > unloaded: nvmet]
> > [ 2830.752807] CPU: 49 UID: 0 PID: 1020 Comm: kworker/49:1H Not
> > tainted 6.15.0+ #2 PREEMPT(lazy)
> > [ 2830.753650] Hardware name: HP ProLiant DL380 Gen9/ProLiant DL380
> > Gen9, BIOS P89 10/05/2016
> > [ 2830.754291] Workqueue: kblockd nvme_requeue_work [nvme_core]
> > [ 2830.755188] RIP: 0010:bdev_count_inflight_rw+0x2a6/0x410
> > [ 2830.755503] Code: fa 48 c1 ea 03 0f b6 14 02 4c 89 f8 83 e0 07 83
> > c0 03 38 d0 7c 08 84 d2 0f 85 59 01 00 00 41 c7 07 00 00 00 00 e9 75
> > ff ff ff <0f> 0b 48 b8 00 00 00 00 00 fc ff df 4c 89 f2 48 c1 ea 03 0f
> > b6 14
> > [ 2830.756887] RSP: 0018:ffffc9000ad973e8 EFLAGS: 00010286
> > [ 2830.757221] RAX: 00000000ffffffff RBX: 0000000000000048 RCX: ffffffffa9b9ee56
> > [ 2830.758007] RDX: 0000000000000000 RSI: 0000000000000048 RDI: ffffffffac36b380
> > [ 2830.758831] RBP: ffffe8ffffa33758 R08: 0000000000000000 R09: fffff91ffff466fd
> > [ 2830.759609] R10: ffffe8ffffa337ef R11: 0000000000000001 R12: ffff888121d16200
> > [ 2830.760405] R13: dffffc0000000000 R14: ffffc9000ad97474 R15: ffffc9000ad97470
> > [ 2830.761226] FS:  0000000000000000(0000) GS:ffff888440550000(0000)
> > knlGS:0000000000000000
> > [ 2830.761724] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [ 2830.762472] CR2: 000055aa8905b038 CR3: 0000000bfae7a001 CR4: 00000000003726f0
> > [ 2830.763293] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > [ 2830.764124] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> > [ 2830.764921] Call Trace:
> > [ 2830.765087]  <TASK>
> > [ 2830.765625]  bdev_count_inflight+0x6d/0xa0
> > [ 2830.765921]  ? __pfx_bdev_count_inflight+0x10/0x10
> > [ 2830.766604]  update_io_ticks+0x1bd/0x210
> > [ 2830.789758]  ? __pfx_update_io_ticks+0x10/0x10
> > [ 2830.823941]  ? nvme_fc_map_data+0x1d0/0x860 [nvme_fc]
> > [ 2830.861999]  bdev_start_io_acct+0x31/0xe0
> > [ 2830.893416]  nvme_mpath_start_request+0x222/0x390 [nvme_core]
> > [ 2830.934768]  nvme_fc_start_fcp_op+0xc4c/0xfe0 [nvme_fc]
> > [ 2830.973158]  ? trace_nvme_setup_cmd+0x149/0x1b0 [nvme_core]
> > [ 2831.011196]  ? __pfx_nvme_fc_start_fcp_op+0x10/0x10 [nvme_fc]
> > [ 2831.050102]  ? nvme_fc_queue_rq+0x1b6/0x4c0 [nvme_fc]
> > [ 2831.085274]  __blk_mq_issue_directly+0xe1/0x1c0
> > [ 2831.117939]  ? __pfx___blk_mq_issue_directly+0x10/0x10
> > [ 2831.153586]  ? blk_mq_request_issue_directly+0xc6/0x190
> > [ 2831.189705]  blk_mq_issue_direct+0x16b/0x690
> > [ 2831.220964]  ? lock_acquire+0x10b/0x150
> > [ 2831.249564]  blk_mq_dispatch_queue_requests+0x31c/0x640
> > [ 2831.267274]  blk_mq_flush_plug_list+0x187/0x6a0
> > [ 2831.267940]  ? trace_block_plug+0x15e/0x1e0
> > [ 2831.268164]  ? blk_add_rq_to_plug+0x2cf/0x460
> > [ 2831.268799]  ? rcu_is_watching+0x15/0xb0
> > [ 2831.269033]  ? __pfx_blk_mq_flush_plug_list+0x10/0x10
> > [ 2831.269316]  ? blk_mq_submit_bio+0x10cc/0x1bc0
> > [ 2831.269969]  __blk_flush_plug+0x27b/0x4d0
> > [ 2831.270200]  ? find_held_lock+0x32/0x90
> > [ 2831.270426]  ? __pfx___blk_flush_plug+0x10/0x10
> > [ 2831.271079]  ? percpu_ref_put_many.constprop.0+0x7a/0x1b0
> > [ 2831.271380]  __submit_bio+0x49b/0x600
> > [ 2831.271594]  ? __pfx___submit_bio+0x10/0x10
> > [ 2831.271843]  ? raw_spin_rq_lock_nested+0x2e/0x130
> > [ 2831.272506]  ? __submit_bio_noacct+0x16d/0x5b0
> > [ 2831.273157]  __submit_bio_noacct+0x16d/0x5b0
> > [ 2831.273805]  ? find_held_lock+0x32/0x90
> > [ 2831.274035]  ? local_clock_noinstr+0xd/0xe0
> > [ 2831.274251]  ? __pfx___submit_bio_noacct+0x10/0x10
> > [ 2831.274901]  ? ktime_get+0x164/0x200
> > [ 2831.275127]  ? lockdep_hardirqs_on+0x78/0x100
> > [ 2831.275777]  ? ktime_get+0xb0/0x200
> > [ 2831.276382]  submit_bio_noacct_nocheck+0x4e1/0x630
> > [ 2831.302650]  ? __pfx___might_resched+0x10/0x10
> > [ 2831.334528]  ? __pfx_submit_bio_noacct_nocheck+0x10/0x10
> > [ 2831.371424]  ? should_fail_bio+0xb5/0x150
> > [ 2831.400963]  ? submit_bio_noacct+0x9ba/0x1b30
> > [ 2831.432384]  nvme_requeue_work+0xa6/0xd0 [nvme_core]
>
> Looks like this problem is related to nvme mpath, and it's using
> bio based disk IO accounting. I'm not familiar with this driver,
> however, can you try the following bpftrace script to check if
> start request and end request are balanced? From the log I guess
> it's related to mpath error handler, probably requeuing I/O.
>

Seems it doesn't work.

# bpftrace nvme.bt
nvme.bt:1:1-27: WARNING: nvme_mpath_start_request is not traceable
(either non-existing, inlined, or marked as "notrace"); attaching to
it will likely fail
k:nvme_mpath_start_request
~~~~~~~~~~~~~~~~~~~~~~~~~~
nvme.bt:4-6: WARNING: nvme_mpath_end_request is not traceable (either
non-existing, inlined, or marked as "notrace"); attaching to it will
likely fail
Attaching 2 probes...
cannot attach kprobe, Invalid argument
ERROR: Error attaching probe: kprobe:nvme_mpath_end_request
# cat nvme.bt
k:nvme_mpath_start_request
{
         @rq[arg0] = 1;
}

k:nvme_mpath_end_request
{
         if (@rq[arg0]) {
                 delete(@rq[arg0]);
         } else {
                 printf("leak end request counter\n %s\n", kstack());
         }
}

> k:nvme_mpath_start_request
> {
>          @rq[arg0] = 1;
> }
>
> k:nvme_mpath_end_request
> {
>          if (@rq[arg0]) {
>                  delete(@rq[arg0]);
>          } else {
>                  printf("leak end request counter\n %s\n", kstack());
>          }
> }
>
> And can you test the following patch?
>

Unfortunately, the issue still can be reproduced with the change.

> diff --git a/drivers/nvme/host/multipath.c b/drivers/nvme/host/multipath.c
> index 878ea8b1a0ac..ad366f0fd8cb 100644
> --- a/drivers/nvme/host/multipath.c
> +++ b/drivers/nvme/host/multipath.c
> @@ -200,14 +200,17 @@ void nvme_mpath_end_request(struct request *rq)
>   {
>          struct nvme_ns *ns = rq->q->queuedata;
>
> -       if (nvme_req(rq)->flags & NVME_MPATH_CNT_ACTIVE)
> +       if (nvme_req(rq)->flags & NVME_MPATH_CNT_ACTIVE) {
>                  atomic_dec_if_positive(&ns->ctrl->nr_active);
> +               nvme_req(rq)->flags &= ~NVME_MPATH_CNT_ACTIVE;
> +       }
>
> -       if (!(nvme_req(rq)->flags & NVME_MPATH_IO_STATS))
> -               return;
> -       bdev_end_io_acct(ns->head->disk->part0, req_op(rq),
> -                        blk_rq_bytes(rq) >> SECTOR_SHIFT,
> -                        nvme_req(rq)->start_time);
> +       if (nvme_req(rq)->flags & NVME_MPATH_IO_STATS) {
> +               bdev_end_io_acct(ns->head->disk->part0, req_op(rq),
> +                                blk_rq_bytes(rq) >> SECTOR_SHIFT,
> +                                nvme_req(rq)->start_time);
> +               nvme_req(rq)->flags &= ~NVME_MPATH_IO_STATS;
> +       }
>   }
>
>   void nvme_kick_requeue_lists(struct nvme_ctrl *ctrl)
>
>
> Thanks,
> Kuai


-- 
Best Regards,
  Yi Zhang

Re: [bug report] WARNING: CPU: 3 PID: 522 at block/genhd.c:144 bdev_count_inflight_rw+0x26e/0x410

[Yu Kuai]

Hi,

在 2025/06/11 8:05, Yi Zhang 写道:
> Unfortunately, the issue still can be reproduced with the change.

Thanks for the test, looks like the problem is not related to
unbalanced nvme_mpath_{start, end}_request, I'll try if I can reporduce
it in my VM.

Kuai