EXT4 IOPS degradation between 4.14 and 5.10

EXT4 IOPS degradation between 4.14 and 5.10

[Bhatnagar, Rishabh]

Hi Jan

As discussed in the previous thread I'm chasing IOPS regression between 
4.14 -> 5.10 kernels.
https://lore.kernel.org/lkml/20230112113820.hjwvieq3ucbwreql@quack3/T/
<https://lore.kernel.org/lkml/20230112113820.hjwvieq3ucbwreql@quack3/T/>

Last issue we discussed was difficult to resolve so keeping it on the 
back burner for now.

I did some more bisecting and saw another series of patches that 
potentially impacts iops score:
72b045aecdd856b083521f2a963705b4c2e59680 (mm: implement 
find_get_pages_range_tag())

Running fio tests on tip as 9c19a9cb1642c074aa8bc7693cd4c038643960ae 
(including the 16 patch series) vs tip as
6b4c54e3787bc03e810062bd257a3b05fd9c72d6 (without the above series) 
shows an IOPS jump.

Fio with buffered io/fsync=1/randwrite

With HEAD as 9c19a9cb1642c074aa8bc7693cd4c038643960ae (with the above 
series)

write: io=445360KB, bw=7418.6KB/s, *iops=463*, runt= 60033msec
clat (usec): min=4, max=32132, avg=311.90, stdev=1812.74
lat (usec): min=5, max=32132, avg=312.28, stdev=1812.74
clat percentiles (usec):
| 1.00th=[ 8], 5.00th=[ 10], 10.00th=[ 16], 20.00th=[ 25],
| 30.00th=[ 36], 40.00th=[ 47], 50.00th=[ 60], 60.00th=[ 71],
| 70.00th=[ 84], 80.00th=[ 97], 90.00th=[ 111], 95.00th=[ 118],
| 99.00th=[11840], 99.50th=[15936], 99.90th=[21888], 99.95th=[23936],

With HEAD as 6b4c54e3787bc03e810062bd257a3b05fd9c72d6(without the above 
series)

write: io=455184KB, bw=7583.4KB/s, *iops=473*, runt= 60024msec
clat (usec): min=6, max=24325, avg=319.72, stdev=1694.52
lat (usec): min=6, max=24326, avg=319.99, stdev=1694.53
clat percentiles (usec):
| 1.00th=[ 9], 5.00th=[ 11], 10.00th=[ 17], 20.00th=[ 26],
| 30.00th=[ 38], 40.00th=[ 50], 50.00th=[ 60], 60.00th=[ 73],
| 70.00th=[ 85], 80.00th=[ 98], 90.00th=[ 111], 95.00th=[ 118],
| 99.00th=[ 9792], 99.50th=[14016], 99.90th=[21888], 99.95th=[22400],
| 99.99th=[24192]


I also see that number of handles per transaction were much higher 
before this patch series

0ms waiting for transaction
0ms request delay
20ms running transaction
0ms transaction was being locked
0ms flushing data (in ordered mode)
10ms logging transaction
*13524us average transaction commit time*
*73 handles per transaction*
0 blocks per transaction
1 logged blocks per transaction

vs after the patch series.

0ms waiting for transaction
0ms request delay
20ms running transaction
0ms transaction was being locked
0ms flushing data (in ordered mode)
20ms logging transaction
*21468us average transaction commit time*
*66 handles per transaction*
1 blocks per transaction
1 logged blocks per transaction

This is probably again helping in bunching the writeback transactions 
and increasing throughput.

I looked at the code to understand what might be going on.
It seems like commit 72b045aecdd856b083521f2a963705b4c2e59680 changes 
the behavior of find_get_pages_range_tag.
Before this commit if find_get_pages_tag cannot find nr_pages 
(PAGEVEC_SIZE) it returns the number of pages found as ret and
sets the *index to the last page it found + 1. After the commit the 
behavior changes such that if we don’t find nr_pages pages
we set the index to end and not to the last found page. (added diff from 
above commit)
Since pagevec_lookup_range_tag is always called in a while loop (index 
<= end) the code before the commit helps in coalescing
writeback of pages if there are multiple threads doing write as it might 
keep finding new dirty (tagged) pages since it doesn’t set index to end.

+ /*
+ * We come here when we got at @end. We take care to not overflow the
+ * index @index as it confuses some of the callers. This breaks the
+ * iteration when there is page at index -1 but that is already broken
+ * anyway.
+ */
+ if (end == (pgoff_t)-1)
+ *index = (pgoff_t)-1;
+ else
+ *index = end + 1;
+out:
rcu_read_unlock();

- if (ret)
- *index = pages[ret - 1]->index + 1;
-

 From the description of the patch i didn't see any mention of this 
functional change.
Was this change intentional and did help some usecase or general 
performance improvement?

Thanks
Rishabh

Re: EXT4 IOPS degradation between 4.14 and 5.10

[Jan Kara]

Hello!

On Wed 25-01-23 16:33:54, Bhatnagar, Rishabh wrote:
> As discussed in the previous thread I'm chasing IOPS regression between 4.14
> -> 5.10 kernels.
> https://lore.kernel.org/lkml/20230112113820.hjwvieq3ucbwreql@quack3/T/
> <https://lore.kernel.org/lkml/20230112113820.hjwvieq3ucbwreql@quack3/T/>
> 
> Last issue we discussed was difficult to resolve so keeping it on the back
> burner for now.
> 
> I did some more bisecting and saw another series of patches that potentially
> impacts iops score:
> 72b045aecdd856b083521f2a963705b4c2e59680 (mm: implement
> find_get_pages_range_tag())
> 
> Running fio tests on tip as 9c19a9cb1642c074aa8bc7693cd4c038643960ae
> (including the 16 patch series) vs tip as
> 6b4c54e3787bc03e810062bd257a3b05fd9c72d6 (without the above series) shows an
> IOPS jump.

Ok, thanks for pinpointing this. That series landed a long time ago ;).

> Fio with buffered io/fsync=1/randwrite

So I'm curious. Do you have any workload that actually does these
synchronous random buffered IOs? Or is it just a benchmarking exercise?

> With HEAD as 9c19a9cb1642c074aa8bc7693cd4c038643960ae (with the above
> series)
> 
> write: io=445360KB, bw=7418.6KB/s, *iops=463*, runt= 60033msec
> clat (usec): min=4, max=32132, avg=311.90, stdev=1812.74
> lat (usec): min=5, max=32132, avg=312.28, stdev=1812.74
> clat percentiles (usec):
> | 1.00th=[ 8], 5.00th=[ 10], 10.00th=[ 16], 20.00th=[ 25],
> | 30.00th=[ 36], 40.00th=[ 47], 50.00th=[ 60], 60.00th=[ 71],
> | 70.00th=[ 84], 80.00th=[ 97], 90.00th=[ 111], 95.00th=[ 118],
> | 99.00th=[11840], 99.50th=[15936], 99.90th=[21888], 99.95th=[23936],
> 
> With HEAD as 6b4c54e3787bc03e810062bd257a3b05fd9c72d6(without the above
> series)
> 
> write: io=455184KB, bw=7583.4KB/s, *iops=473*, runt= 60024msec
> clat (usec): min=6, max=24325, avg=319.72, stdev=1694.52
> lat (usec): min=6, max=24326, avg=319.99, stdev=1694.53
> clat percentiles (usec):
> | 1.00th=[ 9], 5.00th=[ 11], 10.00th=[ 17], 20.00th=[ 26],
> | 30.00th=[ 38], 40.00th=[ 50], 50.00th=[ 60], 60.00th=[ 73],
> | 70.00th=[ 85], 80.00th=[ 98], 90.00th=[ 111], 95.00th=[ 118],
> | 99.00th=[ 9792], 99.50th=[14016], 99.90th=[21888], 99.95th=[22400],
> | 99.99th=[24192]

