* [OOPS, 3.13-rc2] null ptr in dio_complete()
@ 2013-12-03 21:59 Dave Chinner
2013-12-04 1:58 ` Dave Chinner
0 siblings, 1 reply; 13+ messages in thread
From: Dave Chinner @ 2013-12-03 21:59 UTC (permalink / raw)
To: linux-kernel; +Cc: Jens Axboe
Hi Jens,
Not sure who to direct this to or CC, so I figured you are the
person to do that. I just had xfstests generic/299 (an AIO/DIO test)
oops in dio_complete() like so:
[ 9650.586724] general protection fault: 0000 [#1] SMP DEBUG_PAGEALLOC
[ 9650.590131] Modules linked in:
[ 9650.590630] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.13.0-rc2-dgc+ #73
[ 9650.590630] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
[ 9650.590630] task: ffffffff81f35480 ti: ffffffff81f24000 task.ti: ffffffff81f24000
[ 9650.590630] RIP: 0010:[<ffffffff811ee5f1>] [<ffffffff811ee5f1>] aio_complete+0xb1/0x1e0
[ 9650.590630] RSP: 0018:ffff88007f803cf8 EFLAGS: 00010003
[ 9650.590630] RAX: 0000000000000086 RBX: ffff8800688ae000 RCX: 0000000000d6d6d6
[ 9650.590630] RDX: 6b6b6b6b6b6b6b6b RSI: 0000000000001000 RDI: ffff8800688ae1c4
[ 9650.590630] RBP: ffff88007f803d28 R08: 0000000000000000 R09: 000000006b6b6b6c
[ 9650.590630] R10: ff79a1a35779b009 R11: 0000000000000010 R12: ffff88006953a540
[ 9650.590630] R13: 0000000000001000 R14: 0000000000000000 R15: ffff8800688ae1c4
[ 9650.590630] FS: 0000000000000000(0000) GS:ffff88007f800000(0000) knlGS:0000000000000000
[ 9650.590630] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 9650.590630] CR2: 00007ffa9c48448f CR3: 0000000028061000 CR4: 00000000000006f0
[ 9650.590630] Stack:
[ 9650.590630] ffff88007f803d18 0000000000001000 ffff880068b80800 0000000000001000
[ 9650.590630] 0000000000000001 0000000031f6d000 ffff88007f803d68 ffffffff811ddae3
[ 9650.590630] 0000000000000086 ffff880068b80800 0000000000000000 ffff880068b80828
[ 9650.590630] Call Trace:
[ 9650.590630] <IRQ>
[ 9650.590630] [<ffffffff811ddae3>] dio_complete+0xa3/0x140
[ 9650.590630] [<ffffffff811ddc2a>] dio_bio_end_aio+0x7a/0x110
[ 9650.590630] [<ffffffff811ddbb5>] ? dio_bio_end_aio+0x5/0x110
[ 9650.590630] [<ffffffff811d8a9d>] bio_endio+0x1d/0x30
[ 9650.590630] [<ffffffff8175d65f>] blk_mq_complete_request+0x5f/0x120
[ 9650.590630] [<ffffffff8175d736>] __blk_mq_end_io+0x16/0x20
[ 9650.590630] [<ffffffff8175d7a8>] blk_mq_end_io+0x68/0xd0
[ 9650.590630] [<ffffffff818539a7>] virtblk_done+0x67/0x110
[ 9650.590630] [<ffffffff817f74c5>] vring_interrupt+0x35/0x60
[ 9650.590630] [<ffffffff810e4e34>] handle_irq_event_percpu+0x54/0x1e0
[ 9650.590630] [<ffffffff810e5008>] handle_irq_event+0x48/0x70
[ 9650.590630] [<ffffffff8107d6f5>] ? kvm_guest_apic_eoi_write+0x5/0x50
[ 9650.590630] [<ffffffff810e7807>] handle_edge_irq+0x77/0x110
[ 9650.590630] [<ffffffff8104796f>] handle_irq+0xbf/0x150
[ 9650.590630] [<ffffffff810478b5>] ? handle_irq+0x5/0x150
[ 9650.590630] [<ffffffff81aee136>] ? atomic_notifier_call_chain+0x16/0x20
[ 9650.590630] [<ffffffff81af43ca>] do_IRQ+0x5a/0xe0
[ 9650.590630] [<ffffffff81aea16d>] common_interrupt+0x6d/0x6d
[ 9650.590630] <EOI>
[ 9650.590630] [<ffffffff8107e616>] ? native_safe_halt+0x6/0x10
[ 9650.590630] [<ffffffff8104e4f5>] ? default_idle+0x5/0xc0
[ 9650.590630] [<ffffffff8104e50f>] default_idle+0x1f/0xc0
[ 9650.590630] [<ffffffff8104edb6>] arch_cpu_idle+0x26/0x30
[ 9650.590630] [<ffffffff810e4331>] cpu_startup_entry+0x81/0x240
[ 9650.590630] [<ffffffff81ad5d67>] rest_init+0x77/0x80
[ 9650.590630] [<ffffffff8203ceec>] start_kernel+0x3cd/0x3da
[ 9650.590630] [<ffffffff8203c91e>] ? repair_env_string+0x5e/0x5e
[ 9650.590630] [<ffffffff8203c117>] ? early_idt_handlers+0x117/0x120
[ 9650.590630] [<ffffffff8203c5c2>] x86_64_start_reservations+0x2a/0x2c
[ 9650.590630] [<ffffffff8203c70a>] x86_64_start_kernel+0x146/0x155
[ 9650.590630] Code: e8 05 b5 8f 00 44 8b 8b c0 01 00 00 45 31 c0 48 8b 93 98 00 00 00 41 83 c1 01 44 3b 8b 80 00 00 00 44 89 c9 45 0f 42 c1 c1 e9 07 <48> 8b 0c ca 65
[ 9650.590630] RIP [<ffffffff811ee5f1>] aio_complete+0xb1/0x1e0
[ 9650.590630] RSP <ffff88007f803cf8>
I'm not sure if it is related to blk_mq, virtio, dio or bio changes
(or even somethign else), but I haven't seen anything like this
before. I've only seen it once so far (haven't rerun the test yet at
all).
FWIW, I'd also like to point out that I'm seeing XFS on the
virtio stack get perilously close to blowing the stack on 3.13-rc2:
[ 387.048771] fill (11196) used greatest stack depth: 1048 bytes left
This is new - on 3.12 generally the output would be around 2500
bytes left, so somewhere below of XFS there a lot more stack being
consumed in the IO path on 3.13. I'll do some more tracing of this
to try to find out where it is all going....
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [OOPS, 3.13-rc2] null ptr in dio_complete()
2013-12-03 21:59 [OOPS, 3.13-rc2] null ptr in dio_complete() Dave Chinner
@ 2013-12-04 1:58 ` Dave Chinner
2013-12-04 3:38 ` Dave Chinner
2013-12-05 14:22 ` Ming Lei
0 siblings, 2 replies; 13+ messages in thread
From: Dave Chinner @ 2013-12-04 1:58 UTC (permalink / raw)
To: linux-kernel; +Cc: Jens Axboe
On Wed, Dec 04, 2013 at 08:59:40AM +1100, Dave Chinner wrote:
> Hi Jens,
>
> Not sure who to direct this to or CC, so I figured you are the
> person to do that. I just had xfstests generic/299 (an AIO/DIO test)
> oops in dio_complete() like so:
>
> [ 9650.586724] general protection fault: 0000 [#1] SMP DEBUG_PAGEALLOC
> [ 9650.590131] Modules linked in:
> [ 9650.590630] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.13.0-rc2-dgc+ #73
> [ 9650.590630] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
> [ 9650.590630] task: ffffffff81f35480 ti: ffffffff81f24000 task.ti: ffffffff81f24000
> [ 9650.590630] RIP: 0010:[<ffffffff811ee5f1>] [<ffffffff811ee5f1>] aio_complete+0xb1/0x1e0
> [ 9650.590630] RSP: 0018:ffff88007f803cf8 EFLAGS: 00010003
> [ 9650.590630] RAX: 0000000000000086 RBX: ffff8800688ae000 RCX: 0000000000d6d6d6
> [ 9650.590630] RDX: 6b6b6b6b6b6b6b6b RSI: 0000000000001000 RDI: ffff8800688ae1c4
> [ 9650.590630] RBP: ffff88007f803d28 R08: 0000000000000000 R09: 000000006b6b6b6c
> [ 9650.590630] R10: ff79a1a35779b009 R11: 0000000000000010 R12: ffff88006953a540
> [ 9650.590630] R13: 0000000000001000 R14: 0000000000000000 R15: ffff8800688ae1c4
> [ 9650.590630] FS: 0000000000000000(0000) GS:ffff88007f800000(0000) knlGS:0000000000000000
> [ 9650.590630] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> [ 9650.590630] CR2: 00007ffa9c48448f CR3: 0000000028061000 CR4: 00000000000006f0
> [ 9650.590630] Stack:
> [ 9650.590630] ffff88007f803d18 0000000000001000 ffff880068b80800 0000000000001000
> [ 9650.590630] 0000000000000001 0000000031f6d000 ffff88007f803d68 ffffffff811ddae3
> [ 9650.590630] 0000000000000086 ffff880068b80800 0000000000000000 ffff880068b80828
> [ 9650.590630] Call Trace:
> [ 9650.590630] <IRQ>
> [ 9650.590630] [<ffffffff811ddae3>] dio_complete+0xa3/0x140
> [ 9650.590630] [<ffffffff811ddc2a>] dio_bio_end_aio+0x7a/0x110
> [ 9650.590630] [<ffffffff811ddbb5>] ? dio_bio_end_aio+0x5/0x110
> [ 9650.590630] [<ffffffff811d8a9d>] bio_endio+0x1d/0x30
> [ 9650.590630] [<ffffffff8175d65f>] blk_mq_complete_request+0x5f/0x120
> [ 9650.590630] [<ffffffff8175d736>] __blk_mq_end_io+0x16/0x20
> [ 9650.590630] [<ffffffff8175d7a8>] blk_mq_end_io+0x68/0xd0
> [ 9650.590630] [<ffffffff818539a7>] virtblk_done+0x67/0x110
> [ 9650.590630] [<ffffffff817f74c5>] vring_interrupt+0x35/0x60
> [ 9650.590630] [<ffffffff810e4e34>] handle_irq_event_percpu+0x54/0x1e0
> [ 9650.590630] [<ffffffff810e5008>] handle_irq_event+0x48/0x70
> [ 9650.590630] [<ffffffff8107d6f5>] ? kvm_guest_apic_eoi_write+0x5/0x50
> [ 9650.590630] [<ffffffff810e7807>] handle_edge_irq+0x77/0x110
> [ 9650.590630] [<ffffffff8104796f>] handle_irq+0xbf/0x150
> [ 9650.590630] [<ffffffff810478b5>] ? handle_irq+0x5/0x150
> [ 9650.590630] [<ffffffff81aee136>] ? atomic_notifier_call_chain+0x16/0x20
> [ 9650.590630] [<ffffffff81af43ca>] do_IRQ+0x5a/0xe0
> [ 9650.590630] [<ffffffff81aea16d>] common_interrupt+0x6d/0x6d
> [ 9650.590630] <EOI>
> [ 9650.590630] [<ffffffff8107e616>] ? native_safe_halt+0x6/0x10
> [ 9650.590630] [<ffffffff8104e4f5>] ? default_idle+0x5/0xc0
> [ 9650.590630] [<ffffffff8104e50f>] default_idle+0x1f/0xc0
> [ 9650.590630] [<ffffffff8104edb6>] arch_cpu_idle+0x26/0x30
> [ 9650.590630] [<ffffffff810e4331>] cpu_startup_entry+0x81/0x240
> [ 9650.590630] [<ffffffff81ad5d67>] rest_init+0x77/0x80
> [ 9650.590630] [<ffffffff8203ceec>] start_kernel+0x3cd/0x3da
> [ 9650.590630] [<ffffffff8203c91e>] ? repair_env_string+0x5e/0x5e
> [ 9650.590630] [<ffffffff8203c117>] ? early_idt_handlers+0x117/0x120
> [ 9650.590630] [<ffffffff8203c5c2>] x86_64_start_reservations+0x2a/0x2c
> [ 9650.590630] [<ffffffff8203c70a>] x86_64_start_kernel+0x146/0x155
> [ 9650.590630] Code: e8 05 b5 8f 00 44 8b 8b c0 01 00 00 45 31 c0 48 8b 93 98 00 00 00 41 83 c1 01 44 3b 8b 80 00 00 00 44 89 c9 45 0f 42 c1 c1 e9 07 <48> 8b 0c ca 65
> [ 9650.590630] RIP [<ffffffff811ee5f1>] aio_complete+0xb1/0x1e0
> [ 9650.590630] RSP <ffff88007f803cf8>
>
> I'm not sure if it is related to blk_mq, virtio, dio or bio changes
> (or even somethign else), but I haven't seen anything like this
> before. I've only seen it once so far (haven't rerun the test yet at
> all).
And I just hit this from running xfs_repair which is doing
multithreaded direct IO directly on /dev/vdc:
[ 1776.508599] BUG: unable to handle kernel NULL pointer dereference at 0000000000000328
[ 1776.510446] IP: [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
[ 1776.511762] PGD 38e75b067 PUD 41987d067 PMD 0
[ 1776.512577] Oops: 0000 [#1] SMP
[ 1776.512577] Modules linked in:
[ 1776.512577] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.13.0-rc2-dgc+ #75
[ 1776.512577] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
[ 1776.512577] task: ffffffff81f37480 ti: ffffffff81f26000 task.ti: ffffffff81f26000
[ 1776.512577] RIP: 0010:[<ffffffff81755b6a>] [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
[ 1776.512577] RSP: 0000:ffff88011bc03da8 EFLAGS: 00010046
[ 1776.512577] RAX: 0000000010000000 RBX: 0000000000000000 RCX: 0000000000000000
[ 1776.512577] RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffff8800dba59fc0
[ 1776.512577] RBP: ffff88011bc03db8 R08: 0000000000000000 R09: ffff88021a828928
[ 1776.512577] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000000
[ 1776.512577] R13: 0000000000000000 R14: 0000000000002000 R15: 0000000000000000
[ 1776.512577] FS: 0000000000000000(0000) GS:ffff88011bc00000(0000) knlGS:0000000000000000
[ 1776.512577] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 1776.512577] CR2: 0000000000000328 CR3: 000000041a4b0000 CR4: 00000000000006f0
[ 1776.512577] Stack:
[ 1776.512577] 0000000000000000 ffff8800dba59fc0 ffff88011bc03df8 ffffffff8175e4b8
[ 1776.512577] 00000000000001c0 ffff8800dba59fc0 ffffe8fcfbc03a80 ffff88041aac0800
[ 1776.512577] ffff88011ad53b10 0000000000000096 ffff88011bc03e08 ffffffff8175e536
[ 1776.512577] Call Trace:
[ 1776.512577] <IRQ>
[ 1776.512577] [<ffffffff8175e4b8>] blk_mq_complete_request+0xb8/0x120
[ 1776.512577] [<ffffffff8175e536>] __blk_mq_end_io+0x16/0x20
[ 1776.512577] [<ffffffff8175e5a8>] blk_mq_end_io+0x68/0xd0
[ 1776.512577] [<ffffffff81852e47>] virtblk_done+0x67/0x110
[ 1776.512577] [<ffffffff817f7925>] vring_interrupt+0x35/0x60
[ 1776.512577] [<ffffffff810e48a4>] handle_irq_event_percpu+0x54/0x1e0
[ 1776.512577] [<ffffffff810e4a78>] handle_irq_event+0x48/0x70
[ 1776.512577] [<ffffffff810e71d7>] handle_edge_irq+0x77/0x110
[ 1776.512577] [<ffffffff8104796f>] handle_irq+0xbf/0x150
[ 1776.512577] [<ffffffff81aec8c2>] ? __atomic_notifier_call_chain+0x12/0x20
[ 1776.512577] [<ffffffff81aec8e6>] ? atomic_notifier_call_chain+0x16/0x20
[ 1776.512577] [<ffffffff81af2b8a>] do_IRQ+0x5a/0xe0
[ 1776.512577] [<ffffffff81ae892d>] common_interrupt+0x6d/0x6d
[ 1776.512577] <EOI>
[ 1776.512577] [<ffffffff8107e626>] ? native_safe_halt+0x6/0x10
[ 1776.512577] [<ffffffff8104e50f>] default_idle+0x1f/0xc0
[ 1776.512577] [<ffffffff8104edb6>] arch_cpu_idle+0x26/0x30
[ 1776.512577] [<ffffffff810e3d81>] cpu_startup_entry+0x81/0x240
[ 1776.512577] [<ffffffff81ad4f97>] rest_init+0x77/0x80
[ 1776.512577] [<ffffffff82041ee7>] start_kernel+0x3c8/0x3d5
[ 1776.512577] [<ffffffff8204191e>] ? repair_env_string+0x5e/0x5e
[ 1776.512577] [<ffffffff82041117>] ? early_idt_handlers+0x117/0x120
[ 1776.512577] [<ffffffff820415c2>] x86_64_start_reservations+0x2a/0x2c
[ 1776.512577] [<ffffffff8204170a>] x86_64_start_kernel+0x146/0x155
[ 1776.512577] Code: 54 41 89 c4 53 41 83 e4 01 48 2b 97 d8 00 00 00 48 8b 9f d0 00 00 00 4d 63 e4 65 44 8b 04 25 1c b0 00 00 49 8d 74 24 02 49 63 c8 <48> 8b 83 28 03
[ 1776.512577] RIP [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
[ 1776.512577] RSP <ffff88011bc03da8>
[ 1776.512577] CR2: 0000000000000328
[ 1776.512577] ---[ end trace 33a5787221ff13b4 ]---
[ 1776.512577] Kernel panic - not syncing: Fatal exception in interrupt
[ 1776.512577] Shutting down cpus with NMI
So this is looking like another virtio+blk_mq problem....
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [OOPS, 3.13-rc2] null ptr in dio_complete()
2013-12-04 1:58 ` Dave Chinner
@ 2013-12-04 3:38 ` Dave Chinner
2013-12-04 3:47 ` Jens Axboe
2013-12-05 14:22 ` Ming Lei
1 sibling, 1 reply; 13+ messages in thread
From: Dave Chinner @ 2013-12-04 3:38 UTC (permalink / raw)
To: linux-kernel; +Cc: Jens Axboe
On Wed, Dec 04, 2013 at 12:58:38PM +1100, Dave Chinner wrote:
> On Wed, Dec 04, 2013 at 08:59:40AM +1100, Dave Chinner wrote:
> > Hi Jens,
> >
> > Not sure who to direct this to or CC, so I figured you are the
> > person to do that. I just had xfstests generic/299 (an AIO/DIO test)
> > oops in dio_complete() like so:
> >
> > [ 9650.586724] general protection fault: 0000 [#1] SMP DEBUG_PAGEALLOC
> > [ 9650.590131] Modules linked in:
> > [ 9650.590630] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.13.0-rc2-dgc+ #73
> > [ 9650.590630] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
> > [ 9650.590630] task: ffffffff81f35480 ti: ffffffff81f24000 task.ti: ffffffff81f24000
> > [ 9650.590630] RIP: 0010:[<ffffffff811ee5f1>] [<ffffffff811ee5f1>] aio_complete+0xb1/0x1e0
> > [ 9650.590630] RSP: 0018:ffff88007f803cf8 EFLAGS: 00010003
> > [ 9650.590630] RAX: 0000000000000086 RBX: ffff8800688ae000 RCX: 0000000000d6d6d6
> > [ 9650.590630] RDX: 6b6b6b6b6b6b6b6b RSI: 0000000000001000 RDI: ffff8800688ae1c4
> > [ 9650.590630] RBP: ffff88007f803d28 R08: 0000000000000000 R09: 000000006b6b6b6c
> > [ 9650.590630] R10: ff79a1a35779b009 R11: 0000000000000010 R12: ffff88006953a540
> > [ 9650.590630] R13: 0000000000001000 R14: 0000000000000000 R15: ffff8800688ae1c4
> > [ 9650.590630] FS: 0000000000000000(0000) GS:ffff88007f800000(0000) knlGS:0000000000000000
> > [ 9650.590630] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> > [ 9650.590630] CR2: 00007ffa9c48448f CR3: 0000000028061000 CR4: 00000000000006f0
> > [ 9650.590630] Stack:
> > [ 9650.590630] ffff88007f803d18 0000000000001000 ffff880068b80800 0000000000001000
> > [ 9650.590630] 0000000000000001 0000000031f6d000 ffff88007f803d68 ffffffff811ddae3
> > [ 9650.590630] 0000000000000086 ffff880068b80800 0000000000000000 ffff880068b80828
> > [ 9650.590630] Call Trace:
> > [ 9650.590630] <IRQ>
> > [ 9650.590630] [<ffffffff811ddae3>] dio_complete+0xa3/0x140
> > [ 9650.590630] [<ffffffff811ddc2a>] dio_bio_end_aio+0x7a/0x110
> > [ 9650.590630] [<ffffffff811ddbb5>] ? dio_bio_end_aio+0x5/0x110
> > [ 9650.590630] [<ffffffff811d8a9d>] bio_endio+0x1d/0x30
> > [ 9650.590630] [<ffffffff8175d65f>] blk_mq_complete_request+0x5f/0x120
> > [ 9650.590630] [<ffffffff8175d736>] __blk_mq_end_io+0x16/0x20
> > [ 9650.590630] [<ffffffff8175d7a8>] blk_mq_end_io+0x68/0xd0
> > [ 9650.590630] [<ffffffff818539a7>] virtblk_done+0x67/0x110
> > [ 9650.590630] [<ffffffff817f74c5>] vring_interrupt+0x35/0x60
> > [ 9650.590630] [<ffffffff810e4e34>] handle_irq_event_percpu+0x54/0x1e0
> > [ 9650.590630] [<ffffffff810e5008>] handle_irq_event+0x48/0x70
> > [ 9650.590630] [<ffffffff8107d6f5>] ? kvm_guest_apic_eoi_write+0x5/0x50
> > [ 9650.590630] [<ffffffff810e7807>] handle_edge_irq+0x77/0x110
> > [ 9650.590630] [<ffffffff8104796f>] handle_irq+0xbf/0x150
> > [ 9650.590630] [<ffffffff810478b5>] ? handle_irq+0x5/0x150
> > [ 9650.590630] [<ffffffff81aee136>] ? atomic_notifier_call_chain+0x16/0x20
> > [ 9650.590630] [<ffffffff81af43ca>] do_IRQ+0x5a/0xe0
> > [ 9650.590630] [<ffffffff81aea16d>] common_interrupt+0x6d/0x6d
> > [ 9650.590630] <EOI>
> > [ 9650.590630] [<ffffffff8107e616>] ? native_safe_halt+0x6/0x10
> > [ 9650.590630] [<ffffffff8104e4f5>] ? default_idle+0x5/0xc0
> > [ 9650.590630] [<ffffffff8104e50f>] default_idle+0x1f/0xc0
> > [ 9650.590630] [<ffffffff8104edb6>] arch_cpu_idle+0x26/0x30
> > [ 9650.590630] [<ffffffff810e4331>] cpu_startup_entry+0x81/0x240
> > [ 9650.590630] [<ffffffff81ad5d67>] rest_init+0x77/0x80
> > [ 9650.590630] [<ffffffff8203ceec>] start_kernel+0x3cd/0x3da
> > [ 9650.590630] [<ffffffff8203c91e>] ? repair_env_string+0x5e/0x5e
> > [ 9650.590630] [<ffffffff8203c117>] ? early_idt_handlers+0x117/0x120
> > [ 9650.590630] [<ffffffff8203c5c2>] x86_64_start_reservations+0x2a/0x2c
> > [ 9650.590630] [<ffffffff8203c70a>] x86_64_start_kernel+0x146/0x155
> > [ 9650.590630] Code: e8 05 b5 8f 00 44 8b 8b c0 01 00 00 45 31 c0 48 8b 93 98 00 00 00 41 83 c1 01 44 3b 8b 80 00 00 00 44 89 c9 45 0f 42 c1 c1 e9 07 <48> 8b 0c ca 65
> > [ 9650.590630] RIP [<ffffffff811ee5f1>] aio_complete+0xb1/0x1e0
> > [ 9650.590630] RSP <ffff88007f803cf8>
> >
> > I'm not sure if it is related to blk_mq, virtio, dio or bio changes
> > (or even somethign else), but I haven't seen anything like this
> > before. I've only seen it once so far (haven't rerun the test yet at
> > all).
>
> And I just hit this from running xfs_repair which is doing
> multithreaded direct IO directly on /dev/vdc:
>
> [ 1776.508599] BUG: unable to handle kernel NULL pointer dereference at 0000000000000328
> [ 1776.510446] IP: [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
> [ 1776.511762] PGD 38e75b067 PUD 41987d067 PMD 0
> [ 1776.512577] Oops: 0000 [#1] SMP
> [ 1776.512577] Modules linked in:
> [ 1776.512577] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.13.0-rc2-dgc+ #75
> [ 1776.512577] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
> [ 1776.512577] task: ffffffff81f37480 ti: ffffffff81f26000 task.ti: ffffffff81f26000
> [ 1776.512577] RIP: 0010:[<ffffffff81755b6a>] [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
> [ 1776.512577] RSP: 0000:ffff88011bc03da8 EFLAGS: 00010046
> [ 1776.512577] RAX: 0000000010000000 RBX: 0000000000000000 RCX: 0000000000000000
> [ 1776.512577] RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffff8800dba59fc0
> [ 1776.512577] RBP: ffff88011bc03db8 R08: 0000000000000000 R09: ffff88021a828928
> [ 1776.512577] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000000
> [ 1776.512577] R13: 0000000000000000 R14: 0000000000002000 R15: 0000000000000000
> [ 1776.512577] FS: 0000000000000000(0000) GS:ffff88011bc00000(0000) knlGS:0000000000000000
> [ 1776.512577] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> [ 1776.512577] CR2: 0000000000000328 CR3: 000000041a4b0000 CR4: 00000000000006f0
> [ 1776.512577] Stack:
> [ 1776.512577] 0000000000000000 ffff8800dba59fc0 ffff88011bc03df8 ffffffff8175e4b8
> [ 1776.512577] 00000000000001c0 ffff8800dba59fc0 ffffe8fcfbc03a80 ffff88041aac0800
> [ 1776.512577] ffff88011ad53b10 0000000000000096 ffff88011bc03e08 ffffffff8175e536
> [ 1776.512577] Call Trace:
> [ 1776.512577] <IRQ>
> [ 1776.512577] [<ffffffff8175e4b8>] blk_mq_complete_request+0xb8/0x120
> [ 1776.512577] [<ffffffff8175e536>] __blk_mq_end_io+0x16/0x20
> [ 1776.512577] [<ffffffff8175e5a8>] blk_mq_end_io+0x68/0xd0
> [ 1776.512577] [<ffffffff81852e47>] virtblk_done+0x67/0x110
> [ 1776.512577] [<ffffffff817f7925>] vring_interrupt+0x35/0x60
> [ 1776.512577] [<ffffffff810e48a4>] handle_irq_event_percpu+0x54/0x1e0
> [ 1776.512577] [<ffffffff810e4a78>] handle_irq_event+0x48/0x70
> [ 1776.512577] [<ffffffff810e71d7>] handle_edge_irq+0x77/0x110
> [ 1776.512577] [<ffffffff8104796f>] handle_irq+0xbf/0x150
> [ 1776.512577] [<ffffffff81aec8c2>] ? __atomic_notifier_call_chain+0x12/0x20
> [ 1776.512577] [<ffffffff81aec8e6>] ? atomic_notifier_call_chain+0x16/0x20
> [ 1776.512577] [<ffffffff81af2b8a>] do_IRQ+0x5a/0xe0
> [ 1776.512577] [<ffffffff81ae892d>] common_interrupt+0x6d/0x6d
> [ 1776.512577] <EOI>
> [ 1776.512577] [<ffffffff8107e626>] ? native_safe_halt+0x6/0x10
> [ 1776.512577] [<ffffffff8104e50f>] default_idle+0x1f/0xc0
> [ 1776.512577] [<ffffffff8104edb6>] arch_cpu_idle+0x26/0x30
> [ 1776.512577] [<ffffffff810e3d81>] cpu_startup_entry+0x81/0x240
> [ 1776.512577] [<ffffffff81ad4f97>] rest_init+0x77/0x80
> [ 1776.512577] [<ffffffff82041ee7>] start_kernel+0x3c8/0x3d5
> [ 1776.512577] [<ffffffff8204191e>] ? repair_env_string+0x5e/0x5e
> [ 1776.512577] [<ffffffff82041117>] ? early_idt_handlers+0x117/0x120
> [ 1776.512577] [<ffffffff820415c2>] x86_64_start_reservations+0x2a/0x2c
> [ 1776.512577] [<ffffffff8204170a>] x86_64_start_kernel+0x146/0x155
> [ 1776.512577] Code: 54 41 89 c4 53 41 83 e4 01 48 2b 97 d8 00 00 00 48 8b 9f d0 00 00 00 4d 63 e4 65 44 8b 04 25 1c b0 00 00 49 8d 74 24 02 49 63 c8 <48> 8b 83 28 03
> [ 1776.512577] RIP [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
> [ 1776.512577] RSP <ffff88011bc03da8>
> [ 1776.512577] CR2: 0000000000000328
> [ 1776.512577] ---[ end trace 33a5787221ff13b4 ]---
> [ 1776.512577] Kernel panic - not syncing: Fatal exception in interrupt
> [ 1776.512577] Shutting down cpus with NMI
>
> So this is looking like another virtio+blk_mq problem....
This one is definitely reproducable. Just hit it again...
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [OOPS, 3.13-rc2] null ptr in dio_complete()
2013-12-04 3:38 ` Dave Chinner
@ 2013-12-04 3:47 ` Jens Axboe
2013-12-04 4:17 ` Dave Chinner
0 siblings, 1 reply; 13+ messages in thread
From: Jens Axboe @ 2013-12-04 3:47 UTC (permalink / raw)
To: Dave Chinner; +Cc: linux-kernel
On Wed, Dec 04 2013, Dave Chinner wrote:
> On Wed, Dec 04, 2013 at 12:58:38PM +1100, Dave Chinner wrote:
> > On Wed, Dec 04, 2013 at 08:59:40AM +1100, Dave Chinner wrote:
> > > Hi Jens,
> > >
> > > Not sure who to direct this to or CC, so I figured you are the
> > > person to do that. I just had xfstests generic/299 (an AIO/DIO test)
> > > oops in dio_complete() like so:
> > >
> > > [ 9650.586724] general protection fault: 0000 [#1] SMP DEBUG_PAGEALLOC
> > > [ 9650.590131] Modules linked in:
> > > [ 9650.590630] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.13.0-rc2-dgc+ #73
> > > [ 9650.590630] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
> > > [ 9650.590630] task: ffffffff81f35480 ti: ffffffff81f24000 task.ti: ffffffff81f24000
> > > [ 9650.590630] RIP: 0010:[<ffffffff811ee5f1>] [<ffffffff811ee5f1>] aio_complete+0xb1/0x1e0
> > > [ 9650.590630] RSP: 0018:ffff88007f803cf8 EFLAGS: 00010003
> > > [ 9650.590630] RAX: 0000000000000086 RBX: ffff8800688ae000 RCX: 0000000000d6d6d6
> > > [ 9650.590630] RDX: 6b6b6b6b6b6b6b6b RSI: 0000000000001000 RDI: ffff8800688ae1c4
> > > [ 9650.590630] RBP: ffff88007f803d28 R08: 0000000000000000 R09: 000000006b6b6b6c
> > > [ 9650.590630] R10: ff79a1a35779b009 R11: 0000000000000010 R12: ffff88006953a540
> > > [ 9650.590630] R13: 0000000000001000 R14: 0000000000000000 R15: ffff8800688ae1c4
> > > [ 9650.590630] FS: 0000000000000000(0000) GS:ffff88007f800000(0000) knlGS:0000000000000000
> > > [ 9650.590630] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> > > [ 9650.590630] CR2: 00007ffa9c48448f CR3: 0000000028061000 CR4: 00000000000006f0
> > > [ 9650.590630] Stack:
> > > [ 9650.590630] ffff88007f803d18 0000000000001000 ffff880068b80800 0000000000001000
> > > [ 9650.590630] 0000000000000001 0000000031f6d000 ffff88007f803d68 ffffffff811ddae3
> > > [ 9650.590630] 0000000000000086 ffff880068b80800 0000000000000000 ffff880068b80828
> > > [ 9650.590630] Call Trace:
> > > [ 9650.590630] <IRQ>
> > > [ 9650.590630] [<ffffffff811ddae3>] dio_complete+0xa3/0x140
> > > [ 9650.590630] [<ffffffff811ddc2a>] dio_bio_end_aio+0x7a/0x110
> > > [ 9650.590630] [<ffffffff811ddbb5>] ? dio_bio_end_aio+0x5/0x110
> > > [ 9650.590630] [<ffffffff811d8a9d>] bio_endio+0x1d/0x30
> > > [ 9650.590630] [<ffffffff8175d65f>] blk_mq_complete_request+0x5f/0x120
> > > [ 9650.590630] [<ffffffff8175d736>] __blk_mq_end_io+0x16/0x20
> > > [ 9650.590630] [<ffffffff8175d7a8>] blk_mq_end_io+0x68/0xd0
> > > [ 9650.590630] [<ffffffff818539a7>] virtblk_done+0x67/0x110
> > > [ 9650.590630] [<ffffffff817f74c5>] vring_interrupt+0x35/0x60
> > > [ 9650.590630] [<ffffffff810e4e34>] handle_irq_event_percpu+0x54/0x1e0
> > > [ 9650.590630] [<ffffffff810e5008>] handle_irq_event+0x48/0x70
> > > [ 9650.590630] [<ffffffff8107d6f5>] ? kvm_guest_apic_eoi_write+0x5/0x50
> > > [ 9650.590630] [<ffffffff810e7807>] handle_edge_irq+0x77/0x110
> > > [ 9650.590630] [<ffffffff8104796f>] handle_irq+0xbf/0x150
> > > [ 9650.590630] [<ffffffff810478b5>] ? handle_irq+0x5/0x150
> > > [ 9650.590630] [<ffffffff81aee136>] ? atomic_notifier_call_chain+0x16/0x20
> > > [ 9650.590630] [<ffffffff81af43ca>] do_IRQ+0x5a/0xe0
> > > [ 9650.590630] [<ffffffff81aea16d>] common_interrupt+0x6d/0x6d
> > > [ 9650.590630] <EOI>
> > > [ 9650.590630] [<ffffffff8107e616>] ? native_safe_halt+0x6/0x10
> > > [ 9650.590630] [<ffffffff8104e4f5>] ? default_idle+0x5/0xc0
> > > [ 9650.590630] [<ffffffff8104e50f>] default_idle+0x1f/0xc0
> > > [ 9650.590630] [<ffffffff8104edb6>] arch_cpu_idle+0x26/0x30
> > > [ 9650.590630] [<ffffffff810e4331>] cpu_startup_entry+0x81/0x240
> > > [ 9650.590630] [<ffffffff81ad5d67>] rest_init+0x77/0x80
> > > [ 9650.590630] [<ffffffff8203ceec>] start_kernel+0x3cd/0x3da
> > > [ 9650.590630] [<ffffffff8203c91e>] ? repair_env_string+0x5e/0x5e
> > > [ 9650.590630] [<ffffffff8203c117>] ? early_idt_handlers+0x117/0x120
> > > [ 9650.590630] [<ffffffff8203c5c2>] x86_64_start_reservations+0x2a/0x2c
> > > [ 9650.590630] [<ffffffff8203c70a>] x86_64_start_kernel+0x146/0x155
> > > [ 9650.590630] Code: e8 05 b5 8f 00 44 8b 8b c0 01 00 00 45 31 c0 48 8b 93 98 00 00 00 41 83 c1 01 44 3b 8b 80 00 00 00 44 89 c9 45 0f 42 c1 c1 e9 07 <48> 8b 0c ca 65
> > > [ 9650.590630] RIP [<ffffffff811ee5f1>] aio_complete+0xb1/0x1e0
> > > [ 9650.590630] RSP <ffff88007f803cf8>
> > >
> > > I'm not sure if it is related to blk_mq, virtio, dio or bio changes
> > > (or even somethign else), but I haven't seen anything like this
> > > before. I've only seen it once so far (haven't rerun the test yet at
> > > all).
> >
> > And I just hit this from running xfs_repair which is doing
> > multithreaded direct IO directly on /dev/vdc:
> >
> > [ 1776.508599] BUG: unable to handle kernel NULL pointer dereference at 0000000000000328
> > [ 1776.510446] IP: [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
> > [ 1776.511762] PGD 38e75b067 PUD 41987d067 PMD 0
> > [ 1776.512577] Oops: 0000 [#1] SMP
> > [ 1776.512577] Modules linked in:
> > [ 1776.512577] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.13.0-rc2-dgc+ #75
> > [ 1776.512577] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
> > [ 1776.512577] task: ffffffff81f37480 ti: ffffffff81f26000 task.ti: ffffffff81f26000
> > [ 1776.512577] RIP: 0010:[<ffffffff81755b6a>] [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
> > [ 1776.512577] RSP: 0000:ffff88011bc03da8 EFLAGS: 00010046
> > [ 1776.512577] RAX: 0000000010000000 RBX: 0000000000000000 RCX: 0000000000000000
> > [ 1776.512577] RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffff8800dba59fc0
> > [ 1776.512577] RBP: ffff88011bc03db8 R08: 0000000000000000 R09: ffff88021a828928
> > [ 1776.512577] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000000
> > [ 1776.512577] R13: 0000000000000000 R14: 0000000000002000 R15: 0000000000000000
> > [ 1776.512577] FS: 0000000000000000(0000) GS:ffff88011bc00000(0000) knlGS:0000000000000000
> > [ 1776.512577] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> > [ 1776.512577] CR2: 0000000000000328 CR3: 000000041a4b0000 CR4: 00000000000006f0
> > [ 1776.512577] Stack:
> > [ 1776.512577] 0000000000000000 ffff8800dba59fc0 ffff88011bc03df8 ffffffff8175e4b8
> > [ 1776.512577] 00000000000001c0 ffff8800dba59fc0 ffffe8fcfbc03a80 ffff88041aac0800
> > [ 1776.512577] ffff88011ad53b10 0000000000000096 ffff88011bc03e08 ffffffff8175e536
> > [ 1776.512577] Call Trace:
> > [ 1776.512577] <IRQ>
> > [ 1776.512577] [<ffffffff8175e4b8>] blk_mq_complete_request+0xb8/0x120
> > [ 1776.512577] [<ffffffff8175e536>] __blk_mq_end_io+0x16/0x20
> > [ 1776.512577] [<ffffffff8175e5a8>] blk_mq_end_io+0x68/0xd0
> > [ 1776.512577] [<ffffffff81852e47>] virtblk_done+0x67/0x110
> > [ 1776.512577] [<ffffffff817f7925>] vring_interrupt+0x35/0x60
> > [ 1776.512577] [<ffffffff810e48a4>] handle_irq_event_percpu+0x54/0x1e0
> > [ 1776.512577] [<ffffffff810e4a78>] handle_irq_event+0x48/0x70
> > [ 1776.512577] [<ffffffff810e71d7>] handle_edge_irq+0x77/0x110
> > [ 1776.512577] [<ffffffff8104796f>] handle_irq+0xbf/0x150
> > [ 1776.512577] [<ffffffff81aec8c2>] ? __atomic_notifier_call_chain+0x12/0x20
> > [ 1776.512577] [<ffffffff81aec8e6>] ? atomic_notifier_call_chain+0x16/0x20
> > [ 1776.512577] [<ffffffff81af2b8a>] do_IRQ+0x5a/0xe0
> > [ 1776.512577] [<ffffffff81ae892d>] common_interrupt+0x6d/0x6d
> > [ 1776.512577] <EOI>
> > [ 1776.512577] [<ffffffff8107e626>] ? native_safe_halt+0x6/0x10
> > [ 1776.512577] [<ffffffff8104e50f>] default_idle+0x1f/0xc0
> > [ 1776.512577] [<ffffffff8104edb6>] arch_cpu_idle+0x26/0x30
> > [ 1776.512577] [<ffffffff810e3d81>] cpu_startup_entry+0x81/0x240
> > [ 1776.512577] [<ffffffff81ad4f97>] rest_init+0x77/0x80
> > [ 1776.512577] [<ffffffff82041ee7>] start_kernel+0x3c8/0x3d5
> > [ 1776.512577] [<ffffffff8204191e>] ? repair_env_string+0x5e/0x5e
> > [ 1776.512577] [<ffffffff82041117>] ? early_idt_handlers+0x117/0x120
> > [ 1776.512577] [<ffffffff820415c2>] x86_64_start_reservations+0x2a/0x2c
> > [ 1776.512577] [<ffffffff8204170a>] x86_64_start_kernel+0x146/0x155
> > [ 1776.512577] Code: 54 41 89 c4 53 41 83 e4 01 48 2b 97 d8 00 00 00 48 8b 9f d0 00 00 00 4d 63 e4 65 44 8b 04 25 1c b0 00 00 49 8d 74 24 02 49 63 c8 <48> 8b 83 28 03
> > [ 1776.512577] RIP [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
> > [ 1776.512577] RSP <ffff88011bc03da8>
> > [ 1776.512577] CR2: 0000000000000328
> > [ 1776.512577] ---[ end trace 33a5787221ff13b4 ]---
> > [ 1776.512577] Kernel panic - not syncing: Fatal exception in interrupt
> > [ 1776.512577] Shutting down cpus with NMI
> >
> > So this is looking like another virtio+blk_mq problem....
>
> This one is definitely reproducable. Just hit it again...
I'll take a look at this. You don't happen to have gdb dumps of the
lines associated with those crashes? Just to save me some digging
time...
--
Jens Axboe
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [OOPS, 3.13-rc2] null ptr in dio_complete()
2013-12-04 3:47 ` Jens Axboe
@ 2013-12-04 4:17 ` Dave Chinner
2013-12-04 23:56 ` Dave Chinner
0 siblings, 1 reply; 13+ messages in thread
From: Dave Chinner @ 2013-12-04 4:17 UTC (permalink / raw)
To: Jens Axboe; +Cc: linux-kernel
On Tue, Dec 03, 2013 at 08:47:12PM -0700, Jens Axboe wrote:
> On Wed, Dec 04 2013, Dave Chinner wrote:
> > On Wed, Dec 04, 2013 at 12:58:38PM +1100, Dave Chinner wrote:
> > > On Wed, Dec 04, 2013 at 08:59:40AM +1100, Dave Chinner wrote:
> > > > Hi Jens,
> > > >
> > > > Not sure who to direct this to or CC, so I figured you are the
> > > > person to do that. I just had xfstests generic/299 (an AIO/DIO test)
> > > > oops in dio_complete() like so:
> > > >
....
> > > > [ 9650.590630] <IRQ>
> > > > [ 9650.590630] [<ffffffff811ddae3>] dio_complete+0xa3/0x140
> > > > [ 9650.590630] [<ffffffff811ddc2a>] dio_bio_end_aio+0x7a/0x110
> > > > [ 9650.590630] [<ffffffff811ddbb5>] ? dio_bio_end_aio+0x5/0x110
> > > > [ 9650.590630] [<ffffffff811d8a9d>] bio_endio+0x1d/0x30
> > > > [ 9650.590630] [<ffffffff8175d65f>] blk_mq_complete_request+0x5f/0x120
> > > > [ 9650.590630] [<ffffffff8175d736>] __blk_mq_end_io+0x16/0x20
> > > > [ 9650.590630] [<ffffffff8175d7a8>] blk_mq_end_io+0x68/0xd0
> > > > [ 9650.590630] [<ffffffff818539a7>] virtblk_done+0x67/0x110
> > > > [ 9650.590630] [<ffffffff817f74c5>] vring_interrupt+0x35/0x60
.....
> > > And I just hit this from running xfs_repair which is doing
> > > multithreaded direct IO directly on /dev/vdc:
> > >
....
> > > [ 1776.510446] IP: [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
....
> > > [ 1776.512577] [<ffffffff8175e4b8>] blk_mq_complete_request+0xb8/0x120
> > > [ 1776.512577] [<ffffffff8175e536>] __blk_mq_end_io+0x16/0x20
> > > [ 1776.512577] [<ffffffff8175e5a8>] blk_mq_end_io+0x68/0xd0
> > > [ 1776.512577] [<ffffffff81852e47>] virtblk_done+0x67/0x110
> > > [ 1776.512577] [<ffffffff817f7925>] vring_interrupt+0x35/0x60
> > > [ 1776.512577] [<ffffffff810e48a4>] handle_irq_event_percpu+0x54/0x1e0
.....
> > > So this is looking like another virtio+blk_mq problem....
> >
> > This one is definitely reproducable. Just hit it again...
>
> I'll take a look at this. You don't happen to have gdb dumps of the
> lines associated with those crashes? Just to save me some digging
> time...
Only this:
(gdb) l *(dio_complete+0xa3)
0xffffffff811ddae3 is in dio_complete (fs/direct-io.c:282).
277 }
278
279 aio_complete(dio->iocb, ret, 0);
280 }
281
282 kmem_cache_free(dio_cache, dio);
283 return ret;
284 }
285
286 static void dio_aio_complete_work(struct work_struct *work)
And this:
(gdb) l *(blk_account_io_done+0x6a)
0xffffffff81755b6a is in blk_account_io_done (block/blk-core.c:2049).
2044 int cpu;
2045
2046 cpu = part_stat_lock();
2047 part = req->part;
2048
2049 part_stat_inc(cpu, part, ios[rw]);
2050 part_stat_add(cpu, part, ticks[rw], duration);
2051 part_round_stats(cpu, part);
2052 part_dec_in_flight(part, rw);
2053
as I've rebuild the kernel with different patches since the one
running on the machine that is triggering the problem.
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [OOPS, 3.13-rc2] null ptr in dio_complete()
2013-12-04 4:17 ` Dave Chinner
@ 2013-12-04 23:56 ` Dave Chinner
2013-12-05 3:41 ` Jens Axboe
0 siblings, 1 reply; 13+ messages in thread
From: Dave Chinner @ 2013-12-04 23:56 UTC (permalink / raw)
To: Jens Axboe; +Cc: linux-kernel
On Wed, Dec 04, 2013 at 03:17:49PM +1100, Dave Chinner wrote:
> On Tue, Dec 03, 2013 at 08:47:12PM -0700, Jens Axboe wrote:
> > On Wed, Dec 04 2013, Dave Chinner wrote:
> > > On Wed, Dec 04, 2013 at 12:58:38PM +1100, Dave Chinner wrote:
> > > > On Wed, Dec 04, 2013 at 08:59:40AM +1100, Dave Chinner wrote:
> > > > > Hi Jens,
> > > > >
> > > > > Not sure who to direct this to or CC, so I figured you are the
> > > > > person to do that. I just had xfstests generic/299 (an AIO/DIO test)
> > > > > oops in dio_complete() like so:
> > > > >
> ....
> > > > > [ 9650.590630] <IRQ>
> > > > > [ 9650.590630] [<ffffffff811ddae3>] dio_complete+0xa3/0x140
> > > > > [ 9650.590630] [<ffffffff811ddc2a>] dio_bio_end_aio+0x7a/0x110
> > > > > [ 9650.590630] [<ffffffff811ddbb5>] ? dio_bio_end_aio+0x5/0x110
> > > > > [ 9650.590630] [<ffffffff811d8a9d>] bio_endio+0x1d/0x30
> > > > > [ 9650.590630] [<ffffffff8175d65f>] blk_mq_complete_request+0x5f/0x120
> > > > > [ 9650.590630] [<ffffffff8175d736>] __blk_mq_end_io+0x16/0x20
> > > > > [ 9650.590630] [<ffffffff8175d7a8>] blk_mq_end_io+0x68/0xd0
> > > > > [ 9650.590630] [<ffffffff818539a7>] virtblk_done+0x67/0x110
> > > > > [ 9650.590630] [<ffffffff817f74c5>] vring_interrupt+0x35/0x60
> .....
> > > > And I just hit this from running xfs_repair which is doing
> > > > multithreaded direct IO directly on /dev/vdc:
> > > >
> ....
> > > > [ 1776.510446] IP: [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
> ....
> > > > [ 1776.512577] [<ffffffff8175e4b8>] blk_mq_complete_request+0xb8/0x120
> > > > [ 1776.512577] [<ffffffff8175e536>] __blk_mq_end_io+0x16/0x20
> > > > [ 1776.512577] [<ffffffff8175e5a8>] blk_mq_end_io+0x68/0xd0
> > > > [ 1776.512577] [<ffffffff81852e47>] virtblk_done+0x67/0x110
> > > > [ 1776.512577] [<ffffffff817f7925>] vring_interrupt+0x35/0x60
> > > > [ 1776.512577] [<ffffffff810e48a4>] handle_irq_event_percpu+0x54/0x1e0
> .....
> > > > So this is looking like another virtio+blk_mq problem....
> > >
> > > This one is definitely reproducable. Just hit it again...
> >
> > I'll take a look at this. You don't happen to have gdb dumps of the
> > lines associated with those crashes? Just to save me some digging
> > time...
>
> Only this:
>
> (gdb) l *(dio_complete+0xa3)
> 0xffffffff811ddae3 is in dio_complete (fs/direct-io.c:282).
> 277 }
> 278
> 279 aio_complete(dio->iocb, ret, 0);
> 280 }
> 281
> 282 kmem_cache_free(dio_cache, dio);
> 283 return ret;
> 284 }
> 285
> 286 static void dio_aio_complete_work(struct work_struct *work)
>
> And this:
>
> (gdb) l *(blk_account_io_done+0x6a)
> 0xffffffff81755b6a is in blk_account_io_done (block/blk-core.c:2049).
> 2044 int cpu;
> 2045
> 2046 cpu = part_stat_lock();
> 2047 part = req->part;
> 2048
> 2049 part_stat_inc(cpu, part, ios[rw]);
> 2050 part_stat_add(cpu, part, ticks[rw], duration);
> 2051 part_round_stats(cpu, part);
> 2052 part_dec_in_flight(part, rw);
> 2053
>
> as I've rebuild the kernel with different patches since the one
> running on the machine that is triggering the problem.
Any update on this, Jens? I've hit this blk_account_io_done() panic
10 times in the past 2 hours while trying to do xfs_repair
testing....
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [OOPS, 3.13-rc2] null ptr in dio_complete()
2013-12-04 23:56 ` Dave Chinner
@ 2013-12-05 3:41 ` Jens Axboe
2013-12-05 4:49 ` Dave Chinner
0 siblings, 1 reply; 13+ messages in thread
From: Jens Axboe @ 2013-12-05 3:41 UTC (permalink / raw)
To: Dave Chinner; +Cc: linux-kernel
On Thu, Dec 05 2013, Dave Chinner wrote:
> On Wed, Dec 04, 2013 at 03:17:49PM +1100, Dave Chinner wrote:
> > On Tue, Dec 03, 2013 at 08:47:12PM -0700, Jens Axboe wrote:
> > > On Wed, Dec 04 2013, Dave Chinner wrote:
> > > > On Wed, Dec 04, 2013 at 12:58:38PM +1100, Dave Chinner wrote:
> > > > > On Wed, Dec 04, 2013 at 08:59:40AM +1100, Dave Chinner wrote:
> > > > > > Hi Jens,
> > > > > >
> > > > > > Not sure who to direct this to or CC, so I figured you are the
> > > > > > person to do that. I just had xfstests generic/299 (an AIO/DIO test)
> > > > > > oops in dio_complete() like so:
> > > > > >
> > ....
> > > > > > [ 9650.590630] <IRQ>
> > > > > > [ 9650.590630] [<ffffffff811ddae3>] dio_complete+0xa3/0x140
> > > > > > [ 9650.590630] [<ffffffff811ddc2a>] dio_bio_end_aio+0x7a/0x110
> > > > > > [ 9650.590630] [<ffffffff811ddbb5>] ? dio_bio_end_aio+0x5/0x110
> > > > > > [ 9650.590630] [<ffffffff811d8a9d>] bio_endio+0x1d/0x30
> > > > > > [ 9650.590630] [<ffffffff8175d65f>] blk_mq_complete_request+0x5f/0x120
> > > > > > [ 9650.590630] [<ffffffff8175d736>] __blk_mq_end_io+0x16/0x20
> > > > > > [ 9650.590630] [<ffffffff8175d7a8>] blk_mq_end_io+0x68/0xd0
> > > > > > [ 9650.590630] [<ffffffff818539a7>] virtblk_done+0x67/0x110
> > > > > > [ 9650.590630] [<ffffffff817f74c5>] vring_interrupt+0x35/0x60
> > .....
> > > > > And I just hit this from running xfs_repair which is doing
> > > > > multithreaded direct IO directly on /dev/vdc:
> > > > >
> > ....
> > > > > [ 1776.510446] IP: [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
> > ....
> > > > > [ 1776.512577] [<ffffffff8175e4b8>] blk_mq_complete_request+0xb8/0x120
> > > > > [ 1776.512577] [<ffffffff8175e536>] __blk_mq_end_io+0x16/0x20
> > > > > [ 1776.512577] [<ffffffff8175e5a8>] blk_mq_end_io+0x68/0xd0
> > > > > [ 1776.512577] [<ffffffff81852e47>] virtblk_done+0x67/0x110
> > > > > [ 1776.512577] [<ffffffff817f7925>] vring_interrupt+0x35/0x60
> > > > > [ 1776.512577] [<ffffffff810e48a4>] handle_irq_event_percpu+0x54/0x1e0
> > .....
> > > > > So this is looking like another virtio+blk_mq problem....
> > > >
> > > > This one is definitely reproducable. Just hit it again...
> > >
> > > I'll take a look at this. You don't happen to have gdb dumps of the
> > > lines associated with those crashes? Just to save me some digging
> > > time...
> >
> > Only this:
> >
> > (gdb) l *(dio_complete+0xa3)
> > 0xffffffff811ddae3 is in dio_complete (fs/direct-io.c:282).
> > 277 }
> > 278
> > 279 aio_complete(dio->iocb, ret, 0);
> > 280 }
> > 281
> > 282 kmem_cache_free(dio_cache, dio);
> > 283 return ret;
> > 284 }
> > 285
> > 286 static void dio_aio_complete_work(struct work_struct *work)
> >
> > And this:
> >
> > (gdb) l *(blk_account_io_done+0x6a)
> > 0xffffffff81755b6a is in blk_account_io_done (block/blk-core.c:2049).
> > 2044 int cpu;
> > 2045
> > 2046 cpu = part_stat_lock();
> > 2047 part = req->part;
> > 2048
> > 2049 part_stat_inc(cpu, part, ios[rw]);
> > 2050 part_stat_add(cpu, part, ticks[rw], duration);
> > 2051 part_round_stats(cpu, part);
> > 2052 part_dec_in_flight(part, rw);
> > 2053
> >
> > as I've rebuild the kernel with different patches since the one
> > running on the machine that is triggering the problem.
>
> Any update on this, Jens? I've hit this blk_account_io_done() panic
> 10 times in the past 2 hours while trying to do xfs_repair
> testing....
No, sorry, no updates yet... I haven't had time to look into it today.
To reproduce tomorrow, can you mail me your exact setup (kvm invocation,
etc) and how your guest is setup and if there's any special way I need
to run xfstest or xfs_repair?
--
Jens Axboe
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [OOPS, 3.13-rc2] null ptr in dio_complete()
2013-12-05 3:41 ` Jens Axboe
@ 2013-12-05 4:49 ` Dave Chinner
0 siblings, 0 replies; 13+ messages in thread
From: Dave Chinner @ 2013-12-05 4:49 UTC (permalink / raw)
To: Jens Axboe; +Cc: linux-kernel
On Wed, Dec 04, 2013 at 08:41:43PM -0700, Jens Axboe wrote:
> On Thu, Dec 05 2013, Dave Chinner wrote:
> > On Wed, Dec 04, 2013 at 03:17:49PM +1100, Dave Chinner wrote:
> > > On Tue, Dec 03, 2013 at 08:47:12PM -0700, Jens Axboe wrote:
> > > > On Wed, Dec 04 2013, Dave Chinner wrote:
> > > > > On Wed, Dec 04, 2013 at 12:58:38PM +1100, Dave Chinner wrote:
> > > > > > On Wed, Dec 04, 2013 at 08:59:40AM +1100, Dave Chinner wrote:
> > > > > > > Hi Jens,
> > > > > > >
> > > > > > > Not sure who to direct this to or CC, so I figured you are the
> > > > > > > person to do that. I just had xfstests generic/299 (an AIO/DIO test)
> > > > > > > oops in dio_complete() like so:
> > > > > > >
> > > ....
> > > > > > > [ 9650.590630] <IRQ>
> > > > > > > [ 9650.590630] [<ffffffff811ddae3>] dio_complete+0xa3/0x140
> > > > > > > [ 9650.590630] [<ffffffff811ddc2a>] dio_bio_end_aio+0x7a/0x110
> > > > > > > [ 9650.590630] [<ffffffff811ddbb5>] ? dio_bio_end_aio+0x5/0x110
> > > > > > > [ 9650.590630] [<ffffffff811d8a9d>] bio_endio+0x1d/0x30
> > > > > > > [ 9650.590630] [<ffffffff8175d65f>] blk_mq_complete_request+0x5f/0x120
> > > > > > > [ 9650.590630] [<ffffffff8175d736>] __blk_mq_end_io+0x16/0x20
> > > > > > > [ 9650.590630] [<ffffffff8175d7a8>] blk_mq_end_io+0x68/0xd0
> > > > > > > [ 9650.590630] [<ffffffff818539a7>] virtblk_done+0x67/0x110
> > > > > > > [ 9650.590630] [<ffffffff817f74c5>] vring_interrupt+0x35/0x60
> > > .....
> > > > > > And I just hit this from running xfs_repair which is doing
> > > > > > multithreaded direct IO directly on /dev/vdc:
> > > > > >
> > > ....
> > > > > > [ 1776.510446] IP: [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
> > > ....
> > > > > > [ 1776.512577] [<ffffffff8175e4b8>] blk_mq_complete_request+0xb8/0x120
> > > > > > [ 1776.512577] [<ffffffff8175e536>] __blk_mq_end_io+0x16/0x20
> > > > > > [ 1776.512577] [<ffffffff8175e5a8>] blk_mq_end_io+0x68/0xd0
> > > > > > [ 1776.512577] [<ffffffff81852e47>] virtblk_done+0x67/0x110
> > > > > > [ 1776.512577] [<ffffffff817f7925>] vring_interrupt+0x35/0x60
> > > > > > [ 1776.512577] [<ffffffff810e48a4>] handle_irq_event_percpu+0x54/0x1e0
> > > .....
> > > > > > So this is looking like another virtio+blk_mq problem....
> > > > >
> > > > > This one is definitely reproducable. Just hit it again...
> > > >
> > > > I'll take a look at this. You don't happen to have gdb dumps of the
> > > > lines associated with those crashes? Just to save me some digging
> > > > time...
> > >
> > > Only this:
> > >
> > > (gdb) l *(dio_complete+0xa3)
> > > 0xffffffff811ddae3 is in dio_complete (fs/direct-io.c:282).
> > > 277 }
> > > 278
> > > 279 aio_complete(dio->iocb, ret, 0);
> > > 280 }
> > > 281
> > > 282 kmem_cache_free(dio_cache, dio);
> > > 283 return ret;
> > > 284 }
> > > 285
> > > 286 static void dio_aio_complete_work(struct work_struct *work)
> > >
> > > And this:
> > >
> > > (gdb) l *(blk_account_io_done+0x6a)
> > > 0xffffffff81755b6a is in blk_account_io_done (block/blk-core.c:2049).
> > > 2044 int cpu;
> > > 2045
> > > 2046 cpu = part_stat_lock();
> > > 2047 part = req->part;
> > > 2048
> > > 2049 part_stat_inc(cpu, part, ios[rw]);
> > > 2050 part_stat_add(cpu, part, ticks[rw], duration);
> > > 2051 part_round_stats(cpu, part);
> > > 2052 part_dec_in_flight(part, rw);
> > > 2053
> > >
> > > as I've rebuild the kernel with different patches since the one
> > > running on the machine that is triggering the problem.
> >
> > Any update on this, Jens? I've hit this blk_account_io_done() panic
> > 10 times in the past 2 hours while trying to do xfs_repair
> > testing....
>
> No, sorry, no updates yet... I haven't had time to look into it today.
> To reproduce tomorrow, can you mail me your exact setup (kvm invocation,
> etc) and how your guest is setup and if there's any special way I need
> to run xfstest or xfs_repair?
The virtio device that I'm hitting is "/mnt/fast-ssd/vm-100TB-sparse.img"
which is a 100TB file on a 160GB XFS filesystem on an SSD, created
with
$ xfs_io -f -c "truncate 100t" -c "extsize 1m" /mnt/fast-ssd/vm-100TB-sparse.img
If I stat it, I get:
$ xfs_io -c stat /mnt/fast-ssd/vm-100TB-sparse.img
fd.path = "/mnt/fast-ssd/vm-100TB-sparse.img"
fd.flags = non-sync,non-direct,read-write
stat.ino = 131
stat.type = regular file
stat.size = 109951162777600
stat.blocks = 259333400
fsxattr.xflags = 0x800 [----------e---]
fsxattr.projid = 0
fsxattr.extsize = 1048576
fsxattr.nextents = 83108
fsxattr.naextents = 0
dioattr.mem = 0x200
dioattr.miniosz = 512
dioattr.maxiosz = 2147483136
$
The VM is run by this script:
$ cat run-vm-4.sh
#!/bin/sh
sudo /usr/bin/qemu-system-x86_64 \
-no-fd-bootchk \
-localtime \
-boot c \
-serial pty \
-nographic \
-alt-grab \
-smp 16 -m 16384 \
-machine accel=kvm \
-hda /vm-images/vm-4/root.img \
-drive file=/vm-images/vm-4/vm-4-test.img,if=virtio,cache=none \
-drive file=/vm-images/vm-4/vm-4-scratch.img,if=virtio,cache=none \
-drive file=/mnt/fast-ssd/vm-100TB-sparse.img,if=virtio,cache=none \
-drive file=/mnt/large/vm-17TB.img,if=virtio,cache=none \
-net nic,vlan=0,macaddr=00:e4:b6:63:63:70,model=virtio \
-net tap,vlan=0,script=/vm-images/qemu-ifup,downscript=no \
-kernel /vm-images/vm-4/vmlinuz \
-append "console=ttyS0,115200 root=/dev/sda1 numa=fake=4"
$
Inside the guest, I make and populate the XFS filesystem with 50m
inodes like so:
$ $ head -20 fsmark-50-test-xfs.sh
#!/bin/bash
sudo umount /mnt/scratch > /dev/null 2>&1
sudo mkfs.xfs -f $@ -l size=131072b /dev/vdc
sudo mount -o nobarrier,logbsize=256k /dev/vdc /mnt/scratch
sudo chmod 777 /mnt/scratch
cd /home/dave/src/fs_mark-3.3/
sudo sh -c "echo 1 > /proc/sys/fs/xfs/stats_clear"
time ./fs_mark -D 10000 -S0 -n 100000 -s 0 -L 32 \
-d /mnt/scratch/0 -d /mnt/scratch/1 \
-d /mnt/scratch/2 -d /mnt/scratch/3 \
-d /mnt/scratch/4 -d /mnt/scratch/5 \
-d /mnt/scratch/6 -d /mnt/scratch/7 \
-d /mnt/scratch/8 -d /mnt/scratch/9 \
-d /mnt/scratch/10 -d /mnt/scratch/11 \
-d /mnt/scratch/12 -d /mnt/scratch/13 \
-d /mnt/scratch/14 -d /mnt/scratch/15 \
| tee >(stats --trim-outliers | tail -1 1>&2)
sync
sudo umount /mnt/scratch > /dev/null 2>&1
$
It takes about 4 minutes to create all the files here, then
I run repair like this:
$ xfs_repair -v -v -t 1 -o bhash=32768 -o ag_stride=15 /dev/vdc
xfs_repair is driving around 15-18,000 read IOPS from 6-7 threads
on my hardware and takes around 15 minutes to run to completion.
Every second run on average dies with this setup.
I made some mods to xfs-repair this morning and I was getting it to
pushupwards of 60000 read IOPS from ~30 threads using ag_stride=3.
That was tending to trigger the problem in a couple of minutes.
So, really, this is just a highly concurrent, high IOPS direct IO
read workload....
I've also got other VMs running xfstests at much, much lower loads
and concurrency (e.g. 1/2p VMs with image files stored on spinning
rust) that are hitting this same problem once every few hours....
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [OOPS, 3.13-rc2] null ptr in dio_complete()
2013-12-04 1:58 ` Dave Chinner
2013-12-04 3:38 ` Dave Chinner
@ 2013-12-05 14:22 ` Ming Lei
2013-12-05 15:57 ` Jens Axboe
2013-12-05 21:26 ` Dave Chinner
1 sibling, 2 replies; 13+ messages in thread
From: Ming Lei @ 2013-12-05 14:22 UTC (permalink / raw)
To: Dave Chinner; +Cc: linux-kernel, Jens Axboe, Ming Lei
On Wed, 4 Dec 2013 12:58:38 +1100
Dave Chinner <david@fromorbit.com> wrote:
>
> And I just hit this from running xfs_repair which is doing
> multithreaded direct IO directly on /dev/vdc:
>
> [ 1776.508599] BUG: unable to handle kernel NULL pointer dereference at 0000000000000328
> [ 1776.510446] IP: [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
> [ 1776.511762] PGD 38e75b067 PUD 41987d067 PMD 0
> [ 1776.512577] Oops: 0000 [#1] SMP
> [ 1776.512577] Modules linked in:
> [ 1776.512577] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.13.0-rc2-dgc+ #75
> [ 1776.512577] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
> [ 1776.512577] task: ffffffff81f37480 ti: ffffffff81f26000 task.ti: ffffffff81f26000
> [ 1776.512577] RIP: 0010:[<ffffffff81755b6a>] [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
> [ 1776.512577] RSP: 0000:ffff88011bc03da8 EFLAGS: 00010046
> [ 1776.512577] RAX: 0000000010000000 RBX: 0000000000000000 RCX: 0000000000000000
> [ 1776.512577] RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffff8800dba59fc0
> [ 1776.512577] RBP: ffff88011bc03db8 R08: 0000000000000000 R09: ffff88021a828928
> [ 1776.512577] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000000
> [ 1776.512577] R13: 0000000000000000 R14: 0000000000002000 R15: 0000000000000000
> [ 1776.512577] FS: 0000000000000000(0000) GS:ffff88011bc00000(0000) knlGS:0000000000000000
> [ 1776.512577] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> [ 1776.512577] CR2: 0000000000000328 CR3: 000000041a4b0000 CR4: 00000000000006f0
> [ 1776.512577] Stack:
> [ 1776.512577] 0000000000000000 ffff8800dba59fc0 ffff88011bc03df8 ffffffff8175e4b8
> [ 1776.512577] 00000000000001c0 ffff8800dba59fc0 ffffe8fcfbc03a80 ffff88041aac0800
> [ 1776.512577] ffff88011ad53b10 0000000000000096 ffff88011bc03e08 ffffffff8175e536
> [ 1776.512577] Call Trace:
> [ 1776.512577] <IRQ>
> [ 1776.512577] [<ffffffff8175e4b8>] blk_mq_complete_request+0xb8/0x120
> [ 1776.512577] [<ffffffff8175e536>] __blk_mq_end_io+0x16/0x20
> [ 1776.512577] [<ffffffff8175e5a8>] blk_mq_end_io+0x68/0xd0
> [ 1776.512577] [<ffffffff81852e47>] virtblk_done+0x67/0x110
> [ 1776.512577] [<ffffffff817f7925>] vring_interrupt+0x35/0x60
> [ 1776.512577] [<ffffffff810e48a4>] handle_irq_event_percpu+0x54/0x1e0
> [ 1776.512577] [<ffffffff810e4a78>] handle_irq_event+0x48/0x70
> [ 1776.512577] [<ffffffff810e71d7>] handle_edge_irq+0x77/0x110
> [ 1776.512577] [<ffffffff8104796f>] handle_irq+0xbf/0x150
> [ 1776.512577] [<ffffffff81aec8c2>] ? __atomic_notifier_call_chain+0x12/0x20
> [ 1776.512577] [<ffffffff81aec8e6>] ? atomic_notifier_call_chain+0x16/0x20
> [ 1776.512577] [<ffffffff81af2b8a>] do_IRQ+0x5a/0xe0
> [ 1776.512577] [<ffffffff81ae892d>] common_interrupt+0x6d/0x6d
> [ 1776.512577] <EOI>
> [ 1776.512577] [<ffffffff8107e626>] ? native_safe_halt+0x6/0x10
> [ 1776.512577] [<ffffffff8104e50f>] default_idle+0x1f/0xc0
> [ 1776.512577] [<ffffffff8104edb6>] arch_cpu_idle+0x26/0x30
> [ 1776.512577] [<ffffffff810e3d81>] cpu_startup_entry+0x81/0x240
> [ 1776.512577] [<ffffffff81ad4f97>] rest_init+0x77/0x80
> [ 1776.512577] [<ffffffff82041ee7>] start_kernel+0x3c8/0x3d5
> [ 1776.512577] [<ffffffff8204191e>] ? repair_env_string+0x5e/0x5e
> [ 1776.512577] [<ffffffff82041117>] ? early_idt_handlers+0x117/0x120
> [ 1776.512577] [<ffffffff820415c2>] x86_64_start_reservations+0x2a/0x2c
> [ 1776.512577] [<ffffffff8204170a>] x86_64_start_kernel+0x146/0x155
> [ 1776.512577] Code: 54 41 89 c4 53 41 83 e4 01 48 2b 97 d8 00 00 00 48 8b 9f d0 00 00 00 4d 63 e4 65 44 8b 04 25 1c b0 00 00 49 8d 74 24 02 49 63 c8 <48> 8b 83 28 03
> [ 1776.512577] RIP [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
> [ 1776.512577] RSP <ffff88011bc03da8>
> [ 1776.512577] CR2: 0000000000000328
> [ 1776.512577] ---[ end trace 33a5787221ff13b4 ]---
> [ 1776.512577] Kernel panic - not syncing: Fatal exception in interrupt
> [ 1776.512577] Shutting down cpus with NMI
>
> So this is looking like another virtio+blk_mq problem....
This one might be caused by using-after-'free' request because the freed
request may be allocated to another CPU immediately, and the below patch
may be helpful, would you mind testing it?
diff --git a/block/blk-mq.c b/block/blk-mq.c
index 6875736..2358bdf 100644
--- a/block/blk-mq.c
+++ b/block/blk-mq.c
@@ -311,12 +311,12 @@ void blk_mq_complete_request(struct request *rq, int error)
blk_account_io_completion(rq, bytes);
+ blk_account_io_done(rq);
+
if (rq->end_io)
rq->end_io(rq, error);
else
blk_mq_free_request(rq);
-
- blk_account_io_done(rq);
}
void __blk_mq_end_io(struct request *rq, int error)
Thanks,
--
Ming Lei
^ permalink raw reply related [flat|nested] 13+ messages in thread
* Re: [OOPS, 3.13-rc2] null ptr in dio_complete()
2013-12-05 14:22 ` Ming Lei
@ 2013-12-05 15:57 ` Jens Axboe
2013-12-05 21:26 ` Dave Chinner
1 sibling, 0 replies; 13+ messages in thread
From: Jens Axboe @ 2013-12-05 15:57 UTC (permalink / raw)
To: Ming Lei, Dave Chinner; +Cc: linux-kernel
On 12/05/2013 07:22 AM, Ming Lei wrote:
> On Wed, 4 Dec 2013 12:58:38 +1100
> Dave Chinner <david@fromorbit.com> wrote:
>
>>
>> And I just hit this from running xfs_repair which is doing
>> multithreaded direct IO directly on /dev/vdc:
>>
>> [ 1776.508599] BUG: unable to handle kernel NULL pointer dereference at 0000000000000328
>> [ 1776.510446] IP: [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
>> [ 1776.511762] PGD 38e75b067 PUD 41987d067 PMD 0
>> [ 1776.512577] Oops: 0000 [#1] SMP
>> [ 1776.512577] Modules linked in:
>> [ 1776.512577] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.13.0-rc2-dgc+ #75
>> [ 1776.512577] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
>> [ 1776.512577] task: ffffffff81f37480 ti: ffffffff81f26000 task.ti: ffffffff81f26000
>> [ 1776.512577] RIP: 0010:[<ffffffff81755b6a>] [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
>> [ 1776.512577] RSP: 0000:ffff88011bc03da8 EFLAGS: 00010046
>> [ 1776.512577] RAX: 0000000010000000 RBX: 0000000000000000 RCX: 0000000000000000
>> [ 1776.512577] RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffff8800dba59fc0
>> [ 1776.512577] RBP: ffff88011bc03db8 R08: 0000000000000000 R09: ffff88021a828928
>> [ 1776.512577] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000000
>> [ 1776.512577] R13: 0000000000000000 R14: 0000000000002000 R15: 0000000000000000
>> [ 1776.512577] FS: 0000000000000000(0000) GS:ffff88011bc00000(0000) knlGS:0000000000000000
>> [ 1776.512577] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
>> [ 1776.512577] CR2: 0000000000000328 CR3: 000000041a4b0000 CR4: 00000000000006f0
>> [ 1776.512577] Stack:
>> [ 1776.512577] 0000000000000000 ffff8800dba59fc0 ffff88011bc03df8 ffffffff8175e4b8
>> [ 1776.512577] 00000000000001c0 ffff8800dba59fc0 ffffe8fcfbc03a80 ffff88041aac0800
>> [ 1776.512577] ffff88011ad53b10 0000000000000096 ffff88011bc03e08 ffffffff8175e536
>> [ 1776.512577] Call Trace:
>> [ 1776.512577] <IRQ>
>> [ 1776.512577] [<ffffffff8175e4b8>] blk_mq_complete_request+0xb8/0x120
>> [ 1776.512577] [<ffffffff8175e536>] __blk_mq_end_io+0x16/0x20
>> [ 1776.512577] [<ffffffff8175e5a8>] blk_mq_end_io+0x68/0xd0
>> [ 1776.512577] [<ffffffff81852e47>] virtblk_done+0x67/0x110
>> [ 1776.512577] [<ffffffff817f7925>] vring_interrupt+0x35/0x60
>> [ 1776.512577] [<ffffffff810e48a4>] handle_irq_event_percpu+0x54/0x1e0
>> [ 1776.512577] [<ffffffff810e4a78>] handle_irq_event+0x48/0x70
>> [ 1776.512577] [<ffffffff810e71d7>] handle_edge_irq+0x77/0x110
>> [ 1776.512577] [<ffffffff8104796f>] handle_irq+0xbf/0x150
>> [ 1776.512577] [<ffffffff81aec8c2>] ? __atomic_notifier_call_chain+0x12/0x20
>> [ 1776.512577] [<ffffffff81aec8e6>] ? atomic_notifier_call_chain+0x16/0x20
>> [ 1776.512577] [<ffffffff81af2b8a>] do_IRQ+0x5a/0xe0
>> [ 1776.512577] [<ffffffff81ae892d>] common_interrupt+0x6d/0x6d
>> [ 1776.512577] <EOI>
>> [ 1776.512577] [<ffffffff8107e626>] ? native_safe_halt+0x6/0x10
>> [ 1776.512577] [<ffffffff8104e50f>] default_idle+0x1f/0xc0
>> [ 1776.512577] [<ffffffff8104edb6>] arch_cpu_idle+0x26/0x30
>> [ 1776.512577] [<ffffffff810e3d81>] cpu_startup_entry+0x81/0x240
>> [ 1776.512577] [<ffffffff81ad4f97>] rest_init+0x77/0x80
>> [ 1776.512577] [<ffffffff82041ee7>] start_kernel+0x3c8/0x3d5
>> [ 1776.512577] [<ffffffff8204191e>] ? repair_env_string+0x5e/0x5e
>> [ 1776.512577] [<ffffffff82041117>] ? early_idt_handlers+0x117/0x120
>> [ 1776.512577] [<ffffffff820415c2>] x86_64_start_reservations+0x2a/0x2c
>> [ 1776.512577] [<ffffffff8204170a>] x86_64_start_kernel+0x146/0x155
>> [ 1776.512577] Code: 54 41 89 c4 53 41 83 e4 01 48 2b 97 d8 00 00 00 48 8b 9f d0 00 00 00 4d 63 e4 65 44 8b 04 25 1c b0 00 00 49 8d 74 24 02 49 63 c8 <48> 8b 83 28 03
>> [ 1776.512577] RIP [<ffffffff81755b6a>] blk_account_io_done+0x6a/0x180
>> [ 1776.512577] RSP <ffff88011bc03da8>
>> [ 1776.512577] CR2: 0000000000000328
>> [ 1776.512577] ---[ end trace 33a5787221ff13b4 ]---
>> [ 1776.512577] Kernel panic - not syncing: Fatal exception in interrupt
>> [ 1776.512577] Shutting down cpus with NMI
>>
>> So this is looking like another virtio+blk_mq problem....
>
> This one might be caused by using-after-'free' request because the freed
> request may be allocated to another CPU immediately, and the below patch
> may be helpful, would you mind testing it?
>
> diff --git a/block/blk-mq.c b/block/blk-mq.c
> index 6875736..2358bdf 100644
> --- a/block/blk-mq.c
> +++ b/block/blk-mq.c
> @@ -311,12 +311,12 @@ void blk_mq_complete_request(struct request *rq, int error)
>
> blk_account_io_completion(rq, bytes);
>
> + blk_account_io_done(rq);
> +
> if (rq->end_io)
> rq->end_io(rq, error);
> else
> blk_mq_free_request(rq);
> -
> - blk_account_io_done(rq);
> }
>
> void __blk_mq_end_io(struct request *rq, int error)
That's definitely a bug... Good catch, Ming. Applied.
--
Jens Axboe
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [OOPS, 3.13-rc2] null ptr in dio_complete()
2013-12-05 14:22 ` Ming Lei
2013-12-05 15:57 ` Jens Axboe
@ 2013-12-05 21:26 ` Dave Chinner
2013-12-05 23:16 ` Dave Chinner
1 sibling, 1 reply; 13+ messages in thread
From: Dave Chinner @ 2013-12-05 21:26 UTC (permalink / raw)
To: Ming Lei; +Cc: linux-kernel, Jens Axboe
On Thu, Dec 05, 2013 at 10:22:20PM +0800, Ming Lei wrote:
> On Wed, 4 Dec 2013 12:58:38 +1100
> Dave Chinner <david@fromorbit.com> wrote:
>
> >
> > And I just hit this from running xfs_repair which is doing
> > multithreaded direct IO directly on /dev/vdc:
.....
> > So this is looking like another virtio+blk_mq problem....
>
> This one might be caused by using-after-'free' request because the freed
> request may be allocated to another CPU immediately, and the below patch
> may be helpful, would you mind testing it?
>
> diff --git a/block/blk-mq.c b/block/blk-mq.c
> index 6875736..2358bdf 100644
> --- a/block/blk-mq.c
> +++ b/block/blk-mq.c
> @@ -311,12 +311,12 @@ void blk_mq_complete_request(struct request *rq, int error)
>
> blk_account_io_completion(rq, bytes);
>
> + blk_account_io_done(rq);
> +
> if (rq->end_io)
> rq->end_io(rq, error);
> else
> blk_mq_free_request(rq);
> -
> - blk_account_io_done(rq);
> }
>
> void __blk_mq_end_io(struct request *rq, int error)
Testing it now. I'll let you know how it goes in couple of hours.
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [OOPS, 3.13-rc2] null ptr in dio_complete()
2013-12-05 21:26 ` Dave Chinner
@ 2013-12-05 23:16 ` Dave Chinner
2013-12-06 16:46 ` Jens Axboe
0 siblings, 1 reply; 13+ messages in thread
From: Dave Chinner @ 2013-12-05 23:16 UTC (permalink / raw)
To: Ming Lei; +Cc: linux-kernel, Jens Axboe
On Fri, Dec 06, 2013 at 08:26:51AM +1100, Dave Chinner wrote:
> On Thu, Dec 05, 2013 at 10:22:20PM +0800, Ming Lei wrote:
> > On Wed, 4 Dec 2013 12:58:38 +1100
> > Dave Chinner <david@fromorbit.com> wrote:
> >
> > >
> > > And I just hit this from running xfs_repair which is doing
> > > multithreaded direct IO directly on /dev/vdc:
> .....
> > > So this is looking like another virtio+blk_mq problem....
> >
> > This one might be caused by using-after-'free' request because the freed
> > request may be allocated to another CPU immediately, and the below patch
> > may be helpful, would you mind testing it?
> >
> > diff --git a/block/blk-mq.c b/block/blk-mq.c
> > index 6875736..2358bdf 100644
> > --- a/block/blk-mq.c
> > +++ b/block/blk-mq.c
> > @@ -311,12 +311,12 @@ void blk_mq_complete_request(struct request *rq, int error)
> >
> > blk_account_io_completion(rq, bytes);
> >
> > + blk_account_io_done(rq);
> > +
> > if (rq->end_io)
> > rq->end_io(rq, error);
> > else
> > blk_mq_free_request(rq);
> > -
> > - blk_account_io_done(rq);
> > }
> >
> > void __blk_mq_end_io(struct request *rq, int error)
>
> Testing it now. I'll let you know how it goes in couple of hours.
Ok, this looks like it is working correctly. The read/write io stats
are now working properly, too. Thanks for finding the problem
quickly!
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [OOPS, 3.13-rc2] null ptr in dio_complete()
2013-12-05 23:16 ` Dave Chinner
@ 2013-12-06 16:46 ` Jens Axboe
0 siblings, 0 replies; 13+ messages in thread
From: Jens Axboe @ 2013-12-06 16:46 UTC (permalink / raw)
To: Dave Chinner, Ming Lei; +Cc: linux-kernel
On 12/05/2013 04:16 PM, Dave Chinner wrote:
> On Fri, Dec 06, 2013 at 08:26:51AM +1100, Dave Chinner wrote:
>> On Thu, Dec 05, 2013 at 10:22:20PM +0800, Ming Lei wrote:
>>> On Wed, 4 Dec 2013 12:58:38 +1100
>>> Dave Chinner <david@fromorbit.com> wrote:
>>>
>>>>
>>>> And I just hit this from running xfs_repair which is doing
>>>> multithreaded direct IO directly on /dev/vdc:
>> .....
>>>> So this is looking like another virtio+blk_mq problem....
>>>
>>> This one might be caused by using-after-'free' request because the freed
>>> request may be allocated to another CPU immediately, and the below patch
>>> may be helpful, would you mind testing it?
>>>
>>> diff --git a/block/blk-mq.c b/block/blk-mq.c
>>> index 6875736..2358bdf 100644
>>> --- a/block/blk-mq.c
>>> +++ b/block/blk-mq.c
>>> @@ -311,12 +311,12 @@ void blk_mq_complete_request(struct request *rq, int error)
>>>
>>> blk_account_io_completion(rq, bytes);
>>>
>>> + blk_account_io_done(rq);
>>> +
>>> if (rq->end_io)
>>> rq->end_io(rq, error);
>>> else
>>> blk_mq_free_request(rq);
>>> -
>>> - blk_account_io_done(rq);
>>> }
>>>
>>> void __blk_mq_end_io(struct request *rq, int error)
>>
>> Testing it now. I'll let you know how it goes in couple of hours.
>
> Ok, this looks like it is working correctly. The read/write io stats
> are now working properly, too. Thanks for finding the problem
> quickly!
Great, thanks for testing, Dave. The fix is now in Linus' tree.
--
Jens Axboe
^ permalink raw reply [flat|nested] 13+ messages in thread
end of thread, other threads:[~2013-12-06 16:47 UTC | newest]
Thread overview: 13+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2013-12-03 21:59 [OOPS, 3.13-rc2] null ptr in dio_complete() Dave Chinner
2013-12-04 1:58 ` Dave Chinner
2013-12-04 3:38 ` Dave Chinner
2013-12-04 3:47 ` Jens Axboe
2013-12-04 4:17 ` Dave Chinner
2013-12-04 23:56 ` Dave Chinner
2013-12-05 3:41 ` Jens Axboe
2013-12-05 4:49 ` Dave Chinner
2013-12-05 14:22 ` Ming Lei
2013-12-05 15:57 ` Jens Axboe
2013-12-05 21:26 ` Dave Chinner
2013-12-05 23:16 ` Dave Chinner
2013-12-06 16:46 ` Jens Axboe
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).