On Fri, Jun 18, 2021 at 09:08:15AM -0400, Brian Foster wrote: > On Fri, Jun 18, 2021 at 09:43:08AM +1000, Dave Chinner wrote: > > On Thu, Jun 17, 2021 at 12:05:19PM -0700, Darrick J. Wong wrote: > > > On Thu, Jun 17, 2021 at 02:32:30PM -0400, Brian Foster wrote: > > > > On Thu, Jun 17, 2021 at 06:26:09PM +1000, Dave Chinner wrote: > > > > > Hi folks, > > > > > > > > > > This is followup from the first set of log fixes for for-next that > > > > > were posted here: > > > > > > > > > > https://lore.kernel.org/linux-xfs/20210615175719.GD158209@locust/T/#mde2cf0bb7d2ac369815a7e9371f0303efc89f51b > > > > > > > > > > The first two patches of this series are updates for those patches, > > > > > change log below. The rest is the fix for the bigger issue we > > > > > uncovered in investigating the generic/019 failures, being that > > > > > we're triggering a zero-day bug in the way log recovery assigns LSNs > > > > > to checkpoints. > > > > > > > > > > The "simple" fix of using the same ordering code as the commit > > > > > record for the start records in the CIL push turned into a lot of > > > > > patches once I started cleaning it up, separating out all the > > > > > different bits and finally realising all the things I needed to > > > > > change to avoid unintentional logic/behavioural changes. Hence > > > > > there's some code movement, some factoring, API changes to > > > > > xlog_write(), changing where we attach callbacks to commit iclogs so > > > > > they remain correctly ordered if there are multiple commit records > > > > > in the one iclog and then, finally, strictly ordering the start > > > > > records.... > > > > > > > > > > The original "simple fix" I tested last night ran almost a thousand > > > > > cycles of generic/019 without a log hang or recovery failure of any > > > > > kind. The refactored patchset has run a couple hundred cycles of > > > > > g/019 and g/475 over the last few hours without a failure, so I'm > > > > > posting this so we can get a review iteration done while I sleep so > > > > > we can - hopefully - get this sorted out before the end of the week. > > > > > > > > > > > > > My first spin of this included generic/019 and generic/475, ran for 18 > > > > or so iterations and 475 exploded with a stream of asserts followed by a > > > > NULL pointer crash: > > > > > > > > # grep -e Assertion -e BUG dmesg.out > > > > ... > > > > [ 7951.878058] XFS: Assertion failed: atomic_read(&buip->bui_refcount) > 0, file: fs/xfs/xfs_bmap_item.c, line: 57 > > > > [ 7952.261251] XFS: Assertion failed: atomic_read(&buip->bui_refcount) > 0, file: fs/xfs/xfs_bmap_item.c, line: 57 > > > > [ 7952.644444] XFS: Assertion failed: atomic_read(&buip->bui_refcount) > 0, file: fs/xfs/xfs_bmap_item.c, line: 57 > > > > [ 7953.027626] XFS: Assertion failed: atomic_read(&buip->bui_refcount) > 0, file: fs/xfs/xfs_bmap_item.c, line: 57 > > > > [ 7953.410804] BUG: kernel NULL pointer dereference, address: 000000000000031f > > > > [ 7954.118973] BUG: unable to handle page fault for address: ffffa57ccf99fa98 > > > > > > > > I don't know if this is a regression, but I've not seen it before. I've > > > > attempted to spin generic/475 since then to see if it reproduces again, > > > > but so far I'm only running into some of the preexisting issues > > > > associated with that test. > > > > I've not seen anything like that. I can't see how the changes in the > > patchset would affect BUI reference counting in any way. That seems > > more like an underlying intent item shutdown reference count issue > > to me (and we've had a *lot* of them in the past).... > > > > I've not made sense of it either, but at the same time, I've not seen it > in all my testing thus far up until targeting this series, and now I've > seen it twice in as many test runs as my overnight run fell into some > kind of similar haywire state. Unfortunately it seemed to be > spinning/streaming assert output so I lost any record of the initial > crash signature. It wouldn't surprise me if the fundamental problem is > some older bug in another area of code, but it's hard to believe it's > not at least related to this series somehow. > > Also FYI, earlier iterations of generic/475 triggered a couple instances > of the following assert failure before things broke down more severely: > > XFS: Assertion failed: *log_offset + *len <= iclog->ic_size || iclog->ic_state == XLOG_STATE_WANT_SYNC, file: fs/xfs/xfs_log.c, line: 2115 Yup, that's a bogus state check in the asssert. I already have a patch to fix that - the async shutdown can change the iclog state to XLOG_STATE_IOERROR at any time, so any iclog state assert outside of the log->l_icloglock needs also to allow for XLOG_STATE_IOERROR as a valid state. This is one of the problems I was alluding to on #xfs when I said: [18/6/21 14:42] <dchinner> I'm really not liking getting repeatedly caught out by racing, unreferenced iclog state changes during shutdown and having to handle them everywhere. Patch, FYI, below. Cheers, Dave. -- Dave Chinner david@xxxxxxxxxxxxx xfs: fix incorrect assert in xlog_write_single From: Dave Chinner <dchinner@xxxxxxxxxx> generic/475 failed with this assert after a log shutdown: [ 3953.166235] XFS: Assertion failed: *log_offset + *len <= iclog->ic_size || iclog->ic_state == XLOG_STATE_WANT_SYNC, file: fs/xfs/xfs_log.c, line: 2115 The problem is that after the log has shut down, the iclog state is XLOG_STATE_IOERROR. The shutdown can change the iclog state at any time while we are writing to it, so we need to add IOERROR to the valid states here. Note that we already have similar IOERROR state checks in asserts in the xlog_write() code for this reason (e.g. in xlog_write_get_more_iclog_space()) so this is just a case where the IOERROR state check was missed. The IOERROR state will be processed when we release the iclog, so just add the state into the assert and let the iclog release code handle the error. Signed-off-by: Dave Chinner <dchinner@xxxxxxxxxx> --- fs/xfs/xfs_log.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/fs/xfs/xfs_log.c b/fs/xfs/xfs_log.c index 94b6bccb9de9..221c080df305 100644 --- a/fs/xfs/xfs_log.c +++ b/fs/xfs/xfs_log.c @@ -2113,7 +2113,8 @@ xlog_write_single( int index; ASSERT(*log_offset + *len <= iclog->ic_size || - iclog->ic_state == XLOG_STATE_WANT_SYNC); + iclog->ic_state == XLOG_STATE_WANT_SYNC || + iclog->ic_state == XLOG_STATE_IOERROR); ptr = iclog->ic_datap + *log_offset; for (lv = log_vector;