OK, about 2% regression. How stable is that across multiple runs?

> I also see that number of handles per transaction were much higher before
> this patch series
> 
> 0ms waiting for transaction
> 0ms request delay
> 20ms running transaction
> 0ms transaction was being locked
> 0ms flushing data (in ordered mode)
> 10ms logging transaction
> *13524us average transaction commit time*
> *73 handles per transaction*
> 0 blocks per transaction
> 1 logged blocks per transaction
> 
> vs after the patch series.
> 
> 0ms waiting for transaction
> 0ms request delay
> 20ms running transaction
> 0ms transaction was being locked
> 0ms flushing data (in ordered mode)
> 20ms logging transaction
> *21468us average transaction commit time*
> *66 handles per transaction*
> 1 blocks per transaction
> 1 logged blocks per transaction
> 
> This is probably again helping in bunching the writeback transactions and
> increasing throughput.

Yeah, probably.

> I looked at the code to understand what might be going on.
> It seems like commit 72b045aecdd856b083521f2a963705b4c2e59680 changes the
> behavior of find_get_pages_range_tag.
> Before this commit if find_get_pages_tag cannot find nr_pages (PAGEVEC_SIZE)
> it returns the number of pages found as ret and
> sets the *index to the last page it found + 1. After the commit the behavior
> changes such that if we don’t find nr_pages pages
> we set the index to end and not to the last found page. (added diff from
> above commit)
> Since pagevec_lookup_range_tag is always called in a while loop (index <=
> end) the code before the commit helps in coalescing
> writeback of pages if there are multiple threads doing write as it might
> keep finding new dirty (tagged) pages since it doesn’t set index to end.
> 
> + /*
> + * We come here when we got at @end. We take care to not overflow the
> + * index @index as it confuses some of the callers. This breaks the
> + * iteration when there is page at index -1 but that is already broken
> + * anyway.
> + */
> + if (end == (pgoff_t)-1)
> + *index = (pgoff_t)-1;
> + else
> + *index = end + 1;
> +out:
> rcu_read_unlock();
> 
> - if (ret)
> - *index = pages[ret - 1]->index + 1;
> -
> 
> From the description of the patch i didn't see any mention of this
> functional change.
> Was this change intentional and did help some usecase or general performance
> improvement?

So the change was intentional. When I was working on the series, I was
somewhat concerned that the old code could end up in a pathological
situation like:
  We scan range 0-1000000, find the only dirty page at index 0, return it.
  We scan range 1-1000000, find the only dirty page at index 1, return it.
  ...

This way we end up with rather inefficient scanning and in theory malicious
user could livelock writeback like this. That being said this was/is mostly
a theoretical concern.

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: EXT4 IOPS degradation between 4.14 and 5.10

[Bhatnagar, Rishabh]

