Re: fio sync read 4k block size 35% regression

[Wu Fengguang]

On Thu, Jul 02, 2009 at 11:34:20AM +0800, Zhang, Yanmin wrote:
> On Wed, 2009-07-01 at 20:50 +0800, Wu Fengguang wrote:
> > On Wed, Jul 01, 2009 at 01:03:55PM +0800, Zhang, Yanmin wrote:
> > > On Wed, 2009-07-01 at 12:10 +0800, Wu Fengguang wrote:
> > > > On Wed, Jul 01, 2009 at 11:25:33AM +0800, Zhang, Yanmin wrote:
> > > > > Comapraing with 2.6.30, fio sync read (block size 4k) has about 35% regression
> > > > > with kernel 2.6.31-rc1 ïon my stoakley machine with a JBOD (13 SCSI disks).
> > > > > 
> > > > > Every disk has 1 partition and 4 1-GB files. Start 10 processes per disk to
> > > > > do syïnc read sequentinally.
> > > > > 
> > > > > Bisected down to below patch.
> > > > > 
> > > > > 51daa88ebd8e0d437289f589af29d4b39379ea76 is first bad commit
> > > > > commit 51daa88ebd8e0d437289f589af29d4b39379ea76
> > > > > Author: Wu Fengguang <fengguang.wu@xxxxxxxxx>
> > > > > Date:   Tue Jun 16 15:31:24 2009 -0700
> > > > > 
> > > > >     readahead: remove sync/async readahead call dependency
> > > > > 
> > > > >     The readahead call scheme is error-prone in that it expects the call sites
> > > > >     to check for async readahead after doing a sync one.  I.e.
> > > > > 
> > > > >                         if (!page)
> > > > >                                 page_cache_sync_readahead();
> > > > >                         page = find_get_page();
> > > > >                         if (page && PageReadahead(page))
> > > > >                                 page_cache_async_readahead();
> > > > > 
> > > > > 
> > > > > I also test block size 64k and 128k, but they don't have regression. Perhaps
> > > > > the default read_ahead_kb is equal to 128?
> > > > > 
> > > > > Other 2 machines have no such regression. The JBODS of the 2 machines consists
> > > > > of 12 and 7 SATA/SAS disks while every disk has 2 partitions.
> > > > 
> > > > Yanmin, thanks for the tests!
> > > > 
> > > > Maybe the patch posted here can restore the performance:
> > > > 
> > > > http://lkml.org/lkml/2009/5/21/319
> > > I tried it and it doesn't help.
> > 
> > Then let's check what's happening behind the scene :)
> > 
> > Please apply the attached patch and run
> > 
> >         echo 1 > /debug/readahead/trace_enable
> >         # do benchmark
> >         echo 0 > /debug/readahead/trace_enable
> > 
> > and send the dmesg which will contain lots of lines like
> > 
> >         [   54.738105] readahead-initial0(pid=3290(zsh), dev=00:10(0:10), ino=105910(dmesg), req=0+1, ra=0+4-3, async=0) = 2
> >         [   54.751801] readahead-subsequent(pid=3290(dmesg), dev=00:10(0:10), ino=105910(dmesg), req=1+60, ra=4+8-8, async=1, miss=0) = 0
> I enlarged sys log buffer to 2MB and captured below data.

Thank you! Judging from these readahead requests, it's doing perfect
64-page IOs. So the readahead size for sdm1 is 256KB? As long as the
real IO size is 256KB, it should not create that much performance
regression.

However there are some CPU overheads caused by readahead cache hits
(the lines start with ==>). In this case, 4 processes are sequentially
reading the same file, whoever goes first and foremost will trigger
the readahead IO. Or sometimes two processes hit the PG_readahead page
almost at the same time, and submit duplicate readahead requests for
the same page(s). The duplicate efforts will be detected at radix tree
insertion time, so won't lead to duplicate IO.

That is a known issue, and should only cost a little CPU time.

Since I cannot find out the (real) problem by reasoning, can you
provide more data please?
- make sure the regression(s) disappear with 2.6.31-rc1+revert-51daa88ebd8e0
- collect some readahead traces with 2.6.31-rc1+revert-51daa88ebd8e0
- collect some blktrace data on sdm1 with 2.6.31-rc1

        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=143693+1, ra=143757+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=143757+1, ra=143821+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=143821+1, ra=143885+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=143885+1, ra=143949+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=143949+1, ra=144013+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=144013+1, ra=144077+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=144077+1, ra=144141+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=144141+1, ra=144205+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=144205+1, ra=144269+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=144269+1, ra=144333+64-64, async=1) = 64
        readahead-marker(pid=7167(fio), dev=08:c1(sdm1), ino=49156(f4), req=144333+1, ra=144397+64-64, async=1) = 64
        readahead-subsequent(pid=7167(fio), dev=08:c1(sdm1), ino=49156(f4), req=144397+1, ra=144461+64-64, async=1) = 64
        readahead-marker(pid=7102(fio), dev=08:c1(sdm1), ino=49156(f4), req=144461+1, ra=144525+64-64, async=1) = 64
        readahead-marker(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=144525+1, ra=144589+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=144589+1, ra=144653+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=144653+1, ra=144717+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=144717+1, ra=144781+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=144781+1, ra=144845+64-64, async=1) = 64
==>     readahead-marker(pid=7167(fio), dev=08:c1(sdm1), ino=49156(f4), req=144845+1, ra=144909+64-64, async=1) = 64
==>     readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=144909+1, ra=144909+128-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=144973+1, ra=145037+64-64, async=1) = 64
        readahead-marker(pid=7167(fio), dev=08:c1(sdm1), ino=49156(f4), req=145037+1, ra=145101+64-64, async=1) = 64
==>     readahead-subsequent(pid=7167(fio), dev=08:c1(sdm1), ino=49156(f4), req=145101+1, ra=145165+64-64, async=1) = 64
==>     readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=145101+1, ra=145101+128-64, async=1) = 64
==>     readahead-subsequent(pid=7167(fio), dev=08:c1(sdm1), ino=49156(f4), req=145165+1, ra=145229+64-64, async=1) = 64
==>     readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=145165+1, ra=145229+64-64, async=1) = 64
        readahead-subsequent(pid=7115(fio), dev=08:c1(sdm1), ino=49156(f4), req=145229+1, ra=145293+64-64, async=1) = 64
        readahead-marker(pid=7154(fio), dev=08:c1(sdm1), ino=49156(f4), req=145357+1, ra=145421+64-64, async=1) = 64
        readahead-subsequent(pid=7167(fio), dev=08:c1(sdm1), ino=49156(f4), req=145293+1, ra=145293+128-64, async=1) = 64

> In addition, I added new test cases to use mmap to read the files sequentionally.
> On this machine, there is about 40% regression. reverting your patch fixes it.

Does that also involves multiple processes concurrently reading the same file?
 
> On another machine with another JBOD (7 SAS disks), fio_mmap_sync_read_4k (64k/128k)
> has about 30% regression. But it's not caused by your patch. I am bisecting it on the
> 2nd machine now.

That may well related to my readahead patches.

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