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

Groups > linux.kernel > #1211106 > 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-21 12:30 +0200
    Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Dave Chinner <david@fromorbit.com> - 2015-08-22 02:40 +0200
      Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Eryu Guan <eguan@redhat.com> - 2015-08-22 06:50 +0200
        Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Dave Chinner <david@fromorbit.com> - 2015-08-24 03:20 +0200
          Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Eryu Guan <eguan@redhat.com> - 2015-08-24 05:20 +0200
            Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Dave Chinner <david@fromorbit.com> - 2015-08-24 08:30 +0200
              Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Eryu Guan <eguan@redhat.com> - 2015-08-24 10:40 +0200
                Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Dave Chinner <david@fromorbit.com> - 2015-08-24 11:00 +0200
              Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Jan Kara <jack@suse.cz> - 2015-08-24 11:30 +0200
                Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Tejun Heo <tj@kernel.org> - 2015-08-24 17:00 +0200
                  Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Tejun Heo <tj@kernel.org> - 2015-08-24 19:20 +0200
                    Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Jan Kara <jack@suse.cz> - 2015-08-24 21:10 +0200
                      Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Tejun Heo <tj@kernel.org> - 2015-08-24 21:40 +0200
                        Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Jan Kara <jack@suse.cz> - 2015-08-24 23:10 +0200
                          Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Tejun Heo <tj@kernel.org> - 2015-08-24 23:50 +0200
                            Re: [PATCH block/for-linus] writeback: fix syncing of I_DIRTY_TIME  inodes Dave Chinner <david@fromorbit.com> - 2015-08-25 01:00 +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

#1211106 — 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:
[snip]
> 
> 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
> 
> And it's probably best to also include all the writeback
> tracepoints, too, for context. That will tell you what inodes and
> what part of them are getting written back and when....

I finally reproduced generic/048 with both xfs and writeback tracepoints
enabled, please download the trace dat file and trace report file from

http://128.199.137.77/writeback/

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]

#1211374

On Fri, Aug 21, 2015 at 06:20:53PM +0800, Eryu Guan wrote:
> 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:
> [snip]
> > 
> > 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
> > 
> > And it's probably best to also include all the writeback
> > tracepoints, too, for context. That will tell you what inodes and
> > what part of them are getting written back and when....
> 
> I finally reproduced generic/048 with both xfs and writeback tracepoints
> enabled, please download the trace dat file and trace report file from
> 
> http://128.199.137.77/writeback/

OK, so only one inode the wrong size this time. The writeback
tracing is too verbose - it captures everything on the the backing
device so there's a huge amount of noise in the trace, and I can't
filter it easily because everything is recorded as "bdi 253:0" even
though we only want traces from "dev 253:6".

As such, there are lots of missing events in the trace again. We
do not need these writeback tracepoints:

	writeback_mark_inode_dirty
	writeback_dirty_inode_start
	writeback_dirty_inode
	writeback_dirty_page
	writeback_write_inode

And they are the ones causing most of the noise. This brings the
trace down from 7.1 million events to ~90,000 events and brings
the test behaviour right into focus. The inode that had the short
length:

    kworker/u8:1-1563  [002] 71028.844716: writeback_single_inode_start: bdi 253:0: ino=15688963 state=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES|I_SYNC dirtied_when=4356811543 age=18446744069352740 index=0 to_write=34816 wrote=0
    kworker/u8:1-1563  [002] 71028.844718: wbc_writepage:        bdi 253:0: towrt=34816 skip=0 mode=0 kupd=0 bgrd=0 reclm=0 cyclic=0 start=0x0 end=0x7fffffffffffffff
    kworker/u8:1-1563  [002] 71028.844740: xfs_writepage:        dev 253:6 ino 0xef6503 pgoff 0x0 size 0xa00000 offset 0 length 0 delalloc 1 unwritten 0
    kworker/u8:1-1563  [002] 71028.845740: wbc_writepage:        bdi 253:0: towrt=32257 skip=0 mode=0 kupd=0 bgrd=0 reclm=0 cyclic=0 start=0x0 end=0x7fffffffffffffff
    kworker/u8:1-1563  [002] 71028.845741: xfs_writepage:        dev 253:6 ino 0xef6503 pgoff 0x9ff000 size 0xa00000 offset 0 length 0 delalloc 1 unwritten 0
    kworker/u8:1-1563  [002] 71028.845788: writeback_single_inode: bdi 253:0: ino=15688963 state=I_SYNC dirtied_when=4356811543 age=18446744069352740 index=2559 to_write=34816 wrote=2560

And so we can see that writeback pushed all 2560 pages of the file
to disk.

However, because of all the noise, the xfs io completion events are
missing for this inode. I know that at least one of them occurred,
because their is this transaction in the log:

INODE: #regs: 3   ino: 0xef6503  flags: 0x5   dsize: 16
size 0x9ff000 nblocks 0xa00 extsize 0x0 nextents 0x1