On 1/26/23 1:32 AM, Jan Kara wrote:
> CAUTION: This email originated from outside of the organization. Do not click links or open attachments unless you can confirm the sender and know the content is safe.
>
>
>
> Hello!
>
> On Wed 25-01-23 16:33:54, Bhatnagar, Rishabh wrote:
>> As discussed in the previous thread I'm chasing IOPS regression between 4.14
>> -> 5.10 kernels.
>> https://lore.kernel.org/lkml/20230112113820.hjwvieq3ucbwreql@quack3/T/
>> <https://lore.kernel.org/lkml/20230112113820.hjwvieq3ucbwreql@quack3/T/>
>>
>> Last issue we discussed was difficult to resolve so keeping it on the back
>> burner for now.
>>
>> I did some more bisecting and saw another series of patches that potentially
>> impacts iops score:
>> 72b045aecdd856b083521f2a963705b4c2e59680 (mm: implement
>> find_get_pages_range_tag())
>>
>> Running fio tests on tip as 9c19a9cb1642c074aa8bc7693cd4c038643960ae
>> (including the 16 patch series) vs tip as
>> 6b4c54e3787bc03e810062bd257a3b05fd9c72d6 (without the above series) shows an
>> IOPS jump.
> Ok, thanks for pinpointing this. That series landed a long time ago ;).
>
Yes its quite old patch series. I was tracking a regression for teams 
moving to a newer 5.10 (although that's also old) kernel from 4.14.
>> Fio with buffered io/fsync=1/randwrite
> So I'm curious. Do you have any workload that actually does these
> synchronous random buffered IOs? Or is it just a benchmarking exercise?
>
So database team was a running benchmark called hammerdb with 16 
connections where they started noticing dropped
performance for 5.10. We traced it back to filesystem with this 
benchmark. Although the database workload would be something similar
  I guess.

>> With HEAD as 9c19a9cb1642c074aa8bc7693cd4c038643960ae (with the above
>> series)
>>
>> write: io=445360KB, bw=7418.6KB/s, *iops=463*, runt= 60033msec
>> clat (usec): min=4, max=32132, avg=311.90, stdev=1812.74
>> lat (usec): min=5, max=32132, avg=312.28, stdev=1812.74
>> clat percentiles (usec):
>> | 1.00th=[ 8], 5.00th=[ 10], 10.00th=[ 16], 20.00th=[ 25],
>> | 30.00th=[ 36], 40.00th=[ 47], 50.00th=[ 60], 60.00th=[ 71],
>> | 70.00th=[ 84], 80.00th=[ 97], 90.00th=[ 111], 95.00th=[ 118],
>> | 99.00th=[11840], 99.50th=[15936], 99.90th=[21888], 99.95th=[23936],
>>
>> With HEAD as 6b4c54e3787bc03e810062bd257a3b05fd9c72d6(without the above
>> series)
>>
>> write: io=455184KB, bw=7583.4KB/s, *iops=473*, runt= 60024msec
>> clat (usec): min=6, max=24325, avg=319.72, stdev=1694.52
>> lat (usec): min=6, max=24326, avg=319.99, stdev=1694.53
>> clat percentiles (usec):
>> | 1.00th=[ 9], 5.00th=[ 11], 10.00th=[ 17], 20.00th=[ 26],
>> | 30.00th=[ 38], 40.00th=[ 50], 50.00th=[ 60], 60.00th=[ 73],
>> | 70.00th=[ 85], 80.00th=[ 98], 90.00th=[ 111], 95.00th=[ 118],
>> | 99.00th=[ 9792], 99.50th=[14016], 99.90th=[21888], 99.95th=[22400],
>> | 99.99th=[24192]
> OK, about 2% regression. How stable is that across multiple runs?
This is quite consistent. The thing to note here is this test is on 
4.14+ tip with and without
these patch series.
I tried reverting to the same behavior in 5.10 with the following patch 
but i only see a very low improvement. (~1%)

This is because on 5.10 we also have this patch
ext4: avoid unnecessary transaction starts during writeback. (This 
limits the invocation of this function within the while loop)
If i revert the above patch as well along with applying below patch i 
get back around 4% IOPS.

-       if (end == (pgoff_t)-1)
-               *index = (pgoff_t)-1;
-       else
-               *index = end + 1;
+       if (xas.xa_index > end) {
+               if (end == (pgoff_t)-1)
+                       *index = (pgoff_t)-1;
+               else
+                       *index = end + 1;
+       }
+       else if (ret)
+               *index = xas.xa_index + 1;

>
>> I also see that number of handles per transaction were much higher before
>> this patch series
>>
>> 0ms waiting for transaction
>> 0ms request delay
>> 20ms running transaction
>> 0ms transaction was being locked
>> 0ms flushing data (in ordered mode)
>> 10ms logging transaction
>> *13524us average transaction commit time*
>> *73 handles per transaction*
>> 0 blocks per transaction
>> 1 logged blocks per transaction
>>
>> vs after the patch series.
>>
>> 0ms waiting for transaction
>> 0ms request delay
>> 20ms running transaction
>> 0ms transaction was being locked
>> 0ms flushing data (in ordered mode)
>> 20ms logging transaction
>> *21468us average transaction commit time*
>> *66 handles per transaction*
>> 1 blocks per transaction
>> 1 logged blocks per transaction
>>
>> This is probably again helping in bunching the writeback transactions and
>> increasing throughput.
> Yeah, probably.
>
>> I looked at the code to understand what might be going on.
>> It seems like commit 72b045aecdd856b083521f2a963705b4c2e59680 changes the
>> behavior of find_get_pages_range_tag.
>> Before this commit if find_get_pages_tag cannot find nr_pages (PAGEVEC_SIZE)
>> it returns the number of pages found as ret and
>> sets the *index to the last page it found + 1. After the commit the behavior
>> changes such that if we don’t find nr_pages pages
>> we set the index to end and not to the last found page. (added diff from
>> above commit)
>> Since pagevec_lookup_range_tag is always called in a while loop (index <=
>> end) the code before the commit helps in coalescing
>> writeback of pages if there are multiple threads doing write as it might
>> keep finding new dirty (tagged) pages since it doesn’t set index to end.
>>
>> + /*
>> + * We come here when we got at @end. We take care to not overflow the
>> + * index @index as it confuses some of the callers. This breaks the
>> + * iteration when there is page at index -1 but that is already broken
>> + * anyway.
>> + */
>> + if (end == (pgoff_t)-1)
>> + *index = (pgoff_t)-1;
>> + else
>> + *index = end + 1;
>> +out:
>> rcu_read_unlock();
>>
>> - if (ret)
>> - *index = pages[ret - 1]->index + 1;
>> -
>>
>>  From the description of the patch i didn't see any mention of this
>> functional change.
>> Was this change intentional and did help some usecase or general performance
>> improvement?
> So the change was intentional. When I was working on the series, I was
> somewhat concerned that the old code could end up in a pathological
> situation like:
>    We scan range 0-1000000, find the only dirty page at index 0, return it.
>    We scan range 1-1000000, find the only dirty page at index 1, return it.
>    ...
>
> This way we end up with rather inefficient scanning and in theory malicious
> user could livelock writeback like this. That being said this was/is mostly
> a theoretical concern.

Ok so its more of a security concern. But do you think this has a 
latency impact? I didn't see
much latency impact between the two sets and throughput is higher.

>
>                                                                  Honza
> --
> Jan Kara <jack@suse.com>
> SUSE Labs, CR

Re: EXT4 IOPS degradation between 4.14 and 5.10

[Jan Kara]

On Thu 26-01-23 10:23:07, Bhatnagar, Rishabh wrote:
> On 1/26/23 1:32 AM, Jan Kara wrote:
> > On Wed 25-01-23 16:33:54, Bhatnagar, Rishabh wrote:
> > > Fio with buffered io/fsync=1/randwrite
> > So I'm curious. Do you have any workload that actually does these
> > synchronous random buffered IOs? Or is it just a benchmarking exercise?
> > 
> So database team was a running benchmark called hammerdb with 16 connections
> where they started noticing dropped
> performance for 5.10. We traced it back to filesystem with this benchmark.
> Although the database workload would be something similar
>  I guess.

HammerDB is a TPC-C and TPC-H benchmark but details of the IO depend more
on the database it is hammering. Do you know which one? Anyway the most
important fact for me is that it is visible in a real world workload (well,
as much as DB benchmarking is real-world ;)).

> > > With HEAD as 9c19a9cb1642c074aa8bc7693cd4c038643960ae (with the above
> > > series)
> > > 
> > > write: io=445360KB, bw=7418.6KB/s, *iops=463*, runt= 60033msec
> > > clat (usec): min=4, max=32132, avg=311.90, stdev=1812.74
> > > lat (usec): min=5, max=32132, avg=312.28, stdev=1812.74
> > > clat percentiles (usec):
> > > | 1.00th=[ 8], 5.00th=[ 10], 10.00th=[ 16], 20.00th=[ 25],
> > > | 30.00th=[ 36], 40.00th=[ 47], 50.00th=[ 60], 60.00th=[ 71],
> > > | 70.00th=[ 84], 80.00th=[ 97], 90.00th=[ 111], 95.00th=[ 118],
> > > | 99.00th=[11840], 99.50th=[15936], 99.90th=[21888], 99.95th=[23936],
> > > 
> > > With HEAD as 6b4c54e3787bc03e810062bd257a3b05fd9c72d6(without the above
> > > series)
> > > 
> > > write: io=455184KB, bw=7583.4KB/s, *iops=473*, runt= 60024msec
> > > clat (usec): min=6, max=24325, avg=319.72, stdev=1694.52
> > > lat (usec): min=6, max=24326, avg=319.99, stdev=1694.53
> > > clat percentiles (usec):
> > > | 1.00th=[ 9], 5.00th=[ 11], 10.00th=[ 17], 20.00th=[ 26],
> > > | 30.00th=[ 38], 40.00th=[ 50], 50.00th=[ 60], 60.00th=[ 73],
> > > | 70.00th=[ 85], 80.00th=[ 98], 90.00th=[ 111], 95.00th=[ 118],
> > > | 99.00th=[ 9792], 99.50th=[14016], 99.90th=[21888], 99.95th=[22400],
> > > | 99.99th=[24192]
> > OK, about 2% regression. How stable is that across multiple runs?
> This is quite consistent. The thing to note here is this test is on 4.14+
> tip with and without
> these patch series.
> I tried reverting to the same behavior in 5.10 with the following patch but
> i only see a very low improvement. (~1%)

I see. Thanks for experiments.

