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

From: Vitaly V. Bursov
Date: Mon Nov 10 2008 - 12:16:26 EST

Next message: Randy Dunlap: "Re: [PATCH][RESEND] C99 initializers for DEFINE_RATELIMIT_STATE()"
Previous message: Michael Kerrisk: "Re: [1/1] Use pid in inotify events."
In reply to: Jens Axboe: "Re: Slow file transfer speeds with CFQ IO scheduler in some cases"
Next in thread: Jens Axboe: "Re: Slow file transfer speeds with CFQ IO scheduler in some cases"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Jens Axboe wrote:
> On Mon, Nov 10 2008, Jeff Moyer wrote:
>> Jens Axboe <jens.axboe@xxxxxxxxxx> 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.

Linux 2.6.27.5

======================================
[ 618.526302] BUG: unable to handle kernel
NULL pointer dereference
at 0000000000000000
[ 618.526676] IP:
[<ffffffff81111f16>] rb_erase+0x124/0x290
[ 618.526738] PGD 11b96c067
PUD 11b96d067
PMD 0

[ 618.526856] Oops: 0000 [1]
SMP

[ 618.527020] CPU 1

[ 618.527285] Modules linked in:
nfsd
auth_rpcgss
exportfs
netconsole
ipv6
nfs
lockd
nfs_acl
sunrpc
cypress_m8
usbserial
it87
hwmon_vid
hwmon
ppdev
ehci_hcd
ohci_hcd
sg
r8169
thermal
parport_pc
processor
parport
thermal_sys

[ 618.528868] Pid: 2184, comm: md1_raid5 Not tainted 2.6.27.5 #2
[ 618.528918] RIP: 0010:[<ffffffff81111f16>]
[<ffffffff81111f16>] rb_erase+0x124/0x290
[ 618.529087] RSP: 0018:ffff88011d9c9a58 EFLAGS: 00010046
[ 618.529136] RAX: ffff88011d3d7c01 RBX: ffff88011d3d7c00 RCX: 0000000000000000
[ 618.529187] RDX: 000000002d59fabb RSI: ffff88011e44d430 RDI: 0000000000000000
[ 618.529238] RBP: ffff88011e44d430 R08: 0000000000000000 R09: ffff88011c08d8b8
[ 618.529289] R10: 000000002d59fdbb R11: 000000002d59fbbb R12: ffff88011e44d400
[ 618.529339] R13: ffff88011e44d430 R14: ffff88011e44d400 R15: 0000000000800000
[ 618.529390] FS: 00007f6c86182750(0000) GS:ffff88011f86abc0(0000) knlGS:0000000000000000
[ 618.529480] CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
[ 618.529530] CR2: 0000000000000000 CR3: 000000011b9c6000 CR4: 00000000000006e0
[ 618.529580] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 618.529631] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 618.529682] Process md1_raid5 (pid: 2184, threadinfo ffff88011d9c8000, task ffff88011fa5d8e0)
[ 618.529773] Stack:
ffff88011d3d7660
ffff88011d3d7660
ffffffff8110a0b9
ffff88011d3d7630

[ 618.529895] ffffffff8110a0ff
ffff88011d3d7630
ffff88011e44d400
ffff880119a1cc48

[ 618.530085] ffff88011d3d7630
ffff88011e44d400
ffff880119a1cc48
ffff88011d3d7678