It is, however, the last inode to be updated in the log before
the unmount record, and it is the only one that does not have a size
of 0xa00000 bytes. It has the right block count, but it it appears
that we haven't captured the final IO completion transaction. It was
most definitely not the last inode written by writeback; it was the
6th last, and that is ordered correctly given the file name was
"993", the 6th last file created by the test.

However, I see completions for the inode written before (0xef6502)
and after (0xef6504) but none for 0xef6503. Yet from the trace in
the log we know that at least one of them occurred, because there's
a transaction to say it happened.

As it is, there is an off-by-one in the page clustering mapping
check in XFS that is causing the last page of the inode to be issued
as a separate IO. That's not the cause of the problem however,
because we can see from the trace that the IO for the entire file
appears to be issued. What we don't see yet is what is happening on
the IO completion side, and hence why the sync code is not waiting
correctly for all the IO that was issued to be waited on properly.

Eryu, can you try again, this time manually specifying the writeback
tracepoints so you exclude the really noisy ones? You can also drop
the xfs_file_buffered_write and xfs_file_fsync tracepoints as well,
as we can see that the incoming side of the code is doing the right
thing....

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]

#1211399

On Sat, Aug 22, 2015 at 10:30:25AM +1000, Dave Chinner wrote:
> On Fri, Aug 21, 2015 at 06:20:53PM +0800, Eryu Guan wrote:
[snip]
> 
> Eryu, can you try again, this time manually specifying the writeback
> tracepoints so you exclude the really noisy ones? You can also drop
> the xfs_file_buffered_write and xfs_file_fsync tracepoints as well,
> as we can see that the incoming side of the code is doing the right
> thing....

I excluded the writeback tracepoints you mentioned

writeback_mark_inode_dirty
writeback_dirty_inode_start
writeback_dirty_inode
writeback_dirty_page
writeback_write_inode

and left all other writeback tracepoints enabled, also dropped
xfs_file_buffered_write and xfs_file_fsync.

This time I can reproduce generic/048 quickly and please download the
trace info from below

http://128.199.137.77/writeback-v2/

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] | [prev] | [next] | [standalone]

#1211706

On Sat, Aug 22, 2015 at 12:46:09PM +0800, Eryu Guan wrote:
> On Sat, Aug 22, 2015 at 10:30:25AM +1000, Dave Chinner wrote:
> > On Fri, Aug 21, 2015 at 06:20:53PM +0800, Eryu Guan wrote:
> [snip]
> > 
> > Eryu, can you try again, this time manually specifying the writeback
> > tracepoints so you exclude the really noisy ones? You can also drop
> > the xfs_file_buffered_write and xfs_file_fsync tracepoints as well,
> > as we can see that the incoming side of the code is doing the right
> > thing....
> 
> I excluded the writeback tracepoints you mentioned
> 
> writeback_mark_inode_dirty
> writeback_dirty_inode_start
> writeback_dirty_inode
> writeback_dirty_page
> writeback_write_inode
> 
> and left all other writeback tracepoints enabled, also dropped
> xfs_file_buffered_write and xfs_file_fsync.
> 
> This time I can reproduce generic/048 quickly and please download the
> trace info from below
> 
> http://128.199.137.77/writeback-v2/

ok:

$ ls -li /mnt/scr
total 102396
15688948 -rw------- 1 root root        0 Aug 22 14:31 978
15688950 -rw------- 1 root root        0 Aug 22 14:31 980
15688952 -rw------- 1 root root 10481664 Aug 22 14:31 982
15688957 -rw------- 1 root root        0 Aug 22 14:31 987
15688961 -rw------- 1 root root        0 Aug 22 14:31 991
15688963 -rw------- 1 root root        0 Aug 22 14:31 993
15688964 -rw------- 1 root root        0 Aug 22 14:31 994
15688966 -rw------- 1 root root        0 Aug 22 14:31 996
15688967 -rw------- 1 root root        0 Aug 22 14:31 997
15688968 -rw------- 1 root root        0 Aug 22 14:31 998
$

So, looking at what is on disk and what is in the log:

      Inode #		   Size	       block count	flushiter
   dec	    hex	      inode	log    inode   log	inode  log
15688948  0xef64f4      0        0     0xa00  0xa00      0      0
15688950  0xef64f6      0        0     0xa00  0xa00      0      0
15688952  0xef64f8  0x9ff000 0x9ff000  0x9ff  0xa00      1      0
15688957  0xef64fd      0        0     0xa00  0xa00      0      0
15688961  0xef6501      0        0     0xa00  0xa00      0      0
15688963  0xef6503      0        0     0xa00  0xa00      0      0
15688964  0xef6504      0        0     0xa00  0xa00      0      0
15688966  0xef6506      0        0     0xa00  0xa00      0      0
15688967  0xef6507      0        0     0xa00  0xa00      0      0
15688968  0xef6508      0        0     0xa00  0xa00      0      0

Now, inode #15688952 looks like there's some weirdness going on
there with a non-zero flushiter and a block count that doesn't match
between what is in the log and what is on disk. However, this is a
result of the second mount that checks the file sizes and extent
counts - it loads the inode into memory, checks it, and then when
it is purged from the cache on unmount the blocks beyond EOF are
punched away and the inode writen to disk. Hence there is a second
transaction in the log for that inode after all the other inodes
have been unlinked:

INODE: #regs: 3   ino: 0xef64f8  flags: 0x5   dsize: 16
.....
size 0x9ff000 nblocks 0x9ff extsize 0x0 nextents 0x1

It is preceeded in the log by modifications to the AGF and frees
space btree buffers. It's then followed by the superblock buffer and
the unmount record. Hence this is not unexpected.

What it does tell us, though, is that the log never recorded file
size changes for all of the inode with zero size. We see the block
count of 0xa00, which means the delayed allocation transaction
during IO submission has hit the disk, but there are none of the
IO completion transactions in the log.

So let's go look at the event trace now now that we know the EOF
size update transactions were not run before the filesystem shut
down.

 Inode #     writeback		completion
  hex      first     last    first     last
0xef64f4  0-0x9ff000  yes     no        no
0xef64f6  0-0x9ff000  yes     no        no
0xef64f8  0-0x9ff000  yes     no        no
0xef64fd  0-0x9ff000  yes     no        no
0xef6501  0-0x9ff000  yes     no        no
0xef6503     no       no      no        no
0xef6504     no       no      no        no
0xef6506     no       no      no        no
0xef6507     no       no      no        no
0xef6508     no       no      no        no

Ok, so we still can't trust the event trace to be complete - we know
from the log and the on-disk state that that allocation occurred for
those last 5 inodes, so we can't read anything into the fact the
traces for completions are missing.

Eryu, can you change the way you run the event trace to be:

$ sudo trace-cmd <options> -o <outfile location> ./check <test options>

rather than running the trace as a background operation elsewhere?
Maybe that will give better results.

Also, it would be informative to us if you can reproduce this with a
v5 filesystem (i.e. mkfs.xfs -m crc=1) because it has much better
on-disk information for sequence-of-event triage like this. If you
can reproduce it with a v5 filesystem, can you post the trace and
metadump?

Other things to check (separately):

	- change godown to godown -f
	- add a "sleep 5" before running godown after sync
	- add a "sleep 5; sync" before running godown

i.e. I'm wondering if sync is not waiting for everything, and so we
aren't capturing the IO completions because the filesystem is
already shut down by the time they are delivered...

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]

#1211743

On Mon, Aug 24, 2015 at 11:11:23AM +1000, Dave Chinner wrote:
> 
> Eryu, can you change the way you run the event trace to be:
> 
> $ sudo trace-cmd <options> -o <outfile location> ./check <test options>
> 
> rather than running the trace as a background operation elsewhere?
> Maybe that will give better results.

The results are here

http://128.199.137.77/writeback-v3/

> 
> Also, it would be informative to us if you can reproduce this with a
> v5 filesystem (i.e. mkfs.xfs -m crc=1) because it has much better
> on-disk information for sequence-of-event triage like this. If you
> can reproduce it with a v5 filesystem, can you post the trace and
> metadump?

This seems to be harder to reproduce with tracepoints enabled, but I'll
keep trying, and the tests below.

Thanks,
Eryu

> 
> Other things to check (separately):
> 
> 	- change godown to godown -f
> 	- add a "sleep 5" before running godown after sync
> 	- add a "sleep 5; sync" before running godown
> 
> i.e. I'm wondering if sync is not waiting for everything, and so we
> aren't capturing the IO completions because the filesystem is
> already shut down by the time they are delivered...
> 
> Cheers,
> 
> Dave.
> -- 
> Dave Chinner
> david@fromorbit.com
> 
> _______________________________________________
> xfs mailing list
> xfs@oss.sgi.com
> http://oss.sgi.com/mailman/listinfo/xfs
--
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]

#1211828

On Mon, Aug 24, 2015 at 11:18:16AM +0800, Eryu Guan wrote:
> On Mon, Aug 24, 2015 at 11:11:23AM +1000, Dave Chinner wrote:
> > 
> > Eryu, can you change the way you run the event trace to be:
> > 
> > $ sudo trace-cmd <options> -o <outfile location> ./check <test options>
> > 
> > rather than running the trace as a background operation elsewhere?
> > Maybe that will give better results.
> 
> The results are here
> 
> http://128.199.137.77/writeback-v3/

OK, the trace is still missing a few events, but it's much more
complete, and contains the events that tell more of the story:

$ ls -li /mnt/scr
total 51196
15688955 -rw------- 1 root root 10481664 Aug 24 13:06 985
15688959 -rw------- 1 root root        0 Aug 24 13:06 989
15688961 -rw------- 1 root root        0 Aug 24 13:06 991
15688964 -rw------- 1 root root        0 Aug 24 13:06 994
15688966 -rw------- 1 root root        0 Aug 24 13:06 996
$


     Inode #              Size        block count      flushiter
   dec      hex       inode     log    inode   log      inode  log
15688955  0xef64fb  0x9ff000  0x9ff000 0x9ff  0xa00      1      0
15688959  0xef64ff      0        0     0xa00  0xa00      0      0
15688961  0xef6501      0        0     0xa00  0xa00      0      0
15688964  0xef6504      0        0     0xa00  0xa00      0      0
15688966  0xef6506      0        0     0xa00  0xa00      0      0