> This is because on 5.10 we also have this patch
> ext4: avoid unnecessary transaction starts during writeback. (This limits
> the invocation of this function within the while loop)
> If i revert the above patch as well along with applying below patch i get
> back around 4% IOPS.
> 
> -       if (end == (pgoff_t)-1)
> -               *index = (pgoff_t)-1;
> -       else
> -               *index = end + 1;
> +       if (xas.xa_index > end) {
> +               if (end == (pgoff_t)-1)
> +                       *index = (pgoff_t)-1;
> +               else
> +                       *index = end + 1;
> +       }
> +       else if (ret)
> +               *index = xas.xa_index + 1;

Yes, so these patches have kind of magnifying effect together as each
multiplies the number of scanning by 2. So with both of them we get like 4
scans of the inode for dirty pages in one writeback round instead of 1.

> > > I also see that number of handles per transaction were much higher before
> > > this patch series
> > > 
> > > 0ms waiting for transaction
> > > 0ms request delay
> > > 20ms running transaction
> > > 0ms transaction was being locked
> > > 0ms flushing data (in ordered mode)
> > > 10ms logging transaction
> > > *13524us average transaction commit time*
> > > *73 handles per transaction*
> > > 0 blocks per transaction
> > > 1 logged blocks per transaction
> > > 
> > > vs after the patch series.
> > > 
> > > 0ms waiting for transaction
> > > 0ms request delay
> > > 20ms running transaction
> > > 0ms transaction was being locked
> > > 0ms flushing data (in ordered mode)
> > > 20ms logging transaction
> > > *21468us average transaction commit time*
> > > *66 handles per transaction*
> > > 1 blocks per transaction
> > > 1 logged blocks per transaction
> > > 
> > > This is probably again helping in bunching the writeback transactions and
> > > increasing throughput.
> > Yeah, probably.
> > 
> > > I looked at the code to understand what might be going on.
> > > It seems like commit 72b045aecdd856b083521f2a963705b4c2e59680 changes the
> > > behavior of find_get_pages_range_tag.
> > > Before this commit if find_get_pages_tag cannot find nr_pages (PAGEVEC_SIZE)
> > > it returns the number of pages found as ret and
> > > sets the *index to the last page it found + 1. After the commit the behavior
> > > changes such that if we don’t find nr_pages pages
> > > we set the index to end and not to the last found page. (added diff from
> > > above commit)
> > > Since pagevec_lookup_range_tag is always called in a while loop (index <=
> > > end) the code before the commit helps in coalescing
> > > writeback of pages if there are multiple threads doing write as it might
> > > keep finding new dirty (tagged) pages since it doesn’t set index to end.
> > > 
> > > + /*
> > > + * We come here when we got at @end. We take care to not overflow the
> > > + * index @index as it confuses some of the callers. This breaks the
> > > + * iteration when there is page at index -1 but that is already broken
> > > + * anyway.
> > > + */
> > > + if (end == (pgoff_t)-1)
> > > + *index = (pgoff_t)-1;
> > > + else
> > > + *index = end + 1;
> > > +out:
> > > rcu_read_unlock();
> > > 
> > > - if (ret)
> > > - *index = pages[ret - 1]->index + 1;
> > > -
> > > 
> > >  From the description of the patch i didn't see any mention of this
> > > functional change.
> > > Was this change intentional and did help some usecase or general performance
> > > improvement?
> > So the change was intentional. When I was working on the series, I was
> > somewhat concerned that the old code could end up in a pathological
> > situation like:
> >    We scan range 0-1000000, find the only dirty page at index 0, return it.
> >    We scan range 1-1000000, find the only dirty page at index 1, return it.
> >    ...
> > 
> > This way we end up with rather inefficient scanning and in theory malicious
> > user could livelock writeback like this. That being said this was/is mostly
> > a theoretical concern.
> 
> Ok so its more of a security concern. But do you think this has a latency
> impact? I didn't see
> much latency impact between the two sets and throughput is higher.

Yes, I expect there will be latency impact but for this workload probably
relatively small. I expect the expensive part on your workload is the
fsync(2) call, in particular the committing of the transaction and the
flushing of the disk caches as a result of that. Data writes themselves are
relatively cheap. If you had say 1MB blocks instead of 16k ones, I'd expect
the numbers to start looking differently as the cost of IO and of cache
flushing becomes for comparable - obviously it all depends on the details
of the backing storage as well. Perhaps could you measure how much time we
spend in file_write_and_wait_range() calls vs in the whole ext4_sync_file()
call to confirm that?

Overall your tests show we could gain some throughput without sacrificing
too much latency if we somehow batch tiny fsync requests more. The trick is
how to do this without regressing other workloads and also across various
storage types which are going to have very different properties.

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: EXT4 IOPS degradation between 4.14 and 5.10

[Bhatnagar, Rishabh]

