[PATCH] xfs: clear XBF_ASYNC if we attach an iodone callback

[PATCH] xfs: clear XBF_ASYNC if we attach an iodone callback

[Josef Bacik]

While testing nbd disconnects I kept hitting the following hang

Call Trace:
 schedule+0x35/0x80
 xfs_ail_push_all_sync+0xa3/0xe0
 ? prepare_to_wait_event+0x100/0x100
 xfs_unmountfs+0x57/0x190
 xfs_fs_put_super+0x32/0x90
 generic_shutdown_super+0x6f/0xf0
 kill_block_super+0x27/0x70
 deactivate_locked_super+0x3e/0x70
 deactivate_super+0x46/0x60
 cleanup_mnt+0x3f/0x80
 __cleanup_mnt+0x12/0x20
 task_work_run+0x86/0xb0
 exit_to_usermode_loop+0x6d/0x96
 do_syscall_64+0x8b/0xa0
 entry_SYSCALL64_slow_path+0x25/0x25

After some digging around I found that there was a log item on the ail
with a callback of xfs_iflush_done.  A printk confirmed that at the call
to xfs_buf_attach_iodone in xfs_iflush_int had XBF_ASYNC already set,
which means on error we do not call xfs_buf_do_callbacks, which leaves
the log item on the ail list which causes us to hang on unmount.  I
assume the block has XBF_ASYNC set because we did a readahead on it, so
it doesn't really need to have XBF_ASYNC set at this point as we do
actually care about what happens to the buffer once IO is complete.
With this patch my hang no longer happens.

Signed-off-by: Josef Bacik <jbacik@fb.com>
---
 fs/xfs/xfs_buf_item.c | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/fs/xfs/xfs_buf_item.c b/fs/xfs/xfs_buf_item.c
index 2975cb2..24fcb67 100644
--- a/fs/xfs/xfs_buf_item.c
+++ b/fs/xfs/xfs_buf_item.c
@@ -1016,6 +1016,11 @@ xfs_buf_attach_iodone(
 
 	ASSERT(bp->b_iodone == NULL ||
 	       bp->b_iodone == xfs_buf_iodone_callbacks);
+	/*
+	 * Somebody now cares about the fate of this buffer, clear XBF_ASYNC so
+	 * that the iodone callback actually gets called.
+	 */
+	bp->b_flags &= ~XBF_ASYNC;
 	bp->b_iodone = xfs_buf_iodone_callbacks;
 }
 
-- 
2.5.5

Re: [PATCH] xfs: clear XBF_ASYNC if we attach an iodone callback

[Brian Foster]

On Fri, Mar 03, 2017 at 09:46:44AM -0500, Josef Bacik wrote:
> While testing nbd disconnects I kept hitting the following hang
> 
> Call Trace:
>  schedule+0x35/0x80
>  xfs_ail_push_all_sync+0xa3/0xe0
>  ? prepare_to_wait_event+0x100/0x100
>  xfs_unmountfs+0x57/0x190
>  xfs_fs_put_super+0x32/0x90
>  generic_shutdown_super+0x6f/0xf0
>  kill_block_super+0x27/0x70
>  deactivate_locked_super+0x3e/0x70
>  deactivate_super+0x46/0x60
>  cleanup_mnt+0x3f/0x80
>  __cleanup_mnt+0x12/0x20
>  task_work_run+0x86/0xb0
>  exit_to_usermode_loop+0x6d/0x96
>  do_syscall_64+0x8b/0xa0
>  entry_SYSCALL64_slow_path+0x25/0x25
> 
> After some digging around I found that there was a log item on the ail
> with a callback of xfs_iflush_done.  A printk confirmed that at the call
> to xfs_buf_attach_iodone in xfs_iflush_int had XBF_ASYNC already set,
> which means on error we do not call xfs_buf_do_callbacks, which leaves
> the log item on the ail list which causes us to hang on unmount.  I
> assume the block has XBF_ASYNC set because we did a readahead on it, so
> it doesn't really need to have XBF_ASYNC set at this point as we do
> actually care about what happens to the buffer once IO is complete.
> With this patch my hang no longer happens.
> 
> Signed-off-by: Josef Bacik <jbacik@fb.com>
> ---
>  fs/xfs/xfs_buf_item.c | 5 +++++
>  1 file changed, 5 insertions(+)
> 
> diff --git a/fs/xfs/xfs_buf_item.c b/fs/xfs/xfs_buf_item.c
> index 2975cb2..24fcb67 100644
> --- a/fs/xfs/xfs_buf_item.c
> +++ b/fs/xfs/xfs_buf_item.c
> @@ -1016,6 +1016,11 @@ xfs_buf_attach_iodone(
>  
>  	ASSERT(bp->b_iodone == NULL ||
>  	       bp->b_iodone == xfs_buf_iodone_callbacks);
> +	/*
> +	 * Somebody now cares about the fate of this buffer, clear XBF_ASYNC so
> +	 * that the iodone callback actually gets called.
> +	 */
> +	bp->b_flags &= ~XBF_ASYNC;

XBF_ASYNC generally describes the type of I/O being submitted for a
particular buffer (blocking or non), so it being set or not is kind of
outside the scope of xfs_iflush(). It really depends on how the caller
ultimately wants to write the buffer. For example, if we get here via
xfsaild_push()->xfs_inode_item_push(), the latter will do
xfs_buf_delwri_queue() and the former will eventually call
xfs_buf_delwri_submit_nowait(), which submits async I/O and so will
re-add XBF_ASYNC.

It is interesting if this prevents your problem. I can't quite make out
why that would be. The other xfs_iflush() caller is reclaim, which calls
xfs_bwrite() which itself clears XBF_ASYNC before submission.

What I'm guessing you're referring to above wrt to not calling
xfs_buf_do_callbacks() is the async check in
xfs_buf_iodone_callback_error(), which is only relevant on I/O error. If
the buffer I/O succeeds, we should always invoke the iodone callbacks
regardless of async state. Do you observe otherwise or does this I/O
indeed fail?

Anyways, if we change the buffer flags simply to control the behavior of
iodone_callback_error(), we've basically decided to treat an otherwise
async I/O as sync with the assumption that the submitter is going to
handle the I/O error. As mentioned above, we don't really have that
information here so that is kind of a dangerous assumption. At the very
least, it bypasses all of the configurable error handling infrastructure
that is specifically in place for async submitted buffers.

I'm wondering if you're hitting the flush locked inode retry problem
that Carlos has been working on. The problem is basically that if the
I/O fails on a buffer that backs a flush locked inode, we never retry
the buffer and xfsaild basically spins on pushing the inode. What
happens if you enable xfs tracepoints while the fs is hung?

Brian

>  	bp->b_iodone = xfs_buf_iodone_callbacks;
>  }
>  
> -- 
> 2.5.5
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH] xfs: clear XBF_ASYNC if we attach an iodone callback

[Josef Bacik]