Ok, that tallies with the previous symptoms. However, the trace
tells us something different. the xfs_setfilesize events. here's the
last 12 xfs_setfilesize events delivered in the trace (trimmed for
brevity and focus):

ino 0xef64fa isize 0xa00000 disize 0x0 offset 0x0 count 10481664
ino 0xef64fa isize 0xa00000 disize 0x9ff000 offset 0x9ff000 count 409
ino 0xef64fb isize 0xa00000 disize 0x0 offset 0x0 count 10481664
ino 0xef64fb isize 0xa00000 disize 0x9ff000 offset 0x9ff000 count 4096
ino 0xef64ff isize 0xa00000 disize 0x0 offset 0x0 count 10481664
ino 0xef64ff isize 0xa00000 disize 0x9ff000 offset 0x9ff000 count 4096
ino 0xef6501 isize 0xa00000 disize 0x0 offset 0x0 count 10481664
ino 0xef6501 isize 0xa00000 disize 0x9ff000 offset 0x9ff000 count 4096
ino 0xef6504 isize 0xa00000 disize 0x0 offset 0x0 count 10481664
ino 0xef6504 isize 0xa00000 disize 0x9ff000 offset 0x9ff000 count 4096
ino 0xef6506 isize 0xa00000 disize 0x0 offset 0x0 count 10481664
ino 0xef6506 isize 0xa00000 disize 0x9ff000 offset 0x9ff000 count 4096

Yeah, the last 9 transactions corresponding to these events are not
in the log.  Which means, most likely, that they occurred after
->sync_fs forced the log out. THe next thing that happens is the fs
is shut down, and that's preventing the dirty log from being written
to disk.

Eryu, this can be confirmed by add the xfs_log_force event to the
trace.

What I can't see in the traces is where sync is doing a blocking
sync pass on the fileystem. The wbc control structure being passed
to XFS is:

wbc_writepage:        bdi 253:0: towrt=45569 skip=0 mode=0 kupd=0 bgrd=0 reclm=0 cyclic=0 start=0x0 end=0x7fffffffffffffff

Which is not coming from sync_inodes_sb() as the sync mode is
incorrect (i.e. not WB_SYNC_ALL). It looks to me that writeback is
coming from a generic bdi flusher command rather than a directed
superblock sync. i.e. through wakeup_flusher_threads() which sets:

        work->sync_mode = WB_SYNC_NONE;
        work->nr_pages  = nr_pages;
        work->range_cyclic = range_cyclic;
        work->reason    = reason;
        work->auto_free = 1;

as the reason is "sync":

            sync-18849  writeback_queue:      bdi 253:0: sb_dev 0:0 nr_pages=308986 sync_mode=0 kupdate=0 range_cyclic=0 background=0 reason=sync
            sync-18849  writeback_queue:      bdi 253:0: sb_dev 253:1 nr_pages=9223372036854775807 sync_mode=1 kupdate=0 range_cyclic=0 background=0 reason=sync
....
    kworker/u8:1-1563   writeback_exec:       bdi 253:0: sb_dev 0:0 nr_pages=308986 sync_mode=0 kupdate=0 range_cyclic=0 background=0 reason=sync
    kworker/u8:1-1563   writeback_start:      bdi 253:0: sb_dev 0:0 nr_pages=308986 sync_mode=0 kupdate=0 range_cyclic=0 background=0 reason=sync

The next writeback_queue/writeback_exec tracepoint pair are:

....
     kworker/2:1-17163  xfs_setfilesize:      dev 253:6 ino 0xef6506 isize 0xa00000 disize 0x0 offset 0x0 count 10481664
     kworker/2:1-17163  xfs_setfilesize:      dev 253:6 ino 0xef6506 isize 0xa00000 disize 0x9ff000 offset 0x9ff000 count 4096
            sync-18849  wbc_writepage:        bdi 253:0: towrt=9223372036854775798 skip=0 mode=1 kupd=0 bgrd=0 reclm=0 cyclic=0 start=0x0 end=0x7fffffffffffffff
            sync-18849  wbc_writepage:        bdi 253:0: towrt=9223372036854775797 skip=0 mode=1 kupd=0 bgrd=0 reclm=0 cyclic=0 start=0x0 end=0x7fffffffffffffff
            sync-18849  wbc_writepage:        bdi 253:0: towrt=9223372036854775796 skip=0 mode=1 kupd=0 bgrd=0 reclm=0 cyclic=0 start=0x0 end=0x7fffffffffffffff
            sync-18849  wbc_writepage:        bdi 253:0: towrt=9223372036854775795 skip=0 mode=1 kupd=0 bgrd=0 reclm=0 cyclic=0 start=0x0 end=0x7fffffffffffffff
          umount-18852  writeback_queue:      bdi 253:0: sb_dev 253:6 nr_pages=22059 sync_mode=0 kupdate=0 range_cyclic=0 background=0 reason=sync
    kworker/u8:1-1563   writeback_exec:       bdi 253:0: sb_dev 253:6 nr_pages=22059 sync_mode=0 kupdate=0 range_cyclic=0 background=0 reason=sync
....

which shows unmount being the next writeback event queued and
executed after the IO completions have come in (that missed the
log). What is missing is the specific queue/exec events for
sync_sb_inodes() from the sync code for each filesystem.

Anyway, Eryum long and short of it is that you don't need to worry
about testing all the different combinations - we now know that the
completion events are occurring, so let's focus on whether the sync
code is not waiting for them correctly. Can you trace the following
events:

	xfs_log_force
	xfs_setfilesize
	writeback_queue
	writeback_exec
	writeback_start
	writeback_queue_io
	writeback_written
	writeback_pages_written

basically I'm trying to see if we've got all the BDI events as we'd
expect then to be queued and run for sync, and when the ->sync_fs
call occurs during the sync process before shutdown and unmount...

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]

#1211906

On Mon, Aug 24, 2015 at 04:24:25PM +1000, Dave Chinner wrote:
> On Mon, Aug 24, 2015 at 11:18:16AM +0800, Eryu Guan wrote:
> > On Mon, Aug 24, 2015 at 11:11:23AM +1000, Dave Chinner wrote:
> > > 
> > > Eryu, can you change the way you run the event trace to be:
> > > 
> > > $ sudo trace-cmd <options> -o <outfile location> ./check <test options>
> > > 
> > > rather than running the trace as a background operation elsewhere?
> > > Maybe that will give better results.
[snip]
> Anyway, Eryum long and short of it is that you don't need to worry
> about testing all the different combinations - we now know that the
> completion events are occurring, so let's focus on whether the sync
> code is not waiting for them correctly. Can you trace the following
> events:
> 
> 	xfs_log_force
> 	xfs_setfilesize
> 	writeback_queue
> 	writeback_exec
> 	writeback_start
> 	writeback_queue_io
> 	writeback_written
> 	writeback_pages_written
> 
> basically I'm trying to see if we've got all the BDI events as we'd
> expect then to be queued and run for sync, and when the ->sync_fs
> call occurs during the sync process before shutdown and unmount...

I collected two versions of trace info with crc enabled.

http://128.199.137.77/writeback-crc/

This version traced the same events as previous runs.

http://128.199.137.77/writeback-crc-v2/

And this version only traced the events you listed above.


And the results of other tests to check(all done with v4 xfs, with no
tracepoints enabled):

> Other things to check (separately):
>	- change godown to godown -f

Passed 100 loops.

>	- add a "sleep 5" before running godown after sync

Failed, if you need the trace info please let me know.

>	- add a "sleep 5; sync" before running godown

Passed 100 loops.

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] | [prev] | [next] | [standalone]

#1211928

On Mon, Aug 24, 2015 at 04:34:37PM +0800, Eryu Guan wrote:
> On Mon, Aug 24, 2015 at 04:24:25PM +1000, Dave Chinner wrote:
> > On Mon, Aug 24, 2015 at 11:18:16AM +0800, Eryu Guan wrote:
> > > On Mon, Aug 24, 2015 at 11:11:23AM +1000, Dave Chinner wrote:
> > > > 
> > > > Eryu, can you change the way you run the event trace to be:
> > > > 
> > > > $ sudo trace-cmd <options> -o <outfile location> ./check <test options>
> > > > 
> > > > rather than running the trace as a background operation elsewhere?
> > > > Maybe that will give better results.
> [snip]
> > Anyway, Eryum long and short of it is that you don't need to worry
> > about testing all the different combinations - we now know that the
> > completion events are occurring, so let's focus on whether the sync
> > code is not waiting for them correctly. Can you trace the following
> > events:
> > 
> > 	xfs_log_force
> > 	xfs_setfilesize
> > 	writeback_queue
> > 	writeback_exec
> > 	writeback_start
> > 	writeback_queue_io
> > 	writeback_written
> > 	writeback_pages_written
> > 
> > basically I'm trying to see if we've got all the BDI events as we'd
> > expect then to be queued and run for sync, and when the ->sync_fs
> > call occurs during the sync process before shutdown and unmount...
> 
> I collected two versions of trace info with crc enabled.
> 
> http://128.199.137.77/writeback-crc/
> 
> This version traced the same events as previous runs.
> 
> http://128.199.137.77/writeback-crc-v2/
> 
> And this version only traced the events you listed above.

OK, I'll look into these later.

> And the results of other tests to check(all done with v4 xfs, with no
> tracepoints enabled):
> 
> > Other things to check (separately):
> >	- change godown to godown -f
> 
> Passed 100 loops.

Yup, I expected that from the last set of traces - the "-f" flag
triggers a log force before shutdown, and that flushes out
transactions that sync missed.

> >	- add a "sleep 5" before running godown after sync
> 
> Failed, if you need the trace info please let me know.

Expected, still nothing to flush transactions before shutdown.

> >	- add a "sleep 5; sync" before running godown
> 
> Passed 100 loops.

expected - sync flushed the transactions it missed on the first
pass.

Thanks for running these tests!

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]

#1211988

On Mon 24-08-15 16:24:25, Dave Chinner wrote:
> On Mon, Aug 24, 2015 at 11:18:16AM +0800, Eryu Guan wrote:
> > On Mon, Aug 24, 2015 at 11:11:23AM +1000, Dave Chinner wrote:
> > > 
> > > Eryu, can you change the way you run the event trace to be:
> > > 
> > > $ sudo trace-cmd <options> -o <outfile location> ./check <test options>
> > > 
> > > rather than running the trace as a background operation elsewhere?
> > > Maybe that will give better results.
> > 
> > The results are here
> > 
> > http://128.199.137.77/writeback-v3/

<snip>

> What I can't see in the traces is where sync is doing a blocking
> sync pass on the fileystem. The wbc control structure being passed
> to XFS is:
> 
> wbc_writepage:        bdi 253:0: towrt=45569 skip=0 mode=0 kupd=0 bgrd=0 reclm=0 cyclic=0 start=0x0 end=0x7fffffffffffffff
> 
> Which is not coming from sync_inodes_sb() as the sync mode is
> incorrect (i.e. not WB_SYNC_ALL). It looks to me that writeback is
> coming from a generic bdi flusher command rather than a directed
> superblock sync. i.e. through wakeup_flusher_threads() which sets:
> 
>         work->sync_mode = WB_SYNC_NONE;
>         work->nr_pages  = nr_pages;
>         work->range_cyclic = range_cyclic;
>         work->reason    = reason;
>         work->auto_free = 1;
> 
> as the reason is "sync":
> 
>             sync-18849  writeback_queue:      bdi 253:0: sb_dev 0:0 nr_pages=308986 sync_mode=0 kupdate=0 range_cyclic=0 background=0 reason=sync
>             sync-18849  writeback_queue:      bdi 253:0: sb_dev 253:1 nr_pages=9223372036854775807 sync_mode=1 kupdate=0 range_cyclic=0 background=0 reason=sync
> ....
>     kworker/u8:1-1563   writeback_exec:       bdi 253:0: sb_dev 0:0 nr_pages=308986 sync_mode=0 kupdate=0 range_cyclic=0 background=0 reason=sync
>     kworker/u8:1-1563   writeback_start:      bdi 253:0: sb_dev 0:0 nr_pages=308986 sync_mode=0 kupdate=0 range_cyclic=0 background=0 reason=sync
> 
> The next writeback_queue/writeback_exec tracepoint pair are:
> 
> ....
>      kworker/2:1-17163  xfs_setfilesize:      dev 253:6 ino 0xef6506 isize 0xa00000 disize 0x0 offset 0x0 count 10481664
>      kworker/2:1-17163  xfs_setfilesize:      dev 253:6 ino 0xef6506 isize 0xa00000 disize 0x9ff000 offset 0x9ff000 count 4096
>             sync-18849  wbc_writepage:        bdi 253:0: towrt=9223372036854775798 skip=0 mode=1 kupd=0 bgrd=0 reclm=0 cyclic=0 start=0x0 end=0x7fffffffffffffff
>             sync-18849  wbc_writepage:        bdi 253:0: towrt=9223372036854775797 skip=0 mode=1 kupd=0 bgrd=0 reclm=0 cyclic=0 start=0x0 end=0x7fffffffffffffff
>             sync-18849  wbc_writepage:        bdi 253:0: towrt=9223372036854775796 skip=0 mode=1 kupd=0 bgrd=0 reclm=0 cyclic=0 start=0x0 end=0x7fffffffffffffff
>             sync-18849  wbc_writepage:        bdi 253:0: towrt=9223372036854775795 skip=0 mode=1 kupd=0 bgrd=0 reclm=0 cyclic=0 start=0x0 end=0x7fffffffffffffff
>           umount-18852  writeback_queue:      bdi 253:0: sb_dev 253:6 nr_pages=22059 sync_mode=0 kupdate=0 range_cyclic=0 background=0 reason=sync
>     kworker/u8:1-1563   writeback_exec:       bdi 253:0: sb_dev 253:6 nr_pages=22059 sync_mode=0 kupdate=0 range_cyclic=0 background=0 reason=sync
> ....
> 
> which shows unmount being the next writeback event queued and
> executed after the IO completions have come in (that missed the
> log). What is missing is the specific queue/exec events for
> sync_sb_inodes() from the sync code for each filesystem.

Bah, I see the problem and indeed it was introduced by commit e79729123f639
"writeback: don't issue wb_writeback_work if clean". The problem is that
we bail out of sync_inodes_sb() if there is no dirty IO. Which is wrong
because we have to wait for any outstanding IO (i.e. call wait_sb_inodes())
regardless of dirty state! And that also explains why Tejun's patch fixes
the problem because it backs out the change to the exit condition in
sync_inodes_sb().

So Tejun's patch from this thread is indeed fixing the real problem but the
comment in sync_inodes_sb() should be fixed to mention wait_sb_inodes()
must be called in all cases... Tejun, will you fixup the comment please?

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR
--
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]

#1212287

Hello, Jan.

On Mon, Aug 24, 2015 at 11:19:59AM +0200, Jan Kara wrote:
> > which shows unmount being the next writeback event queued and
> > executed after the IO completions have come in (that missed the
> > log). What is missing is the specific queue/exec events for
> > sync_sb_inodes() from the sync code for each filesystem.
> 
> Bah, I see the problem and indeed it was introduced by commit e79729123f639
> "writeback: don't issue wb_writeback_work if clean". The problem is that
> we bail out of sync_inodes_sb() if there is no dirty IO. Which is wrong
> because we have to wait for any outstanding IO (i.e. call wait_sb_inodes())
> regardless of dirty state! And that also explains why Tejun's patch fixes
> the problem because it backs out the change to the exit condition in
> sync_inodes_sb().

Dang, I'm an idiot sandwich.

> So Tejun's patch from this thread is indeed fixing the real problem but the
> comment in sync_inodes_sb() should be fixed to mention wait_sb_inodes()
> must be called in all cases... Tejun, will you fixup the comment please?

Will post an updated patch.  Kudos to Eryu and Dave for chasing it
down.

Thanks a lot.

-- 
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]

#1212370

Hello,

On Mon, Aug 24, 2015 at 10:51:50AM -0400, Tejun Heo wrote:
> > Bah, I see the problem and indeed it was introduced by commit e79729123f639
> > "writeback: don't issue wb_writeback_work if clean". The problem is that
> > we bail out of sync_inodes_sb() if there is no dirty IO. Which is wrong
> > because we have to wait for any outstanding IO (i.e. call wait_sb_inodes())
> > regardless of dirty state! And that also explains why Tejun's patch fixes
> > the problem because it backs out the change to the exit condition in
> > sync_inodes_sb().
> 
> Dang, I'm an idiot sandwich.

A question tho, so this means that an inode may contain dirty or
writeback pages w/o the inode being on one of the dirty lists.
Looking at the generic filesystem and writeback code, this doesn't
seem true in general.  Is this something xfs specific?

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]

#1212433

On Mon 24-08-15 13:11:44, Tejun Heo wrote:
> Hello,
> 
> On Mon, Aug 24, 2015 at 10:51:50AM -0400, Tejun Heo wrote:
> > > Bah, I see the problem and indeed it was introduced by commit e79729123f639
> > > "writeback: don't issue wb_writeback_work if clean". The problem is that
> > > we bail out of sync_inodes_sb() if there is no dirty IO. Which is wrong
> > > because we have to wait for any outstanding IO (i.e. call wait_sb_inodes())
> > > regardless of dirty state! And that also explains why Tejun's patch fixes
> > > the problem because it backs out the change to the exit condition in
> > > sync_inodes_sb().
> > 
> > Dang, I'm an idiot sandwich.
> 
> A question tho, so this means that an inode may contain dirty or
> writeback pages w/o the inode being on one of the dirty lists.
> Looking at the generic filesystem and writeback code, this doesn't
> seem true in general.  Is this something xfs specific?

Inode may contain writeback pages (but not dirty pages) without being on
any of the dirty lists. That is correct. Josef Bacik had patches to create
a list to track inodes with pages under writeback but they clashed with
your patch series and they didn't get rebased yet AFAIR.

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR
--
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]

#1212455

Hello, Jan.

On Mon, Aug 24, 2015 at 09:08:47PM +0200, Jan Kara wrote:
> Inode may contain writeback pages (but not dirty pages) without being on
> any of the dirty lists. That is correct. Josef Bacik had patches to create

Hmmm... Can you please expand on how / why that happens?  It's kinda
weird to require writeback to walk all inodes regardless of their
dirty states.

> a list to track inodes with pages under writeback but they clashed with
> your patch series and they didn't get rebased yet AFAIR.

Wouldn't it make more sense to simply put them on one of the existing
b_* lists?

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]

#1212506

On Mon 24-08-15 15:32:42, Tejun Heo wrote:
> Hello, Jan.
> 
> On Mon, Aug 24, 2015 at 09:08:47PM +0200, Jan Kara wrote:
> > Inode may contain writeback pages (but not dirty pages) without being on
> > any of the dirty lists. That is correct. Josef Bacik had patches to create
> 
> Hmmm... Can you please expand on how / why that happens?  It's kinda
> weird to require writeback to walk all inodes regardless of their
> dirty states.

It is inefficient, yes. But note that 'writeback' and 'dirty' states are
completely independent. Page can be in any of the !dirty & !writeback,
dirty & !writeback, !dirty & writeback, dirty & writeback states. So mixing
tracking of writeback and dirty state of an inode just makes the code even
messier.

> > a list to track inodes with pages under writeback but they clashed with
> > your patch series and they didn't get rebased yet AFAIR.
> 
> Wouldn't it make more sense to simply put them on one of the existing
> b_* lists?

Logically it just doesn't make sense because as I wrote above dirty and
writeback states are completely independent. Also you'd have to detect &
skip inodes that don't really have any dirty pages to write and all the
detection of "is there any data to write" would get more complicated. A
separate list for inodes under writeback as Josef did is IMO the cleanest
solution.

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR
--
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]

#1212531

Hello,

On Mon, Aug 24, 2015 at 11:09:27PM +0200, Jan Kara wrote:
> It is inefficient, yes. But note that 'writeback' and 'dirty' states are
> completely independent. Page can be in any of the !dirty & !writeback,

That isn't true for pages being dirtied through set_page_dirty().
It's guaranteed that a dirty inode remains on one of the b_* lists
till there's no dirty page and writeback is complete.

> dirty & !writeback, !dirty & writeback, dirty & writeback states. So mixing
> tracking of writeback and dirty state of an inode just makes the code even
> messier.

I'm curious where and why they would deviate.  Can you give me some
examples?  AFAICS, anything which uses the usual set_page_dirty() path
shouldn't do that.

> > > a list to track inodes with pages under writeback but they clashed with
> > > your patch series and they didn't get rebased yet AFAIR.
> > 
> > Wouldn't it make more sense to simply put them on one of the existing
> > b_* lists?
> 
> Logically it just doesn't make sense because as I wrote above dirty and
> writeback states are completely independent. Also you'd have to detect &
> skip inodes that don't really have any dirty pages to write and all the
> detection of "is there any data to write" would get more complicated. A
> separate list for inodes under writeback as Josef did is IMO the cleanest
> solution.

Given that the usual code path tracks dirty and writeback together, I
don't think it's nonsensical; however, I'm more curious how common
writeback w/o dirtying case is.

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]

#1212565

On Mon, Aug 24, 2015 at 05:45:35PM -0400, Tejun Heo wrote:
> Hello,
> 
> On Mon, Aug 24, 2015 at 11:09:27PM +0200, Jan Kara wrote:
> > It is inefficient, yes. But note that 'writeback' and 'dirty' states are
> > completely independent. Page can be in any of the !dirty & !writeback,
> 
> That isn't true for pages being dirtied through set_page_dirty().
> It's guaranteed that a dirty inode remains on one of the b_* lists
> till there's no dirty page and writeback is complete.

IO submission calls clear_page_dirty_for_io(), so by the time that
all the pages have been submitted for IO, there are no dirty pages.
IO submission also calls set_page_writeback() once the filesystem
has decided to do IO on the page, and then IO completion calls
end_page_writeback() to clear that state.

IOWs, the page transitions from (dirty && !writeback) before
submission to (!dirty && writeback) after submission, and to (!dirty
&& !writeback) once IO completion occurs.

And you'll note that filemap_fdatawait() blocks on pages with the
PAGECACHE_TAG_WRITEBACK tag set in the mapping tree, not dirty
pages. Hence sync has to wait for all pages to transition out of
writeback before we can consider the inode to be clean.

> > dirty & !writeback, !dirty & writeback, dirty & writeback states. So mixing
> > tracking of writeback and dirty state of an inode just makes the code even
> > messier.
> 
> I'm curious where and why they would deviate.  Can you give me some
> examples?  AFAICS, anything which uses the usual set_page_dirty() path
> shouldn't do that.

mmaped files.

page_mkwrite dirties page		(dirty && !writeback)
writepage clear_page_dirty_for_io	(!dirty && !writeback)
writepage starts writeback		(!dirty && writeback)
page_mkwrite dirties page		(dirty && writeback)
io completes				(dirty && !writeback)

This is done so we don't lose dirty state from page faults whilst
the page is under IO and hence have sync miss the page next time
through....

Of course, this behaviour is different if you have a filesystem or
block device that requires stable pages (e.g. btrfs for data CRC
validity). In this case, the page fault will block until the
writeback state goes away...

> > > > a list to track inodes with pages under writeback but they clashed with
> > > > your patch series and they didn't get rebased yet AFAIR.
> > > 
> > > Wouldn't it make more sense to simply put them on one of the existing
> > > b_* lists?
> > 
> > Logically it just doesn't make sense because as I wrote above dirty and
> > writeback states are completely independent. Also you'd have to detect &
> > skip inodes that don't really have any dirty pages to write and all the
> > detection of "is there any data to write" would get more complicated. A
> > separate list for inodes under writeback as Josef did is IMO the cleanest
> > solution.
> 
> Given that the usual code path tracks dirty and writeback together, I
> don't think it's nonsensical; however, I'm more curious how common
> writeback w/o dirtying case is.

I suspect you've misunderstood the progression here. You can't get
writeback without first going through dirty. But the transition to
writeback clears the dirty page state so that we can capture page
state changes while writeback is in progress.

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]

#1212568

Hello,

On Mon, Aug 24, 2015 at 05:45:35PM -0400, Tejun Heo wrote:
> That isn't true for pages being dirtied through set_page_dirty().
> It's guaranteed that a dirty inode remains on one of the b_* lists
> till there's no dirty page and writeback is complete.

I got confused here.  inodes get removed from b_* once all IOs are
issued.

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