On 1/27/23 4:17 AM, Jan Kara wrote:
> CAUTION: This email originated from outside of the organization. Do not click links or open attachments unless you can confirm the sender and know the content is safe.
>
>
>
> On Thu 26-01-23 10:23:07, Bhatnagar, Rishabh wrote:
>> On 1/26/23 1:32 AM, Jan Kara wrote:
>>> On Wed 25-01-23 16:33:54, Bhatnagar, Rishabh wrote:
>>>> Fio with buffered io/fsync=1/randwrite
>>> So I'm curious. Do you have any workload that actually does these
>>> synchronous random buffered IOs? Or is it just a benchmarking exercise?
>>>
>> So database team was a running benchmark called hammerdb with 16 connections
>> where they started noticing dropped
>> performance for 5.10. We traced it back to filesystem with this benchmark.
>> Although the database workload would be something similar
>>   I guess.
> HammerDB is a TPC-C and TPC-H benchmark but details of the IO depend more
> on the database it is hammering. Do you know which one? Anyway the most
> important fact for me is that it is visible in a real world workload (well,
> as much as DB benchmarking is real-world ;)).
I believe its the MySQL database though not so sure.
>
>>>> With HEAD as 9c19a9cb1642c074aa8bc7693cd4c038643960ae (with the above
>>>> series)
>>>>
>>>> write: io=445360KB, bw=7418.6KB/s, *iops=463*, runt= 60033msec
>>>> clat (usec): min=4, max=32132, avg=311.90, stdev=1812.74
>>>> lat (usec): min=5, max=32132, avg=312.28, stdev=1812.74
>>>> clat percentiles (usec):
>>>> | 1.00th=[ 8], 5.00th=[ 10], 10.00th=[ 16], 20.00th=[ 25],
>>>> | 30.00th=[ 36], 40.00th=[ 47], 50.00th=[ 60], 60.00th=[ 71],
>>>> | 70.00th=[ 84], 80.00th=[ 97], 90.00th=[ 111], 95.00th=[ 118],
>>>> | 99.00th=[11840], 99.50th=[15936], 99.90th=[21888], 99.95th=[23936],
>>>>
>>>> With HEAD as 6b4c54e3787bc03e810062bd257a3b05fd9c72d6(without the above
>>>> series)
>>>>
>>>> write: io=455184KB, bw=7583.4KB/s, *iops=473*, runt= 60024msec
>>>> clat (usec): min=6, max=24325, avg=319.72, stdev=1694.52
>>>> lat (usec): min=6, max=24326, avg=319.99, stdev=1694.53
>>>> clat percentiles (usec):
>>>> | 1.00th=[ 9], 5.00th=[ 11], 10.00th=[ 17], 20.00th=[ 26],
>>>> | 30.00th=[ 38], 40.00th=[ 50], 50.00th=[ 60], 60.00th=[ 73],
>>>> | 70.00th=[ 85], 80.00th=[ 98], 90.00th=[ 111], 95.00th=[ 118],
>>>> | 99.00th=[ 9792], 99.50th=[14016], 99.90th=[21888], 99.95th=[22400],
>>>> | 99.99th=[24192]
>>> OK, about 2% regression. How stable is that across multiple runs?
>> This is quite consistent. The thing to note here is this test is on 4.14+
>> tip with and without
>> these patch series.
>> I tried reverting to the same behavior in 5.10 with the following patch but
>> i only see a very low improvement. (~1%)
> I see. Thanks for experiments.
>
>> This is because on 5.10 we also have this patch
>> ext4: avoid unnecessary transaction starts during writeback. (This limits
>> the invocation of this function within the while loop)
>> If i revert the above patch as well along with applying below patch i get
>> back around 4% IOPS.
>>
>> -       if (end == (pgoff_t)-1)
>> -               *index = (pgoff_t)-1;
>> -       else
>> -               *index = end + 1;
>> +       if (xas.xa_index > end) {
>> +               if (end == (pgoff_t)-1)
>> +                       *index = (pgoff_t)-1;
>> +               else
>> +                       *index = end + 1;
>> +       }
>> +       else if (ret)
>> +               *index = xas.xa_index + 1;
> Yes, so these patches have kind of magnifying effect together as each
> multiplies the number of scanning by 2. So with both of them we get like 4
> scans of the inode for dirty pages in one writeback round instead of 1.
>
>>>> I also see that number of handles per transaction were much higher before
>>>> this patch series
>>>>
>>>> 0ms waiting for transaction
>>>> 0ms request delay
>>>> 20ms running transaction
>>>> 0ms transaction was being locked
>>>> 0ms flushing data (in ordered mode)
>>>> 10ms logging transaction
>>>> *13524us average transaction commit time*
>>>> *73 handles per transaction*
>>>> 0 blocks per transaction
>>>> 1 logged blocks per transaction
>>>>
>>>> vs after the patch series.
>>>>
>>>> 0ms waiting for transaction
>>>> 0ms request delay
>>>> 20ms running transaction
>>>> 0ms transaction was being locked
>>>> 0ms flushing data (in ordered mode)
>>>> 20ms logging transaction
>>>> *21468us average transaction commit time*
>>>> *66 handles per transaction*
>>>> 1 blocks per transaction
>>>> 1 logged blocks per transaction
>>>>
>>>> This is probably again helping in bunching the writeback transactions and
>>>> increasing throughput.
>>> Yeah, probably.
>>>
>>>> I looked at the code to understand what might be going on.
>>>> It seems like commit 72b045aecdd856b083521f2a963705b4c2e59680 changes the
>>>> behavior of find_get_pages_range_tag.
>>>> Before this commit if find_get_pages_tag cannot find nr_pages (PAGEVEC_SIZE)
>>>> it returns the number of pages found as ret and
>>>> sets the *index to the last page it found + 1. After the commit the behavior
>>>> changes such that if we don’t find nr_pages pages
>>>> we set the index to end and not to the last found page. (added diff from
>>>> above commit)
>>>> Since pagevec_lookup_range_tag is always called in a while loop (index <=
>>>> end) the code before the commit helps in coalescing
>>>> writeback of pages if there are multiple threads doing write as it might
>>>> keep finding new dirty (tagged) pages since it doesn’t set index to end.
>>>>
>>>> + /*
>>>> + * We come here when we got at @end. We take care to not overflow the
>>>> + * index @index as it confuses some of the callers. This breaks the
>>>> + * iteration when there is page at index -1 but that is already broken
>>>> + * anyway.
>>>> + */
>>>> + if (end == (pgoff_t)-1)
>>>> + *index = (pgoff_t)-1;
>>>> + else
>>>> + *index = end + 1;
>>>> +out:
>>>> rcu_read_unlock();
>>>>
>>>> - if (ret)
>>>> - *index = pages[ret - 1]->index + 1;
>>>> -
>>>>
>>>>   From the description of the patch i didn't see any mention of this
>>>> functional change.
>>>> Was this change intentional and did help some usecase or general performance
>>>> improvement?
>>> So the change was intentional. When I was working on the series, I was
>>> somewhat concerned that the old code could end up in a pathological
>>> situation like:
>>>     We scan range 0-1000000, find the only dirty page at index 0, return it.
>>>     We scan range 1-1000000, find the only dirty page at index 1, return it.
>>>     ...
>>>
>>> This way we end up with rather inefficient scanning and in theory malicious
>>> user could livelock writeback like this. That being said this was/is mostly
>>> a theoretical concern.
>> Ok so its more of a security concern. But do you think this has a latency
>> impact? I didn't see
>> much latency impact between the two sets and throughput is higher.
> Yes, I expect there will be latency impact but for this workload probably
> relatively small. I expect the expensive part on your workload is the
> fsync(2) call, in particular the committing of the transaction and the
> flushing of the disk caches as a result of that. Data writes themselves are
> relatively cheap. If you had say 1MB blocks instead of 16k ones, I'd expect
> the numbers to start looking differently as the cost of IO and of cache
> flushing becomes for comparable - obviously it all depends on the details
> of the backing storage as well. Perhaps could you measure how much time we
> spend in file_write_and_wait_range() calls vs in the whole ext4_sync_file()
> call to confirm that?
>
> Overall your tests show we could gain some throughput without sacrificing
> too much latency if we somehow batch tiny fsync requests more. The trick is
> how to do this without regressing other workloads and also across various
> storage types which are going to have very different properties.
>
>                                                                  Honza
> --
> Jan Kara <jack@suse.com>
> SUSE Labs, CR

Yeah i agree fsync is much more expensive operation than just dirtying 
buffers in page cache.
I did use the ext4dist tool from bcc to get the distribution of write vs 
fsync.
Overall fsync is much more expensive operation so yeah if we can get 
higher throughput here with batching
it shouldn't impact fsync latency that much.

operation = write
      usecs               : count     distribution
          0 -> 1          : 0 |                                        |
          2 -> 3          : 0 |                                        |
          4 -> 7          : 84 |                                        |
          8 -> 15         : 1833 |************                            |
         16 -> 31         : 3148 |********************                    |
         32 -> 63         : 4149 |***************************             |
         64 -> 127        : 6083 |****************************************|
        128 -> 255        : 46 |                                        |
        256 -> 511        : 0 |                                        |
        512 -> 1023       : 6 |                                        |
       1024 -> 2047       : 63 |                                        |
       2048 -> 4095       : 44 |                                        |
       4096 -> 8191       : 190 |*                                       |
       8192 -> 16383      : 191 |*                                       |
      16384 -> 32767      : 201 |*                                       |
      32768 -> 65535      : 43 |                                        |