[ 618.530154] Call Trace:
[ 618.530252] [<ffffffff8110a0b9>] ? rb_erase_init+0x9/0x17
[ 618.530303] [<ffffffff8110a0ff>] ? cfq_prio_tree_add+0x38/0xa8
[ 618.530354] [<ffffffff8110b12b>] ? cfq_add_rq_rb+0xb5/0xc8
[ 618.530404] [<ffffffff8110b198>] ? cfq_insert_request+0x5a/0x356
[ 618.530457] [<ffffffff811000a1>] ? elv_insert+0x14b/0x218
[ 618.530510] [<ffffffff810ab757>] ? bio_phys_segments+0xf/0x15
[ 618.530561] [<ffffffff811028dc>] ? __make_request+0x3b9/0x3eb
[ 618.530612] [<ffffffff8110120c>] ? generic_make_request+0x30b/0x346
[ 618.530665] [<ffffffff811baae4>] ? raid5_end_write_request+0x0/0xb8
[ 618.530716] [<ffffffff811b8ace>] ? ops_run_io+0x16a/0x1c1
[ 618.530767] [<ffffffff811ba524>] ? handle_stripe5+0x9b5/0x9d6
[ 618.530818] [<ffffffff811bbef8>] ? handle_stripe+0xc3a/0xc6a
[ 618.530870] [<ffffffff81253782>] ? thread_return+0x3a/0xaa
[ 618.530921] [<ffffffff811bc2be>] ? raid5d+0x396/0x3cd
[ 618.530972] [<ffffffff81253bc8>] ? schedule_timeout+0x1e/0xad
[ 618.531023] [<ffffffff811c715f>] ? md_thread+0xdd/0xf9
[ 618.531075] [<ffffffff81044f9c>] ? autoremove_wake_function+0x0/0x2e
[ 618.531127] [<ffffffff811c7082>] ? md_thread+0x0/0xf9
[ 618.531177] [<ffffffff81044e80>] ? kthread+0x47/0x73
[ 618.531228] [<ffffffff8102f867>] ? schedule_tail+0x28/0x60
[ 618.531279] [<ffffffff8100cda9>] ? child_rip+0xa/0x11
[ 618.531330] [<ffffffff81044e39>] ? kthread+0x0/0x73
[ 618.531380] [<ffffffff8100cd9f>] ? child_rip+0x0/0x11
[ 618.531428]
[ 618.531474]
[ 618.531521] Code:
eb
0a
48
89
4b
08
eb
04
48
89
4d
00
41
ff
c8
0f
85
7f
01
00
00
e9
5d
01
00
00
48
8b
7b
10
48
39
cf
0f
85
a5
00
00
00
48
8b
7b
08

8b
07
a8
01
75
1a
48
83
c8
01
48
89
ee
48
89
07
48
83
23
fe

[ 618.532199] RIP
[<ffffffff81111f16>] rb_erase+0x124/0x290
[ 618.532510] RSP <ffff88011d9c9a58>
[ 618.532510] CR2: 0000000000000000
[ 618.532510] ---[ end trace db64b81474e1505e ]---

======================================

[ 334.271949] BUG: unable to handle kernel
NULL pointer dereference
at 0000000000000010
[ 334.272213] IP:
[<ffffffff81111bbf>] __rb_rotate_left+0x7/0x5b
[ 334.27 PGD 11c15d067
PUD 11c140067
PMD 0

[ 334.272508] Oops: 0000 [1]
SMP

[ 334.272508] CPU 1

[ 334.272508] Modules linked in:
nfsd
auth_rpcgss
exportfs
netconsole
ipv6
nfs
lockd
nfs_acl
sunrpc
cypress_m8
usbserial
it87
hwmon_vid
hwmon
ppdev
parport_pc
ehci_hcd
ohci_hcd
thermal
parport
sg
processor
r8169
thermal_sys

[ 334.272508] Pid: 2185, comm: md1_raid5 Not tainted 2.6.27.5 #2
[ 334.272508] RIP: 0010:[<ffffffff81111bbf>]
[<ffffffff81111bbf>] __rb_rotate_left+0x7/0x5b
[ 334.272508] RSP: 0018:ffff88011d591a48 EFLAGS: 00010082
[ 334.272508] RAX: ffff88011cc20a20 RBX: ffff88011cc20a20 RCX: 0000000000000000
[ 334.272508] RDX: 0000000000000000 RSI: ffff88011f8bae30 RDI: ffff88011cc20a20
[ 334.272508] RBP: ffff88011cc20a20 R08: ffff88011cc20a20 R09: ffff88011ac6b3f8
[ 334.272508] R10: 000000002d5a237b R11: 000000002d5a30bb R12: ffff88011cc20a20
[ 334.272508] R13: 0000000000000000 R14: ffff88011f8bae30 R15: 0000000000800010
[ 334.272508] FS: 00007fb5925496f0(0000) GS:ffff88011f86abc0(0000) knlGS:0000000000000000
[ 334.272508] CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
[ 334.272508] CR2: 0000000000000010 CR3: 000000011c18c000 CR4: 00000000000006e0
[ 334.272508] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 334.272508] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 334.272508] Process md1_raid5 (pid: 2185, threadinfo ffff88011d590000, task ffff88011fb12860)
[ 334.272508] Stack:
ffffffff81111d20
ffff88011cc209f0
ffff88011cc20a20
ffff88011f8bae00

