Problem With XFS + KVM

[Dave Chinner]

On Thu, Mar 04, 2021 at 10:34:29PM +0000, Chaitanya Kulkarni wrote:
> 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.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]

That looks like a KVM or local_irq_save()/local_irq_restore problem.
kvm_wait() does:

static void kvm_wait(u8 *ptr, u8 val)
{
        unsigned long flags;

        if (in_nmi())
                return;

        local_irq_save(flags);

        if (READ_ONCE(*ptr) != val)
                goto out;

        /*
         * halt until it's our turn and kicked. Note that we do safe halt
         * for irq enabled case to avoid hang when lock info is overwritten
         * in irq spinlock slowpath and no spurious interrupt occur to save us.
         */
        if (arch_irqs_disabled_flags(flags))
                halt();
        else
                safe_halt();

out:
        local_irq_restore(flags);
}

And the warning is coming from the local_irq_restore() call
indicating that interrupts are not disabled when they should be.
The interrupt state is being modified entirely within the kvm_wait()
code here, so none of the high level XFS code has any influence on
behaviour here.

Cheers,

Dave.
-- 
Dave Chinner
david at fromorbit.com