Re: filesystem benchmarking fun

[Chris Mason <chris.mason@oracle.com>]

On Wed, May 16, 2007 at 01:37:26PM -0700, Andrew Morton wrote:
> On Wed, 16 May 2007 16:14:14 -0400
> Chris Mason <chris.mason@oracle.com> wrote:
> 
> > On Wed, May 16, 2007 at 01:04:13PM -0700, Andrew Morton wrote:
> > > > The good news is that if you let it run long enough, the times
> > > > stabilize.  The bad news is:
> > > > 
> > > > create dir kernel-86 222MB in 15.85 seconds (14.03 MB/s)
> > > > create dir kernel-87 222MB in 28.67 seconds (7.76 MB/s)
> > > > create dir kernel-88 222MB in 18.12 seconds (12.27 MB/s)
> > > > create dir kernel-89 222MB in 19.77 seconds (11.25 MB/s)
> > > 
> > > well hang on.  Doesn't this just mean that the first few runs were writing
> > > into pagecache and the later ones were blocking due to dirty-memory limits?
> > > 
> > > Or do you have a sync in there?
> > > 
> > There's no sync,  but if you watch vmstat you can clearly see the log
> > flushes, even when the overall create times are 11MB/s.  vmstat goes
> > 30MB/s -> 4MB/s or less, then back up to 30MB/s.
> 
> How do you know that it is a log flush rather than, say, pdflush
> hitting the blockdev inode and doing a big seeky write?

I don't...it gets especially tricky because ext3_writepage starts
a transaction, and so pdflush does hit the log flushing code too.

So, in comes systemtap.  I instrumented submit_bh to look for seeks
(defined as writes more than 16 blocks apart) when the process was
inside __log_wait_for_space.  The probe is attached, it is _really_
quick and dirty because I'm about to run out the door.

Watching vmstat, every time the __log_wait_for_space hits lots of seeks,
vmstat goes into the 2-4MB/s range.  Not a scientific match up, but
here's some sample output:

7824 ext3 done waiting for space total wrote 3155 blocks seeks 2241
7827 ext3 done waiting for space total wrote 855 blocks seeks 598
7827 ext3 done waiting for space total wrote 2547 blocks seeks 1759
7653 ext3 done waiting for space total wrote 2273 blocks seeks 1609

I also recorded the total size of each seek, 66% of them where 6000
blocks or more.

-chris

global in_process
global writers
global last
global seeks

probe kernel.function("__log_wait_for_space@fs/jbd/checkpoint.c") {
    printf("%d ext3 waiting for space\n", pid())
    p = pid()
    writers[p] = 0
    in_process[p] = 1
    last[p] = 0
    seeks[p] = 0
}

probe kernel.function("__log_wait_for_space@fs/jbd/checkpoint.c").return {
    p = pid()
    in_process[p] = 0
    printf("%d ext3 done waiting for space total wrote %d blocks seeks %d\n", p,
	  writers[p], seeks[p])
}

probe kernel.function("submit_bh") {
    p = pid()
    in_proc = in_process[p]
    if (in_proc != 0) {
	writers[p] += 1
	block = $bh->b_blocknr
	last_block = last[p]
	diff = 0
	if (last_block != 0) {
	    if (last_block < block && block - last_block > 16) {
		diff = block - last_block
	    }
	    if (last_block > block && last_block - block > 16) {
		diff = last_block - block
	    }
	}
	    
	last[p] = block
	if (diff != 0) {
	    printf("seek log write pid %d last %d this %d diff %d\n",
		       p, last_block, block, diff);
	    seeks[p] += 1
	}
    }
}