[ 334.272508] ffff88011f8bae30
ffff88011f8bae00
ffffffff8110a164
ffff88011cc209f0

[ 334.272508] ffff88011cc20a20
ffff88011f8bae30
ffff88011cc209f0
ffff88011f8bae00

[ 334.272508] Call Trace:
[ 334.272508] [<ffffffff81111d20>] ? rb_insert_color+0xb2/0xda
[ 334.272508] [<ffffffff8110a164>] ? cfq_prio_tree_add+0x9d/0xa8
[ 334.272508] [<ffffffff8110b12b>] ? cfq_add_rq_rb+0xb5/0xc8
[ 334.272508] [<ffffffff8110b198>] ? cfq_insert_request+0x5a/0x356
[ 334.272508] [<ffffffff811000a1>] ? elv_insert+0x14b/0x218
[ 334.272508] [<ffffffff810ab757>] ? bio_phys_segments+0xf/0x15
[ 334.272508] [<ffffffff811028dc>] ? __make_request+0x3b9/0x3eb
[ 334.272508] [<ffffffff8110120c>] ? generic_make_request+0x30b/0x346
[ 334.272508] [<ffffffff811baae4>] ? raid5_end_write_request+0x0/0xb8
[ 334.272508] [<ffffffff811b8ace>] ? ops_run_io+0x16a/0x1c1
[ 334.272508] [<ffffffff811ba524>] ? handle_stripe5+0x9b5/0x9d6
[ 334.272508] [<ffffffff811bbef8>] ? handle_stripe+0xc3a/0xc6a
[ 334.272508] [<ffffffff810296e5>] ? pick_next_task_fair+0x8d/0x9c
[ 334.272508] [<ffffffff81253782>] ? thread_return+0x3a/0xaa
[ 334.272508] [<ffffffff811bc2be>] ? raid5d+0x396/0x3cd
[ 334.272508] [<ffffffff81253bc8>] ? schedule_timeout+0x1e/0xad
[ 334.272508] [<ffffffff811c715f>] ? md_thread+0xdd/0xf9
[ 334.272508] [<ffffffff81044f9c>] ? autoremove_wake_function+0x0/0x2e
[ 334.272508] [<ffffffff811c7082>] ? md_thread+0x0/0xf9
[ 334.272508] [<ffffffff81044e80>] ? kthread+0x47/0x73
[ 334.272508] [<ffffffff8102f867>] ? schedule_tail+0x28/0x60
[ 334.272508] [<ffffffff8100cda9>] ? child_rip+0xa/0x11
[ 334.272508] [<ffffffff81044e39>] ? kthread+0x0/0x73
[ 334.272508] [<ffffffff8100cd9f>] ? child_rip+0x0/0x11
[ 334.272508]
[ 334.272508]
[ 334.272508] Code:
00
31
c0
eb
19
ff
c0
48
89
ee
48
c7
c7
e8
39
44
81
89
43
08
e8
3a
33
14
00
b8
01
00
00
00
5a
5b
5d
c3
90
90
48
8b
4f
08
4c
8b
07

8b
51
10
49
83
e0
fc
48
85
d2
48
89
57
08
74
0c
48
8b
02
83

[ 334.272508] RIP
[<ffffffff81111bbf>] __rb_rotate_left+0x7/0x5b
[ 334.272508] RSP <ffff88011d591a48>
[ 334.272508] CR2: 0000000000000010
[ 334.272508] ---[ end trace f1bde8b7b9263879 ]---
======================================

--
Thanks,
Vitaly
--
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/

Next message: Randy Dunlap: "Re: [PATCH][RESEND] C99 initializers for DEFINE_RATELIMIT_STATE()"
Previous message: Michael Kerrisk: "Re: [1/1] Use pid in inotify events."
In reply to: Jens Axboe: "Re: Slow file transfer speeds with CFQ IO scheduler in some cases"
Next in thread: Jens Axboe: "Re: Slow file transfer speeds with CFQ IO scheduler in some cases"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]