* [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