On Wed, Feb 28, 2024 at 03:13:04PM -0500, Brian Foster wrote:
> On Wed, Feb 28, 2024 at 03:03:06PM -0500, Kent Overstreet wrote:
> > On Wed, Feb 28, 2024 at 02:47:26PM -0500, Brian Foster wrote:
> > > Hi Kent,
> > >
> > > Firstly, I confirmed that today's master seems to avoid the splat I sent
> > > previously (re: your comment about a reverse journal replay patch or
> > > some such).
> > >
> > > I still reproduce the stall issue on this system. After peeling away at
> > > it, I was eventually able to reproduce without the drop writes
> > > (dm-flakey) behavior from the test, and with fio using either the libaio
> > > or sync I/O engine options. The sync I/O mode fortunately provides a
> > > more useful stack trace:
> > >
> > > # cat /proc/177747/stack
> > > [<0>] bch2_dio_write_flush+0x122/0x160 [bcachefs]
> > > [<0>] bch2_direct_write+0xb53/0xce0 [bcachefs]
> > > [<0>] bch2_write_iter+0x142/0xc70 [bcachefs]
> > > [<0>] vfs_write+0x29b/0x470
> > > [<0>] ksys_write+0x6f/0xf0
> > > [<0>] do_syscall_64+0x86/0x170
> > > [<0>] entry_SYSCALL_64_after_hwframe+0x6e/0x76
> > >
> > > ... which resolves down to the closure_sync() call in
> > > bch2_dio_write_flush(). The problem seems to go away if I remove the
> > > preceding journal flush from that function. This seems to rule out
> > > io_uring/aio and instead suggest that we're getting stuck somehow
> > > waiting on a journal flush.
> > >
> > > Based on that I went back to the first commit before 746a33c96b7a0
> > > ("bcachefs: better journal pipelining"). With that, I can run hundreds
> > > of iterations of generic/703 without a problem, so this appears to be a
> > > regression associated with the journal pipeline improvements. I'm
> > > currently re-running on the last known good commit with my test tweaks
> > > backed out (i.e. so back to io_uring and drop writes) just to
> > > corroborate that it's the same problem, but so far it's running as
> > > expected...
> >
> > So I suppose the journal must be getting stuck, and a journal write
> > isn't completing - what does sysfs internal/journal_debug say when it
> > happens?
> >
>
> dirty journal entries: 0/32768
> seq: 11
> seq_ondisk: 11
> last_seq: 12
> last_seq_ondisk: 11
> flushed_seq_ondisk: 11
> watermark: stripe
> each entry reserved: 346
> nr flush writes: 10
> nr noflush writes: 1
> average write size: 10.9 KiB
> nr direct reclaim: 0
> nr background reclaim: 25
> reclaim kicked: 0
> reclaim runs in: 0 ms
> current entry sectors: 512
> current entry error: ok
> current entry: closed
> unwritten entries:
> last buf closed
> replay done: 1
> space:
> discarded 512:244736
> clean ondisk 512:244736
> clean 512:244736
> total 512:245760
> dev 0:
> nr 480
> bucket size 512
> available 478:266
> discard_idx 1
> dirty_ondisk 1 (seq 11)
> dirty_idx 1 (seq 11)
> cur_idx 1 (seq 11)
>
I might see it - journal_last_unwritten_seq() is now wrong, it's
assuming that j->seq_ondisk + 1 hasn't been submitted yet.
bch2_journal_flush_seq_async() then sets that journal buf to "must be a
flush write", but if it's already been submitted - whoops
But your journal_debug says seq_ondisk == flushed_seq_ondisk, so maybe
that's not actually it here?