operation = fsync
      usecs               : count     distribution
          0 -> 1          : 0 |                                        |
          2 -> 3          : 0 |                                        |
          4 -> 7          : 0 |                                        |
          8 -> 15         : 0 |                                        |
         16 -> 31         : 0 |                                        |
         32 -> 63         : 0 |                                        |
         64 -> 127        : 0 |                                        |
        128 -> 255        : 0 |                                        |
        256 -> 511        : 1 |                                        |
        512 -> 1023       : 27 |                                        |
       1024 -> 2047       : 62 |                                        |
       2048 -> 4095       : 212 |*                                       |
       4096 -> 8191       : 56 |                                        |
       8192 -> 16383      : 94 |                                        |
      16384 -> 32767      : 1070 |*****                                   |
      32768 -> 65535      : 7649 |****************************************|
      65536 -> 131071     : 6901 |************************************    |

Re: EXT4 IOPS degradation between 4.14 and 5.10

[Jan Kara]

On Mon 30-01-23 09:45:32, Bhatnagar, Rishabh wrote:
> 
> On 1/27/23 4:17 AM, Jan Kara wrote:
> > CAUTION: This email originated from outside of the organization. Do not click links or open attachments unless you can confirm the sender and know the content is safe.
> > 
> > 
> > 
> > On Thu 26-01-23 10:23:07, Bhatnagar, Rishabh wrote:
> > > On 1/26/23 1:32 AM, Jan Kara wrote:
> > > > On Wed 25-01-23 16:33:54, Bhatnagar, Rishabh wrote:
> > > > > Fio with buffered io/fsync=1/randwrite
> > > > So I'm curious. Do you have any workload that actually does these
> > > > synchronous random buffered IOs? Or is it just a benchmarking exercise?
> > > > 
> > > So database team was a running benchmark called hammerdb with 16 connections
> > > where they started noticing dropped
> > > performance for 5.10. We traced it back to filesystem with this benchmark.
> > > Although the database workload would be something similar
> > >   I guess.
> > HammerDB is a TPC-C and TPC-H benchmark but details of the IO depend more
> > on the database it is hammering. Do you know which one? Anyway the most
> > important fact for me is that it is visible in a real world workload (well,
> > as much as DB benchmarking is real-world ;)).
> I believe its the MySQL database though not so sure.

Well, in that case I think your MySQL DB is somewhat misconfigured. At
least as far as we have been consulting MySQL / MariaDB developers
regarding benchmarking, they suggested we should configure the database to
use direct IO and increase DB internal buffers instead of relying on
buffered IO and pagecache behavior. And if your fio job is representative
of the IO load the DB really creates, I'd agree that that would be a saner
and likely more performant configuration ;)

> > > > > + /*
> > > > > + * We come here when we got at @end. We take care to not overflow the
> > > > > + * index @index as it confuses some of the callers. This breaks the
> > > > > + * iteration when there is page at index -1 but that is already broken
> > > > > + * anyway.
> > > > > + */
> > > > > + if (end == (pgoff_t)-1)
> > > > > + *index = (pgoff_t)-1;
> > > > > + else
> > > > > + *index = end + 1;
> > > > > +out:
> > > > > rcu_read_unlock();
> > > > > 
> > > > > - if (ret)
> > > > > - *index = pages[ret - 1]->index + 1;
> > > > > -
> > > > > 
> > > > >   From the description of the patch i didn't see any mention of this
> > > > > functional change.
> > > > > Was this change intentional and did help some usecase or general performance
> > > > > improvement?
> > > > So the change was intentional. When I was working on the series, I was
> > > > somewhat concerned that the old code could end up in a pathological
> > > > situation like:
> > > >     We scan range 0-1000000, find the only dirty page at index 0, return it.
> > > >     We scan range 1-1000000, find the only dirty page at index 1, return it.
> > > >     ...
> > > > 
> > > > This way we end up with rather inefficient scanning and in theory malicious
> > > > user could livelock writeback like this. That being said this was/is mostly
> > > > a theoretical concern.
> > > Ok so its more of a security concern. But do you think this has a latency
> > > impact? I didn't see
> > > much latency impact between the two sets and throughput is higher.
> > Yes, I expect there will be latency impact but for this workload probably
> > relatively small. I expect the expensive part on your workload is the
> > fsync(2) call, in particular the committing of the transaction and the
> > flushing of the disk caches as a result of that. Data writes themselves are
> > relatively cheap. If you had say 1MB blocks instead of 16k ones, I'd expect
> > the numbers to start looking differently as the cost of IO and of cache
> > flushing becomes for comparable - obviously it all depends on the details
> > of the backing storage as well. Perhaps could you measure how much time we
> > spend in file_write_and_wait_range() calls vs in the whole ext4_sync_file()
> > call to confirm that?
> > 
> > Overall your tests show we could gain some throughput without sacrificing
> > too much latency if we somehow batch tiny fsync requests more. The trick is
> > how to do this without regressing other workloads and also across various
> > storage types which are going to have very different properties.
> 
> Yeah i agree fsync is much more expensive operation than just dirtying
> buffers in page cache.  I did use the ext4dist tool from bcc to get the
> distribution of write vs fsync.  Overall fsync is much more expensive
> operation so yeah if we can get higher throughput here with batching it
> shouldn't impact fsync latency that much.

Well, I was more interested in file_write_and_wait_range() vs
ext4_sync_file() latency comparison. write(2) calls are indeed very fast
because they just copy into the page cache so that is not very interesting.
But file_write_and_wait_range() is more interesting because that measures
the cost of writing file data to the disk while whole ext4_sync_file()
measures the cost of writing file data to the disk + the cost of flushing
the journal and I'm interested in how much is the flushing of the journal
costly compared to the data writeback.

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: EXT4 IOPS degradation between 4.14 and 5.10

[Bhatnagar, Rishabh]

