Hi,
I'm running fio verification job with XFS formatted file system on 5.12-rc1
with NVMeOF file backend target inside QEMU test machine.
I'm getting a following message intermittently it is happening since
yesterday.
This can be easily reproduces with runing block tests nvme/011 :-
nvme/011 (run data verification fio job on NVMeOF file-backed ns) [failed]
runtime 270.553s ... 268.552s
something found in dmesg:
[ 340.781752] run blktests nvme/011 at 2021-03-04 14:22:34
[ 340.857161] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
[ 340.890225] nvmet: creating controller 1 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:e4cfc949-8f19-4db2-a232-ab360b79204a.
[ 340.892477] nvme nvme0: Please enable CONFIG_NVME_MULTIPATH for
full support of multi-port devices.
[ 340.892937] nvme nvme0: creating 64 I/O queues.
[ 340.913759] nvme nvme0: new ctrl: "blktests-subsystem-1"
[ 586.495375] nvme nvme0: Removing ctrl: NQN "blktests-subsystem-1"
[ 587.766464] ------------[ cut here ]------------
[ 587.766535] raw_local_irq_restore() called with IRQs enabled
[ 587.766561] WARNING: CPU: 14 PID: 12543 at
kernel/locking/irqflag-debug.c:10 warn_bogus_irq_restore+0x1d/0x20
...
(See '/root/blktests/results/nodev/nvme/011.dmesg' for the entire
message)
Please let me know what kind of more details I can provide to resolve
this issue.
Here is the dmesg outout :-
------------[ cut here ]------------
[ 587.766535] raw_local_irq_restore() called with IRQs enabled
[ 587.766561] WARNING: CPU: 14 PID: 12543 at
kernel/locking/irqflag-debug.c:10 warn_bogus_irq_restore+0x1d/0x20
[ 587.766571] Modules linked in: nvme_loop nvme_fabrics nvmet nvme_core
loop xt_CHECKSUM xt_MASQUERADE tun bridge stp llc ip6t_rpfilter
ipt_REJECT nf_reject_ipv4 ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set
nfnetlink ebtable_nat ebtable_broute ip6table_nat ip6table_mangle
ip6table_security ip6table_raw iptable_nat nf_nat nf_conntrack
nf_defrag_ipv6 nf_defrag_ipv4 iptable_mangle iptable_security
iptable_raw ebtable_filter ebtables ip6table_filter ip6_tables rfkill
iptable_filter intel_rapl_msr intel_rapl_common kvm_amd ccp kvm btrfs
irqbypass crct10dif_pclmul crc32_pclmul blake2b_generic
ghash_clmulni_intel xor zstd_compress ppdev bochs_drm drm_vram_helper
aesni_intel drm_ttm_helper ttm crypto_simd cryptd drm_kms_helper
syscopyarea sysfillrect sysimgblt fb_sys_fops raid6_pq drm i2c_piix4 sg
parport_pc joydev i2c_core parport pcspkr nfsd auth_rpcgss nfs_acl lockd
grace sunrpc ip_tables xfs libcrc32c sd_mod ata_generic pata_acpi
virtio_net net_failover failover ata_piix virtio_pci
[ 587.766786] crc32c_intel virtio_pci_modern_dev libata virtio_ring
serio_raw t10_pi virtio floppy dm_mirror dm_region_hash dm_log dm_mod
[last unloaded: nvme_core]
[ 587.766819] CPU: 14 PID: 12543 Comm: rm Not tainted 5.12.0-rc1nvme+ #165
[ 587.766823] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS rel-1.12.0-59-gc9ba5276e321-prebuilt.qemu.org 04/01/2014
[ 587.766826] RIP: 0010:warn_bogus_irq_restore+0x1d/0x20
[ 587.766831] Code: 24 48 c7 c7 e0 f2 0f 82 e8 80 c3 fb ff 80 3d 15 1c
09 01 00 74 01 c3 48 c7 c7 70 6c 10 82 c6 05 04 1c 09 01 01 e8 cc c2 fb
ff <0f> 0b c3 55 53 44 8b 05 63 b4 0c 01 65 48 8b 1c 25 40 7e 01 00 45
[ 587.766835] RSP: 0018:ffffc900086cf990 EFLAGS: 00010286
[ 587.766840] RAX: 0000000000000000 RBX: 0000000000000003 RCX:
0000000000000027
[ 587.766843] RDX: 0000000000000000 RSI: ffff8897d37e8a30 RDI:
ffff8897d37e8a38
[ 587.766846] RBP: ffff888138764888 R08: 0000000000000001 R09:
0000000000000001
[ 587.766848] R10: 000000009f0f619c R11: 00000000b7972d21 R12:
0000000000000200
[ 587.766851] R13: 0000000000000001 R14: 0000000000000100 R15:
00000000003c0000
[ 587.766855] FS: 00007f6992aec740(0000) GS:ffff8897d3600000(0000)
knlGS:0000000000000000
[ 587.766858] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 587.766860] CR2: 0000000000bcf1c8 CR3: 00000017d29e8000 CR4:
00000000003506e0
[ 587.766864] Call Trace:
[ 587.766867] kvm_wait+0x8c/0x90
[ 587.766876] __pv_queued_spin_lock_slowpath+0x265/0x2a0
[ 587.766893] do_raw_spin_lock+0xb1/0xc0
[ 587.766898] _raw_spin_lock+0x61/0x70
[ 587.766904] xfs_extent_busy_trim+0x2f/0x200 [xfs]
[ 587.766975] xfs_alloc_compute_aligned+0x3d/0xd0 [xfs]
[ 587.767027] xfs_alloc_ag_vextent_size+0x18f/0x930 [xfs]
[ 587.767085] xfs_alloc_ag_vextent+0x11e/0x140 [xfs]
[ 587.767133] xfs_alloc_fix_freelist+0x1fb/0x4c0 [xfs]
[ 587.767201] xfs_free_extent_fix_freelist+0x64/0xb0 [xfs]
[ 587.767262] __xfs_free_extent+0x58/0x170 [xfs]
[ 587.767317] xfs_trans_free_extent+0x53/0x140 [xfs]
[ 587.767391] xfs_extent_free_finish_item+0x23/0x40 [xfs]
[ 587.767493] xfs_defer_finish_noroll+0x222/0x800 [xfs]
[ 587.767553] xfs_defer_finish+0x13/0x70 [xfs]
[ 587.767607] xfs_itruncate_extents_flags+0xd4/0x340 [xfs]
[ 587.767673] xfs_inactive_truncate+0xa3/0xf0 [xfs]
[ 587.767735] xfs_inactive+0xb5/0x140 [xfs]
[ 587.767796] xfs_fs_destroy_inode+0xc1/0x240 [xfs]
[ 587.767858] destroy_inode+0x3b/0x70
[ 587.767868] do_unlinkat+0x280/0x330
[ 587.767881] do_syscall_64+0x33/0x40
[ 587.767886] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 587.767893] RIP: 0033:0x7f699261dfad
[ 587.767898] Code: e1 0e 2d 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f
1f 84 00 00 00 00 00 0f 1f 44 00 00 48 63 d2 48 63 ff b8 07 01 00 00 0f
05 <48> 3d 00 f0 ff ff 77 02 f3 c3 48 8b 15 aa 0e 2d 00 f7 d8 64 89 02
[ 587.767901] RSP: 002b:00007ffd1f7ea248 EFLAGS: 00000206 ORIG_RAX:
0000000000000107
[ 587.767906] RAX: ffffffffffffffda RBX: 0000000000bcf2f0 RCX:
00007f699261dfad
[ 587.767908] RDX: 0000000000000000 RSI: 0000000000bce0c0 RDI:
ffffffffffffff9c
[ 587.767911] RBP: 0000000000000000 R08: 0000000000000000 R09:
0000000000000000
[ 587.767913] R10: 00007ffd1f7e9ec0 R11: 0000000000000206 R12:
0000000000bce05c
[ 587.767916] R13: 00007ffd1f7ea3b0 R14: 0000000000bcf2f0 R15:
0000000000000000
[ 587.767938] irq event stamp: 771691
[ 587.767941] hardirqs last enabled at (771697): [<ffffffff81121db9>]
console_unlock+0x4e9/0x610
[ 587.767948] hardirqs last disabled at (771702): [<ffffffff81121d32>]
console_unlock+0x462/0x610
[ 587.767952] softirqs last enabled at (770516): [<ffffffffa0249ae7>]
xfs_buf_find.isra.27+0x657/0xb90 [xfs]
[ 587.768011] softirqs last disabled at (770514): [<ffffffffa02497c5>]
xfs_buf_find.isra.27+0x335/0xb90 [xfs]
[ 587.768070] ---[ end trace 4eaf6d15d7cbe576 ]---
[ 609.672358] run blktests nvme/012 at 2021-03-04 14:27:03
[ 609.745797] loop0: detected capacity change from 0 to 2097152
[ 609.764592] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
[ 609.800956] nvmet: creating controller 1 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:e4cfc949-8f19-4db2-a232-ab360b79204a.
[ 609.802545] nvme nvme0: Please enable CONFIG_NVME_MULTIPATH for full
support of multi-port devices.
[ 609.802909] nvme nvme0: creating 64 I/O queues.
[ 609.823959] nvme nvme0: new ctrl: "blktests-subsystem-1"
[ 611.525467] XFS (nvme0n1): Mounting V5 Filesystem
[ 611.534398] XFS (nvme0n1): Ending clean mount
[ 611.534715] xfs filesystem being mounted at /mnt/blktests supports
timestamps until 2038 (0x7fffffff)
-ck
