Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1210170 > unrolled thread

Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME inodes

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Eryu Guan <eguan@redhat.com> - 2015-08-20 08:20 +0200
    Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Tejun Heo <tj@kernel.org> - 2015-08-20 19:00 +0200
      Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Dave Chinner <david@fromorbit.com> - 2015-08-21 01:10 +0200
        Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Tejun Heo <tj@kernel.org> - 2015-08-24 20:20 +0200
          Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Dave Chinner <david@fromorbit.com> - 2015-08-25 00:30 +0200
            Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Tejun Heo <tj@kernel.org> - 2015-08-25 01:00 +0200

#1210170 — Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME inodes

On Wed, Aug 19, 2015 at 07:56:11AM +1000, Dave Chinner wrote:
> On Tue, Aug 18, 2015 at 12:54:39PM -0700, Tejun Heo wrote:
> > Hello,
> > 
> > On Tue, Aug 18, 2015 at 10:47:18AM -0700, Tejun Heo wrote:
> > > Hmm... the only possibility I can think of is tot_write_bandwidth
> > > being zero when it shouldn't be.  I've been staring at the code for a
> > > while now but nothing rings a bell.  Time for another debug patch, I
> > > guess.
> > 
> > So, I can now reproduce the bug (it takes a lot of trials but lowering
> > the number of tested files helps quite a bit) and instrumented all the
> > early exit paths w/o the fix patch.  bdi_has_dirty_io() and
> > wb_has_dirty_io() are never out of sync with the actual dirty / io
> > lists even when the test 048 fails, so the bug at least is not caused
> > by writeback skipping due to buggy bdi/wb_has_dirty_io() result.
> > Whenever it skips, all the lists are actually empty (verified while
> > holding list_lock).
> > 
> > One suspicion I have is that this could be a subtle timing issue which
> > is being exposed by the new short-cut path.  Anything which adds delay
> > seems to make the issue go away.  Dave, does anything ring a bell?
> 
> No, it doesn't. The data writeback mechanisms XFS uses are all
> generic. It marks inodes I_DIRTY_PAGES and lets the generic code
> take care of everything else. Yes, we do delayed allocation during
> writeback, and we log the inode size updates during IO completion,
> so if inode sizes are not getting updated, then Occam's Razor
> suggests that writeback is not happening.
> 
> I'd suggest looking at some of the XFS tracepoints during the test:
> 
> tracepoint			trigger
> xfs_file_buffered_write		once per write syscall
> xfs_file_sync			once per fsync per inode
> xfs_vm_writepage		every ->writepage call
> xfs_setfilesize			every IO completion that updates inode size

I gave the tracepoints a try, but my root fs is xfs so I got many
noises. I'll try to install a new vm with ext4 as root fs. But I'm not
sure if the new vm could reproduce the failure, will see.

BTW, I guess xfs_vm_writepage should be xfs_writepage, and xfs_file_sync
should be xfs_file_fsync?

Thanks,
Eryu
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [next] | [standalone]

#1210629

Hello, Eryu.  Thanks a lot for the trace.

So, this is from the end of the trace from the failed test.

...
    kworker/u8:1-1563  [002] 22016.987530: xfs_writepage:        dev 253:6 ino 0xef64fe pgoff 0x9ff000 size 0xa00000 offset 0 length 0 delalloc 1 unwritten 0
     kworker/2:1-49    [002] 22017.373595: xfs_setfilesize:      dev 253:6 ino 0xef6504 isize 0xa00000 disize 0x0 offset 0x0 count 10481664
...

Maybe I'm misunderstanding the code but all xfs_writepage() calls are
from unbound workqueues - the writeback workers - while
xfs_setfilesize() are from bound workqueues, so I wondered why that
was and looked at the code and the setsize functions are run off of a
separate work item which is queued from the end_bio callback and I
can't tell who would be waiting for them.  Dave, what am I missing?

Thanks.

-- 
tejun
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1210779

On Thu, Aug 20, 2015 at 09:55:37AM -0700, Tejun Heo wrote:
> Hello, Eryu.  Thanks a lot for the trace.
> 
> So, this is from the end of the trace from the failed test.
> 
> ...
>     kworker/u8:1-1563  [002] 22016.987530: xfs_writepage:        dev 253:6 ino 0xef64fe pgoff 0x9ff000 size 0xa00000 offset 0 length 0 delalloc 1 unwritten 0
>      kworker/2:1-49    [002] 22017.373595: xfs_setfilesize:      dev 253:6 ino 0xef6504 isize 0xa00000 disize 0x0 offset 0x0 count 10481664
> ...
> 
> Maybe I'm misunderstanding the code but all xfs_writepage() calls are
> from unbound workqueues - the writeback workers - while
> xfs_setfilesize() are from bound workqueues, so I wondered why that
> was and looked at the code and the setsize functions are run off of a
> separate work item which is queued from the end_bio callback and I
> can't tell who would be waiting for them.  Dave, what am I missing?

xfs_setfilesize runs transactions, so it can't be run from IO
completion context as it needs to block (i.e. on log space or inode
locks). It also can't block log IO completion, nor metadata Io
completion, as only log IO completion can free log space, and the
inode lock might be waiting on metadata buffer IO completion (e.g.
during delayed allocation). Hence we have multiple IO completion
workqueues to keep these things separated and deadlock free. i.e.
they all get punted to a workqueue where they are then processed in
a context that can block safely.

>     kworker/u8:1-1563  [002] 22016.987530: xfs_writepage:        dev 253:6 ino 0xef64fe pgoff 0x9ff000 size 0xa00000 offset 0 length 0 delalloc 1 unwritten 0

