[BUG 4.4.26] bio->bi_bdev == NULL in raid6 return_io()

From: Konstantin Khlebnikov
Date: Sat Nov 05 2016 - 06:56:40 EST


return_io() resolves request_queue even if trace point isn't active:

static inline struct request_queue *bdev_get_queue(struct block_device *bdev)
{
return bdev->bd_disk->queue; /* this is never NULL */
}

static void return_io(struct bio_list *return_bi)
{
struct bio *bi;
while ((bi = bio_list_pop(return_bi)) != NULL) {
bi->bi_iter.bi_size = 0;
trace_block_bio_complete(bdev_get_queue(bi->bi_bdev),
bi, 0);
bio_endio(bi);
}
}

kernel build with gcc version 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5) from ubuntu precise

<6>[ 1659.710716] md: md2: resync done.
<6>[ 1659.968273] md: resync of RAID array md0
<6>[ 1659.968281] md: minimum _guaranteed_ speed: 1000 KB/sec/disk.
<6>[ 1659.968284] md: using maximum available idle IO bandwidth (but not more than 200000 KB/sec) for resync.
<6>[ 1659.968310] md: using 128k window, over a total of 16770816k.
<6>[ 1659.968311] md: resuming resync of md0 from checkpoint.
<7>[ 1659.968674] RAID conf printout:
<7>[ 1659.968678] --- level:6 rd:6 wd:6
<7>[ 1659.968680] disk 0, o:1, dev:sda3
<7>[ 1659.968682] disk 1, o:1, dev:sdc3
<7>[ 1659.968683] disk 2, o:1, dev:sdb3
<7>[ 1659.968684] disk 3, o:1, dev:sdd3
<7>[ 1659.968685] disk 4, o:1, dev:sde3
<7>[ 1659.968686] disk 5, o:1, dev:sdf3
<7>[ 1779.468199] RAID conf printout:
<7>[ 1779.468204] --- level:6 rd:6 wd:6
<7>[ 1779.468206] disk 0, o:1, dev:sda1
<7>[ 1779.468208] disk 1, o:1, dev:sdc1
<7>[ 1779.468209] disk 2, o:1, dev:sdb1
<7>[ 1779.468210] disk 3, o:1, dev:sdd1
<7>[ 1779.468211] disk 4, o:1, dev:sde1
<7>[ 1779.468212] disk 5, o:1, dev:sdf1
<1>[ 4658.730260] IP: return_io (include/linux/blkdev.h:825 drivers/md/raid5.c:231) raid456
<4>[ 4658.737189] PGD 0
<4>[ 4658.739452] Oops: 0000 [#1] SMP
<4>[ 4658.743080] Modules linked in: netconsole(E) configfs(E) unix_diag(E) tcp_diag(E) inet_diag(E) ip6t_REJECT(E) nf_reject_ipv6(E) ip6table_filter(E) ip6table_mangle(E) ip6_tables(E) ipt_R
EJECT(E) nf_reject_ipv4(E) iptable_filter(E) iptable_mangle(E) ip_tables(E) x_tables(E) ipmi_devintf(E) nfsd(E) nfs_acl(E) auth_rpcgss(E) nfs(E) fscache(E) lockd(E) sunrpc(E) grace(E) cls_u32
(E) sch_prio(E) ipmi_ssif(E) intel_rapl(E) iosf_mbi(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) 8021q(E) coretemp(E) mrp(E) garp(E) stp(E) kvm_intel(E) llc(E) kvm(E) irqbypass(E) crc32_pcl
mul(E) sb_edac(E) serio_raw(E) joydev(E) input_leds(E) edac_core(E) mei_me(E) mei(E) ioatdma(E) lpc_ich(E) ipmi_si(E) 8250_fintek(E) ipmi_msghandler(E) shpchp(E) wmi(E) mac_hid(E) ip6_tunnel(
E) tunnel6(E) ipip(E) ip_tunnel(E) tunnel4(E) xfs(E)<4>[ 4658.822823] raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) hid_generic(E) usb
hid(E) raid6_pq(E) libcrc32c(E) hid(E) igb(E) i2c_algo_bit(E) raid1(E) isci(E) dca(E) raid0(E) ptp(E) multipath(E) libsas(E) ahci(E) pps_core(E) scsi_transport_sas(E) psmouse(E) libahci(E) fj
es(E) linear(E)
<4>[ 4658.855131] CPU: 14 PID: 501 Comm: md2_raid6 Tainted: G E 4.4.26-9 #1
<4>[ 4658.863621] Hardware name: Supermicro X9DRW/X9DRW, BIOS 3.00 07/05/2013
<4>[ 4658.871041] task: ffff882035781a80 ti: ffff882033c08000 task.ti: ffff882033c08000
<4>[ 4658.879455] RIP: return_io (include/linux/blkdev.h:825 drivers/md/raid5.c:231) raid456
<4>[ 4658.889155] RSP: 0018:ffff882033c0bb18 EFLAGS: 00010246
<4>[ 4658.895118] RAX: 0000000000000000 RBX: ffff881ff22af2c0 RCX: ffff881ff22af4e0
<4>[ 4658.903122] RDX: 0000000000000000 RSI: ffff881ff22af2c0 RDI: ffff882033c0bc28
<4>[ 4658.911127] RBP: ffff882033c0bb48 R08: 0000000000000000 R09: 0000000000000000
<4>[ 4658.919130] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88203643db00
<4>[ 4658.927134] R13: 0000000000000006 R14: 0000000000000004 R15: ffff882033c0bc28
<4>[ 4658.935139] FS: 0000000000000000(0000) GS:ffff88203f380000(0000) knlGS:0000000000000000
<4>[ 4658.944233] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[ 4658.950683] CR2: 0000000000000098 CR3: 0000000001e0b000 CR4: 00000000000406e0
<4>[ 4658.958682] Stack:
<4>[ 4658.960952] ffff882033c0bb78 ffff881ff22af2c0 ffff8820354b0800 0000000000000006
<4>[ 4658.969329] 0000000000000004 0000000000000006 ffff882033c0bc88 ffffffffa015c0dd
<4>[ 4658.977697] 0000000000000000 ffff8820354b0a78 0000000000000000 0000000000000000
<4>[ 4658.986067] Call Trace:
<4>[ 4658.988827] handle_stripe (drivers/md/raid5.c:4635) raid456
<4>[ 4658.996156] ? default_wake_function (kernel/sched/core.c:3376)
<4>[ 4659.003190] ? autoremove_wake_function (kernel/sched/wait.c:295)
<4>[ 4659.010516] ? __wake_up_common (kernel/sched/wait.c:73)
<4>[ 4659.017065] handle_active_stripes.isra.49 (drivers/md/raid5.c:5776) raid456
<4>[ 4659.025877] raid5d (drivers/md/raid5.c:5889) raid456
<4>[ 4659.032428] ? _raw_spin_lock_irqsave (./arch/x86/include/asm/paravirt.h:696 ./arch/x86/include/asm/qspinlock.h:28 include/asm-generic/qspinlock.h:102 include/linux/spinlock.h:155 include/linux/spinlock_api_smp.h:121 kernel/locking/spinlock.c:159)
<4>[ 4659.039559] md_thread (drivers/md/md.c:7099)
<4>[ 4659.045434] ? add_wait_queue (kernel/sched/wait.c:292)
<4>[ 4659.051786] ? md_rdev_init (drivers/md/md.c:7083)
<4>[ 4659.058140] kthread (kernel/kthread.c:209)
<4>[ 4659.063618] ? flush_kthread_worker (kernel/kthread.c:178)
<4>[ 4659.070554] ret_from_fork (arch/x86/entry/entry_64.S:469)
<4>[ 4659.076619] ? flush_kthread_worker (kernel/kthread.c:178)
<4>[ 4659.083553] Code: 83 ec 08 eb 41 49 8b 04 24 48 85 c0 49 89 07 0f 84 a3 00 00 00 49 8b 44 24 08 49 c7 04 24 00 00 00 00 41 c7 44 24 28 00 00 00 00 <48> 8b 80 98 00 00 00 4c 8b a8 c0 03 00 00 66 66 66 66 90 4c 89
All code
========
0: 83 ec 08 sub $0x8,%esp
3: eb 41 jmp 0x46
5: 49 8b 04 24 mov (%r12),%rax
9: 48 85 c0 test %rax,%rax
c: 49 89 07 mov %rax,(%r15)
f: 0f 84 a3 00 00 00 je 0xb8
15: 49 8b 44 24 08 mov 0x8(%r12),%rax
1a: 49 c7 04 24 00 00 00 movq $0x0,(%r12)
21: 00
22: 41 c7 44 24 28 00 00 movl $0x0,0x28(%r12)
29: 00 00
2b:* 48 8b 80 98 00 00 00 mov 0x98(%rax),%rax <-- trapping instruction
32: 4c 8b a8 c0 03 00 00 mov 0x3c0(%rax),%r13
39: 66 66 66 66 90 data32 data32 data32 xchg %ax,%ax
3e: 4c rex.WR
3f: 89 .byte 0x89

Code starting with the faulting instruction
===========================================
0: 48 8b 80 98 00 00 00 mov 0x98(%rax),%rax
7: 4c 8b a8 c0 03 00 00 mov 0x3c0(%rax),%r13
e: 66 66 66 66 90 data32 data32 data32 xchg %ax,%ax
13: 4c rex.WR
14: 89 .byte 0x89
<1>[ 4659.105577] RIP return_io (include/linux/blkdev.h:825 drivers/md/raid5.c:231) raid456


Couple times kernel failed second dereference

<6>[ 1815.549178] md: md2: resync done.
<7>[ 1815.675433] RAID conf printout:
<7>[ 1815.675439] --- level:6 rd:6 wd:6
<7>[ 1815.675441] disk 0, o:1, dev:sda3
<7>[ 1815.675442] disk 1, o:1, dev:sdb3
<7>[ 1815.675443] disk 2, o:1, dev:sdc3
<7>[ 1815.675444] disk 3, o:1, dev:sdd3
<7>[ 1815.675445] disk 4, o:1, dev:sde3
<7>[ 1815.675446] disk 5, o:1, dev:sdf3

<1>[ 2698.718595] IP: return_io (include/linux/blkdev.h:825 drivers/md/raid5.c:231) raid456
<4>[ 2698.725521] PGD 0
<4>[ 2698.727774] Oops: 0000 [#1] SMP
<4>[ 2698.731409] Modules linked in: netconsole(E) configfs(E) unix_diag(E) tcp_diag(E) inet_diag(E) ip6table_filter(E) ip6_tables(E) iptable_filter(E) ip_tables(E) x_tables(E) ipmi_devintf(E
) nfsd(E) nfs_acl(E) auth_rpcgss(E) nfs(E) fscache(E) lockd(E) sunrpc(E) grace(E) cls_u32(E) sch_prio(E) ipmi_ssif(E) intel_rapl(E) iosf_mbi(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) cor
etemp(E) kvm_intel(E) kvm(E) 8021q(E) irqbypass(E) mrp(E) garp(E) crc32_pclmul(E) stp(E) llc(E) serio_raw(E) input_leds(E) joydev(E) sb_edac(E) edac_core(E) mei_me(E) lpc_ich(E) mei(E) ipmi_s
i(E) ioatdma(E) ipmi_msghandler(E) 8250_fintek(E) shpchp(E) wmi(E) mac_hid(E) ip6_tunnel(E) tunnel6(E) ipip(E) ip_tunnel(E) tunnel4(E) xfs(E) raid10(E) raid456(E) async_raid6_recov(E) async_m
emcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E)<4>[ 2698.811146] hid_generic(E) raid6_pq(E) libcrc32c(E) usbhid(E) igb(E) hid(E) i2c_algo_bit(E) raid1(E) isci(E) dca(E) raid0(E) libsas(
E) ahci(E) ptp(E) multipath(E) psmouse(E) libahci(E) scsi_transport_sas(E) pps_core(E) linear(E) fjes(E)
<4>[ 2698.833480] CPU: 2 PID: 514 Comm: md2_raid6 Tainted: G E 4.4.26-9 #1
<4>[ 2698.841845] Hardware name: Supermicro X9DRW/X9DRW, BIOS 3.0c 10/30/2014
<4>[ 2698.849241] task: ffff882033ec1a80 ti: ffff882033ef4000 task.ti: ffff882033ef4000
<4>[ 2698.857656] RIP: return_io (include/linux/blkdev.h:825 drivers/md/raid5.c:231) raid456
<4>[ 2698.867346] RSP: 0018:ffff882033ef7b18 EFLAGS: 00010246
<4>[ 2698.873307] RAX: 0000000000000000 RBX: ffff881fef26afd0 RCX: ffff881fef26b1f0
<4>[ 2698.881311] RDX: 0000000000000000 RSI: ffff881fef26afd0 RDI: ffff882033ef7c28
<4>[ 2698.889314] RBP: ffff882033ef7b48 R08: 0000000000000000 R09: 0000000000000000
<4>[ 2698.897319] R10: 0000000000000000 R11: 0000000000000000 R12: ffff880f9880cd00
<4>[ 2698.905322] R13: 0000000000000006 R14: 0000000000000004 R15: ffff882033ef7c28
<4>[ 2698.913327] FS: 0000000000000000(0000) GS:ffff88103fa80000(0000) knlGS:0000000000000000
<4>[ 2698.922420] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[ 2698.928869] CR2: 00000000000003c0 CR3: 0000000001e0b000 CR4: 00000000000406e0
<4>[ 2698.936871] Stack:
<4>[ 2698.939153] ffff882033ef7b78 ffff881fef26afd0 ffff8810355cbc00 0000000000000006
<4>[ 2698.947512] 0000000000000004 0000000000000006 ffff882033ef7c88 ffffffffa01970dd
<4>[ 2698.955867] 0000000000000000 ffff8810355cbe78 0000000000000000 0000000000000000
<4>[ 2698.964222] Call Trace:
<4>[ 2698.966982] handle_stripe (drivers/md/raid5.c:4635) raid456
<4>[ 2698.974318] ? default_wake_function (kernel/sched/core.c:3376)
<4>[ 2698.981350] ? autoremove_wake_function (kernel/sched/wait.c:295)
<4>[ 2698.988665] ? __wake_up_common (kernel/sched/wait.c:73)
<4>[ 2698.995214] handle_active_stripes.isra.49 (drivers/md/raid5.c:5776) raid456
<4>[ 2699.004020] raid5d (drivers/md/raid5.c:5889) raid456
<4>[ 2699.010571] ? _raw_spin_lock_irqsave (./arch/x86/include/asm/paravirt.h:696 ./arch/x86/include/asm/qspinlock.h:28 include/asm-generic/qspinlock.h:102 include/linux/spinlock.h:155 include/linux/spinlock_api_smp.h:121 kernel/locking/spinlock.c:159)
<4>[ 2699.017711] md_thread (drivers/md/md.c:7099)
<4>[ 2699.023592] ? add_wait_queue (kernel/sched/wait.c:292)
<4>[ 2699.029952] ? md_rdev_init (drivers/md/md.c:7083)
<4>[ 2699.036305] kthread (kernel/kthread.c:209)
<4>[ 2699.041783] ? flush_kthread_worker (kernel/kthread.c:178)
<4>[ 2699.048719] ret_from_fork (arch/x86/entry/entry_64.S:469)
<4>[ 2699.054779] ? flush_kthread_worker (kernel/kthread.c:178)
<4>[ 2699.061713] Code: 04 24 48 85 c0 49 89 07 0f 84 a3 00 00 00 49 8b 44 24 08 49 c7 04 24 00 00 00 00 41 c7 44 24 28 00 00 00 00 48 8b 80 98 00 00 00 <4c> 8b a8 c0 03 00 00 66 66 66 66 90 4c 89 e7 e8 f4 09 20 e1 4d
All code
========
0: 04 24 add $0x24,%al
2: 48 85 c0 test %rax,%rax
5: 49 89 07 mov %rax,(%r15)
8: 0f 84 a3 00 00 00 je 0xb1
e: 49 8b 44 24 08 mov 0x8(%r12),%rax
13: 49 c7 04 24 00 00 00 movq $0x0,(%r12)
1a: 00
1b: 41 c7 44 24 28 00 00 movl $0x0,0x28(%r12)
22: 00 00
24: 48 8b 80 98 00 00 00 mov 0x98(%rax),%rax
2b:* 4c 8b a8 c0 03 00 00 mov 0x3c0(%rax),%r13 <-- trapping instruction
32: 66 66 66 66 90 data32 data32 data32 xchg %ax,%ax
37: 4c 89 e7 mov %r12,%rdi
3a: e8 f4 09 20 e1 callq 0xffffffffe1200a33
3f: 4d rex.WRB

Code starting with the faulting instruction
===========================================
0: 4c 8b a8 c0 03 00 00 mov 0x3c0(%rax),%r13
7: 66 66 66 66 90 data32 data32 data32 xchg %ax,%ax
c: 4c 89 e7 mov %r12,%rdi
f: e8 f4 09 20 e1 callq 0xffffffffe1200a08
14: 4d rex.WRB


--
Konstantin