On 2/8/23 6:02 AM, Jan Kara wrote:
> CAUTION: This email originated from outside of the organization. Do not click links or open attachments unless you can confirm the sender and know the content is safe.
>
>
>
> On Mon 30-01-23 09:45:32, Bhatnagar, Rishabh wrote:
>> On 1/27/23 4:17 AM, Jan Kara wrote:
>>> CAUTION: This email originated from outside of the organization. Do not click links or open attachments unless you can confirm the sender and know the content is safe.
>>>
>>>
>>>
>>> On Thu 26-01-23 10:23:07, Bhatnagar, Rishabh wrote:
>>>> On 1/26/23 1:32 AM, Jan Kara wrote:
>>>>> On Wed 25-01-23 16:33:54, Bhatnagar, Rishabh wrote:
>>>>>> Fio with buffered io/fsync=1/randwrite
>>>>> So I'm curious. Do you have any workload that actually does these
>>>>> synchronous random buffered IOs? Or is it just a benchmarking exercise?
>>>>>
>>>> So database team was a running benchmark called hammerdb with 16 connections
>>>> where they started noticing dropped
>>>> performance for 5.10. We traced it back to filesystem with this benchmark.
>>>> Although the database workload would be something similar
>>>>    I guess.
>>> HammerDB is a TPC-C and TPC-H benchmark but details of the IO depend more
>>> on the database it is hammering. Do you know which one? Anyway the most
>>> important fact for me is that it is visible in a real world workload (well,
>>> as much as DB benchmarking is real-world ;)).
>> I believe its the MySQL database though not so sure.
> Well, in that case I think your MySQL DB is somewhat misconfigured. At
> least as far as we have been consulting MySQL / MariaDB developers
> regarding benchmarking, they suggested we should configure the database to
> use direct IO and increase DB internal buffers instead of relying on
> buffered IO and pagecache behavior. And if your fio job is representative
> of the IO load the DB really creates, I'd agree that that would be a saner
> and likely more performant configuration ;)
>
>>>>>> + /*
>>>>>> + * We come here when we got at @end. We take care to not overflow the
>>>>>> + * index @index as it confuses some of the callers. This breaks the
>>>>>> + * iteration when there is page at index -1 but that is already broken
>>>>>> + * anyway.
>>>>>> + */
>>>>>> + if (end == (pgoff_t)-1)
>>>>>> + *index = (pgoff_t)-1;
>>>>>> + else
>>>>>> + *index = end + 1;
>>>>>> +out:
>>>>>> rcu_read_unlock();
>>>>>>
>>>>>> - if (ret)
>>>>>> - *index = pages[ret - 1]->index + 1;
>>>>>> -
>>>>>>
>>>>>>    From the description of the patch i didn't see any mention of this
>>>>>> functional change.
>>>>>> Was this change intentional and did help some usecase or general performance
>>>>>> improvement?
>>>>> So the change was intentional. When I was working on the series, I was
>>>>> somewhat concerned that the old code could end up in a pathological
>>>>> situation like:
>>>>>      We scan range 0-1000000, find the only dirty page at index 0, return it.
>>>>>      We scan range 1-1000000, find the only dirty page at index 1, return it.
>>>>>      ...
>>>>>
>>>>> This way we end up with rather inefficient scanning and in theory malicious
>>>>> user could livelock writeback like this. That being said this was/is mostly
>>>>> a theoretical concern.
>>>> Ok so its more of a security concern. But do you think this has a latency
>>>> impact? I didn't see
>>>> much latency impact between the two sets and throughput is higher.
>>> Yes, I expect there will be latency impact but for this workload probably
>>> relatively small. I expect the expensive part on your workload is the
>>> fsync(2) call, in particular the committing of the transaction and the
>>> flushing of the disk caches as a result of that. Data writes themselves are
>>> relatively cheap. If you had say 1MB blocks instead of 16k ones, I'd expect
>>> the numbers to start looking differently as the cost of IO and of cache
>>> flushing becomes for comparable - obviously it all depends on the details
>>> of the backing storage as well. Perhaps could you measure how much time we
>>> spend in file_write_and_wait_range() calls vs in the whole ext4_sync_file()
>>> call to confirm that?
>>>
>>> Overall your tests show we could gain some throughput without sacrificing
>>> too much latency if we somehow batch tiny fsync requests more. The trick is
>>> how to do this without regressing other workloads and also across various
>>> storage types which are going to have very different properties.
>> Yeah i agree fsync is much more expensive operation than just dirtying
>> buffers in page cache.  I did use the ext4dist tool from bcc to get the
>> distribution of write vs fsync.  Overall fsync is much more expensive
>> operation so yeah if we can get higher throughput here with batching it
>> shouldn't impact fsync latency that much.
> Well, I was more interested in file_write_and_wait_range() vs
> ext4_sync_file() latency comparison. write(2) calls are indeed very fast
> because they just copy into the page cache so that is not very interesting.
> But file_write_and_wait_range() is more interesting because that measures
> the cost of writing file data to the disk while whole ext4_sync_file()
> measures the cost of writing file data to the disk + the cost of flushing
> the journal and I'm interested in how much is the flushing of the journal
> costly compared to the data writeback.

Sorry i misunderstood your comment. Here is the revised data. Flushing 
journal
very heavy compared to flushing data.

ext4_sync_file:       ~18.6 msecs
fdatawrite_range:   ~ 4usecs
fdatawait_range:     ~ 83.6usecs
fc_commit:             ~18.6 msecs

Tracing 1 functions for "ext4_sync_file"


      nsecs               : count     distribution
    1048576 -> 2097151    : 75 |                                        |
    2097152 -> 4194303    : 1496 |****                                    |
    4194304 -> 8388607    : 3461 |**********                              |
    8388608 -> 16777215   : 6693 |********************                    |
   16777216 -> 33554431   : 13355 |****************************************|
   33554432 -> 67108863   : 1631 |****                                    |

avg = 18624922 nsecs, total: 505778389231 nsecs, count: 27156


Tracing 1 functions for "__filemap_fdatawrite_range"

      nsecs               : count     distribution
        512 -> 1023       : 0 |                                        |
       1024 -> 2047       : 1 |**                                      |
       2048 -> 4095       : 14 |****************************************|
       4096 -> 8191       : 5 |**************                          |
       8192 -> 16383      : 1 |**                                      |

avg = 3943 nsecs, total: 82809 nsecs, count: 21

Tracing 1 functions for "__filemap_fdatawait_range

      nsecs               : count     distribution
        128 -> 255        : 0 |                                        |
        256 -> 511        : 1 |********************                    |
        512 -> 1023       : 2 |****************************************|
       1024 -> 2047       : 2 |****************************************|
       2048 -> 4095       : 0 |                                        |
       4096 -> 8191       : 0 |                                        |
       8192 -> 16383      : 0 |                                        |
      16384 -> 32767      : 0 |                                        |
      32768 -> 65535      : 0 |                                        |
      65536 -> 131071     : 0 |                                        |
     131072 -> 262143     : 0 |                                        |
     262144 -> 524287     : 1 |********************                    |

avg = 83644 nsecs, total: 501866 nsecs, count: 6

Tracing 1 functions for "ext4_fc_commit

      nsecs               : count     distribution
    1048576 -> 2097151    : 70 |                                        |
    2097152 -> 4194303    : 1512 |****                                    |
    4194304 -> 8388607    : 3436 |**********                              |
    8388608 -> 16777215   : 6699 |********************                    |
   16777216 -> 33554431   : 13349 |****************************************|
   33554432 -> 67108863   : 1641 |****                                    |

avg = 18622010 nsecs, total: 505699318966 nsecs, count: 27156

Thanks
Rishabh

>
>                                                                  Honza
> --
> Jan Kara <jack@suse.com>
> SUSE Labs, CR

Re: EXT4 IOPS degradation between 4.14 and 5.10

[Theodore Ts'o]

On Wed, Feb 08, 2023 at 03:02:47PM +0100, Jan Kara wrote:
> > I believe its the MySQL database though not so sure.
> 
> Well, in that case I think your MySQL DB is somewhat misconfigured. At
> least as far as we have been consulting MySQL / MariaDB developers
> regarding benchmarking, they suggested we should configure the database to
> use direct IO and increase DB internal buffers instead of relying on
> buffered IO and pagecache behavior. And if your fio job is representative
> of the IO load the DB really creates, I'd agree that that would be a saner
> and likely more performant configuration ;)