On Fri, 2017-03-03 at 15:49 -0500, Brian Foster wrote:
> On Fri, Mar 03, 2017 at 09:46:44AM -0500, Josef Bacik wrote:
> > 
> > While testing nbd disconnects I kept hitting the following hang
> > 
> > Call Trace:
> >  schedule+0x35/0x80
> >  xfs_ail_push_all_sync+0xa3/0xe0
> >  ? prepare_to_wait_event+0x100/0x100
> >  xfs_unmountfs+0x57/0x190
> >  xfs_fs_put_super+0x32/0x90
> >  generic_shutdown_super+0x6f/0xf0
> >  kill_block_super+0x27/0x70
> >  deactivate_locked_super+0x3e/0x70
> >  deactivate_super+0x46/0x60
> >  cleanup_mnt+0x3f/0x80
> >  __cleanup_mnt+0x12/0x20
> >  task_work_run+0x86/0xb0
> >  exit_to_usermode_loop+0x6d/0x96
> >  do_syscall_64+0x8b/0xa0
> >  entry_SYSCALL64_slow_path+0x25/0x25
> > 
> > After some digging around I found that there was a log item on the
> > ail
> > with a callback of xfs_iflush_done.  A printk confirmed that at the
> > call
> > to xfs_buf_attach_iodone in xfs_iflush_int had XBF_ASYNC already
> > set,
> > which means on error we do not call xfs_buf_do_callbacks, which
> > leaves
> > the log item on the ail list which causes us to hang on unmount.  I
> > assume the block has XBF_ASYNC set because we did a readahead on
> > it, so
> > it doesn't really need to have XBF_ASYNC set at this point as we do
> > actually care about what happens to the buffer once IO is complete.
> > With this patch my hang no longer happens.
> > 
> > Signed-off-by: Josef Bacik <jbacik@fb.com>
> > ---
> >  fs/xfs/xfs_buf_item.c | 5 +++++
> >  1 file changed, 5 insertions(+)
> > 
> > diff --git a/fs/xfs/xfs_buf_item.c b/fs/xfs/xfs_buf_item.c
> > index 2975cb2..24fcb67 100644
> > --- a/fs/xfs/xfs_buf_item.c
> > +++ b/fs/xfs/xfs_buf_item.c
> > @@ -1016,6 +1016,11 @@ xfs_buf_attach_iodone(
> >  
> >  	ASSERT(bp->b_iodone == NULL ||
> >  	       bp->b_iodone == xfs_buf_iodone_callbacks);
> > +	/*
> > +	 * Somebody now cares about the fate of this buffer, clear
> > XBF_ASYNC so
> > +	 * that the iodone callback actually gets called.
> > +	 */
> > +	bp->b_flags &= ~XBF_ASYNC;
> XBF_ASYNC generally describes the type of I/O being submitted for a
> particular buffer (blocking or non), so it being set or not is kind
> of
> outside the scope of xfs_iflush(). It really depends on how the
> caller
> ultimately wants to write the buffer. For example, if we get here via
> xfsaild_push()->xfs_inode_item_push(), the latter will do
> xfs_buf_delwri_queue() and the former will eventually call
> xfs_buf_delwri_submit_nowait(), which submits async I/O and so will
> re-add XBF_ASYNC.
> 
> It is interesting if this prevents your problem. I can't quite make
> out
> why that would be. The other xfs_iflush() caller is reclaim, which
> calls
> xfs_bwrite() which itself clears XBF_ASYNC before submission.
> 
> What I'm guessing you're referring to above wrt to not calling
> xfs_buf_do_callbacks() is the async check in
> xfs_buf_iodone_callback_error(), which is only relevant on I/O error.
> If
> the buffer I/O succeeds, we should always invoke the iodone callbacks
> regardless of async state. Do you observe otherwise or does this I/O
> indeed fail?
> 
> Anyways, if we change the buffer flags simply to control the behavior
> of
> iodone_callback_error(), we've basically decided to treat an
> otherwise
> async I/O as sync with the assumption that the submitter is going to
> handle the I/O error. As mentioned above, we don't really have that
> information here so that is kind of a dangerous assumption. At the
> very
> least, it bypasses all of the configurable error handling
> infrastructure
> that is specifically in place for async submitted buffers.
> 
> I'm wondering if you're hitting the flush locked inode retry problem
> that Carlos has been working on. The problem is basically that if the
> I/O fails on a buffer that backs a flush locked inode, we never retry
> the buffer and xfsaild basically spins on pushing the inode. What
> happens if you enable xfs tracepoints while the fs is hung?

Sorry for some reason my reply to linux-xfs got eaten.  It made it to
Darrick but vger is being weird (sometimes it fails to get an email,
sometimes it works fine).

So yes my patch doesn't actually work, I just didn't notice that the
problem had happened until after I sent the page.

I'm doing this on a 4.6 kernel, I haven't actually tried it on a
upstream kernel but my original assumption was it was still available
to hit on an upstream kernel.  Basically on 4.6 we _always_ resubmit
the IO once if it fails, and then just drop the buffer if we've re-
submitted once.  We never do the xfs_buf_do_callbacks() call, which
seems wrong since as you say basically everything will set XBF_ASYNC.

What I've done to fix it for 4.6 was in the second case where we just
drop the buffer was to go ahead and do the xfs_buf_do_callbacks() call
and then clear the fspriv and iodone callback on the buffer, and that
actually made the problem go away.  Looking at the upstream code if
it's a permanent IO error we still do the callbacks, so I think the
problem I've hit has already been fixed upstream.  I'll verify next
week just to be sure, since I can usually hit the problem in less than
5 minutes of my reproducer.  Thanks,

Josef

Re: [PATCH] xfs: clear XBF_ASYNC if we attach an iodone callback

[Brian Foster]

On Fri, Mar 03, 2017 at 04:34:16PM -0500, Josef Bacik wrote:
> On Fri, 2017-03-03 at 15:49 -0500, Brian Foster wrote:
> > On Fri, Mar 03, 2017 at 09:46:44AM -0500, Josef Bacik wrote:
> > > 
> > > While testing nbd disconnects I kept hitting the following hang
> > > 
> > > Call Trace:
> > >  schedule+0x35/0x80
> > >  xfs_ail_push_all_sync+0xa3/0xe0
> > >  ? prepare_to_wait_event+0x100/0x100
> > >  xfs_unmountfs+0x57/0x190
> > >  xfs_fs_put_super+0x32/0x90
> > >  generic_shutdown_super+0x6f/0xf0
> > >  kill_block_super+0x27/0x70
> > >  deactivate_locked_super+0x3e/0x70
> > >  deactivate_super+0x46/0x60
> > >  cleanup_mnt+0x3f/0x80
> > >  __cleanup_mnt+0x12/0x20
> > >  task_work_run+0x86/0xb0
> > >  exit_to_usermode_loop+0x6d/0x96
> > >  do_syscall_64+0x8b/0xa0
> > >  entry_SYSCALL64_slow_path+0x25/0x25
> > > 
> > > After some digging around I found that there was a log item on the
> > > ail
> > > with a callback of xfs_iflush_done.  A printk confirmed that at the
> > > call
> > > to xfs_buf_attach_iodone in xfs_iflush_int had XBF_ASYNC already
> > > set,
> > > which means on error we do not call xfs_buf_do_callbacks, which
> > > leaves
> > > the log item on the ail list which causes us to hang on unmount.  I
> > > assume the block has XBF_ASYNC set because we did a readahead on
> > > it, so
> > > it doesn't really need to have XBF_ASYNC set at this point as we do
> > > actually care about what happens to the buffer once IO is complete.
> > > With this patch my hang no longer happens.
> > > 
> > > Signed-off-by: Josef Bacik <jbacik@fb.com>
> > > ---
> > >  fs/xfs/xfs_buf_item.c | 5 +++++
> > >  1 file changed, 5 insertions(+)
> > > 
> > > diff --git a/fs/xfs/xfs_buf_item.c b/fs/xfs/xfs_buf_item.c
> > > index 2975cb2..24fcb67 100644
> > > --- a/fs/xfs/xfs_buf_item.c
> > > +++ b/fs/xfs/xfs_buf_item.c
> > > @@ -1016,6 +1016,11 @@ xfs_buf_attach_iodone(
> > >  
> > >  	ASSERT(bp->b_iodone == NULL ||
> > >  	       bp->b_iodone == xfs_buf_iodone_callbacks);
> > > +	/*
> > > +	 * Somebody now cares about the fate of this buffer, clear
> > > XBF_ASYNC so
> > > +	 * that the iodone callback actually gets called.
> > > +	 */
> > > +	bp->b_flags &= ~XBF_ASYNC;
> > XBF_ASYNC generally describes the type of I/O being submitted for a
> > particular buffer (blocking or non), so it being set or not is kind
> > of
> > outside the scope of xfs_iflush(). It really depends on how the
> > caller
> > ultimately wants to write the buffer. For example, if we get here via
> > xfsaild_push()->xfs_inode_item_push(), the latter will do
> > xfs_buf_delwri_queue() and the former will eventually call
> > xfs_buf_delwri_submit_nowait(), which submits async I/O and so will
> > re-add XBF_ASYNC.
> > 
> > It is interesting if this prevents your problem. I can't quite make
> > out
> > why that would be. The other xfs_iflush() caller is reclaim, which
> > calls
> > xfs_bwrite() which itself clears XBF_ASYNC before submission.
> > 
> > What I'm guessing you're referring to above wrt to not calling
> > xfs_buf_do_callbacks() is the async check in
> > xfs_buf_iodone_callback_error(), which is only relevant on I/O error.
> > If
> > the buffer I/O succeeds, we should always invoke the iodone callbacks
> > regardless of async state. Do you observe otherwise or does this I/O
> > indeed fail?
> > 
> > Anyways, if we change the buffer flags simply to control the behavior
> > of
> > iodone_callback_error(), we've basically decided to treat an
> > otherwise
> > async I/O as sync with the assumption that the submitter is going to
> > handle the I/O error. As mentioned above, we don't really have that
> > information here so that is kind of a dangerous assumption. At the
> > very
> > least, it bypasses all of the configurable error handling
> > infrastructure
> > that is specifically in place for async submitted buffers.
> > 
> > I'm wondering if you're hitting the flush locked inode retry problem
> > that Carlos has been working on. The problem is basically that if the
> > I/O fails on a buffer that backs a flush locked inode, we never retry
> > the buffer and xfsaild basically spins on pushing the inode. What
> > happens if you enable xfs tracepoints while the fs is hung?
> 
> Sorry for some reason my reply to linux-xfs got eaten.  It made it to
> Darrick but vger is being weird (sometimes it fails to get an email,
> sometimes it works fine).
> 
> So yes my patch doesn't actually work, I just didn't notice that the
> problem had happened until after I sent the page.
> 
> I'm doing this on a 4.6 kernel, I haven't actually tried it on a
> upstream kernel but my original assumption was it was still available
> to hit on an upstream kernel.  Basically on 4.6 we _always_ resubmit
> the IO once if it fails, and then just drop the buffer if we've re-
> submitted once.  We never do the xfs_buf_do_callbacks() call, which
> seems wrong since as you say basically everything will set XBF_ASYNC.
> 

The XBF_WRITE_FAIL resubmission is an internal retry thing intended to
deal with transient errors. Assuming the internal retry fails, we do
release the buffer but note that the higher level item is still tracked
on the AIL (which basically just tracks that the inode is in the
physical log and we're waiting on the metadata writeback to complete to
free up space in the log).

IOWs, while the I/O path doesn't retry and releases the buffer, the
intent is that the next xfsaild_push() cycle will retry the I/O (this is
the part that is actually broken for flush locked inodes).

> What I've done to fix it for 4.6 was in the second case where we just
> drop the buffer was to go ahead and do the xfs_buf_do_callbacks() call
> and then clear the fspriv and iodone callback on the buffer, and that
> actually made the problem go away.  Looking at the upstream code if
> it's a permanent IO error we still do the callbacks, so I think the
> problem I've hit has already been fixed upstream.  I'll verify next
> week just to be sure, since I can usually hit the problem in less than
> 5 minutes of my reproducer.  Thanks,
> 

Ok, just be aware that while that might allow your hung unmount case to
progress, what you're doing in the general/runtime case is treating a
buffer that fails the I/O twice as successfully completed. E.g., see
that xfs_iflush_done() invokes xfs_trans_ail_delete_bulk() which removes
the inode item from the AIL as if it were written back to its final
location on disk.

It might not be straightforward to reproduce because in practice I/O
errors won't occur, may mean the device is broken and the fs is going to
shutdown anyways, or some other dirty inode backed by the same buffer
might flush it, but otherwise this sounds like a path to corruption. For
example, suppose we modify an inode, commit the transaction etc. such
that the inode makes it to the log. At this point, the buffer is now
available for writeback. Say we attempt the buffer writeback and it
fails both initially and for the internal retry. IIUC, the change you've
made will basically release the inode from the AIL at this point as if
it succeeded, but clearly the updated inode has not made it to disk. If
the device otherwise goes back to normal and no more I/O errors occur,
we've basically just thrown away the change to the inode and corrupted
the fs.

Brian

> Josef

Re: [PATCH] xfs: clear XBF_ASYNC if we attach an iodone callback

[Josef Bacik]

> On Mar 3, 2017, at 5:20 PM, Brian Foster <bfoster@redhat.com> wrote:
> 
>> On Fri, Mar 03, 2017 at 04:34:16PM -0500, Josef Bacik wrote:
>>> On Fri, 2017-03-03 at 15:49 -0500, Brian Foster wrote:
>>>> On Fri, Mar 03, 2017 at 09:46:44AM -0500, Josef Bacik wrote:
>>>> 
>>>> While testing nbd disconnects I kept hitting the following hang
>>>> 
>>>> Call Trace:
>>>>  schedule+0x35/0x80
>>>>  xfs_ail_push_all_sync+0xa3/0xe0
>>>>  ? prepare_to_wait_event+0x100/0x100
>>>>  xfs_unmountfs+0x57/0x190
>>>>  xfs_fs_put_super+0x32/0x90
>>>>  generic_shutdown_super+0x6f/0xf0
>>>>  kill_block_super+0x27/0x70
>>>>  deactivate_locked_super+0x3e/0x70
>>>>  deactivate_super+0x46/0x60
>>>>  cleanup_mnt+0x3f/0x80
>>>>  __cleanup_mnt+0x12/0x20
>>>>  task_work_run+0x86/0xb0
>>>>  exit_to_usermode_loop+0x6d/0x96
>>>>  do_syscall_64+0x8b/0xa0
>>>>  entry_SYSCALL64_slow_path+0x25/0x25
>>>> 
>>>> After some digging around I found that there was a log item on the
>>>> ail
>>>> with a callback of xfs_iflush_done.  A printk confirmed that at the
>>>> call
>>>> to xfs_buf_attach_iodone in xfs_iflush_int had XBF_ASYNC already
>>>> set,
>>>> which means on error we do not call xfs_buf_do_callbacks, which
>>>> leaves
>>>> the log item on the ail list which causes us to hang on unmount.  I
>>>> assume the block has XBF_ASYNC set because we did a readahead on
>>>> it, so
>>>> it doesn't really need to have XBF_ASYNC set at this point as we do
>>>> actually care about what happens to the buffer once IO is complete.
>>>> With this patch my hang no longer happens.
>>>> 
>>>> Signed-off-by: Josef Bacik <jbacik@fb.com>
>>>> ---
>>>>  fs/xfs/xfs_buf_item.c | 5 +++++
>>>>  1 file changed, 5 insertions(+)
>>>> 
>>>> diff --git a/fs/xfs/xfs_buf_item.c b/fs/xfs/xfs_buf_item.c
>>>> index 2975cb2..24fcb67 100644
>>>> --- a/fs/xfs/xfs_buf_item.c
>>>> +++ b/fs/xfs/xfs_buf_item.c
>>>> @@ -1016,6 +1016,11 @@ xfs_buf_attach_iodone(
>>>>  
>>>>      ASSERT(bp->b_iodone == NULL ||
>>>>             bp->b_iodone == xfs_buf_iodone_callbacks);
>>>> +    /*
>>>> +     * Somebody now cares about the fate of this buffer, clear
>>>> XBF_ASYNC so
>>>> +     * that the iodone callback actually gets called.
>>>> +     */
>>>> +    bp->b_flags &= ~XBF_ASYNC;
>>> XBF_ASYNC generally describes the type of I/O being submitted for a
>>> particular buffer (blocking or non), so it being set or not is kind
>>> of
>>> outside the scope of xfs_iflush(). It really depends on how the
>>> caller
>>> ultimately wants to write the buffer. For example, if we get here via
>>> xfsaild_push()->xfs_inode_item_push(), the latter will do
>>> xfs_buf_delwri_queue() and the former will eventually call
>>> xfs_buf_delwri_submit_nowait(), which submits async I/O and so will
>>> re-add XBF_ASYNC.
>>> 
>>> It is interesting if this prevents your problem. I can't quite make
>>> out
>>> why that would be. The other xfs_iflush() caller is reclaim, which
>>> calls
>>> xfs_bwrite() which itself clears XBF_ASYNC before submission.
>>> 
>>> What I'm guessing you're referring to above wrt to not calling
>>> xfs_buf_do_callbacks() is the async check in
>>> xfs_buf_iodone_callback_error(), which is only relevant on I/O error.
>>> If
>>> the buffer I/O succeeds, we should always invoke the iodone callbacks
>>> regardless of async state. Do you observe otherwise or does this I/O
>>> indeed fail?
>>> 
>>> Anyways, if we change the buffer flags simply to control the behavior
>>> of
>>> iodone_callback_error(), we've basically decided to treat an
>>> otherwise
>>> async I/O as sync with the assumption that the submitter is going to
>>> handle the I/O error. As mentioned above, we don't really have that
>>> information here so that is kind of a dangerous assumption. At the
>>> very
>>> least, it bypasses all of the configurable error handling
>>> infrastructure
>>> that is specifically in place for async submitted buffers.
>>> 
>>> I'm wondering if you're hitting the flush locked inode retry problem
>>> that Carlos has been working on. The problem is basically that if the
>>> I/O fails on a buffer that backs a flush locked inode, we never retry
>>> the buffer and xfsaild basically spins on pushing the inode. What
>>> happens if you enable xfs tracepoints while the fs is hung?
>> 
>> Sorry for some reason my reply to linux-xfs got eaten.  It made it to
>> Darrick but vger is being weird (sometimes it fails to get an email,
>> sometimes it works fine).
>> 
>> So yes my patch doesn't actually work, I just didn't notice that the
>> problem had happened until after I sent the page.
>> 
>> I'm doing this on a 4.6 kernel, I haven't actually tried it on a
>> upstream kernel but my original assumption was it was still available
>> to hit on an upstream kernel.  Basically on 4.6 we _always_ resubmit
>> the IO once if it fails, and then just drop the buffer if we've re-
>> submitted once.  We never do the xfs_buf_do_callbacks() call, which
>> seems wrong since as you say basically everything will set XBF_ASYNC.
>> 
> 
> The XBF_WRITE_FAIL resubmission is an internal retry thing intended to
> deal with transient errors. Assuming the internal retry fails, we do
> release the buffer but note that the higher level item is still tracked
> on the AIL (which basically just tracks that the inode is in the
> physical log and we're waiting on the metadata writeback to complete to
> free up space in the log).
> 
> IOWs, while the I/O path doesn't retry and releases the buffer, the
> intent is that the next xfsaild_push() cycle will retry the I/O (this is
> the part that is actually broken for flush locked inodes).

Yeah this sounds like what is happening, as I'll see xfs errors every N seconds while its hanging, so it's retrying the IO, it's just not failing out gracefully. What would be the course of action here?  I can apply things and run them here pretty quickly.

> 
>> What I've done to fix it for 4.6 was in the second case where we just
>> drop the buffer was to go ahead and do the xfs_buf_do_callbacks() call
>> and then clear the fspriv and iodone callback on the buffer, and that
>> actually made the problem go away.  Looking at the upstream code if
>> it's a permanent IO error we still do the callbacks, so I think the
>> problem I've hit has already been fixed upstream.  I'll verify next
>> week just to be sure, since I can usually hit the problem in less than
>> 5 minutes of my reproducer.  Thanks,
>> 
> 
> Ok, just be aware that while that might allow your hung unmount case to
> progress, what you're doing in the general/runtime case is treating a
> buffer that fails the I/O twice as successfully completed. E.g., see
> that xfs_iflush_done() invokes xfs_trans_ail_delete_bulk() which removes
> the inode item from the AIL as if it were written back to its final
> location on disk.
> 
> It might not be straightforward to reproduce because in practice I/O
> errors won't occur, may mean the device is broken and the fs is going to
> shutdown anyways, or some other dirty inode backed by the same buffer
> might flush it, but otherwise this sounds like a path to corruption. For
> example, suppose we modify an inode, commit the transaction etc. such
> that the inode makes it to the log. At this point, the buffer is now
> available for writeback. Say we attempt the buffer writeback and it
> fails both initially and for the internal retry. IIUC, the change you've
> made will basically release the inode from the AIL at this point as if
> it succeeded, but clearly the updated inode has not made it to disk. If
> the device otherwise goes back to normal and no more I/O errors occur,
> we've basically just thrown away the change to the inode and corrupted
> the fs.

Well thankfully this is when the device goes completely away so I'm not worried about that, but yeah that's not an excellent general solution.  Though it looked like it was tripping the shutdown code in the iflush code, but this isn't my area.  Thanks,

Josef

Re: [PATCH] xfs: clear XBF_ASYNC if we attach an iodone callback

[Brian Foster]

cc Carlos

On Sat, Mar 04, 2017 at 01:26:50AM +0000, Josef Bacik wrote:
> 
> > On Mar 3, 2017, at 5:20 PM, Brian Foster <bfoster@redhat.com> wrote:
> > 
> >> On Fri, Mar 03, 2017 at 04:34:16PM -0500, Josef Bacik wrote:
> >>> On Fri, 2017-03-03 at 15:49 -0500, Brian Foster wrote:
> >>>> On Fri, Mar 03, 2017 at 09:46:44AM -0500, Josef Bacik wrote:
> >>>> 
> >>>> While testing nbd disconnects I kept hitting the following hang
> >>>> 
> >>>> Call Trace:
> >>>>  schedule+0x35/0x80
> >>>>  xfs_ail_push_all_sync+0xa3/0xe0
> >>>>  ? prepare_to_wait_event+0x100/0x100
> >>>>  xfs_unmountfs+0x57/0x190
> >>>>  xfs_fs_put_super+0x32/0x90
> >>>>  generic_shutdown_super+0x6f/0xf0
> >>>>  kill_block_super+0x27/0x70
> >>>>  deactivate_locked_super+0x3e/0x70
> >>>>  deactivate_super+0x46/0x60
> >>>>  cleanup_mnt+0x3f/0x80
> >>>>  __cleanup_mnt+0x12/0x20
> >>>>  task_work_run+0x86/0xb0
> >>>>  exit_to_usermode_loop+0x6d/0x96
> >>>>  do_syscall_64+0x8b/0xa0
> >>>>  entry_SYSCALL64_slow_path+0x25/0x25
> >>>> 
> >>>> After some digging around I found that there was a log item on the
> >>>> ail
> >>>> with a callback of xfs_iflush_done.  A printk confirmed that at the
> >>>> call
> >>>> to xfs_buf_attach_iodone in xfs_iflush_int had XBF_ASYNC already
> >>>> set,
> >>>> which means on error we do not call xfs_buf_do_callbacks, which
> >>>> leaves
> >>>> the log item on the ail list which causes us to hang on unmount.  I
> >>>> assume the block has XBF_ASYNC set because we did a readahead on
> >>>> it, so
> >>>> it doesn't really need to have XBF_ASYNC set at this point as we do
> >>>> actually care about what happens to the buffer once IO is complete.
> >>>> With this patch my hang no longer happens.
> >>>> 
> >>>> Signed-off-by: Josef Bacik <jbacik@fb.com>
> >>>> ---
> >>>>  fs/xfs/xfs_buf_item.c | 5 +++++
> >>>>  1 file changed, 5 insertions(+)
> >>>> 
> >>>> diff --git a/fs/xfs/xfs_buf_item.c b/fs/xfs/xfs_buf_item.c
> >>>> index 2975cb2..24fcb67 100644
> >>>> --- a/fs/xfs/xfs_buf_item.c
> >>>> +++ b/fs/xfs/xfs_buf_item.c
> >>>> @@ -1016,6 +1016,11 @@ xfs_buf_attach_iodone(
> >>>>  
> >>>>      ASSERT(bp->b_iodone == NULL ||
> >>>>             bp->b_iodone == xfs_buf_iodone_callbacks);
> >>>> +    /*
> >>>> +     * Somebody now cares about the fate of this buffer, clear
> >>>> XBF_ASYNC so
> >>>> +     * that the iodone callback actually gets called.
> >>>> +     */
> >>>> +    bp->b_flags &= ~XBF_ASYNC;
> >>> XBF_ASYNC generally describes the type of I/O being submitted for a
> >>> particular buffer (blocking or non), so it being set or not is kind
> >>> of
> >>> outside the scope of xfs_iflush(). It really depends on how the
> >>> caller
> >>> ultimately wants to write the buffer. For example, if we get here via
> >>> xfsaild_push()->xfs_inode_item_push(), the latter will do
> >>> xfs_buf_delwri_queue() and the former will eventually call
> >>> xfs_buf_delwri_submit_nowait(), which submits async I/O and so will
> >>> re-add XBF_ASYNC.
> >>> 
> >>> It is interesting if this prevents your problem. I can't quite make
> >>> out
> >>> why that would be. The other xfs_iflush() caller is reclaim, which
> >>> calls
> >>> xfs_bwrite() which itself clears XBF_ASYNC before submission.
> >>> 
> >>> What I'm guessing you're referring to above wrt to not calling
> >>> xfs_buf_do_callbacks() is the async check in
> >>> xfs_buf_iodone_callback_error(), which is only relevant on I/O error.
> >>> If
> >>> the buffer I/O succeeds, we should always invoke the iodone callbacks
> >>> regardless of async state. Do you observe otherwise or does this I/O
> >>> indeed fail?
> >>> 
> >>> Anyways, if we change the buffer flags simply to control the behavior
> >>> of
> >>> iodone_callback_error(), we've basically decided to treat an
> >>> otherwise
> >>> async I/O as sync with the assumption that the submitter is going to
> >>> handle the I/O error. As mentioned above, we don't really have that
> >>> information here so that is kind of a dangerous assumption. At the
> >>> very
> >>> least, it bypasses all of the configurable error handling
> >>> infrastructure
> >>> that is specifically in place for async submitted buffers.
> >>> 
> >>> I'm wondering if you're hitting the flush locked inode retry problem
> >>> that Carlos has been working on. The problem is basically that if the
> >>> I/O fails on a buffer that backs a flush locked inode, we never retry
> >>> the buffer and xfsaild basically spins on pushing the inode. What
> >>> happens if you enable xfs tracepoints while the fs is hung?
> >> 
> >> Sorry for some reason my reply to linux-xfs got eaten.  It made it to
> >> Darrick but vger is being weird (sometimes it fails to get an email,
> >> sometimes it works fine).
> >> 
> >> So yes my patch doesn't actually work, I just didn't notice that the
> >> problem had happened until after I sent the page.
> >> 
> >> I'm doing this on a 4.6 kernel, I haven't actually tried it on a
> >> upstream kernel but my original assumption was it was still available
> >> to hit on an upstream kernel.  Basically on 4.6 we _always_ resubmit
> >> the IO once if it fails, and then just drop the buffer if we've re-
> >> submitted once.  We never do the xfs_buf_do_callbacks() call, which
> >> seems wrong since as you say basically everything will set XBF_ASYNC.
> >> 
> > 
> > The XBF_WRITE_FAIL resubmission is an internal retry thing intended to
> > deal with transient errors. Assuming the internal retry fails, we do
> > release the buffer but note that the higher level item is still tracked
> > on the AIL (which basically just tracks that the inode is in the
> > physical log and we're waiting on the metadata writeback to complete to
> > free up space in the log).
> > 
> > IOWs, while the I/O path doesn't retry and releases the buffer, the
> > intent is that the next xfsaild_push() cycle will retry the I/O (this is
> > the part that is actually broken for flush locked inodes).
> 
> Yeah this sounds like what is happening, as I'll see xfs errors every N seconds while its hanging, so it's retrying the IO, it's just not failing out gracefully. What would be the course of action here?  I can apply things and run them here pretty quickly.
> 

If it is actually the flush lock issue, Carlos was working on a proper
fix for that. I'm not sure where that stands currently, however..
Carlos?

If there isn't anything available to test quite yet, there was also a
poc patch[1] more to verify what the problem was. I believe that one is
at least safe, but still probably not production worthy as it may have
performance ramifications. It should at least tell you whether that is
the problem or something else is going on here.

Oh, commit e6b3bb789 ("xfs: add "fail at unmount" error handling
configuration") may also be interesting here if the fs doesn't shutdown
on unmount. That one looks like it came after v4.6 as well.

Brian

[1] http://www.spinics.net/lists/linux-xfs/msg01018.html

> > 
> >> What I've done to fix it for 4.6 was in the second case where we just
> >> drop the buffer was to go ahead and do the xfs_buf_do_callbacks() call
> >> and then clear the fspriv and iodone callback on the buffer, and that
> >> actually made the problem go away.  Looking at the upstream code if
> >> it's a permanent IO error we still do the callbacks, so I think the
> >> problem I've hit has already been fixed upstream.  I'll verify next
> >> week just to be sure, since I can usually hit the problem in less than
> >> 5 minutes of my reproducer.  Thanks,
> >> 
> > 
> > Ok, just be aware that while that might allow your hung unmount case to
> > progress, what you're doing in the general/runtime case is treating a
> > buffer that fails the I/O twice as successfully completed. E.g., see
> > that xfs_iflush_done() invokes xfs_trans_ail_delete_bulk() which removes
> > the inode item from the AIL as if it were written back to its final
> > location on disk.
> > 
> > It might not be straightforward to reproduce because in practice I/O
> > errors won't occur, may mean the device is broken and the fs is going to
> > shutdown anyways, or some other dirty inode backed by the same buffer
> > might flush it, but otherwise this sounds like a path to corruption. For
> > example, suppose we modify an inode, commit the transaction etc. such
> > that the inode makes it to the log. At this point, the buffer is now
> > available for writeback. Say we attempt the buffer writeback and it
> > fails both initially and for the internal retry. IIUC, the change you've
> > made will basically release the inode from the AIL at this point as if
> > it succeeded, but clearly the updated inode has not made it to disk. If
> > the device otherwise goes back to normal and no more I/O errors occur,
> > we've basically just thrown away the change to the inode and corrupted
> > the fs.
> 
> Well thankfully this is when the device goes completely away so I'm not worried about that, but yeah that's not an excellent general solution.  Though it looked like it was tripping the shutdown code in the iflush code, but this isn't my area.  Thanks,
> 
> Josef--
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH] xfs: clear XBF_ASYNC if we attach an iodone callback

[Josef Bacik]

On Sat, 2017-03-04 at 08:58 -0500, Brian Foster wrote:
> cc Carlos
> 
> On Sat, Mar 04, 2017 at 01:26:50AM +0000, Josef Bacik wrote:
> > 
> > 
> > > 
> > > On Mar 3, 2017, at 5:20 PM, Brian Foster <bfoster@redhat.com>
> > > wrote:
> > > 
> > > > 
> > > > On Fri, Mar 03, 2017 at 04:34:16PM -0500, Josef Bacik wrote:
> > > > > 
> > > > > On Fri, 2017-03-03 at 15:49 -0500, Brian Foster wrote:
> > > > > > 
> > > > > > On Fri, Mar 03, 2017 at 09:46:44AM -0500, Josef Bacik
> > > > > > wrote:
> > > > > > 
> > > > > > While testing nbd disconnects I kept hitting the following
> > > > > > hang
> > > > > > 
> > > > > > Call Trace:
> > > > > >  schedule+0x35/0x80
> > > > > >  xfs_ail_push_all_sync+0xa3/0xe0
> > > > > >  ? prepare_to_wait_event+0x100/0x100
> > > > > >  xfs_unmountfs+0x57/0x190
> > > > > >  xfs_fs_put_super+0x32/0x90
> > > > > >  generic_shutdown_super+0x6f/0xf0
> > > > > >  kill_block_super+0x27/0x70
> > > > > >  deactivate_locked_super+0x3e/0x70
> > > > > >  deactivate_super+0x46/0x60
> > > > > >  cleanup_mnt+0x3f/0x80
> > > > > >  __cleanup_mnt+0x12/0x20
> > > > > >  task_work_run+0x86/0xb0
> > > > > >  exit_to_usermode_loop+0x6d/0x96
> > > > > >  do_syscall_64+0x8b/0xa0
> > > > > >  entry_SYSCALL64_slow_path+0x25/0x25
> > > > > > 
> > > > > > After some digging around I found that there was a log item
> > > > > > on the
> > > > > > ail
> > > > > > with a callback of xfs_iflush_done.  A printk confirmed
> > > > > > that at the
> > > > > > call
> > > > > > to xfs_buf_attach_iodone in xfs_iflush_int had XBF_ASYNC
> > > > > > already
> > > > > > set,
> > > > > > which means on error we do not call xfs_buf_do_callbacks,
> > > > > > which
> > > > > > leaves
> > > > > > the log item on the ail list which causes us to hang on
> > > > > > unmount.  I
> > > > > > assume the block has XBF_ASYNC set because we did a
> > > > > > readahead on
> > > > > > it, so
> > > > > > it doesn't really need to have XBF_ASYNC set at this point
> > > > > > as we do
> > > > > > actually care about what happens to the buffer once IO is
> > > > > > complete.
> > > > > > With this patch my hang no longer happens.
> > > > > > 
> > > > > > Signed-off-by: Josef Bacik <jbacik@fb.com>
> > > > > > ---
> > > > > >  fs/xfs/xfs_buf_item.c | 5 +++++
> > > > > >  1 file changed, 5 insertions(+)
> > > > > > 
> > > > > > diff --git a/fs/xfs/xfs_buf_item.c b/fs/xfs/xfs_buf_item.c
> > > > > > index 2975cb2..24fcb67 100644
> > > > > > --- a/fs/xfs/xfs_buf_item.c
> > > > > > +++ b/fs/xfs/xfs_buf_item.c
> > > > > > @@ -1016,6 +1016,11 @@ xfs_buf_attach_iodone(
> > > > > >  
> > > > > >      ASSERT(bp->b_iodone == NULL ||
> > > > > >             bp->b_iodone == xfs_buf_iodone_callbacks);
> > > > > > +    /*
> > > > > > +     * Somebody now cares about the fate of this buffer,
> > > > > > clear
> > > > > > XBF_ASYNC so
> > > > > > +     * that the iodone callback actually gets called.
> > > > > > +     */
> > > > > > +    bp->b_flags &= ~XBF_ASYNC;
> > > > > XBF_ASYNC generally describes the type of I/O being submitted
> > > > > for a
> > > > > particular buffer (blocking or non), so it being set or not
> > > > > is kind
> > > > > of
> > > > > outside the scope of xfs_iflush(). It really depends on how
> > > > > the
> > > > > caller
> > > > > ultimately wants to write the buffer. For example, if we get
> > > > > here via
> > > > > xfsaild_push()->xfs_inode_item_push(), the latter will do
> > > > > xfs_buf_delwri_queue() and the former will eventually call
> > > > > xfs_buf_delwri_submit_nowait(), which submits async I/O and
> > > > > so will
> > > > > re-add XBF_ASYNC.
> > > > > 
> > > > > It is interesting if this prevents your problem. I can't
> > > > > quite make
> > > > > out
> > > > > why that would be. The other xfs_iflush() caller is reclaim,
> > > > > which
> > > > > calls
> > > > > xfs_bwrite() which itself clears XBF_ASYNC before submission.
> > > > > 
> > > > > What I'm guessing you're referring to above wrt to not
> > > > > calling
> > > > > xfs_buf_do_callbacks() is the async check in
> > > > > xfs_buf_iodone_callback_error(), which is only relevant on
> > > > > I/O error.
> > > > > If
> > > > > the buffer I/O succeeds, we should always invoke the iodone
> > > > > callbacks
> > > > > regardless of async state. Do you observe otherwise or does
> > > > > this I/O
> > > > > indeed fail?
> > > > > 
> > > > > Anyways, if we change the buffer flags simply to control the
> > > > > behavior
> > > > > of
> > > > > iodone_callback_error(), we've basically decided to treat an
> > > > > otherwise
> > > > > async I/O as sync with the assumption that the submitter is
> > > > > going to
> > > > > handle the I/O error. As mentioned above, we don't really
> > > > > have that
> > > > > information here so that is kind of a dangerous assumption.
> > > > > At the
> > > > > very
> > > > > least, it bypasses all of the configurable error handling
> > > > > infrastructure
> > > > > that is specifically in place for async submitted buffers.
> > > > > 
> > > > > I'm wondering if you're hitting the flush locked inode retry
> > > > > problem
> > > > > that Carlos has been working on. The problem is basically
> > > > > that if the
> > > > > I/O fails on a buffer that backs a flush locked inode, we
> > > > > never retry
> > > > > the buffer and xfsaild basically spins on pushing the inode.
> > > > > What
> > > > > happens if you enable xfs tracepoints while the fs is hung?
> > > > Sorry for some reason my reply to linux-xfs got eaten.  It made
> > > > it to
> > > > Darrick but vger is being weird (sometimes it fails to get an
> > > > email,
> > > > sometimes it works fine).
> > > > 
> > > > So yes my patch doesn't actually work, I just didn't notice
> > > > that the
> > > > problem had happened until after I sent the page.
> > > > 
> > > > I'm doing this on a 4.6 kernel, I haven't actually tried it on
> > > > a
> > > > upstream kernel but my original assumption was it was still
> > > > available
> > > > to hit on an upstream kernel.  Basically on 4.6 we _always_
> > > > resubmit
> > > > the IO once if it fails, and then just drop the buffer if we've
> > > > re-
> > > > submitted once.  We never do the xfs_buf_do_callbacks() call,
> > > > which
> > > > seems wrong since as you say basically everything will set
> > > > XBF_ASYNC.
> > > > 
> > > The XBF_WRITE_FAIL resubmission is an internal retry thing
> > > intended to
> > > deal with transient errors. Assuming the internal retry fails, we
> > > do
> > > release the buffer but note that the higher level item is still
> > > tracked
> > > on the AIL (which basically just tracks that the inode is in the
> > > physical log and we're waiting on the metadata writeback to
> > > complete to
> > > free up space in the log).
> > > 
> > > IOWs, while the I/O path doesn't retry and releases the buffer,
> > > the
> > > intent is that the next xfsaild_push() cycle will retry the I/O
> > > (this is
> > > the part that is actually broken for flush locked inodes).
> > Yeah this sounds like what is happening, as I'll see xfs errors
> > every N seconds while its hanging, so it's retrying the IO, it's
> > just not failing out gracefully. What would be the course of action
> > here?  I can apply things and run them here pretty quickly.
> > 
> If it is actually the flush lock issue, Carlos was working on a
> proper
> fix for that. I'm not sure where that stands currently, however..
> Carlos?
> 
> If there isn't anything available to test quite yet, there was also a
> poc patch[1] more to verify what the problem was. I believe that one
> is
> at least safe, but still probably not production worthy as it may
> have
> performance ramifications. It should at least tell you whether that
> is
> the problem or something else is going on here.
> 
> Oh, commit e6b3bb789 ("xfs: add "fail at unmount" error handling
> configuration") may also be interesting here if the fs doesn't
> shutdown
> on unmount. That one looks like it came after v4.6 as well.

Ok I looked at that patch and the email that Dave sent in response,
which sounds like what I'm hitting.  Looking at the 4.6 code we simply
drop the xfs_buf if our IO retry fails and assume that the upper layer
will take care of things if it cares.  Meanwhile the thing writing out
the AIL doesn't actually know if things went wrong
unless xfs_iflush_done() is run.

In the upstream code you guys do this

        if (!(bp->b_flags & (XBF_STALE | XBF_WRITE_FAIL)) 
             bp->b_last_error != bp->b_error) {                    
                bp->b_flags |= (XBF_WRITE | XBF_DONE | XBF_WRITE_FAIL);
                bp->b_last_error = bp->b_error;                  
                if (cfg->retry_timeout != XFS_ERR_RETRY_FOREVER &&
                    !bp->b_first_retry_time)
                        bp->b_first_retry_time = jiffies;
                                                               
                xfs_buf_ioerror(bp, 0);                        
                xfs_buf_submit(bp);                                  
                return true;
        }

so you retry once, and the second time through we will return false if
we are unmounting, which means that xfs_buf_do_callbacks gets called.

Now you say that xfs_buf_do_callbacks() being called when we errored
out is dangerous, but I don't understand why.  We have this code

        if (need_ail) {
                struct xfs_log_item *log_items[need_ail];
                int i = 0;
                spin_lock(&ailp->xa_lock);
                for (blip = lip; blip; blip = blip->li_bio_list) {
                        iip = INODE_ITEM(blip);
                        if (iip->ili_logged &&
                            blip->li_lsn == iip->ili_flush_lsn) {
                                log_items[i++] = blip;
                        }
                        ASSERT(i <= need_ail);
                }
                /* xfs_trans_ail_delete_bulk() drops the AIL lock. */
                xfs_trans_ail_delete_bulk(ailp, log_items, i,
                                          SHUTDOWN_CORRUPT_INCORE);
        }

and need_ail is set if we didn't actually end up on disk properly.  So
we delete the thing and mark the fs as fucked.  Am I mis-reading what
is going on here?  This is what I did to our 4.6 tree (in testing
still, not actually pushed to production)

        if (bp->b_flags & XBF_ASYNC) {
                ASSERT(bp->b_iodone != NULL);

                trace_xfs_buf_item_iodone_async(bp, _RET_IP_);

                xfs_buf_ioerror(bp, 0); /* errno of 0 unsets the flag
*/

                if (!(bp->b_flags & (XBF_STALE|XBF_WRITE_FAIL))) {
                        bp->b_flags |= XBF_WRITE | XBF_ASYNC |
                                       XBF_DONE | XBF_WRITE_FAIL;
                        xfs_buf_submit(bp);
                } else {
+                       xfs_buf_do_callbacks(bp);
+                       bp->b_fspriv = NULL;
+                       bp->b_iodone = NULL;
                        xfs_buf_relse(bp);
                }

                return;
        }

I've marked the things that I changed with '+'.  So we do the retry,
and on the second go around we do the callbacks which trips the logic
in xfs_iflush_done() to clean up the AIL and complain loudly.  I'm not
seeing the danger here, in fact it seems like the appropriate thing to
do as xfs_iflush_done() appears to do the correct thing if we call it
when something failed.  Thanks,

Josef

Re: [PATCH] xfs: clear XBF_ASYNC if we attach an iodone callback

[Dave Chinner]

On Mon, Mar 06, 2017 at 02:00:13PM -0500, Josef Bacik wrote:
> so you retry once, and the second time through we will return false if
> we are unmounting, which means that xfs_buf_do_callbacks gets called.
> 
> Now you say that xfs_buf_do_callbacks() being called when we errored
> out is dangerous, but I don't understand why.  We have this code
> 
>         if (need_ail) {
>                 struct xfs_log_item *log_items[need_ail];
>                 int i = 0;
>                 spin_lock(&ailp->xa_lock);
>                 for (blip = lip; blip; blip = blip->li_bio_list) {
>                         iip = INODE_ITEM(blip);
>                         if (iip->ili_logged &&
>                             blip->li_lsn == iip->ili_flush_lsn) {
>                                 log_items[i++] = blip;
>                         }
>                         ASSERT(i <= need_ail);
>                 }
>                 /* xfs_trans_ail_delete_bulk() drops the AIL lock. */
>                 xfs_trans_ail_delete_bulk(ailp, log_items, i,
>                                           SHUTDOWN_CORRUPT_INCORE);
>         }

[ Your cut-n-paste is horribly mangled in something non-ascii. ]

> and need_ail is set if we didn't actually end up on disk properly.  So
> we delete the thing and mark the fs as fucked.  Am I mis-reading what
> is going on here?

Yes. That won't shut down the filesystem on an inode write error. It
will simply remove the inode from the AIL, the error will do dropped
on the floor, and the filesystem will not be shut down even though
it's now in a corrupt state. xfs_trans_ail_delete_bulk() only shuts
down the filesytem if it doesn't find the item being removed form
the AIL in the AIL.

As I keep telling people, what needs to happen is this:

	1. buffer write error occurs
	2. retries exhausted, mark buffer as errored, run callbacks
	3. xfs_iflush_done() (and other iodone callbacks) need to
	   look at the buffer error state to determine what to do.
	4. if the buffer is errored and recovery is not possible,
	   the callback needs to shut down the filesytem.
	5. the callback then needs to call flush abort function for
	   item (e.g. xfs_iflush_abort()) rather than the normal
	   IO completion processing path.

>  This is what I did to our 4.6 tree (in testing
> still, not actually pushed to production)
>
>         if (bp->b_flags & XBF_ASYNC) {
>                 ASSERT(bp->b_iodone != NULL);
> 
>                 trace_xfs_buf_item_iodone_async(bp, _RET_IP_);
> 
>                 xfs_buf_ioerror(bp, 0); /* errno of 0 unsets the flag
> */
> 
>                 if (!(bp->b_flags & (XBF_STALE|XBF_WRITE_FAIL))) {
>                         bp->b_flags |= XBF_WRITE | XBF_ASYNC |
>                                        XBF_DONE | XBF_WRITE_FAIL;
>                         xfs_buf_submit(bp);
>                 } else {
> +                       xfs_buf_do_callbacks(bp);
> +                       bp->b_fspriv = NULL;
> +                       bp->b_iodone = NULL;
>                         xfs_buf_relse(bp);
>                 }
> 
>                 return;
>         }

It's likely you'll end up with silent on disk corruption if you do
that because it's just tossing the error state away.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [PATCH] xfs: clear XBF_ASYNC if we attach an iodone callback

[Josef Bacik]

> On Mar 6, 2017, at 8:23 PM, Dave Chinner <david@fromorbit.com> wrote:
> 
>> On Mon, Mar 06, 2017 at 02:00:13PM -0500, Josef Bacik wrote:
>> so you retry once, and the second time through we will return false if
>> we are unmounting, which means that xfs_buf_do_callbacks gets called.
>> 
>> Now you say that xfs_buf_do_callbacks() being called when we errored
>> out is dangerous, but I don't understand why.  We have this code
>> 
>>         if (need_ail) {
>>                 struct xfs_log_item *log_items[need_ail];
>>                 int i = 0;
>>                 spin_lock(&ailp->xa_lock);
>>                 for (blip = lip; blip; blip = blip->li_bio_list) {
>>                         iip = INODE_ITEM(blip);
>>                         if (iip->ili_logged &&
>>                             blip->li_lsn == iip->ili_flush_lsn) {
>>                                 log_items[i++] = blip;
>>                         }
>>                         ASSERT(i <= need_ail);
>>                 }
>>                 /* xfs_trans_ail_delete_bulk() drops the AIL lock. */
>>                 xfs_trans_ail_delete_bulk(ailp, log_items, i,
>>                                           SHUTDOWN_CORRUPT_INCORE);
>>         }
> 
> [ Your cut-n-paste is horribly mangled in something non-ascii. ]
> 

Yeah I keep trying new mail clients and it's just not going well.

>> and need_ail is set if we didn't actually end up on disk properly.  So
>> we delete the thing and mark the fs as fucked.  Am I mis-reading what
>> is going on here?
> 
> Yes. That won't shut down the filesystem on an inode write error. It
> will simply remove the inode from the AIL, the error will do dropped
> on the floor, and the filesystem will not be shut down even though
> it's now in a corrupt state. xfs_trans_ail_delete_bulk() only shuts
> down the filesytem if it doesn't find the item being removed form
> the AIL in the AIL.
> 
> As I keep telling people, what needs to happen is this:
> 
>    1. buffer write error occurs
>    2. retries exhausted, mark buffer as errored, run callbacks
>    3. xfs_iflush_done() (and other iodone callbacks) need to
>       look at the buffer error state to determine what to do.
>    4. if the buffer is errored and recovery is not possible,
>       the callback needs to shut down the filesytem.
>    5. the callback then needs to call flush abort function for
>       item (e.g. xfs_iflush_abort()) rather than the normal
>       IO completion processing path.
> 
>>  This is what I did to our 4.6 tree (in testing
>> still, not actually pushed to production)
>> 
>>         if (bp->b_flags & XBF_ASYNC) {
>>                 ASSERT(bp->b_iodone != NULL);
>> 
>>                 trace_xfs_buf_item_iodone_async(bp, _RET_IP_);
>> 
>>                 xfs_buf_ioerror(bp, 0); /* errno of 0 unsets the flag
>> */
>> 
>>                 if (!(bp->b_flags & (XBF_STALE|XBF_WRITE_FAIL))) {
>>                         bp->b_flags |= XBF_WRITE | XBF_ASYNC |
>>                                        XBF_DONE | XBF_WRITE_FAIL;
>>                         xfs_buf_submit(bp);
>>                 } else {
>> +                       xfs_buf_do_callbacks(bp);
>> +                       bp->b_fspriv = NULL;
>> +                       bp->b_iodone = NULL;
>>                         xfs_buf_relse(bp);
>>                 }
>> 
>>                 return;
>>         }
> 
> It's likely you'll end up with silent on disk corruption if you do
> that because it's just tossing the error state away.

Ok great this is what I needed, thanks Dave,

Josef

Re: [PATCH] xfs: clear XBF_ASYNC if we attach an iodone callback

[Josef Bacik]

On Tue, 2017-03-07 at 12:22 +1100, Dave Chinner wrote:
> On Mon, Mar 06, 2017 at 02:00:13PM -0500, Josef Bacik wrote:
> > 
> > so you retry once, and the second time through we will return false
> > if
> > we are unmounting, which means that xfs_buf_do_callbacks gets
> > called.
> > 
> > Now you say that xfs_buf_do_callbacks() being called when we
> > errored
> > out is dangerous, but I don't understand why.  We have this code
> > 
> >         if (need_ail) {
> >                 struct xfs_log_item *log_items[need_ail];
> >                 int i = 0;
> >                 spin_lock(&ailp->xa_lock);
> >                 for (blip = lip; blip; blip = blip->li_bio_list) {
> >                         iip = INODE_ITEM(blip);
> >                         if (iip->ili_logged &&
> >                             blip->li_lsn == iip->ili_flush_lsn) {
> >                                 log_items[i++] = blip;
> >                         }
> >                         ASSERT(i <= need_ail);
> >                 }
> >                 /* xfs_trans_ail_delete_bulk() drops the AIL lock.
> > */
> >                 xfs_trans_ail_delete_bulk(ailp, log_items, i,
> >                                           SHUTDOWN_CORRUPT_INCORE);
> >         }
> [ Your cut-n-paste is horribly mangled in something non-ascii. ]
> 
> > 
> > and need_ail is set if we didn't actually end up on disk properly.
> >  So
> > we delete the thing and mark the fs as fucked.  Am I mis-reading
> > what
> > is going on here?
> Yes. That won't shut down the filesystem on an inode write error. It
> will simply remove the inode from the AIL, the error will do dropped
> on the floor, and the filesystem will not be shut down even though
> it's now in a corrupt state. xfs_trans_ail_delete_bulk() only shuts
> down the filesytem if it doesn't find the item being removed form
> the AIL in the AIL.
> 
> As I keep telling people, what needs to happen is this:
> 
> 	1. buffer write error occurs
> 	2. retries exhausted, mark buffer as errored, run callbacks
> 	3. xfs_iflush_done() (and other iodone callbacks) need to
> 	   look at the buffer error state to determine what to do.
> 	4. if the buffer is errored and recovery is not possible,
> 	   the callback needs to shut down the filesytem.
> 	5. the callback then needs to call flush abort function for
> 	   item (e.g. xfs_iflush_abort()) rather than the normal
> 	   IO completion processing path.
> 
> > 
> >  This is what I did to our 4.6 tree (in testing
> > still, not actually pushed to production)
> > 
> >         if (bp->b_flags & XBF_ASYNC) {
> >                 ASSERT(bp->b_iodone != NULL);
> > 
> >                 trace_xfs_buf_item_iodone_async(bp, _RET_IP_);
> > 
> >                 xfs_buf_ioerror(bp, 0); /* errno of 0 unsets the
> > flag
> > */
> > 
> >                 if (!(bp->b_flags & (XBF_STALE|XBF_WRITE_FAIL))) {
> >                         bp->b_flags |= XBF_WRITE | XBF_ASYNC
> >                                        XBF_DONE | XBF_WRITE_FAIL;
> >                         xfs_buf_submit(bp);
> >                 } else {
> > +                       xfs_buf_do_callbacks(bp);
> > +                       bp->b_fspriv = NULL;
> > +                       bp->b_iodone = NULL;
> >                         xfs_buf_relse(bp);
> >                 }
> > 
> >                 return;
> >         }
> It's likely you'll end up with silent on disk corruption if you do
> that because it's just tossing the error state away.

I think I'm getting a handle on this, but I wonder if we don't have
this problem currently?  We get an error on a buffer, we retry it and
it fails again.  If we don't have XFS_ERR_RETRY_FOREVER set then we
error out and do the normal callbacks as if nothing ever happened, and
we get the silent corruption without shutting down the file system.
 How is the code as it stands without XFS_ERR_RETRY_FOREVER safe?
 Thanks,

Josef

Re: [PATCH] xfs: clear XBF_ASYNC if we attach an iodone callback

[Brian Foster]

On Tue, Mar 07, 2017 at 10:56:05AM -0500, Josef Bacik wrote:
> On Tue, 2017-03-07 at 12:22 +1100, Dave Chinner wrote:
> > On Mon, Mar 06, 2017 at 02:00:13PM -0500, Josef Bacik wrote:
> > > 
> > > so you retry once, and the second time through we will return false
> > > if
> > > we are unmounting, which means that xfs_buf_do_callbacks gets
> > > called.
> > > 
> > > Now you say that xfs_buf_do_callbacks() being called when we
> > > errored
> > > out is dangerous, but I don't understand why.  We have this code
> > > 
> > >         if (need_ail) {
> > >                 struct xfs_log_item *log_items[need_ail];
> > >                 int i = 0;
> > >                 spin_lock(&ailp->xa_lock);
> > >                 for (blip = lip; blip; blip = blip->li_bio_list) {
> > >                         iip = INODE_ITEM(blip);
> > >                         if (iip->ili_logged &&
> > >                             blip->li_lsn == iip->ili_flush_lsn) {
> > >                                 log_items[i++] = blip;
> > >                         }
> > >                         ASSERT(i <= need_ail);
> > >                 }
> > >                 /* xfs_trans_ail_delete_bulk() drops the AIL lock.
> > > */
> > >                 xfs_trans_ail_delete_bulk(ailp, log_items, i,
> > >                                           SHUTDOWN_CORRUPT_INCORE);
> > >         }
> > [ Your cut-n-paste is horribly mangled in something non-ascii. ]
> > 
> > > 
> > > and need_ail is set if we didn't actually end up on disk properly.
> > >  So
> > > we delete the thing and mark the fs as fucked.  Am I mis-reading
> > > what
> > > is going on here?
> > Yes. That won't shut down the filesystem on an inode write error. It
> > will simply remove the inode from the AIL, the error will do dropped
> > on the floor, and the filesystem will not be shut down even though
> > it's now in a corrupt state. xfs_trans_ail_delete_bulk() only shuts
> > down the filesytem if it doesn't find the item being removed form
> > the AIL in the AIL.
> > 
> > As I keep telling people, what needs to happen is this:
> > 
> > 	1. buffer write error occurs
> > 	2. retries exhausted, mark buffer as errored, run callbacks
> > 	3. xfs_iflush_done() (and other iodone callbacks) need to
> > 	   look at the buffer error state to determine what to do.
> > 	4. if the buffer is errored and recovery is not possible,
> > 	   the callback needs to shut down the filesytem.
> > 	5. the callback then needs to call flush abort function for
> > 	   item (e.g. xfs_iflush_abort()) rather than the normal
> > 	   IO completion processing path.
> > 
> > > 
> > >  This is what I did to our 4.6 tree (in testing
> > > still, not actually pushed to production)
> > > 
> > >         if (bp->b_flags & XBF_ASYNC) {
> > >                 ASSERT(bp->b_iodone != NULL);
> > > 
> > >                 trace_xfs_buf_item_iodone_async(bp, _RET_IP_);
> > > 
> > >                 xfs_buf_ioerror(bp, 0); /* errno of 0 unsets the
> > > flag
> > > */
> > > 
> > >                 if (!(bp->b_flags & (XBF_STALE|XBF_WRITE_FAIL))) {
> > >                         bp->b_flags |= XBF_WRITE | XBF_ASYNC
> > >                                        XBF_DONE | XBF_WRITE_FAIL;
> > >                         xfs_buf_submit(bp);
> > >                 } else {
> > > +                       xfs_buf_do_callbacks(bp);
> > > +                       bp->b_fspriv = NULL;
> > > +                       bp->b_iodone = NULL;
> > >                         xfs_buf_relse(bp);
> > >                 }
> > > 
> > >                 return;
> > >         }
> > It's likely you'll end up with silent on disk corruption if you do
> > that because it's just tossing the error state away.
> 
> I think I'm getting a handle on this, but I wonder if we don't have
> this problem currently?  We get an error on a buffer, we retry it and
> it fails again.  If we don't have XFS_ERR_RETRY_FOREVER set then we
> error out and do the normal callbacks as if nothing ever happened, and
> we get the silent corruption without shutting down the file system.
>  How is the code as it stands without XFS_ERR_RETRY_FOREVER safe?
>  Thanks,
> 

We shouldn't get into a situation where we run the callbacks when the
I/O has failed and the fs isn't shut down. IOWs, we do run the callbacks
only when the I/O succeeds, or it fails and the fs is shutdown as a
result (never when the I/O fails but we haven't shut down, which is the
problematic case the patch above introduces).

That tunable error handling logic (XFS_ERR_RETRY_FOREVER) basically
determines when an I/O error is considered permanent, which means
retries are futile and we have no choice but to shutdown the fs. E.g.,
if an error is deemed permanent, we jump to permanent_error:

        /*
         * Permanent error - we need to trigger a shutdown if we haven't already
         * to indicate that inconsistency will result from this action.
         */
permanent_error:
        xfs_force_shutdown(mp, SHUTDOWN_META_IO_ERROR);
out_stale:
        xfs_buf_stale(bp);
        bp->b_flags |= XBF_DONE;
        trace_xfs_buf_error_relse(bp, _RET_IP_);
        return false;
}

... which shuts down the filesystem before we go any farther.

Brian

> Josef

Re: [PATCH] xfs: clear XBF_ASYNC if we attach an iodone callback

[Carlos Maiolino]

Hi,

I really apologize for my late reply, March was a busy month and this thread got
lost on my mailbox.

I'll try to come back to this fix as soon as possible,

> > > > 
> > > >                 return;
> > > >         }
> > > It's likely you'll end up with silent on disk corruption if you do
> > > that because it's just tossing the error state away.
> > 
> > I think I'm getting a handle on this, but I wonder if we don't have
> > this problem currently?  We get an error on a buffer, we retry it and
> > it fails again.  If we don't have XFS_ERR_RETRY_FOREVER set then we
> > error out and do the normal callbacks as if nothing ever happened, and
> > we get the silent corruption without shutting down the file system.
> >  How is the code as it stands without XFS_ERR_RETRY_FOREVER safe?
> >  Thanks,
> > 
> 
> We shouldn't get into a situation where we run the callbacks when the
> I/O has failed and the fs isn't shut down. IOWs, we do run the callbacks
> only when the I/O succeeds, or it fails and the fs is shutdown as a
> result (never when the I/O fails but we haven't shut down, which is the
> problematic case the patch above introduces).
> 
> That tunable error handling logic (XFS_ERR_RETRY_FOREVER) basically
> determines when an I/O error is considered permanent, which means
> retries are futile and we have no choice but to shutdown the fs. E.g.,
> if an error is deemed permanent, we jump to permanent_error:
> 
>         /*
>          * Permanent error - we need to trigger a shutdown if we haven't already
>          * to indicate that inconsistency will result from this action.
>          */
> permanent_error:
>         xfs_force_shutdown(mp, SHUTDOWN_META_IO_ERROR);
> out_stale:
>         xfs_buf_stale(bp);
>         bp->b_flags |= XBF_DONE;
>         trace_xfs_buf_error_relse(bp, _RET_IP_);
>         return false;
> }
> 
> ... which shuts down the filesystem before we go any farther.
> 
> Brian
> 
> > Josef

Josef, did you have any success in avoiding this lockup problem with the
fail/retry mechanism mentioned? Or do you keep seeing it?


-- 
Carlos