Re: Slow file transfer speeds with CFQ IO scheduler in some cases

[Jens Axboe <jens.axboe@oracle.com>]

On Mon, Nov 10 2008, Jens Axboe wrote:
> On Mon, Nov 10 2008, Vitaly V. Bursov wrote:
> > Jens Axboe wrote:
> > > On Mon, Nov 10 2008, Vitaly V. Bursov wrote:
> > >> Jens Axboe wrote:
> > >>> On Mon, Nov 10 2008, Jeff Moyer wrote:
> > >>>> Jens Axboe <jens.axboe@oracle.com> writes:
> > >>>>
> > >>>>> http://bugzilla.kernel.org/attachment.cgi?id=18473&action=view
> > >>>> Funny, I was going to ask the same question.  ;)  The reason Jens wants
> > >>>> you to try this patch is that nfsd may be farming off the I/O requests
> > >>>> to different threads which are then performing interleaved I/O.  The
> > >>>> above patch tries to detect this and allow cooperating processes to get
> > >>>> disk time instead of waiting for the idle timeout.
> > >>> Precisely :-)
> > >>>
> > >>> The only reason I haven't merged it yet is because of worry of extra
> > >>> cost, but I'll throw some SSD love at it and see how it turns out.
> > >>>
> > >> Sorry, but I get "oops" same moment nfs read transfer starts.
> > >> I can get directory list via nfs, read files locally (not
> > >> carefully tested, though)
> > >>
> > >> Dumps captured via netconsole, so these may not be completely accurate
> > >> but hopefully will give a hint.
> > > 
> > > Interesting, strange how that hasn't triggered here. Or perhaps the
> > > version that Jeff posted isn't the one I tried. Anyway, search for:
> > > 
> > >         RB_CLEAR_NODE(&cfqq->rb_node);
> > > 
> > > and add a
> > > 
> > >         RB_CLEAR_NODE(&cfqq->prio_node);
> > > 
> > > just below that. It's in cfq_find_alloc_queue(). I think that should fix
> > > it.
> > > 
> > 
> > Same problem.
> > 
> > I did make clean; make -j3; sync; on (2 times) patched kernel and it went OK
> > but It won't boot anymore with cfq with same error...
> > 
> > Switching cfq io scheduler at runtime (booting with "as") appears to work with
> > two parallel local dd reads.
> > 
> > But when NFS server starts up:
> > 
> > [  469.000105] BUG: unable to handle kernel
> > NULL pointer dereference
> > at 0000000000000000
> > [  469.000305] IP:
> > [<ffffffff81111f2a>] rb_erase+0x124/0x290
> > ...
> > 
> > [  469.001905] Pid: 2296, comm: md1_raid5 Not tainted 2.6.27.5 #4
> > [  469.001982] RIP: 0010:[<ffffffff81111f2a>]
> > [<ffffffff81111f2a>] rb_erase+0x124/0x290
> > ...
> > [  469.002509] Call Trace:
> > [  469.002509]  [<ffffffff8110a0b9>] ? rb_erase_init+0x9/0x17
> > [  469.002509]  [<ffffffff8110a0ff>] ? cfq_prio_tree_add+0x38/0xa8
> > [  469.002509]  [<ffffffff8110b13d>] ? cfq_add_rq_rb+0xb5/0xc8
> > [  469.002509]  [<ffffffff8110b1aa>] ? cfq_insert_request+0x5a/0x356
> > [  469.002509]  [<ffffffff811000a1>] ? elv_insert+0x14b/0x218
> > [  469.002509]  [<ffffffff810ab757>] ? bio_phys_segments+0xf/0x15
> > [  469.002509]  [<ffffffff811028dc>] ? __make_request+0x3b9/0x3eb
> > [  469.002509]  [<ffffffff8110120c>] ? generic_make_request+0x30b/0x346
> > [  469.002509]  [<ffffffff811baaf4>] ? raid5_end_write_request+0x0/0xb8
> > [  469.002509]  [<ffffffff811b8ade>] ? ops_run_io+0x16a/0x1c1
> > [  469.002509]  [<ffffffff811ba534>] ? handle_stripe5+0x9b5/0x9d6
> > [  469.002509]  [<ffffffff811bbf08>] ? handle_stripe+0xc3a/0xc6a
> > [  469.002509]  [<ffffffff810296e5>] ? pick_next_task_fair+0x8d/0x9c
> > [  469.002509]  [<ffffffff81253792>] ? thread_return+0x3a/0xaa
> > [  469.002509]  [<ffffffff811bc2ce>] ? raid5d+0x396/0x3cd
> > [  469.002509]  [<ffffffff81253bd8>] ? schedule_timeout+0x1e/0xad
> > [  469.002509]  [<ffffffff811c716f>] ? md_thread+0xdd/0xf9
> > [  469.002509]  [<ffffffff81044f9c>] ? autoremove_wake_function+0x0/0x2e
> > [  469.002509]  [<ffffffff811c7092>] ? md_thread+0x0/0xf9
> > [  469.002509]  [<ffffffff81044e80>] ? kthread+0x47/0x73
> > [  469.002509]  [<ffffffff8102f867>] ? schedule_tail+0x28/0x60
> > [  469.002509]  [<ffffffff8100cda9>] ? child_rip+0xa/0x11
> > [  469.002509]  [<ffffffff81044e39>] ? kthread+0x0/0x73
> > [  469.002509]  [<ffffffff8100cd9f>] ? child_rip+0x0/0x11
> > ...
> > [  469.002509] RIP
> > [<ffffffff81111f2a>] rb_erase+0x124/0x290
> > [  469.002509]  RSP <ffff88011d4c7a58>
> > [  469.002509] CR2: 0000000000000000
> > [  469.002509] ---[ end trace acdef779aeb56048 ]---
> > 
> > 
> > "Best" result I got with NFS was
> > avg-cpu:  %user   %nice %system %iowait  %steal   %idle
> >            0,00    0,00    0,20    0,65    0,00   99,15
> > 
> > Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
> > sda              11,30     0,00    7,60    0,00   245,60     0,00    32,32     0,01    1,18   0,79   0,60
> > sdb              12,10     0,00    8,00    0,00   246,40     0,00    30,80     0,01    1,62   0,62   0,50
> > 
> > and it lasted around 30 seconds.
> 
> OK, I'll throw some NFS at this patch in the morning and do some
> measurements as well, so it can get queued up.

I spotted a bug - if the ioprio of a process gets changed, it needs to
be repositioned in the cooperator tree or we'll end up doing erase on a
wrong root. Perhaps that is what is biting you here.

-- 
Jens Axboe