Re: [PATCH v2 05/13] xfs: ratelimit unmount time per-buffer I/O error message

[Brian Foster <bfoster@redhat.com>]

On Fri, Apr 24, 2020 at 07:14:37AM +1000, Dave Chinner wrote:
> On Thu, Apr 23, 2020 at 10:29:58AM -0400, Brian Foster wrote:
> > On Thu, Apr 23, 2020 at 02:46:04PM +1000, Dave Chinner wrote:
> > > On Wed, Apr 22, 2020 at 01:54:21PM -0400, Brian Foster wrote:
> > > > At unmount time, XFS emits a warning for every in-core buffer that
> > > > might have undergone a write error. In practice this behavior is
> > > > probably reasonable given that the filesystem is likely short lived
> > > > once I/O errors begin to occur consistently. Under certain test or
> > > > otherwise expected error conditions, this can spam the logs and slow
> > > > down the unmount.
> > > > 
> > > > We already have a ratelimit state defined for buffers failing
> > > > writeback. Fold this state into the buftarg and reuse it for the
> > > > unmount time errors.
> > > > 
> > > > Signed-off-by: Brian Foster <bfoster@redhat.com>
> > > 
> > > Looks fine, but I suspect we both missed something here:
> > > xfs_buf_ioerror_alert() was made a ratelimited printk in the last
> > > cycle:
> > > 
> > > void
> > > xfs_buf_ioerror_alert(
> > >         struct xfs_buf          *bp,
> > >         xfs_failaddr_t          func)
> > > {
> > >         xfs_alert_ratelimited(bp->b_mount,
> > > "metadata I/O error in \"%pS\" at daddr 0x%llx len %d error %d",
> > >                         func, (uint64_t)XFS_BUF_ADDR(bp), bp->b_length,
> > >                         -bp->b_error);
> > > }
> > > 
> > 
> > Yeah, I hadn't noticed that.
> > 
> > > Hence I think all these buffer error alerts can be brought under the
> > > same rate limiting variable. Something like this in xfs_message.c:
> > > 
> > 
> > One thing to note is that xfs_alert_ratelimited() ultimately uses
> > the DEFAULT_RATELIMIT_INTERVAL of 5s. The ratelimit we're generalizing
> > here uses 30s (both use a burst of 10). That seems reasonable enough to
> > me for I/O errors so I'm good with the changes below.
> > 
> > FWIW, that also means we could just call xfs_buf_alert_ratelimited()
> > from xfs_buf_item_push() if we're also Ok with using an "alert" instead
> > of a "warn." I'm not immediately aware of a reason to use one over the
> > other (xfs_wait_buftarg() already uses alert) so I'll try that unless I
> > hear an objection.
> 
> SOunds fine to me.
> 
> > The xfs_wait_buftarg() ratelimit presumably remains
> > open coded because it's two separate calls and we probably don't want
> > them to individually count against the limit.
> 
> That's why I suggested dropping the second "run xfs_repair" message
> and triggering a shutdown after the wait loop. That way we don't
> issue "run xfs_repair" for every single failed buffer (largely
> noise!), and we get a non-rate-limited common "run xfs-repair"
> message once we processed all the failed writes.
> 

Sorry, must have missed that in the last reply. I don't think we want to
shut down here because XBF_WRITE_FAIL only reflects that the internal
async write retry (e.g. the one historically used to mitigate transient
I/O errors) has occurred on the buffer, not necessarily that the
immediately previous I/O has failed. For that reason I've kind of looked
at this particular instance as more of a warning that I/O errors have
occurred in the past and the user might want to verify it didn't result
in unexpected damage. FWIW, I've observed plenty of these messages long
after I've disabled error injection and allowed I/O to proceed and the
fs to unmount cleanly.

Looking at it again, the wording of the message is much stronger than a
warning (i.e. "Corruption Alert", "permanent write failures"), so
perhaps we should revisit what we're actually trying to accomplish with
this message. Note that we do have the buffer push time alert to
indicate that I/O errors and retries are occurring, as well as error
handling logic to shutdown on I/O failure while the fs is unmounting
(xfs_buf_iodone_callback_error()), so both of those cases are
fundamentally covered already.

ISTM that leaves at least a few simple options for the
xfs_wait_buftarg() message:

1.) Remove it.
2.) Massage it into more of a "Warning: buffer I/O errors have occurred
in the past" type of message. This could perhaps retain the existing
XBF_WRITE_FAIL logic, but use a flag to lift it out of the loop and thus
avoid the need to rate limit it at all.
3.) Fix up the logic to only dump (ratelimited) specifics on buffers
that have actually failed I/O. This means we use the existing message
but perhaps check ->b_error instead of XBF_WRITE_FAIL. We still don't
need to shut down (I'd probably add an assert), but we could also lift
the second xfs_repair line of the message out of the loop to reduce the
noise.

We could also look into clearing XBF_WRITE_RETRY on successful I/O
completion, FWIW. The existing logic kind of bugs me regardless.
Thoughts?

Brian

> Cheers,
> 
> Dave.
> -- 
> Dave Chinner
> david@fromorbit.com
>