Could it possibly be Postgres?  I happen to know that Amazon RDS and
Google Cloud SQL support both MySQL and Postgres, and there are some
optimizations that some of us in the Cloud space have been pursuing
which are much easier because MySQL uses Direct I/O, but unfortunately
Postgres uses buffered I/O and doens't support DIO.  :-(

							- Ted

Re: EXT4 IOPS degradation between 4.14 and 5.10

[Jan Kara]

On Wed 08-02-23 11:17:21, Bhatnagar, Rishabh wrote:
> > > > > > > + /*
> > > > > > > + * We come here when we got at @end. We take care to not overflow the
> > > > > > > + * index @index as it confuses some of the callers. This breaks the
> > > > > > > + * iteration when there is page at index -1 but that is already broken
> > > > > > > + * anyway.
> > > > > > > + */
> > > > > > > + if (end == (pgoff_t)-1)
> > > > > > > + *index = (pgoff_t)-1;
> > > > > > > + else
> > > > > > > + *index = end + 1;
> > > > > > > +out:
> > > > > > > rcu_read_unlock();
> > > > > > > 
> > > > > > > - if (ret)
> > > > > > > - *index = pages[ret - 1]->index + 1;
> > > > > > > -
> > > > > > > 
> > > > > > >    From the description of the patch i didn't see any mention of this
> > > > > > > functional change.
> > > > > > > Was this change intentional and did help some usecase or general performance
> > > > > > > improvement?
> > > > > > So the change was intentional. When I was working on the series, I was
> > > > > > somewhat concerned that the old code could end up in a pathological
> > > > > > situation like:
> > > > > >      We scan range 0-1000000, find the only dirty page at index 0, return it.
> > > > > >      We scan range 1-1000000, find the only dirty page at index 1, return it.
> > > > > >      ...
> > > > > > 
> > > > > > This way we end up with rather inefficient scanning and in theory malicious
> > > > > > user could livelock writeback like this. That being said this was/is mostly
> > > > > > a theoretical concern.
> > > > > Ok so its more of a security concern. But do you think this has a latency
> > > > > impact? I didn't see
> > > > > much latency impact between the two sets and throughput is higher.
> > > > Yes, I expect there will be latency impact but for this workload probably
> > > > relatively small. I expect the expensive part on your workload is the
> > > > fsync(2) call, in particular the committing of the transaction and the
> > > > flushing of the disk caches as a result of that. Data writes themselves are
> > > > relatively cheap. If you had say 1MB blocks instead of 16k ones, I'd expect
> > > > the numbers to start looking differently as the cost of IO and of cache
> > > > flushing becomes for comparable - obviously it all depends on the details
> > > > of the backing storage as well. Perhaps could you measure how much time we
> > > > spend in file_write_and_wait_range() calls vs in the whole ext4_sync_file()
> > > > call to confirm that?
> > > > 
> > > > Overall your tests show we could gain some throughput without sacrificing
> > > > too much latency if we somehow batch tiny fsync requests more. The trick is
> > > > how to do this without regressing other workloads and also across various
> > > > storage types which are going to have very different properties.
> > > Yeah i agree fsync is much more expensive operation than just dirtying
> > > buffers in page cache.  I did use the ext4dist tool from bcc to get the
> > > distribution of write vs fsync.  Overall fsync is much more expensive
> > > operation so yeah if we can get higher throughput here with batching it
> > > shouldn't impact fsync latency that much.
> > Well, I was more interested in file_write_and_wait_range() vs
> > ext4_sync_file() latency comparison. write(2) calls are indeed very fast
> > because they just copy into the page cache so that is not very interesting.
> > But file_write_and_wait_range() is more interesting because that measures
> > the cost of writing file data to the disk while whole ext4_sync_file()
> > measures the cost of writing file data to the disk + the cost of flushing
> > the journal and I'm interested in how much is the flushing of the journal
> > costly compared to the data writeback.
> 
> Sorry i misunderstood your comment. Here is the revised data. Flushing
> journal very heavy compared to flushing data.
> 
> ext4_sync_file:       ~18.6 msecs
> fdatawrite_range:   ~ 4usecs
> fdatawait_range:     ~ 83.6usecs
> fc_commit:             ~18.6 msecs
> 
> Tracing 1 functions for "ext4_sync_file"
> 
> 
>      nsecs               : count     distribution
>    1048576 -> 2097151    : 75 |                                        |
>    2097152 -> 4194303    : 1496 |****                                    |
>    4194304 -> 8388607    : 3461 |**********                              |
>    8388608 -> 16777215   : 6693 |********************                    |
>   16777216 -> 33554431   : 13355 |****************************************|
>   33554432 -> 67108863   : 1631 |****                                    |
> 
> avg = 18624922 nsecs, total: 505778389231 nsecs, count: 27156
> 
> 
> Tracing 1 functions for "__filemap_fdatawrite_range"
> 
>      nsecs               : count     distribution
>        512 -> 1023       : 0 |                                        |
>       1024 -> 2047       : 1 |**                                      |
>       2048 -> 4095       : 14 |****************************************|
>       4096 -> 8191       : 5 |**************                          |
>       8192 -> 16383      : 1 |**                                      |
> 
> avg = 3943 nsecs, total: 82809 nsecs, count: 21
> 
> Tracing 1 functions for "__filemap_fdatawait_range
> 
>      nsecs               : count     distribution
>        128 -> 255        : 0 |                                        |
>        256 -> 511        : 1 |********************                    |
>        512 -> 1023       : 2 |****************************************|
>       1024 -> 2047       : 2 |****************************************|
>       2048 -> 4095       : 0 |                                        |
>       4096 -> 8191       : 0 |                                        |
>       8192 -> 16383      : 0 |                                        |
>      16384 -> 32767      : 0 |                                        |
>      32768 -> 65535      : 0 |                                        |
>      65536 -> 131071     : 0 |                                        |
>     131072 -> 262143     : 0 |                                        |
>     262144 -> 524287     : 1 |********************                    |
> 
> avg = 83644 nsecs, total: 501866 nsecs, count: 6
> 
> Tracing 1 functions for "ext4_fc_commit
> 
>      nsecs               : count     distribution
>    1048576 -> 2097151    : 70 |                                        |
>    2097152 -> 4194303    : 1512 |****                                    |
>    4194304 -> 8388607    : 3436 |**********                              |
>    8388608 -> 16777215   : 6699 |********************                    |
>   16777216 -> 33554431   : 13349 |****************************************|
>   33554432 -> 67108863   : 1641 |****                                    |
> 
> avg = 18622010 nsecs, total: 505699318966 nsecs, count: 27156

Thanks for the data! So indeed as I suspected for your storage the
transaction commit (likely due to the flushing of disk caches) costs the
vast majority of time. I guess I'll try to experiment with this a bit if we
can somehow achieve more batching in ext4_sync_file()...

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR