Message-ID: <20200925023427.GB2388140@T590>
Date:   Fri, 25 Sep 2020 10:34:27 +0800
From:   Ming Lei <ming.lei@...hat.com>
To:     "Theodore Y. Ts'o" <tytso@....edu>
Cc:     Jens Axboe <axboe@...nel.dk>, linux-ext4@...r.kernel.org,
        "linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>,
        linux-block@...r.kernel.org,
        Linus Torvalds <torvalds@...ux-foundation.org>
Subject: Re: REGRESSION: 37f4a24c2469: blk-mq: centralise related handling
 into blk_mq_get_driver_tag

On Fri, Sep 25, 2020 at 09:14:16AM +0800, Ming Lei wrote:
> On Thu, Sep 24, 2020 at 10:33:45AM -0400, Theodore Y. Ts'o wrote:
> > On Thu, Sep 24, 2020 at 08:59:01AM +0800, Ming Lei wrote:
> > > 
> > > The list corruption issue can be reproduced on kvm/qumu guest too when
> > > running xfstests(ext4) generic/038.
> > > 
> > > However, the issue may become not reproduced when adding or removing memory
> > > debug options, such as adding KASAN.
> > 
> > Can you reliably reprodue this crash?  And if so, with what config and
> > what kernel version.
> 
> Yeah, it can be reproduced reliably by running xfstests(ext4)
> generic/038 over virtio-scsi(test device)/virtio-blk(scratch device).
> 
> The kernel is -rc4, and not test -rc5 yet.
> 
> It is exactly the config you provided, and I just enabled CDROM & ISOFS
> against your config for passing cloud-init data via cdrom to VM.
> 
> > One of the reasons why I had gone silent on this bug is that I've been
> > trying many, many configurations and configurations which reliably
> > reproduced on say, -rc4 would not reproduce on -rc5, and then I would
> > get a completely different set of results on -rc6.  So I've been
> > trying to run a lot of different experiments to try to understand what
> > might be going on, since it seems pretty clear this must be a very
> > timing-sensitive failure.
> > 
> > I also found that the re-occrance went down significantly if I enabled
> > KASAN, and while it didn't go away, I wasn't able to get a KASAN
> > failure to trigger, either.  Turning off CONFIG_PROVE_LOCKING and a
> > *lot* of other debugging configs made the problem vanish in -rc4, but
> > that trick didn't work with -rc5 or -rc6.
> 
> The issue can be reproduced reliably in my environment after
> disabling LOCKDEP only for disabling KMEMLEAK only.
> 
> But after disabling DEBUG_OBJECTS, it becomes hard to trigger.
> 
> > 
> > Each time I discovered one of these things, I was about to post to the
> > e-mail thread, only to have a confirmation test run on a different
> > kernel version make the problem go away.  In particular, your revert
> > helped with -rc4 and -rc6 IIRC, but it didn't help in -rc5.....
> > 
> > HOWEVER, thanks to a hint from a colleague at $WORK, and realizing
> > that one of the stack traces had virtio balloon in the trace, I
> > realized that when I switched the GCE VM type from e1-standard-2 to
> > n1-standard-2 (where e1 VM's are cheaper because they use
> > virtio-balloon to better manage host OS memory utilization), problem
> > has become, much, *much* rarer (and possibly has gone away, although
> > I'm going to want to run a lot more tests before I say that
> > conclusively) on my test setup.  At the very least, using an n1 VM
> > (which doesn't have virtio-balloon enabled in the hypervisor) is
> > enough to unblock ext4 development.
> > 
> > Any chance your kvm/qemu configuration might have been using
> > virtio-ballon?  Because other ext4 developers who have been using
> > kvm-xftests have not had any problems....
> 
> I don't setup virtio-ballon, see the attached script for setting the VM.
> 
> > 
> > > When I enable PAGE_POISONING, double free on kmalloc(192) is captured:
> > > 
> > > [ 1198.317139] slab: double free detected in cache 'kmalloc-192', objp ffff89ada7584300^M
> > > [ 1198.326651] ------------[ cut here ]------------^M
> > > [ 1198.327969] kernel BUG at mm/slab.c:2535!^M
> > > [ 1198.329129] invalid opcode: 0000 [#1] SMP PTI^M
> > > [ 1198.333776] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.9.0-rc4_quiesce_srcu-xfstests #102^M
> > > [ 1198.336085] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.13.0-48-gd9c812dda519-prebuilt.qemu.org 04/01/2014^M
> > > [ 1198.339826] RIP: 0010:free_block.cold.92+0x13/0x15^M
> > > [ 1198.341472] Code: 8d 44 05 f0 eb d0 48 63 83 e0 00 00 00 48 8d 54 05 f8 e9 4b 81 ff ff 48 8b 73 58 48 89 ea 48 c7 c7 98 e7 4a 9c e8 20 c3 eb ff <0f> 0b 48 8b 73 58 48 c7 c2 20 e8 4a 9c 48 c7 c7 70 32 22 9c e8 19^M
> > > [ 1198.347331] RSP: 0018:ffff982e40710be8 EFLAGS: 00010046^M
> > > [ 1198.349091] RAX: 0000000000000048 RBX: ffff89adb6441400 RCX: 0000000000000000^M
> > > [ 1198.351839] RDX: 0000000000000000 RSI: ffff89adbaa97800 RDI: ffff89adbaa97800^M
> > > [ 1198.354572] RBP: ffff89ada7584300 R08: 0000000000000417 R09: 0000000000000057^M
> > > [ 1198.357150] R10: 0000000000000001 R11: ffff982e40710aa5 R12: ffff89adbaaae598^M
> > > [ 1198.359067] R13: ffffe7bc819d6108 R14: ffffe7bc819d6100 R15: ffff89adb6442280^M
> > > [ 1198.360975] FS:  0000000000000000(0000) GS:ffff89adbaa80000(0000) knlGS:0000000000000000^M
> > > [ 1198.363202] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033^M
> > > [ 1198.365986] CR2: 000055f6a3811318 CR3: 000000017adca005 CR4: 0000000000770ee0^M
> > > [ 1198.368679] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000^M
> > > [ 1198.371386] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400^M
> > > [ 1198.374203] PKRU: 55555554^M
> > > [ 1198.375174] Call Trace:^M
> > > [ 1198.376165]  <IRQ>^M
> > > [ 1198.376908]  ___cache_free+0x56d/0x770^M
> > > [ 1198.378355]  ? kmem_freepages+0xa0/0xf0^M
> > > [ 1198.379814]  kfree+0x91/0x120^M
> > > [ 1198.382121]  kmem_freepages+0xa0/0xf0^M
> > > [ 1198.383474]  slab_destroy+0x9f/0x120^M
> > > [ 1198.384779]  slabs_destroy+0x6d/0x90^M
> > > [ 1198.386110]  ___cache_free+0x632/0x770^M
> > > [ 1198.387547]  ? kmem_freepages+0xa0/0xf0^M
> > > [ 1198.389016]  kfree+0x91/0x120^M
> > > [ 1198.390160]  kmem_freepages+0xa0/0xf0^M
> > > [ 1198.391551]  slab_destroy+0x9f/0x120^M
> > > [ 1198.392964]  slabs_destroy+0x6d/0x90^M
> > > [ 1198.394439]  ___cache_free+0x632/0x770^M
> > > [ 1198.395896]  kmem_cache_free.part.75+0x19/0x70^M
> > > [ 1198.397791]  rcu_core+0x1eb/0x6b0^M
> > > [ 1198.399829]  ? ktime_get+0x37/0xa0^M
> > > [ 1198.401343]  __do_softirq+0xdf/0x2c5^M
> > > [ 1198.403010]  asm_call_on_stack+0x12/0x20^M
> > > [ 1198.404847]  </IRQ>^M
> > > [ 1198.405799]  do_softirq_own_stack+0x39/0x50^M
> > > [ 1198.407621]  irq_exit_rcu+0x97/0xa0^M
> > > [ 1198.409127]  sysvec_apic_timer_interrupt+0x2c/0x80^M
> > > [ 1198.410608]  asm_sysvec_apic_timer_interrupt+0x12/0x20^M
> > > [ 1198.411883] RIP: 0010:default_idle+0x13/0x20^M
> > > [ 1198.412994] Code: 89 44 24 20 48 83 c0 22 48 89 44 24 28 eb c7 e8 03 93 ff ff cc cc cc 0f 1f 44 00 00 e9 07 00 00 00 0f 00 2d 11 ec 55 00 fb f4 <c3> 66 66 2e 0f 1f 84 00 00 00 00 00 90 0f 1f 44 00 00 65 48 8b 04^M
> > 
> > Hmm, so that this looks like some kind of RCU involvement?  Some kind
> > of object that had been scheduled to be freed via RCU, but then got
> > freed before RCU cleanup happened?
> > 
> > The question then is what subsystem the object involved came from.
> 
> Right now, I don't get time to investigate further. It shouldn't be
> hard to locate where the 192 slab allocation is from, together with RCU
> involved.
> 
> BTW, the double free is triggered by the following change on your
> config:
> 
> - disable lockdep
> - disable kmemleak
> - enable PAGE_POISONING

oops, double free is captured by enabling CONFIG_DEBUG_SLAB instead of
PAGE_POISONING, looks it is triggered reliably too.

Thanks,
Ming

Powered by blists - more mailing lists