On Tue, Sep 29, 2020 at 9:37 PM Coly Li <colyli@xxxxxxx> wrote:
>
> On 2020/9/30 03:18, Marc Smith wrote:
> > Hi Coly,
> >
> > So nearly one year later, and I haven't hit this issue since running
> > 5.4.x until now. It seems to happen on a system for just ONE of the
> > backing devices (4 backing devices per cache device). Running Linux
> > 5.4.45 (vanilla kernel.org):
> >
> > --snip--
> > [ 1597.707235] bcache: bch_journal_replay() journal replay done, 0
> > keys in 1 entries, seq 1412486
> > [ 1597.712131] bcache: bch_cached_dev_attach() Caching md123 as
> > bcache3 on set 521f7664-690d-4680-9b0d-1299fcee4321
> > [ 1597.715109] bcache: bch_cached_dev_attach() Caching md124 as
> > bcache2 on set 521f7664-690d-4680-9b0d-1299fcee4321
> > [ 1597.718674] bcache: bch_cached_dev_attach() Caching md125 as
> > bcache1 on set 521f7664-690d-4680-9b0d-1299fcee4321
> > [ 1597.723378] ------------[ cut here ]------------
> > [ 1597.723381] kernel BUG at drivers/md/bcache/writeback.c:562!
> > [ 1597.723389] invalid opcode: 0000 [#1] SMP NOPTI
> > [ 1597.723514] CPU: 0 PID: 2356 Comm: bcache_writebac Kdump: loaded
> > Tainted: G OE 5.4.45-esos.prod #1
> > [ 1597.723746] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011
> > [ 1597.723877] RIP: 0010:dirty_pred+0x17/0x21 [bcache]
> > [ 1597.723991] Code: 09 89 43 68 5b 5d 41 5c e9 e4 fd ff ff f0 48 0f
> > b3 3e c3 48 8b 06 8b 8f 38 f4 ff ff 48 89 c2 81 e2 ff ff 0f 00 48 39
> > d1 74 02 <0f> 0b 48 c1 e8 24 83 e0 01 c3 41 56 41 55 41 54 55 48 89 fd
> > 48 83
> > [ 1597.724426] RSP: 0018:ffffc900007f7bf0 EFLAGS: 00010297
> > [ 1597.724543] RAX: 9000000001000002 RBX: ffff88855f800c50 RCX: 0000000000000001
> > [ 1597.724699] RDX: 0000000000000002 RSI: ffff8885125a4f08 RDI: ffff88855f800c50
> > [ 1597.724857] RBP: ffff8885125a4f08 R08: 0000000000000001 R09: 0000000000000001
> > [ 1597.725015] R10: 9000000001000002 R11: 0000000000000001 R12: ffffc900007f7dd0
> > [ 1597.725175] R13: ffff8885a8797400 R14: ffff8885a87974c8 R15: 0000000000000000
> > [ 1597.725309] FS: 0000000000000000(0000) GS:ffff888627a00000(0000)
> > knlGS:0000000000000000
> > [ 1597.725428] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [ 1597.725517] CR2: 0000000000ce9d00 CR3: 000000059f304000 CR4: 0000000000340ef0
> > [ 1597.725623] Call Trace:
> > [ 1597.725672] refill_keybuf_fn+0x66/0x1a3 [bcache]
> > [ 1597.725743] ? mca_find+0x50/0x50 [bcache]
> > [ 1597.726310] bch_btree_map_keys_recurse+0x79/0x14c [bcache]
> > [ 1597.726433] bcache: bch_cached_dev_attach() Caching md126 as
> > bcache0 on set 521f7664-690d-4680-9b0d-1299fcee4321
> > [ 1597.726880] ? __switch_to_asm+0x34/0x70
> > [ 1597.728612] bcache: register_cache() registered cache device dm-0
> > [ 1597.729128] ? bch_btree_node_get+0xce/0x1bd [bcache]
> > [ 1597.730553] ? mca_find+0x50/0x50 [bcache]
> > [ 1597.731102] bch_btree_map_keys_recurse+0xc1/0x14c [bcache]
> > [ 1597.731672] ? __switch_to_asm+0x40/0x70
> > [ 1597.732219] ? __switch_to_asm+0x34/0x70
> > [ 1597.732770] ? __schedule+0x492/0x4b5
> > [ 1597.733319] ? rwsem_optimistic_spin+0x186/0x1ae
> > [ 1597.733873] ? mca_find+0x50/0x50 [bcache]
> > [ 1597.734431] bch_btree_map_keys+0x87/0xd5 [bcache]
> > [ 1597.734987] ? clear_bit+0x6/0x6 [bcache]
> > [ 1597.735537] bch_refill_keybuf+0x81/0x1ae [bcache]
> > [ 1597.736091] ? remove_wait_queue+0x41/0x41
> > [ 1597.736645] ? clear_bit+0x6/0x6 [bcache]
> > [ 1597.737189] bch_writeback_thread+0x35e/0x507 [bcache]
> > [ 1597.737755] ? read_dirty+0x448/0x448 [bcache]
> > [ 1597.738311] kthread+0xe4/0xe9
> > [ 1597.738843] ? kthread_flush_worker+0x70/0x70
> > [ 1597.739405] ret_from_fork+0x22/0x40
> > [ 1597.739951] Modules linked in: nvmet_fc(O) nvmet_rdma(O) nvmet(O)
> > bcache qla2xxx_scst(OE) nvme_fc(O) nvme_fabrics(O) bonding
> > cls_switchtec(O) qede qed mlx5_core(O) mlxfw(O) bna rdmavt(O)
> > ib_umad(O) rdma_ucm(O) ib_uverbs(O) ib_srp(O) rdma_cm(O) ib_cm(O)
> > iw_cm(O) iw_cxgb4(O) iw_cxgb3(O) ib_qib(O) mlx4_ib(O) mlx4_core(O)
> > ib_core(O) ib_mthca(O) nvme(O) nvme_core(O) mlx_compat(O)
> > [ 1597.743363] ---[ end trace 095defe1dc682fed ]---
> > [ 1597.743983] RIP: 0010:dirty_pred+0x17/0x21 [bcache]
> > [ 1597.746015] Code: 09 89 43 68 5b 5d 41 5c e9 e4 fd ff ff f0 48 0f
> > b3 3e c3 48 8b 06 8b 8f 38 f4 ff ff 48 89 c2 81 e2 ff ff 0f 00 48 39
> > d1 74 02 <0f> 0b 48 c1 e8 24 83 e0 01 c3 41 56 41 55 41 54 55 48 89 fd
> > 48 83
> > [ 1597.747806] RSP: 0018:ffffc900007f7bf0 EFLAGS: 00010297
> > [ 1597.748449] RAX: 9000000001000002 RBX: ffff88855f800c50 RCX: 0000000000000001
> > [ 1597.749097] RDX: 0000000000000002 RSI: ffff8885125a4f08 RDI: ffff88855f800c50
> > [ 1597.749769] RBP: ffff8885125a4f08 R08: 0000000000000001 R09: 0000000000000001
> > [ 1597.750427] R10: 9000000001000002 R11: 0000000000000001 R12: ffffc900007f7dd0
> > [ 1597.751073] R13: ffff8885a8797400 R14: ffff8885a87974c8 R15: 0000000000000000
> > [ 1597.751745] FS: 0000000000000000(0000) GS:ffff888627a00000(0000)
> > knlGS:0000000000000000
> > [ 1597.752900] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [ 1597.753544] CR2: 0000000000ce9d00 CR3: 000000059f304000 CR4: 0000000000340ef0
> > --snip--
> >
> > This line at the beginning of that snippet above catches my eye (when
> > registering the cache device):
> > [ 1597.707235] bcache: bch_journal_replay() journal replay done, 0
> > keys in 1 entries, seq 1412486
> >
> > This machine was in a crashed state, and then upon resetting it, I hit
> > the issue above when registering the backing/cache devices. Is the
> > cache/journal perhaps corrupted? Any way to manually
> > intervene/resolve?
> >
> > Thanks for your time.
>
> Hi Marc,
>
> Thanks for the reporting. Maybe this is a hidden issue in btree code
> (just a quick guess without any evidence).
>
> For the journal information you mentioned,
> "[ 1597.707235] bcache: bch_journal_replay() journal replay done, 0
> keys in 1 entries, seq 1412486"
> Because a journal_meta() operation may only flush a journal set block
> with cache set meta data without any extra btree key, the message itself
> is legal. I am not able to get suspicious clue from it.
Okay, thank you for the explanation. I took a peek at
bch_journal_replay() and understand now.
>
> Maybe the new kernel just improves to make less mistake for the hidden
> bug, but the root cause is not identified yet.
>
> BTW, there are 2 things in my brain,
> 1) Do you have this patch in your kernel,
> commit be23e837333a ("bcache: fix potential deadlock problem in
> btree_gc_coalesce")
No, looks like this fix came with 5.4.49 (I'm using .45 currently).
Will update ASAP.
> 2) The journal and btree flush issue was not totally fixed in v5.4. If I
> remember correctly the (currently) final fixes went into mainline kernel
> in v5.6. Could you please to try v5.6 stable tree see whether the
> situation might be better.
I can't move to or really test all that well 5.6.x at this moment.
However, if you know of a specific patch or set of patches you could
point me at, I could look at back porting these to 5.4.x for my use.
>
> It's pity that I am not able to tell where the problem immediately. But
> I keep this issue in my mind and I will try to trace it.
>
> Thank you again, for the important issue report.
Understood, thank you.
--Marc
>
> Coly Li