There will be one of these per page that is submitted to XFS. There
won't be one per page, because XFS clusters writes itself. This
trace is telling us that the page at offset 0x9ff000 was submitted,
the in-memory size of the inode at this time is 0xa00000 (i.e. this
is the last dirty page in memory) and that the it is a delayed
allocation extent (i.e. hasn't been written before).

>      kworker/2:1-49    [002] 22017.373595: xfs_setfilesize:      dev 253:6 ino 0xef6504 isize 0xa00000 disize 0x0 offset 0x0 count 10481664

There will be one of these per IO completion that extents the inode
size. This one tells us the in-memory inode size is 0xa00000, the
current on-disk inode size is 0, and the IO being completed spans
the offsets 0 to 10481664 (0x9ff000). Which means it does not
include the page submitted by the above trace, and after the setsize
transaction, isize=0xa00000 and disize=0x9ff000.

Note that these two traces are from different inodes - you need to
match traces from "ino 0xef6504" with other traces from the same
inode.

Also, note that the trace is not complete - there are many, many
missing trace events in the output....

What is interesting from the trace is that all the file size updates
have this pattern:

    kworker/2:1-49    [002] 22017.377918: xfs_setfilesize:      dev 253:6 ino 0xef64fd isize 0xa00000 disize 0x0 offset 0x0 count 10481664
    kworker/2:1-49    [002] 22017.378438: xfs_setfilesize:	dev 253:6 ino 0xef64fd isize 0xa00000 disize 0x9ff000 offset 0x9ff000 count 4096

There are two IOs being done - one for everything but the last page,
and one for the last page. This is either a result of the writeback
context limiting the number of pages per writeback slice, or the
page clustering that XFS does in xfs_vm_writepage() not quite
getting everything right (maybe an off-by-one?).

However, this doesn't appear to be a contributing factor. The 9
files that have the wrong file size at the end of the test match up
exactly with the last 9 writepage submissions and IO completions;
they happen after all the IO completions occur for all the good
files.

This implies that the sync is either not submitting all the inodes
for IO correctly or it is not waiting for all the inodes it
submitted to be marked clean. We really need the writeback control
tracepoints in the output to determine exactly what the sync was
doing when it submitted these last inodes for writeback....

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1212396

Hello, Dave.

On Fri, Aug 21, 2015 at 09:04:51AM +1000, Dave Chinner wrote:
> > Maybe I'm misunderstanding the code but all xfs_writepage() calls are
> > from unbound workqueues - the writeback workers - while
> > xfs_setfilesize() are from bound workqueues, so I wondered why that
> > was and looked at the code and the setsize functions are run off of a
> > separate work item which is queued from the end_bio callback and I
> > can't tell who would be waiting for them.  Dave, what am I missing?
> 
> xfs_setfilesize runs transactions, so it can't be run from IO
> completion context as it needs to block (i.e. on log space or inode
> locks). It also can't block log IO completion, nor metadata Io
> completion, as only log IO completion can free log space, and the
> inode lock might be waiting on metadata buffer IO completion (e.g.
> during delayed allocation). Hence we have multiple IO completion
> workqueues to keep these things separated and deadlock free. i.e.
> they all get punted to a workqueue where they are then processed in
> a context that can block safely.

I'm still a bit confused.  What prevents the following from happening?

1. io completion of last dirty page of an inode and work item for
   xfs_setfilesize() is queued.

2. inode removed from dirty list.

3. __sync_filesystem() invokes sync_inodes_sb().  There are no dirty
   pages, so it finishes.

4. xfs_fs_sync_fs() is called which calls _xfs_log_force() but the
   work item from #1 hasn't run yet, so the size update isn't written
   out.

5. Crash.

Is it that _xfs_log_force() waits for the setfilesize transaction
created during writepage?

Thanks.

-- 
tejun
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1212558

On Mon, Aug 24, 2015 at 02:10:38PM -0400, Tejun Heo wrote:
> Hello, Dave.
> 
> On Fri, Aug 21, 2015 at 09:04:51AM +1000, Dave Chinner wrote:
> > > Maybe I'm misunderstanding the code but all xfs_writepage() calls are
> > > from unbound workqueues - the writeback workers - while
> > > xfs_setfilesize() are from bound workqueues, so I wondered why that
> > > was and looked at the code and the setsize functions are run off of a
> > > separate work item which is queued from the end_bio callback and I
> > > can't tell who would be waiting for them.  Dave, what am I missing?
> > 
> > xfs_setfilesize runs transactions, so it can't be run from IO
> > completion context as it needs to block (i.e. on log space or inode
> > locks). It also can't block log IO completion, nor metadata Io
> > completion, as only log IO completion can free log space, and the
> > inode lock might be waiting on metadata buffer IO completion (e.g.
> > during delayed allocation). Hence we have multiple IO completion
> > workqueues to keep these things separated and deadlock free. i.e.
> > they all get punted to a workqueue where they are then processed in
> > a context that can block safely.
> 
> I'm still a bit confused.  What prevents the following from happening?
> 
> 1. io completion of last dirty page of an inode and work item for
>    xfs_setfilesize() is queued.
> 
> 2. inode removed from dirty list.

The inode has already been removed from the dirty list - that
happens at inode writeback submission time, not IO completion.

> 3. __sync_filesystem() invokes sync_inodes_sb().  There are no dirty
>    pages, so it finishes.

There are no dirty pages, but the pages aren't clean, either. i.e
they are still under writeback.  Hence we need to invoke
wait_inodes_sb() to wait for writeback on all pages to complete
before returning.

> 4. xfs_fs_sync_fs() is called which calls _xfs_log_force() but the
>    work item from #1 hasn't run yet, so the size update isn't written
>    out.

The bug here is that wait_inodes_sb() has not been run, therefore
->syncfs is being run before IO completions have been processed and
pages marked clean.

> 5. Crash.
> 
> Is it that _xfs_log_force() waits for the setfilesize transaction
> created during writepage?

No, it's wait_inodes_sb() that does the waiting for data IO
completion for sync.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1212564

Hello, Dave.

On Tue, Aug 25, 2015 at 08:27:20AM +1000, Dave Chinner wrote:
> > I'm still a bit confused.  What prevents the following from happening?
> > 
> > 1. io completion of last dirty page of an inode and work item for
> >    xfs_setfilesize() is queued.
> > 
> > 2. inode removed from dirty list.
> 
> The inode has already been removed from the dirty list - that
> happens at inode writeback submission time, not IO completion.

Ah, yeah, right, somehow was thinking requeue_io() was being called
from completion path.  That's where I was confused.

Thanks.

-- 
tejun
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web