[PATCH] Btrfs: fix abnormal long waiting in fsync

[PATCH] Btrfs: fix abnormal long waiting in fsync

[Liu Bo]

xfstests generic/127 detected this problem.

With commit 7fc34a62ca4434a79c68e23e70ed26111b7a4cf8, now fsync will only flush
data within the passed range.  This is the cause of the above problem,
-- btrfs's fsync has a stage called 'sync log' which will wait for all the
ordered extents it've recorded to finish.

In xfstests/generic/127, with mixed operations such as truncate, fallocate,
punch hole, and mapwrite, we get some pre-allocated extents, and mapwrite will
mmap, and then msync.  And I find that msync will wait for quite a long time
(about 20s in my case), thanks to ftrace, it turns out that the previous
fallocate calls 'btrfs_wait_ordered_range()' to flush dirty pages, but as the
range of dirty pages may be larger than 'btrfs_wait_ordered_range()' wants,
there can be some ordered extents created but not getting corresponding pages
flushed, then they're left in memory until we fsync which runs into the
stage 'sync log', and fsync will just wait for the system writeback thread
to flush those pages and get ordered extents finished, so the latency is
inevitable.

This adds a non-blocked flush, filemap_flush(), in btrfs_sync_file() to fix
that.

Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
---
 fs/btrfs/file.c | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/fs/btrfs/file.c b/fs/btrfs/file.c
index 1f2b99c..1af395d 100644
--- a/fs/btrfs/file.c
+++ b/fs/btrfs/file.c
@@ -2002,6 +2002,8 @@ int btrfs_sync_file(struct file *file, loff_t start, loff_t end, int datasync)
 
 	if (ret != BTRFS_NO_LOG_SYNC) {
 		if (!ret) {
+			filemap_flush(inode->i_mapping);
+
 			ret = btrfs_sync_log(trans, root, &ctx);
 			if (!ret) {
 				ret = btrfs_end_transaction(trans, root);
-- 
1.8.1.4

Re: [PATCH] Btrfs: fix abnormal long waiting in fsync

[Miao Xie]

On Tue, 15 Jul 2014 17:31:14 +0800, Liu Bo wrote:
> xfstests generic/127 detected this problem.
> 
> With commit 7fc34a62ca4434a79c68e23e70ed26111b7a4cf8, now fsync will only flush
> data within the passed range.  This is the cause of the above problem,
> -- btrfs's fsync has a stage called 'sync log' which will wait for all the
> ordered extents it've recorded to finish.
> 
> In xfstests/generic/127, with mixed operations such as truncate, fallocate,
> punch hole, and mapwrite, we get some pre-allocated extents, and mapwrite will
> mmap, and then msync.  And I find that msync will wait for quite a long time
> (about 20s in my case), thanks to ftrace, it turns out that the previous
> fallocate calls 'btrfs_wait_ordered_range()' to flush dirty pages, but as the
> range of dirty pages may be larger than 'btrfs_wait_ordered_range()' wants,

btrfs_sync_file also calls 'btrfs_wait_ordered_range()' and introduces the same
problem.

> there can be some ordered extents created but not getting corresponding pages
> flushed, then they're left in memory until we fsync which runs into the
> stage 'sync log', and fsync will just wait for the system writeback thread
> to flush those pages and get ordered extents finished, so the latency is
> inevitable.
> 
> This adds a non-blocked flush, filemap_flush(), in btrfs_sync_file() to fix
> that.

I think this fix is not so good, because it will flush the pages that is not
relative to the current sync. I think the key reason is btrfs_wait_logged_extents(),
that just wait the ordered extents, not flush the relative dirty pages.

So the more reasonable fix is to use btrfs_start_ordered_extent() instead of
wait_event in btrfs_wait_logged_extents().

(This above is just my analysis)

Thanks
Miao

> 
> Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
> ---
>  fs/btrfs/file.c | 2 ++
>  1 file changed, 2 insertions(+)
> 
> diff --git a/fs/btrfs/file.c b/fs/btrfs/file.c
> index 1f2b99c..1af395d 100644
> --- a/fs/btrfs/file.c
> +++ b/fs/btrfs/file.c
> @@ -2002,6 +2002,8 @@ int btrfs_sync_file(struct file *file, loff_t start, loff_t end, int datasync)
>  
>  	if (ret != BTRFS_NO_LOG_SYNC) {
>  		if (!ret) {
> +			filemap_flush(inode->i_mapping);
> +
>  			ret = btrfs_sync_log(trans, root, &ctx);
>  			if (!ret) {
>  				ret = btrfs_end_transaction(trans, root);
> 

Re: [PATCH] Btrfs: fix abnormal long waiting in fsync

[constantine]

unsubscribe

Re: [PATCH] Btrfs: fix abnormal long waiting in fsync

[Liu Bo]

On Tue, Jul 15, 2014 at 06:22:10PM +0800, Miao Xie wrote:
> On Tue, 15 Jul 2014 17:31:14 +0800, Liu Bo wrote:
> > xfstests generic/127 detected this problem.
> > 
> > With commit 7fc34a62ca4434a79c68e23e70ed26111b7a4cf8, now fsync will only flush
> > data within the passed range.  This is the cause of the above problem,
> > -- btrfs's fsync has a stage called 'sync log' which will wait for all the
> > ordered extents it've recorded to finish.
> > 
> > In xfstests/generic/127, with mixed operations such as truncate, fallocate,
> > punch hole, and mapwrite, we get some pre-allocated extents, and mapwrite will
> > mmap, and then msync.  And I find that msync will wait for quite a long time
> > (about 20s in my case), thanks to ftrace, it turns out that the previous
> > fallocate calls 'btrfs_wait_ordered_range()' to flush dirty pages, but as the
> > range of dirty pages may be larger than 'btrfs_wait_ordered_range()' wants,
> 
> btrfs_sync_file also calls 'btrfs_wait_ordered_range()' and introduces the same
> problem.

Yeah, looks that it will.

> 
> > there can be some ordered extents created but not getting corresponding pages
> > flushed, then they're left in memory until we fsync which runs into the
> > stage 'sync log', and fsync will just wait for the system writeback thread
> > to flush those pages and get ordered extents finished, so the latency is
> > inevitable.
> > 
> > This adds a non-blocked flush, filemap_flush(), in btrfs_sync_file() to fix
> > that.
> 
> I think this fix is not so good, because it will flush the pages that is not
> relative to the current sync. I think the key reason is btrfs_wait_logged_extents(),
> that just wait the ordered extents, not flush the relative dirty pages.
> 
> So the more reasonable fix is to use btrfs_start_ordered_extent() instead of
> wait_event in btrfs_wait_logged_extents().

It should work, the only difference is that here we wait for
BTRFS_ORDERED_IO_DONE instead of COMPLETE.  Will give a shot.

thanks,
-liubo

> 
> (This above is just my analysis)
> 
> Thanks
> Miao
> 
> > 
> > Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
> > ---
> >  fs/btrfs/file.c | 2 ++
> >  1 file changed, 2 insertions(+)
> > 
> > diff --git a/fs/btrfs/file.c b/fs/btrfs/file.c
> > index 1f2b99c..1af395d 100644
> > --- a/fs/btrfs/file.c
> > +++ b/fs/btrfs/file.c
> > @@ -2002,6 +2002,8 @@ int btrfs_sync_file(struct file *file, loff_t start, loff_t end, int datasync)
> >  
> >  	if (ret != BTRFS_NO_LOG_SYNC) {
> >  		if (!ret) {
> > +			filemap_flush(inode->i_mapping);
> > +
> >  			ret = btrfs_sync_log(trans, root, &ctx);
> >  			if (!ret) {
> >  				ret = btrfs_end_transaction(trans, root);
> > 
> 

[PATCH v2] Btrfs: fix abnormal long waiting in fsync

[Liu Bo]

xfstests generic/127 detected this problem.

With commit 7fc34a62ca4434a79c68e23e70ed26111b7a4cf8, now fsync will only flush
data within the passed range.  This is the cause of the above problem,
-- btrfs's fsync has a stage called 'sync log' which will wait for all the
ordered extents it've recorded to finish.

In xfstests/generic/127, with mixed operations such as truncate, fallocate,
punch hole, and mapwrite, we get some pre-allocated extents, and mapwrite will
mmap, and then msync.  And I find that msync will wait for quite a long time
(about 20s in my case), thanks to ftrace, it turns out that the previous
fallocate calls 'btrfs_wait_ordered_range()' to flush dirty pages, but as the
range of dirty pages may be larger than 'btrfs_wait_ordered_range()' wants,
there can be some ordered extents created but not getting corresponding pages
flushed, then they're left in memory until we fsync which runs into the
stage 'sync log', and fsync will just wait for the system writeback thread
to flush those pages and get ordered extents finished, so the latency is
inevitable.

This adds a flush similar to btrfs_start_ordered_extent() in
btrfs_wait_logged_extents() to fix that.

Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
---
v2: 
   Move flush part into btrfs_wait_logged_extents() to get the flush range
   more precise.

 fs/btrfs/ordered-data.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/fs/btrfs/ordered-data.c b/fs/btrfs/ordered-data.c
index e12441c..3b52a76 100644
--- a/fs/btrfs/ordered-data.c
+++ b/fs/btrfs/ordered-data.c
@@ -484,8 +484,16 @@ void btrfs_wait_logged_extents(struct btrfs_root *log, u64 transid)
 					   log_list);
 		list_del_init(&ordered->log_list);
 		spin_unlock_irq(&log->log_extents_lock[index]);
+
+		WARN_ON(!ordered->inode);
+		if (!test_bit(BTRFS_ORDERED_DIRECT, &ordered->flags))
+			filemap_fdatawrite_range(ordered->inode->i_mapping,
+				ordered->file_offset,
+				ordered->file_offset + ordered->len - 1);
+
 		wait_event(ordered->wait, test_bit(BTRFS_ORDERED_IO_DONE,
 						   &ordered->flags));
+
 		btrfs_put_ordered_extent(ordered);
 		spin_lock_irq(&log->log_extents_lock[index]);
 	}
-- 
1.8.1.4

Re: [PATCH v2] Btrfs: fix abnormal long waiting in fsync

[Miao Xie]

On Wed, 16 Jul 2014 15:37:05 +0800, Liu Bo wrote:
> xfstests generic/127 detected this problem.
> 
> With commit 7fc34a62ca4434a79c68e23e70ed26111b7a4cf8, now fsync will only flush
> data within the passed range.  This is the cause of the above problem,
> -- btrfs's fsync has a stage called 'sync log' which will wait for all the
> ordered extents it've recorded to finish.
> 
> In xfstests/generic/127, with mixed operations such as truncate, fallocate,
> punch hole, and mapwrite, we get some pre-allocated extents, and mapwrite will
> mmap, and then msync.  And I find that msync will wait for quite a long time
> (about 20s in my case), thanks to ftrace, it turns out that the previous
> fallocate calls 'btrfs_wait_ordered_range()' to flush dirty pages, but as the
> range of dirty pages may be larger than 'btrfs_wait_ordered_range()' wants,
> there can be some ordered extents created but not getting corresponding pages
> flushed, then they're left in memory until we fsync which runs into the
> stage 'sync log', and fsync will just wait for the system writeback thread
> to flush those pages and get ordered extents finished, so the latency is
> inevitable.
> 
> This adds a flush similar to btrfs_start_ordered_extent() in
> btrfs_wait_logged_extents() to fix that.
> 
> Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
> ---
> v2: 
>    Move flush part into btrfs_wait_logged_extents() to get the flush range
>    more precise.
> 
>  fs/btrfs/ordered-data.c | 8 ++++++++
>  1 file changed, 8 insertions(+)
> 
> diff --git a/fs/btrfs/ordered-data.c b/fs/btrfs/ordered-data.c
> index e12441c..3b52a76 100644
> --- a/fs/btrfs/ordered-data.c
> +++ b/fs/btrfs/ordered-data.c
> @@ -484,8 +484,16 @@ void btrfs_wait_logged_extents(struct btrfs_root *log, u64 transid)
>  					   log_list);
>  		list_del_init(&ordered->log_list);
>  		spin_unlock_irq(&log->log_extents_lock[index]);
> +
> +		WARN_ON(!ordered->inode);
> +		if (!test_bit(BTRFS_ORDERED_DIRECT, &ordered->flags))
> +			filemap_fdatawrite_range(ordered->inode->i_mapping,
> +				ordered->file_offset,
> +				ordered->file_offset + ordered->len - 1);

I can use bytes_left to filter the ordered extents that have been written out.

The other is OK.

Reviewed-by: Miao Xie <miaox@cn.fujitsu.com>

> +
>  		wait_event(ordered->wait, test_bit(BTRFS_ORDERED_IO_DONE,
>  						   &ordered->flags));
> +
>  		btrfs_put_ordered_extent(ordered);
>  		spin_lock_irq(&log->log_extents_lock[index]);
>  	}
> 

Re: [PATCH v2] Btrfs: fix abnormal long waiting in fsync

[Liu Bo]

On Wed, Jul 16, 2014 at 05:36:07PM +0800, Miao Xie wrote:
> On Wed, 16 Jul 2014 15:37:05 +0800, Liu Bo wrote:
> > xfstests generic/127 detected this problem.
> > 
> > With commit 7fc34a62ca4434a79c68e23e70ed26111b7a4cf8, now fsync will only flush
> > data within the passed range.  This is the cause of the above problem,
> > -- btrfs's fsync has a stage called 'sync log' which will wait for all the
> > ordered extents it've recorded to finish.
> > 
> > In xfstests/generic/127, with mixed operations such as truncate, fallocate,
> > punch hole, and mapwrite, we get some pre-allocated extents, and mapwrite will
> > mmap, and then msync.  And I find that msync will wait for quite a long time
> > (about 20s in my case), thanks to ftrace, it turns out that the previous
> > fallocate calls 'btrfs_wait_ordered_range()' to flush dirty pages, but as the
> > range of dirty pages may be larger than 'btrfs_wait_ordered_range()' wants,
> > there can be some ordered extents created but not getting corresponding pages
> > flushed, then they're left in memory until we fsync which runs into the
> > stage 'sync log', and fsync will just wait for the system writeback thread
> > to flush those pages and get ordered extents finished, so the latency is
> > inevitable.
> > 
> > This adds a flush similar to btrfs_start_ordered_extent() in
> > btrfs_wait_logged_extents() to fix that.
> > 
> > Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
> > ---
> > v2: 
> >    Move flush part into btrfs_wait_logged_extents() to get the flush range
> >    more precise.
> > 
> >  fs/btrfs/ordered-data.c | 8 ++++++++
> >  1 file changed, 8 insertions(+)
> > 
> > diff --git a/fs/btrfs/ordered-data.c b/fs/btrfs/ordered-data.c
> > index e12441c..3b52a76 100644
> > --- a/fs/btrfs/ordered-data.c
> > +++ b/fs/btrfs/ordered-data.c
> > @@ -484,8 +484,16 @@ void btrfs_wait_logged_extents(struct btrfs_root *log, u64 transid)
> >  					   log_list);
> >  		list_del_init(&ordered->log_list);
> >  		spin_unlock_irq(&log->log_extents_lock[index]);
> > +
> > +		WARN_ON(!ordered->inode);
> > +		if (!test_bit(BTRFS_ORDERED_DIRECT, &ordered->flags))
> > +			filemap_fdatawrite_range(ordered->inode->i_mapping,
> > +				ordered->file_offset,
> > +				ordered->file_offset + ordered->len - 1);
> 
> I can use bytes_left to filter the ordered extents that have been written out.

I prefer to use BTRFS_ORDERED_IO_DONE, but no big difference with bytes_left :)

> 
> The other is OK.
> 
> Reviewed-by: Miao Xie <miaox@cn.fujitsu.com>

thanks,
-liubo

> 
> > +
> >  		wait_event(ordered->wait, test_bit(BTRFS_ORDERED_IO_DONE,
> >  						   &ordered->flags));
> > +
> >  		btrfs_put_ordered_extent(ordered);
> >  		spin_lock_irq(&log->log_extents_lock[index]);
> >  	}
> > 
> 

[PATCH v3] Btrfs: fix abnormal long waiting in fsync

[Liu Bo]

xfstests generic/127 detected this problem.

With commit 7fc34a62ca4434a79c68e23e70ed26111b7a4cf8, now fsync will only flush
data within the passed range.  This is the cause of the above problem,
-- btrfs's fsync has a stage called 'sync log' which will wait for all the
ordered extents it've recorded to finish.

In xfstests/generic/127, with mixed operations such as truncate, fallocate,
punch hole, and mapwrite, we get some pre-allocated extents, and mapwrite will
mmap, and then msync.  And I find that msync will wait for quite a long time
(about 20s in my case), thanks to ftrace, it turns out that the previous
fallocate calls 'btrfs_wait_ordered_range()' to flush dirty pages, but as the
range of dirty pages may be larger than 'btrfs_wait_ordered_range()' wants,
there can be some ordered extents created but not getting corresponding pages
flushed, then they're left in memory until we fsync which runs into the
stage 'sync log', and fsync will just wait for the system writeback thread
to flush those pages and get ordered extents finished, so the latency is
inevitable.

This adds a flush similar to btrfs_start_ordered_extent() in
btrfs_wait_logged_extents() to fix that.

Reviewed-by: Miao Xie <miaox@cn.fujitsu.com>
Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
---
v3:
   Add a check for IO_DONE flag to avoid unnecessary flush.
v2: 
   Move flush part into btrfs_wait_logged_extents() to get the flush range
   more precise.

 fs/btrfs/ordered-data.c | 11 +++++++++++
 1 file changed, 11 insertions(+)

diff --git a/fs/btrfs/ordered-data.c b/fs/btrfs/ordered-data.c
index e12441c..7187b14 100644
--- a/fs/btrfs/ordered-data.c
+++ b/fs/btrfs/ordered-data.c
@@ -484,8 +484,19 @@ void btrfs_wait_logged_extents(struct btrfs_root *log, u64 transid)
 					   log_list);
 		list_del_init(&ordered->log_list);
 		spin_unlock_irq(&log->log_extents_lock[index]);
+
+		if (!test_bit(BTRFS_ORDERED_IO_DONE, &ordered->flags) &&
+		    !test_bit(BTRFS_ORDERED_DIRECT, &ordered->flags)) {
+			struct inode *inode = ordered->inode;
+			u64 start = ordered->file_offset;
+			u64 end = ordered->file_offset + ordered->len - 1;
+
+			WARN_ON(!inode);
+			filemap_fdatawrite_range(inode->i_mapping, start, end);
+		}
 		wait_event(ordered->wait, test_bit(BTRFS_ORDERED_IO_DONE,
 						   &ordered->flags));
+
 		btrfs_put_ordered_extent(ordered);
 		spin_lock_irq(&log->log_extents_lock[index]);
 	}
-- 
1.8.1.4

Re: [PATCH v3] Btrfs: fix abnormal long waiting in fsync

[Chris Mason]

On 07/17/2014 04:08 AM, Liu Bo wrote:
> xfstests generic/127 detected this problem.
> 
> With commit 7fc34a62ca4434a79c68e23e70ed26111b7a4cf8, now fsync will only flush
> data within the passed range.  This is the cause of the above problem,
> -- btrfs's fsync has a stage called 'sync log' which will wait for all the
> ordered extents it've recorded to finish.
> 
> In xfstests/generic/127, with mixed operations such as truncate, fallocate,
> punch hole, and mapwrite, we get some pre-allocated extents, and mapwrite will
> mmap, and then msync.  And I find that msync will wait for quite a long time
> (about 20s in my case), thanks to ftrace, it turns out that the previous
> fallocate calls 'btrfs_wait_ordered_range()' to flush dirty pages, but as the
> range of dirty pages may be larger than 'btrfs_wait_ordered_range()' wants,
> there can be some ordered extents created but not getting corresponding pages
> flushed, then they're left in memory until we fsync which runs into the
> stage 'sync log', and fsync will just wait for the system writeback thread
> to flush those pages and get ordered extents finished, so the latency is
> inevitable.
> 
> This adds a flush similar to btrfs_start_ordered_extent() in
> btrfs_wait_logged_extents() to fix that.

I was able to trigger the stalls with plain fsx as well.  Thanks!

-chris