Crash during SATA reads

Crash during SATA reads

[Glenn Maynard]

I'm hitting a frequent crash during a simple 'dd if=/dev/sdb | gzip >
/dev/null'.  It's reading off of a 500G drive, and tends to reproduce
something on the order of once per 50-100 gigs of data.  I havn't yet
reproduced it without gzip in the middle.  No partitions of /dev/sdb
are mounted.  It's reproduced several times with the same trace.

BUG: unable to handle kernel NULL pointer dereference at (null)
IP: [<(null)>] (null)
*pde = 00000000
Oops: 0000 [#1] PREEMPT
last sysfs file:
Modules linked in: netconsole rtc atl1c

Pid: 1311, comm: gzip Not tainted (2.6.31.6 #1) G31M-ES2L
EIP: 0060:[<00000000>] EFLAGS: 00010246 CPU: 0
EIP is at 0x0
EAX: c1ae78c0 EBX: c107cca9 ECX: c1ae78c0 EDX: 00000000
ESI: c1ae78c0 EDI: dfa3b2c0 EBP: df29bed0 ESP: df29be94
 DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
Process gzip (pid: 1311, ti=df29a000 task=df916800 task.ti=df29a000)
Stack:
 c107ccb1 c107e549 00000200 c11587bc 00000000 00000001 df430a94 00000000
<0> 00000000 00005000 0000b000 00000000 dfa3b2c0 00000000 dfa3b2c0 dfa0f168
<0> c1158936 dfa20980 00000000 c11589ed 00000000 dfa20980 00000000 dfa3b2c0
Call Trace:
 [<c107ccb1>] ? end_bio_bh_io_sync+0x28/0x30
 [<c107e549>] ? bio_endio+0x24/0x26
 [<c11587bc>] ? blk_update_request+0xdf/0x24e
 [<c1158936>] ? blk_update_bidi_request+0xb/0x41
 [<c11589ed>] ? blk_end_bidi_request+0x10/0x4f
 [<c1158a5c>] ? blk_end_request+0x7/0xc
 [<c11abcb2>] ? scsi_end_request+0x17/0x69
 [<c11abfc3>] ? scsi_io_completion+0x173/0x335
 [<c11a8330>] ? scsi_finish_command+0x70/0x86
 [<c11ac6a6>] ? scsi_softirq_done+0xd7/0xdc
 [<c115b3f1>] ? blk_done_softirq+0x51/0x5d
 [<c101bde0>] ? __do_softirq+0x5f/0xc8
 [<c101be6b>] ? do_softirq+0x22/0x26
 [<c101becd>] ? irq_exit+0x29/0x34
 [<c1004097>] ? do_IRQ+0x53/0x63
 [<c1002ea9>] ? common_interrupt+0x29/0x30
Code:  Bad EIP value.
EIP: [<00000000>] 0x0 SS:ESP 0068:df29be94
CR2: 0000000000000000
---[ end trace 79f49d6371afc159 ]---
Kernel panic - not syncing: Fatal exception in interrupt
Pid: 1311, comm: gzip Tainted: G      D    2.6.31.6 #1
Call Trace:
 [<c101824c>] ? panic+0x41/0xde
 [<c1004dcf>] ? oops_end+0x5c/0x66
 [<c107cca9>] ? end_bio_bh_io_sync+0x20/0x30
 [<c100eca7>] ? bad_area_nosemaphore+0xa/0xc
 [<c126564e>] ? error_code+0x5e/0x64
 [<c107cca9>] ? end_bio_bh_io_sync+0x20/0x30
 [<c107007b>] ? file_update_time+0x8c/0xd8
 [<c100ee87>] ? do_page_fault+0x0/0x1f9
 [<c107ccb1>] ? end_bio_bh_io_sync+0x28/0x30
 [<c107e549>] ? bio_endio+0x24/0x26
 [<c11587bc>] ? blk_update_request+0xdf/0x24e
 [<c1158936>] ? blk_update_bidi_request+0xb/0x41
 [<c11589ed>] ? blk_end_bidi_request+0x10/0x4f
 [<c1158a5c>] ? blk_end_request+0x7/0xc
 [<c11abcb2>] ? scsi_end_request+0x17/0x69
 [<c11abfc3>] ? scsi_io_completion+0x173/0x335
 [<c11a8330>] ? scsi_finish_command+0x70/0x86
 [<c11ac6a6>] ? scsi_softirq_done+0xd7/0xdc
 [<c115b3f1>] ? blk_done_softirq+0x51/0x5d
 [<c101bde0>] ? __do_softirq+0x5f/0xc8
 [<c101be6b>] ? do_softirq+0x22/0x26
 [<c101becd>] ? irq_exit+0x29/0x34
 [<c1004097>] ? do_IRQ+0x53/0x63
 [<c1002ea9>] ? common_interrupt+0x29/0x30

0000:00:00.0 Host bridge: Intel Corporation: Unknown device 29c0 (rev 10)
        Subsystem: Giga-byte Technology: Unknown device 5000
        Flags: bus master, fast devsel, latency 0
        Capabilities: [e0] #09 [b10b]

0000:00:01.0 PCI bridge: Intel Corporation: Unknown device 29c1 (rev
10) (prog-if 00 [Normal decode])
        Flags: bus master, fast devsel, latency 0
        Bus: primary=00, secondary=01, subordinate=01, sec-latency=0
        I/O behind bridge: 0000c000-0000cfff
        Memory behind bridge: f0000000-f3ffffff
        Prefetchable memory behind bridge: 00000000e0000000-00000000eff00000
        Capabilities: [88] #0d [0000]
        Capabilities: [80] Power Management version 3
        Capabilities: [90] Message Signalled Interrupts: 64bit-
Queue=0/0 Enable-
        Capabilities: [a0] #10 [0141]

0000:00:1b.0 0403: Intel Corporation 82801G (ICH7 Family) High
Definition Audio Controller (rev 01)
        Subsystem: Giga-byte Technology: Unknown device a002
        Flags: bus master, fast devsel, latency 0, IRQ 12
        Memory at f4100000 (64-bit, non-prefetchable) [size=16K]
        Capabilities: [50] Power Management version 2
        Capabilities: [60] Message Signalled Interrupts: 64bit+
Queue=0/0 Enable-
        Capabilities: [70] #10 [0091]

0000:00:1c.0 PCI bridge: Intel Corporation 82801G (ICH7 Family) PCI
Express Port 1 (rev 01) (prog-if 00 [Normal decode])
        Flags: bus master, fast devsel, latency 0
        Bus: primary=00, secondary=02, subordinate=02, sec-latency=0
        I/O behind bridge: 0000b000-0000bfff
        Capabilities: [40] #10 [0141]
        Capabilities: [80] Message Signalled Interrupts: 64bit-
Queue=0/0 Enable-
        Capabilities: [90] #0d [0000]
        Capabilities: [a0] Power Management version 2

0000:00:1c.1 PCI bridge: Intel Corporation 82801G (ICH7 Family) PCI
Express Port 2 (rev 01) (prog-if 00 [Normal decode])
        Flags: bus master, fast devsel, latency 0
        Bus: primary=00, secondary=03, subordinate=03, sec-latency=0
        I/O behind bridge: 0000d000-0000dfff
        Memory behind bridge: f4000000-f40fffff
        Capabilities: [40] #10 [0141]
        Capabilities: [80] Message Signalled Interrupts: 64bit-
Queue=0/0 Enable-
        Capabilities: [90] #0d [0000]
        Capabilities: [a0] Power Management version 2

0000:00:1d.0 USB Controller: Intel Corporation 82801G (ICH7 Family)
USB UHCI #1 (rev 01) (prog-if 00 [UHCI])
        Subsystem: Giga-byte Technology: Unknown device 5004
        Flags: bus master, medium devsel, latency 0, IRQ 5
        I/O ports at e000 [size=32]

0000:00:1d.1 USB Controller: Intel Corporation 82801G (ICH7 Family)
USB UHCI #2 (rev 01) (prog-if 00 [UHCI])
        Subsystem: Giga-byte Technology: Unknown device 5004
        Flags: bus master, medium devsel, latency 0, IRQ 11
        I/O ports at e100 [size=32]

0000:00:1d.2 USB Controller: Intel Corporation 82801G (ICH7 Family)
USB UHCI #3 (rev 01) (prog-if 00 [UHCI])
        Subsystem: Giga-byte Technology: Unknown device 5004
        Flags: bus master, medium devsel, latency 0, IRQ 3
        I/O ports at e200 [size=32]

0000:00:1d.3 USB Controller: Intel Corporation 82801G (ICH7 Family)
USB UHCI #4 (rev 01) (prog-if 00 [UHCI])
        Subsystem: Giga-byte Technology: Unknown device 5004
        Flags: bus master, medium devsel, latency 0, IRQ 12
        I/O ports at e300 [size=32]

0000:00:1d.7 USB Controller: Intel Corporation 82801G (ICH7 Family)
USB2 EHCI Controller (rev 01) (prog-if 20 [EHCI])
        Subsystem: Giga-byte Technology: Unknown device 5006
        Flags: bus master, medium devsel, latency 0, IRQ 5
        Memory at f4104000 (32-bit, non-prefetchable) [size=1K]
        Capabilities: [50] Power Management version 2

0000:00:1e.0 PCI bridge: Intel Corporation 82801 PCI Bridge (rev e1)
(prog-if 01 [Subtractive decode])
        Flags: bus master, fast devsel, latency 0
        Bus: primary=00, secondary=04, subordinate=04, sec-latency=32
        I/O behind bridge: 0000a000-0000afff
        Capabilities: [50] #0d [0000]

0000:00:1f.0 ISA bridge: Intel Corporation 82801GB/GR (ICH7 Family)
LPC Interface Bridge (rev 01)
        Subsystem: Giga-byte Technology: Unknown device 5001
        Flags: bus master, medium devsel, latency 0
        Capabilities: [e0] #09 [100c]

0000:00:1f.2 IDE interface: Intel Corporation 82801GB/GR/GH (ICH7
Family) Serial ATA Storage Controllers cc=IDE (rev 01) (prog-if 8a
[Master SecP PriP])
        Subsystem: Giga-byte Technology: Unknown device b002
        Flags: bus master, 66MHz, medium devsel, latency 0, IRQ 11
        I/O ports at 01f0 [size=8]
        I/O ports at 03f4 [size=1]
        I/O ports at 0170 [size=8]
        I/O ports at 0374 [size=1]
        I/O ports at f000 [size=16]
        Capabilities: [70] Power Management version 2

0000:00:1f.3 SMBus: Intel Corporation 82801G (ICH7 Family) SMBus
Controller (rev 01)
        Subsystem: Giga-byte Technology: Unknown device 5001
        Flags: medium devsel, IRQ 11
        I/O ports at 0500 [size=32]

0000:01:00.0 VGA compatible controller: nVidia Corporation: Unknown
device 06e4 (rev a1) (prog-if 00 [VGA])
        Flags: bus master, fast devsel, latency 0, IRQ 12
        Memory at f2000000 (32-bit, non-prefetchable) [size=16M]
        Memory at e0000000 (64-bit, prefetchable) [size=256M]
        Memory at f0000000 (64-bit, non-prefetchable) [size=32M]
        I/O ports at c000 [size=128]
        Expansion ROM at f3000000 [disabled] [size=128K]
        Capabilities: [60] Power Management version 3
        Capabilities: [68] Message Signalled Interrupts: 64bit+
Queue=0/0 Enable-
        Capabilities: [78] #10 [0001]

0000:03:00.0 Ethernet controller: Unknown device 1969:1063 (rev c0)
        Subsystem: Giga-byte Technology: Unknown device e000
        Flags: bus master, fast devsel, latency 0, IRQ 10
        Memory at f4000000 (64-bit, non-prefetchable) [size=256K]
        I/O ports at d000 [size=128]
        Capabilities: [40] Power Management version 3
        Capabilities: [48] Message Signalled Interrupts: 64bit+
Queue=0/0 Enable-
        Capabilities: [58] #10 [0001]
        Capabilities: [6c] Vital Product Data

processor       : 0
vendor_id       : GenuineIntel
cpu family      : 6
model           : 23
model name      : Intel(R) Celeron(R) CPU        E3200  @ 2.40GHz
stepping        : 10
cpu MHz         : 2400.036
cache size      : 1024 KB
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 13
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge
mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe nx
lm constant_tsc arch_perfmon pebs bts pni dtes64 monitor ds_cpl vmx
est tm2 ssse3 cx16 xtpr pdcm xsave lahf_lm tpr_shadow vnmi
flexpriority
bogomips        : 4800.07
clflush size    : 64
power management:

-- 
Glenn Maynard

Re: Crash during SATA reads

[Jeff Garzik]

[-- Attachment #1: Type: text/plain, Size: 2400 bytes --]

On 11/11/2009 04:18 AM, Glenn Maynard wrote:
> Pid: 1311, comm: gzip Not tainted (2.6.31.6 #1) G31M-ES2L
> EIP: 0060:[<00000000>] EFLAGS: 00010246 CPU: 0
> EIP is at 0x0
> EAX: c1ae78c0 EBX: c107cca9 ECX: c1ae78c0 EDX: 00000000
> ESI: c1ae78c0 EDI: dfa3b2c0 EBP: df29bed0 ESP: df29be94
>   DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
> Process gzip (pid: 1311, ti=df29a000 task=df916800 task.ti=df29a000)
> Stack:
>   c107ccb1 c107e549 00000200 c11587bc 00000000 00000001 df430a94 00000000
> <0>  00000000 00005000 0000b000 00000000 dfa3b2c0 00000000 dfa3b2c0 dfa0f168
> <0>  c1158936 dfa20980 00000000 c11589ed 00000000 dfa20980 00000000 dfa3b2c0
> Call Trace:
>   [<c107ccb1>] ? end_bio_bh_io_sync+0x28/0x30
>   [<c107e549>] ? bio_endio+0x24/0x26
>   [<c11587bc>] ? blk_update_request+0xdf/0x24e
>   [<c1158936>] ? blk_update_bidi_request+0xb/0x41
>   [<c11589ed>] ? blk_end_bidi_request+0x10/0x4f
>   [<c1158a5c>] ? blk_end_request+0x7/0xc
>   [<c11abcb2>] ? scsi_end_request+0x17/0x69
>   [<c11abfc3>] ? scsi_io_completion+0x173/0x335
>   [<c11a8330>] ? scsi_finish_command+0x70/0x86
>   [<c11ac6a6>] ? scsi_softirq_done+0xd7/0xdc
>   [<c115b3f1>] ? blk_done_softirq+0x51/0x5d
>   [<c101bde0>] ? __do_softirq+0x5f/0xc8
>   [<c101be6b>] ? do_softirq+0x22/0x26
>   [<c101becd>] ? irq_exit+0x29/0x34
>   [<c1004097>] ? do_IRQ+0x53/0x63
>   [<c1002ea9>] ? common_interrupt+0x29/0x30
> Code:  Bad EIP value.
> EIP: [<00000000>] 0x0 SS:ESP 0068:df29be94
> CR2: 0000000000000000
> ---[ end trace 79f49d6371afc159 ]---
> Kernel panic - not syncing: Fatal exception in interrupt
> Pid: 1311, comm: gzip Tainted: G      D    2.6.31.6 #1
> Call Trace:
>   [<c101824c>] ? panic+0x41/0xde
>   [<c1004dcf>] ? oops_end+0x5c/0x66
>   [<c107cca9>] ? end_bio_bh_io_sync+0x20/0x30
>   [<c100eca7>] ? bad_area_nosemaphore+0xa/0xc
>   [<c126564e>] ? error_code+0x5e/0x64
>   [<c107cca9>] ? end_bio_bh_io_sync+0x20/0x30
>   [<c107007b>] ? file_update_time+0x8c/0xd8
>   [<c100ee87>] ? do_page_fault+0x0/0x1f9
>   [<c107ccb1>] ? end_bio_bh_io_sync+0x28/0x30
>   [<c107e549>] ? bio_endio+0x24/0x26
>   [<c11587bc>] ? blk_update_request+0xdf/0x24e
>   [<c1158936>] ? blk_update_bidi_request+0xb/0x41
>   [<c11589ed>] ? blk_end_bidi_request+0x10/0x4f

Looks like it is dying somewhere in the block layer, maybe the 
bh->b_end_io() pointer is NULL.

Does the attached patch trigger the added BUG_ON() statement?

	Jeff




[-- Attachment #2: patch --]
[-- Type: text/plain, Size: 386 bytes --]

diff --git a/fs/buffer.c b/fs/buffer.c
index 6fa5302..267e4d1 100644
--- a/fs/buffer.c
+++ b/fs/buffer.c
@@ -2939,6 +2939,7 @@ static void end_bio_bh_io_sync(struct bio *bio, int err)
 	if (unlikely (test_bit(BIO_QUIET,&bio->bi_flags)))
 		set_bit(BH_Quiet, &bh->b_state);
 
+	BUG_ON(bh->b_end_io == NULL);
 	bh->b_end_io(bh, test_bit(BIO_UPTODATE, &bio->bi_flags));
 	bio_put(bio);
 }

Re: Crash during SATA reads

[Glenn Maynard]

2009/11/11 Jeff Garzik <jeff@garzik.org>:
> Looks like it is dying somewhere in the block layer, maybe the
> bh->b_end_io() pointer is NULL.
>
> Does the attached patch trigger the added BUG_ON() statement?

I had that thought, too, but that change seems to have masked the
problem; I'm having trouble reproducing it at all.

-- 
Glenn Maynard

Re: Crash during SATA reads

[Glenn Maynard]

Another trace, this time a bit deeper:

BUG: unable to handle kernel NULL pointer dereference at (null)
IP: [<c1079e7b>] end_buffer_async_read+0x59/0xc5
*pde = 00000000
Oops: 0000 [#1] PREEMPT
last sysfs file:
Modules linked in: netconsole atl1c rtc

Pid: 1300, comm: gzip Not tainted (2.6.31.6 #5) G31M-ES2L
EIP: 0060:[<c1079e7b>] EFLAGS: 00010013 CPU: 0
EIP is at end_buffer_async_read+0x59/0xc5
EAX: 00000000 EBX: c1ae7b38 ECX: 00000000 EDX: c1079e22
ESI: 00000202 EDI: c17b5040 EBP: 00000000 ESP: df1dde80
 DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
Process gzip (pid: 1300, ti=df1dc000 task=df866420 task.ti=df1dc000)
Stack:
 ce632840 ce632840 df91de78 df1dded0 c107ccb9 c107cc89 c107e551 00000200
<0> c11587c4 00000000 00000001 df430298 00000000 00000000 0000be00 00004200
<0> 00000000 df91de78 00000000 df91de78 df8ef168 c115893e df8a6c80 00000000
Call Trace:
 [<c107ccb9>] ? end_bio_bh_io_sync+0x30/0x38
 [<c107cc89>] ? end_bio_bh_io_sync+0x0/0x38
 [<c107e551>] ? bio_endio+0x24/0x26
 [<c11587c4>] ? blk_update_request+0xdf/0x24e
 [<c115893e>] ? blk_update_bidi_request+0xb/0x41
 [<c11589f5>] ? blk_end_bidi_request+0x10/0x4f
 [<c1158a64>] ? blk_end_request+0x7/0xc
 [<c11abcb2>] ? scsi_end_request+0x17/0x69
 [<c11abfc3>] ? scsi_io_completion+0x173/0x335
 [<c11a8330>] ? scsi_finish_command+0x70/0x86
 [<c11ac6a6>] ? scsi_softirq_done+0xd7/0xdc
 [<c115b3f9>] ? blk_done_softirq+0x51/0x5d
 [<c101bde0>] ? __do_softirq+0x5f/0xc8
 [<c101be6b>] ? do_softirq+0x22/0x26
 [<c101becd>] ? irq_exit+0x29/0x34
 [<c1004097>] ? do_IRQ+0x53/0x63
 [<c1002ea9>] ? common_interrupt+0x29/0x30
Code: e8 d2 fd ff ff 80 0f 02 f6 47 01 08 75 04 0f 0b eb fe 9c 5e fa
89 e0 25 00 e0 ff ff ff 40 14 80 23 7f 89 d8 e8 58 fd ff ff 89 d9 <8b>
11 b8 00 00 00 00 f6 c2 01 0f 44 e8 f6 c2 80 74 09 80 e2 04
EIP: [<c1079e7b>] end_buffer_async_read+0x59/0xc5 SS:ESP 0068:df1dde80
CR2: 0000000000000000
---[ end trace 2e93648aef49fa0e ]---

It looks like buffer_tmp was NULL during end_buffer_async_read's
buffer_uptodate(tmp).


This one just happened when I interrupted the dd:

BUG: unable to handle kernel NULL pointer dereference at 00000004
IP: [<c107ae05>] block_invalidatepage+0x22/0x54
*pde = 00000000
Oops: 0000 [#1] PREEMPT
last sysfs file:
Modules linked in: netconsole atl1c rtc

Pid: 1296, comm: dd Not tainted (2.6.31.6 #6) G31M-ES2L
EIP: 0060:[<c107ae05>] EFLAGS: 00010217 CPU: 0
EIP is at block_invalidatepage+0x22/0x54
EAX: 00000000 EBX: c14f1540 ECX: 00000002 EDX: 00001000
ESI: 00000000 EDI: 00001000 EBP: c8d4fc88 ESP: df1d7ed0
 DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
Process dd (pid: 1296, ti=df1d6000 task=df87bc00 task.ti=df1d6000)
Stack:
 00000000 c14f1540 00000000 c14f1540 00064156 c1048c29 c14f1540 c1048cab
<0> 00000001 c1048def ffffffff 00000000 df4cff54 0000000e 00000000 c13f0440
<0> c14f1540 c14f2ae0 c13f7a40 c13f7e80 c13fd220 c13efd40 c13efd60 c13f01c0
Call Trace:
 [<c1048c29>] ? do_invalidatepage+0x1d/0x1f
 [<c1048cab>] ? truncate_complete_page+0x19/0x4b
 [<c1048def>] ? truncate_inode_pages_range+0xd1/0x2af
 [<c1048fd6>] ? truncate_inode_pages+0x9/0xc
 [<c107fb83>] ? __blkdev_put+0x47/0xec
 [<c1060fe7>] ? __fput+0xc4/0x177
 [<c105fa8a>] ? filp_close+0x4c/0x52
 [<c105faee>] ? sys_close+0x5e/0x99
 [<c10027f0>] ? sysenter_do_call+0x12/0x22
Code: bf 89 d8 5b e9 ee ed ff ff 55 57 56 53 89 c3 56 89 14 24 31 d2
8b 00 a8 01 75 04 0f 0b eb fe f6 c4 08 74 33 8b 6b 0c 89 e8 89 d7 <8b>
70 04 03 78 14 39 14 24 77 05 e8 97 ff ff ff 39 ee 89 fa 89
EIP: [<c107ae05>] block_invalidatepage+0x22/0x54 SS:ESP 0068:df1d7ed0
CR2: 0000000000000004
---[ end trace 64b0df80bcbb02ce ]---

Here, it looks like bh is NULL in block_invalidatepage's loop, dying
at bh->b_size.

I'm not sure where to go from here.

-- 
Glenn Maynard

Re: Crash during SATA reads

[Jeff Garzik]

On 11/11/2009 04:09 PM, Glenn Maynard wrote:
> Another trace, this time a bit deeper:
>
> BUG: unable to handle kernel NULL pointer dereference at (null)
> IP: [<c1079e7b>] end_buffer_async_read+0x59/0xc5
> *pde = 00000000
> Oops: 0000 [#1] PREEMPT
> last sysfs file:
> Modules linked in: netconsole atl1c rtc
>
> Pid: 1300, comm: gzip Not tainted (2.6.31.6 #5) G31M-ES2L
> EIP: 0060:[<c1079e7b>] EFLAGS: 00010013 CPU: 0
> EIP is at end_buffer_async_read+0x59/0xc5
> EAX: 00000000 EBX: c1ae7b38 ECX: 00000000 EDX: c1079e22
> ESI: 00000202 EDI: c17b5040 EBP: 00000000 ESP: df1dde80
>   DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
> Process gzip (pid: 1300, ti=df1dc000 task=df866420 task.ti=df1dc000)
> Stack:
>   ce632840 ce632840 df91de78 df1dded0 c107ccb9 c107cc89 c107e551 00000200
> <0>  c11587c4 00000000 00000001 df430298 00000000 00000000 0000be00 00004200
> <0>  00000000 df91de78 00000000 df91de78 df8ef168 c115893e df8a6c80 00000000
> Call Trace:
>   [<c107ccb9>] ? end_bio_bh_io_sync+0x30/0x38
>   [<c107cc89>] ? end_bio_bh_io_sync+0x0/0x38
>   [<c107e551>] ? bio_endio+0x24/0x26
>   [<c11587c4>] ? blk_update_request+0xdf/0x24e
>   [<c115893e>] ? blk_update_bidi_request+0xb/0x41
>   [<c11589f5>] ? blk_end_bidi_request+0x10/0x4f
>   [<c1158a64>] ? blk_end_request+0x7/0xc
>   [<c11abcb2>] ? scsi_end_request+0x17/0x69
>   [<c11abfc3>] ? scsi_io_completion+0x173/0x335
>   [<c11a8330>] ? scsi_finish_command+0x70/0x86
>   [<c11ac6a6>] ? scsi_softirq_done+0xd7/0xdc
>   [<c115b3f9>] ? blk_done_softirq+0x51/0x5d
>   [<c101bde0>] ? __do_softirq+0x5f/0xc8
>   [<c101be6b>] ? do_softirq+0x22/0x26
>   [<c101becd>] ? irq_exit+0x29/0x34
>   [<c1004097>] ? do_IRQ+0x53/0x63
>   [<c1002ea9>] ? common_interrupt+0x29/0x30
> Code: e8 d2 fd ff ff 80 0f 02 f6 47 01 08 75 04 0f 0b eb fe 9c 5e fa
> 89 e0 25 00 e0 ff ff ff 40 14 80 23 7f 89 d8 e8 58 fd ff ff 89 d9<8b>
> 11 b8 00 00 00 00 f6 c2 01 0f 44 e8 f6 c2 80 74 09 80 e2 04
> EIP: [<c1079e7b>] end_buffer_async_read+0x59/0xc5 SS:ESP 0068:df1dde80
> CR2: 0000000000000000
> ---[ end trace 2e93648aef49fa0e ]---
>
> It looks like buffer_tmp was NULL during end_buffer_async_read's
> buffer_uptodate(tmp).
>
>
> This one just happened when I interrupted the dd:
>
> BUG: unable to handle kernel NULL pointer dereference at 00000004
> IP: [<c107ae05>] block_invalidatepage+0x22/0x54
> *pde = 00000000
> Oops: 0000 [#1] PREEMPT
> last sysfs file:
> Modules linked in: netconsole atl1c rtc
>
> Pid: 1296, comm: dd Not tainted (2.6.31.6 #6) G31M-ES2L
> EIP: 0060:[<c107ae05>] EFLAGS: 00010217 CPU: 0
> EIP is at block_invalidatepage+0x22/0x54
> EAX: 00000000 EBX: c14f1540 ECX: 00000002 EDX: 00001000
> ESI: 00000000 EDI: 00001000 EBP: c8d4fc88 ESP: df1d7ed0
>   DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
> Process dd (pid: 1296, ti=df1d6000 task=df87bc00 task.ti=df1d6000)
> Stack:
>   00000000 c14f1540 00000000 c14f1540 00064156 c1048c29 c14f1540 c1048cab
> <0>  00000001 c1048def ffffffff 00000000 df4cff54 0000000e 00000000 c13f0440
> <0>  c14f1540 c14f2ae0 c13f7a40 c13f7e80 c13fd220 c13efd40 c13efd60 c13f01c0
> Call Trace:
>   [<c1048c29>] ? do_invalidatepage+0x1d/0x1f
>   [<c1048cab>] ? truncate_complete_page+0x19/0x4b
>   [<c1048def>] ? truncate_inode_pages_range+0xd1/0x2af
>   [<c1048fd6>] ? truncate_inode_pages+0x9/0xc
>   [<c107fb83>] ? __blkdev_put+0x47/0xec
>   [<c1060fe7>] ? __fput+0xc4/0x177
>   [<c105fa8a>] ? filp_close+0x4c/0x52
>   [<c105faee>] ? sys_close+0x5e/0x99
>   [<c10027f0>] ? sysenter_do_call+0x12/0x22
> Code: bf 89 d8 5b e9 ee ed ff ff 55 57 56 53 89 c3 56 89 14 24 31 d2
> 8b 00 a8 01 75 04 0f 0b eb fe f6 c4 08 74 33 8b 6b 0c 89 e8 89 d7<8b>
> 70 04 03 78 14 39 14 24 77 05 e8 97 ff ff ff 39 ee 89 fa 89
> EIP: [<c107ae05>] block_invalidatepage+0x22/0x54 SS:ESP 0068:df1d7ed0
> CR2: 0000000000000004
> ---[ end trace 64b0df80bcbb02ce ]---
>
> Here, it looks like bh is NULL in block_invalidatepage's loop, dying
> at bh->b_size.
>
> I'm not sure where to go from here.

I would poke Jens Axboe (block maintainer) and linux-scsi, the issuer of 
these commands.

Also, providing filesystem info (ext3? ext4? XFS? btrfs?) and info on 
your workload would be helpful.

	Jeff

Re: Crash during SATA reads

[Glenn Maynard]

On Wed, Nov 11, 2009 at 4:39 PM, Jeff Garzik <jeff@garzik.org> wrote:
> I would poke Jens Axboe (block maintainer) and linux-scsi, the issuer of
> these commands.

(Looks like you poked for me; thanks.)

> Also, providing filesystem info (ext3? ext4? XFS? btrfs?) and info on your
> workload would be helpful.

These crashes happen while running "dd if=/dev/sdb | gzip > /dev/null"
in 2.6.31.6.  I'm just making a raw image of another drive.  Removing
gzip masks the problem.  It happens anywhere between almost
immediately to after running for 15-30 minutes.

All filesystems are XFS, but none of sdb's partitions are mounted and
I'm reading the device directly (/dev/sdb, not a partition).  The
system that's making the image is mounted read-only and isn't running
anything else.

(Another backtrace at http://lkml.org/lkml/2009/11/11/81.)

Here's a curious one; EIP appears to be in data:

Pid: 1312, comm: gzip Not tainted (2.6.31.6 #6) G31M-ES2L
EIP: 0060:[<c1ae78e4>] EFLAGS: 00010286 CPU: 0
EIP is at 0xc1ae78e4
EAX: c1ae78c0 EBX: c107ccb1 ECX: c1ae78c0 EDX: 00000001
ESI: c1ae78c0 EDI: dfa39069 EBP: c7d29ed0 ESP: c7d29e94
 DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
Process gzip (pid: 1312, ti=c7d28000 task=df8b6080 task.ti=c7d28000)
Stack:
 c107ccc1 c107e559 00000200 c11587cc 00000000 df8a6c80 dfa07168 00000000
<0> 00000000 0000c000 00004000 00000000 dfa39068 00000000 dfa39068 dfa07168
<0> c1158946 df8a6c80 00000000 c11589fd 00000000 df8a6c80 00000000 dfa39068
Call Trace:
 [<c107ccc1>] ? end_bio_bh_io_sync+0x30/0x38
 [<c107e559>] ? bio_endio+0x24/0x26
 [<c11587cc>] ? blk_update_request+0xdf/0x24e
 [<c1158946>] ? blk_update_bidi_request+0xb/0x41
 [<c11589fd>] ? blk_end_bidi_request+0x10/0x4f
 [<c1158a6c>] ? blk_end_request+0x7/0xc
 [<c11abcc2>] ? scsi_end_request+0x17/0x69
 [<c11abfd3>] ? scsi_io_completion+0x173/0x335
 [<c11a8340>] ? scsi_finish_command+0x70/0x86
 [<c11ac6b6>] ? scsi_softirq_done+0xd7/0xdc
 [<c115b401>] ? blk_done_softirq+0x51/0x5d
 [<c101bde0>] ? __do_softirq+0x5f/0xc8
 [<c101be6b>] ? do_softirq+0x22/0x26
 [<c101becd>] ? irq_exit+0x29/0x34
 [<c1004097>] ? do_IRQ+0x53/0x63
 [<c1002ea9>] ? common_interrupt+0x29/0x30
Code: 00 00 00 00 00 00 00 c0 72 77 83 00 00 00 00 40 79 ae c1 40 8e
4c df 09 00 00 f0 00 00 00 00 01 00 00 00 01 00 00 00 00 00 00 00 <00>
02 00 00 00 02 00 00 04 00 00 00 ff ff ff ff 01 00 00 00 08
EIP: [<c1ae78e4>] 0xc1ae78e4 SS:ESP 0068:c7d29e94
CR2: 0000000000000001
---[ end trace fb168fcf160f6893 ]---

-- 
Glenn Maynard

Re: Crash during SATA reads

[Dmitry Monakhov]

Glenn Maynard <glenn@zewt.org> writes:

> On Wed, Nov 11, 2009 at 4:39 PM, Jeff Garzik <jeff@garzik.org> wrote:
>> I would poke Jens Axboe (block maintainer) and linux-scsi, the issuer of
>> these commands.
>
> (Looks like you poked for me; thanks.)
>
>> Also, providing filesystem info (ext3? ext4? XFS? btrfs?) and info on your
>> workload would be helpful.
>
> These crashes happen while running "dd if=/dev/sdb | gzip > /dev/null"
> in 2.6.31.6.  I'm just making a raw image of another drive.  Removing
> gzip masks the problem.  It happens anywhere between almost
> immediately to after running for 15-30 minutes.
>
> All filesystems are XFS, but none of sdb's partitions are mounted and
> I'm reading the device directly (/dev/sdb, not a partition).  The
> system that's making the image is mounted read-only and isn't running
> anything else.
>
> (Another backtrace at http://lkml.org/lkml/2009/11/11/81.)
Seems what you have use-after-free here.
You probably have to add some debug info in to bio->end_io method
May be something like this.
diff --git a/fs/buffer.c b/fs/buffer.c
index 6fa5302..ce95791 100644
--- a/fs/buffer.c
+++ b/fs/buffer.c
@@ -2930,6 +2930,10 @@ EXPORT_SYMBOL(generic_block_bmap);
 static void end_bio_bh_io_sync(struct bio *bio, int err)
 {
 	struct buffer_head *bh = bio->bi_private;
+	BIO_BUG_ON(!atomic_read(&bio->bi_cnt));
+	BUG_ON(!bh);
+	BUG_ON(!bh->b_page);
+	BUG_ON(!bh->b_this_page);
 
 	if (err == -EOPNOTSUPP) {
 		set_bit(BIO_EOPNOTSUPP, &bio->bi_flags);


>
> Here's a curious one; EIP appears to be in data:
>
> Pid: 1312, comm: gzip Not tainted (2.6.31.6 #6) G31M-ES2L
> EIP: 0060:[<c1ae78e4>] EFLAGS: 00010286 CPU: 0
> EIP is at 0xc1ae78e4
> EAX: c1ae78c0 EBX: c107ccb1 ECX: c1ae78c0 EDX: 00000001
> ESI: c1ae78c0 EDI: dfa39069 EBP: c7d29ed0 ESP: c7d29e94
>  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
> Process gzip (pid: 1312, ti=c7d28000 task=df8b6080 task.ti=c7d28000)
> Stack:
>  c107ccc1 c107e559 00000200 c11587cc 00000000 df8a6c80 dfa07168 00000000
> <0> 00000000 0000c000 00004000 00000000 dfa39068 00000000 dfa39068 dfa07168
> <0> c1158946 df8a6c80 00000000 c11589fd 00000000 df8a6c80 00000000 dfa39068
> Call Trace:
>  [<c107ccc1>] ? end_bio_bh_io_sync+0x30/0x38
>  [<c107e559>] ? bio_endio+0x24/0x26
>  [<c11587cc>] ? blk_update_request+0xdf/0x24e
>  [<c1158946>] ? blk_update_bidi_request+0xb/0x41
>  [<c11589fd>] ? blk_end_bidi_request+0x10/0x4f
>  [<c1158a6c>] ? blk_end_request+0x7/0xc
>  [<c11abcc2>] ? scsi_end_request+0x17/0x69
>  [<c11abfd3>] ? scsi_io_completion+0x173/0x335
>  [<c11a8340>] ? scsi_finish_command+0x70/0x86
>  [<c11ac6b6>] ? scsi_softirq_done+0xd7/0xdc
>  [<c115b401>] ? blk_done_softirq+0x51/0x5d
>  [<c101bde0>] ? __do_softirq+0x5f/0xc8
>  [<c101be6b>] ? do_softirq+0x22/0x26
>  [<c101becd>] ? irq_exit+0x29/0x34
>  [<c1004097>] ? do_IRQ+0x53/0x63
>  [<c1002ea9>] ? common_interrupt+0x29/0x30
> Code: 00 00 00 00 00 00 00 c0 72 77 83 00 00 00 00 40 79 ae c1 40 8e
> 4c df 09 00 00 f0 00 00 00 00 01 00 00 00 01 00 00 00 00 00 00 00 <00>
> 02 00 00 00 02 00 00 04 00 00 00 ff ff ff ff 01 00 00 00 08
> EIP: [<c1ae78e4>] 0xc1ae78e4 SS:ESP 0068:c7d29e94
> CR2: 0000000000000001
> ---[ end trace fb168fcf160f6893 ]---

Re: Crash during SATA reads

[Glenn Maynard]

On Wed, Nov 11, 2009 at 9:28 PM, Dmitry Monakhov <dmonakhov@openvz.org> wrote:
> Seems what you have use-after-free here.
> You probably have to add some debug info in to bio->end_io method
> May be something like this.

That's what it looks like, but won't these checks trigger on the use
(and give the same trace), when we need to know where the free is
happening?  The problem is manifesting in several places (bogus or
NULL bh->b_end_io in end_bio_bh_io_sync(); bh->b_this_page == NULL--I
think, havn't reproduced that again to confirm--in
block_invalidatepage()).  I'm not sure how to figure out where the
free might be happening; it's tricky enough in userspace with Valgrind
available.

I tried logging alloc_buffer_head and free_buffer_head, but it was too
much output (if it's not masking the problem entirely by changing the
timing too much, it would take ages to repro).

I just repro'd it (took several hours this time), on the
BUG_ON(!bh->b_page); assertion.  This one happened while doing a
partition copy (/dev/sdb2) rather than /dev/sdb.  Trace follows
(though I doubt it offers any new information).  Hopefully somebody
has an idea of where to look next...


kernel BUG at fs/buffer.c:2934!
invalid opcode: 0000 [#1] PREEMPT
last sysfs file:
/sys/devices/pci0000:00/0000:00:1f.2/host1/target1:0:0/1:0:0:0/model
Modules linked in: netconsole atl1c rtc

Pid: 0, comm: swapper Not tainted (2.6.31.6 #16) G31M-ES2L
EIP: 0060:[<c107cce3>] EFLAGS: 00010282 CPU: 0
EIP is at end_bio_bh_io_sync+0x20/0x63
EAX: c1ae78c0 EBX: c107cce3 ECX: c1ae78c0 EDX: 00000000
ESI: c1ae78c0 EDI: d9e5c450 EBP: c1351eac ESP: c1351e74
 DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 0068
Process swapper (pid: 0, ti=c1350000 task=c1356260 task.ti=c1350000)
Stack:
 c107e5b5 00000400 c1158828 00000000 df8a62c0 df8ef5a4 00000000 00000000
<0> 00012c00 0000d400 00000000 d9e5c450 00000000 d9e5c450 df8ef168 c11589a2
<0> df8a6500 00000000 c1158a59 00000000 df8a6500 00000000 d9e5c450 c1158ac8
Call Trace:
 [<c107e5b5>] ? bio_endio+0x24/0x26
 [<c1158828>] ? blk_update_request+0xdf/0x24e
 [<c11589a2>] ? blk_update_bidi_request+0xb/0x41
 [<c1158a59>] ? blk_end_bidi_request+0x10/0x4f
 [<c1158ac8>] ? blk_end_request+0x7/0xc
 [<c11abd12>] ? scsi_end_request+0x17/0x69
 [<c11ac023>] ? scsi_io_completion+0x173/0x335
 [<c11a8390>] ? scsi_finish_command+0x70/0x86
 [<c11ac706>] ? scsi_softirq_done+0xd7/0xdc
 [<c115b45d>] ? blk_done_softirq+0x51/0x5d
 [<c101bde0>] ? __do_softirq+0x5f/0xc8
 [<c101be6b>] ? do_softirq+0x22/0x26
 [<c101becd>] ? irq_exit+0x29/0x34
 [<c1004097>] ? do_IRQ+0x53/0x63
 [<c1002ea9>] ? common_interrupt+0x29/0x30
 [<c100716e>] ? mwait_idle+0x3c/0x44
 [<c1001423>] ? cpu_idle+0x19/0x3a
 [<c13885aa>] ? start_kernel+0x1a4/0x1a6
Code: 54 24 18 83 c4 48 5b 5e 5f 5d c3 56 53 89 c3 8b 48 40 8b 40 34
85 c0 75 04 0f 0b eb fe 85 c9 75 04 0f 0b eb fe 83 79 08 00 75 04 <0f>
0b eb fe 83 79 04 00 75 04 0f 0b eb fe 83 fa a1 75 08 80 4b
EIP: [<c107cce3>] end_bio_bh_io_sync+0x20/0x63 SS:ESP 0068:c1351e74

-- 
Glenn Maynard

Re: Crash during SATA reads

[Jens Axboe]

On Wed, Nov 11 2009, Jeff Garzik wrote:
> On 11/11/2009 04:09 PM, Glenn Maynard wrote:
>> Another trace, this time a bit deeper:
>>
>> BUG: unable to handle kernel NULL pointer dereference at (null)
>> IP: [<c1079e7b>] end_buffer_async_read+0x59/0xc5
>> *pde = 00000000
>> Oops: 0000 [#1] PREEMPT
>> last sysfs file:
>> Modules linked in: netconsole atl1c rtc
>>
>> Pid: 1300, comm: gzip Not tainted (2.6.31.6 #5) G31M-ES2L
>> EIP: 0060:[<c1079e7b>] EFLAGS: 00010013 CPU: 0
>> EIP is at end_buffer_async_read+0x59/0xc5
>> EAX: 00000000 EBX: c1ae7b38 ECX: 00000000 EDX: c1079e22
>> ESI: 00000202 EDI: c17b5040 EBP: 00000000 ESP: df1dde80
>>   DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
>> Process gzip (pid: 1300, ti=df1dc000 task=df866420 task.ti=df1dc000)
>> Stack:
>>   ce632840 ce632840 df91de78 df1dded0 c107ccb9 c107cc89 c107e551 00000200
>> <0>  c11587c4 00000000 00000001 df430298 00000000 00000000 0000be00 00004200
>> <0>  00000000 df91de78 00000000 df91de78 df8ef168 c115893e df8a6c80 00000000
>> Call Trace:
>>   [<c107ccb9>] ? end_bio_bh_io_sync+0x30/0x38
>>   [<c107cc89>] ? end_bio_bh_io_sync+0x0/0x38
>>   [<c107e551>] ? bio_endio+0x24/0x26
>>   [<c11587c4>] ? blk_update_request+0xdf/0x24e
>>   [<c115893e>] ? blk_update_bidi_request+0xb/0x41
>>   [<c11589f5>] ? blk_end_bidi_request+0x10/0x4f
>>   [<c1158a64>] ? blk_end_request+0x7/0xc
>>   [<c11abcb2>] ? scsi_end_request+0x17/0x69
>>   [<c11abfc3>] ? scsi_io_completion+0x173/0x335
>>   [<c11a8330>] ? scsi_finish_command+0x70/0x86
>>   [<c11ac6a6>] ? scsi_softirq_done+0xd7/0xdc
>>   [<c115b3f9>] ? blk_done_softirq+0x51/0x5d
>>   [<c101bde0>] ? __do_softirq+0x5f/0xc8
>>   [<c101be6b>] ? do_softirq+0x22/0x26
>>   [<c101becd>] ? irq_exit+0x29/0x34
>>   [<c1004097>] ? do_IRQ+0x53/0x63
>>   [<c1002ea9>] ? common_interrupt+0x29/0x30
>> Code: e8 d2 fd ff ff 80 0f 02 f6 47 01 08 75 04 0f 0b eb fe 9c 5e fa
>> 89 e0 25 00 e0 ff ff ff 40 14 80 23 7f 89 d8 e8 58 fd ff ff 89 d9<8b>
>> 11 b8 00 00 00 00 f6 c2 01 0f 44 e8 f6 c2 80 74 09 80 e2 04
>> EIP: [<c1079e7b>] end_buffer_async_read+0x59/0xc5 SS:ESP 0068:df1dde80
>> CR2: 0000000000000000
>> ---[ end trace 2e93648aef49fa0e ]---
>>
>> It looks like buffer_tmp was NULL during end_buffer_async_read's
>> buffer_uptodate(tmp).
>>
>>
>> This one just happened when I interrupted the dd:
>>
>> BUG: unable to handle kernel NULL pointer dereference at 00000004
>> IP: [<c107ae05>] block_invalidatepage+0x22/0x54
>> *pde = 00000000
>> Oops: 0000 [#1] PREEMPT
>> last sysfs file:
>> Modules linked in: netconsole atl1c rtc
>>
>> Pid: 1296, comm: dd Not tainted (2.6.31.6 #6) G31M-ES2L
>> EIP: 0060:[<c107ae05>] EFLAGS: 00010217 CPU: 0
>> EIP is at block_invalidatepage+0x22/0x54
>> EAX: 00000000 EBX: c14f1540 ECX: 00000002 EDX: 00001000
>> ESI: 00000000 EDI: 00001000 EBP: c8d4fc88 ESP: df1d7ed0
>>   DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
>> Process dd (pid: 1296, ti=df1d6000 task=df87bc00 task.ti=df1d6000)
>> Stack:
>>   00000000 c14f1540 00000000 c14f1540 00064156 c1048c29 c14f1540 c1048cab
>> <0>  00000001 c1048def ffffffff 00000000 df4cff54 0000000e 00000000 c13f0440
>> <0>  c14f1540 c14f2ae0 c13f7a40 c13f7e80 c13fd220 c13efd40 c13efd60 c13f01c0
>> Call Trace:
>>   [<c1048c29>] ? do_invalidatepage+0x1d/0x1f
>>   [<c1048cab>] ? truncate_complete_page+0x19/0x4b
>>   [<c1048def>] ? truncate_inode_pages_range+0xd1/0x2af
>>   [<c1048fd6>] ? truncate_inode_pages+0x9/0xc
>>   [<c107fb83>] ? __blkdev_put+0x47/0xec
>>   [<c1060fe7>] ? __fput+0xc4/0x177
>>   [<c105fa8a>] ? filp_close+0x4c/0x52
>>   [<c105faee>] ? sys_close+0x5e/0x99
>>   [<c10027f0>] ? sysenter_do_call+0x12/0x22
>> Code: bf 89 d8 5b e9 ee ed ff ff 55 57 56 53 89 c3 56 89 14 24 31 d2
>> 8b 00 a8 01 75 04 0f 0b eb fe f6 c4 08 74 33 8b 6b 0c 89 e8 89 d7<8b>
>> 70 04 03 78 14 39 14 24 77 05 e8 97 ff ff ff 39 ee 89 fa 89
>> EIP: [<c107ae05>] block_invalidatepage+0x22/0x54 SS:ESP 0068:df1d7ed0
>> CR2: 0000000000000004
>> ---[ end trace 64b0df80bcbb02ce ]---
>>
>> Here, it looks like bh is NULL in block_invalidatepage's loop, dying
>> at bh->b_size.
>>
>> I'm not sure where to go from here.
>
> I would poke Jens Axboe (block maintainer) and linux-scsi, the issuer of  
> these commands.

So the device isn't mounted, which means that we'll default to 1k
blocks. I think that's a big clue here, as you'll have 4 buffer_heads
pointing to the same page. And one of your oopses is indeed in the
->b_this_page unroll.

Can you trigger this if you mount/umount the device first?

-- 
Jens Axboe

Re: Crash during SATA reads

[Glenn Maynard]

On Thu, Nov 12, 2009 at 4:16 AM, Jens Axboe <jens.axboe@oracle.com> wrote:
> So the device isn't mounted, which means that we'll default to 1k
> blocks. I think that's a big clue here, as you'll have 4 buffer_heads
> pointing to the same page. And one of your oopses is indeed in the
> ->b_this_page unroll.
>
> Can you trigger this if you mount/umount the device first?

Yeah.  I've reproduced it reading from /dev/sda (the drive the root
partition is mounted on) with no second drive attached, too.

I'm currently reproducing it with "dd if=/dev/sda of=/dev/sdb", since
that reproduces faster and more reproducably than just reading.
Here's a trace from one of these:

BUG: unable to handle kernel NULL pointer dereference at 000000c0
IP: [<c1097067>] bdevname+0x8/0x13
*pde = 00000000
Oops: 0000 [#1] PREEMPT
last sysfs file:
/sys/devices/pci0000:00/0000:00:1f.2/host1/target1:0:0/1:0:0:0/model
Modules linked in: netconsole atl1c rtc

Pid: 151, comm: pdflush Not tainted (2.6.31.6 #17) G31M-ES2L
EIP: 0060:[<c1097067>] EFLAGS: 00010246 CPU: 0
EIP is at bdevname+0x8/0x13
EAX: df4ddcf0 EBX: 00000000 ECX: df87fd54 EDX: 00000000
ESI: d5cfa0c0 EDI: 00000000 EBP: 00000001 ESP: df87fd38
 DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 0068
Process pdflush (pid: 151, ti=df87e000 task=df8caae0 task.ti=df87e000)
Stack:
 c11582ff 0006d250 00000000 fffffffb 00000002 00000246 c1ae7e80 00011200
<0> 00011210 df83a9e0 c1043b26 df87fd60 00000004 00000101 c101be1c 00000000
<0> 00000000 d5cfa0c0 00000001 c11583e4 00000001 df83aa00 df83aa00 c107d6db
Call Trace:
 [<c11582ff>] ? generic_make_request+0x1cc/0x209
 [<c1043b26>] ? mempool_alloc+0x1e/0xd6
 [<c101be1c>] ? __do_softirq+0x9b/0xc8
 [<c11583e4>] ? submit_bio+0xa8/0xb0
 [<c107d6db>] ? bio_alloc_bioset+0x3e/0xa4
 [<c107ce92>] ? submit_bh+0x127/0x152
 [<c107b117>] ? __block_write_full_page+0x1ff/0x2d8
 [<c107eafd>] ? blkdev_get_block+0x0/0x46
 [<c107cc5e>] ? block_write_full_page_endio+0xe2/0xec
 [<c1079ef7>] ? end_buffer_async_write+0x0/0xd4
 [<c107eafd>] ? blkdev_get_block+0x0/0x46
 [<c107cc72>] ? block_write_full_page+0xa/0xc
 [<c1079ef7>] ? end_buffer_async_write+0x0/0xd4
 [<c104750c>] ? __writepage+0x8/0x1d
 [<c1047407>] ? write_cache_pages+0x1bf/0x2bc
 [<c1047504>] ? __writepage+0x0/0x1d
 [<c1047521>] ? generic_writepages+0x0/0x1f
 [<c104753d>] ? generic_writepages+0x1c/0x1f
 [<c1047562>] ? do_writepages+0x22/0x32
 [<c1076444>] ? writeback_single_inode+0xad/0x1b2
 [<c1076672>] ? generic_sync_sb_inodes+0x129/0x26e
 [<c1047c80>] ? pdflush+0x0/0x2d
 [<c1076820>] ? writeback_inodes+0x64/0xb4
 [<c1047040>] ? background_writeout+0x5f/0x91
 [<c1047bab>] ? __pdflush+0xcf/0x1a4
 [<c1047ca9>] ? pdflush+0x29/0x2d
 [<c1046fe1>] ? background_writeout+0x0/0x91
 [<c1047c80>] ? pdflush+0x0/0x2d
 [<c1026d72>] ? kthread+0x6b/0x70
 [<c1026d07>] ? kthread+0x0/0x70
 [<c1002f93>] ? kernel_thread_helper+0x7/0x10
Code: 09 56 53 68 f7 09 2e c1 eb 07 56 53 68 90 0a 2e c1 6a 20 55 e8
f0 01 0d 00 83 c4 14 5b 89 e8 5e 5f 5d c3 89 d1 8b 50 48 8b 40 54 <8b>
92 c0 00 00 00 e9 92 ff ff ff 53 89 d3 89 c2 81 e2 ff ff 0f
EIP: [<c1097067>] bdevname+0x8/0x13 SS:ESP 0068:df87fd38
CR2: 00000000000000c0

-- 
Glenn Maynard

Re: Crash during SATA reads

[Jens Axboe]

On Thu, Nov 12 2009, Glenn Maynard wrote:
> On Thu, Nov 12, 2009 at 4:16 AM, Jens Axboe <jens.axboe@oracle.com> wrote:
> > So the device isn't mounted, which means that we'll default to 1k
> > blocks. I think that's a big clue here, as you'll have 4 buffer_heads
> > pointing to the same page. And one of your oopses is indeed in the
> > ->b_this_page unroll.
> >
> > Can you trigger this if you mount/umount the device first?
> 
> Yeah.  I've reproduced it reading from /dev/sda (the drive the root
> partition is mounted on) with no second drive attached, too.
> 
> I'm currently reproducing it with "dd if=/dev/sda of=/dev/sdb", since
> that reproduces faster and more reproducably than just reading.
> Here's a trace from one of these:
> 
> BUG: unable to handle kernel NULL pointer dereference at 000000c0
> IP: [<c1097067>] bdevname+0x8/0x13
> *pde = 00000000
> Oops: 0000 [#1] PREEMPT
> last sysfs file:
> /sys/devices/pci0000:00/0000:00:1f.2/host1/target1:0:0/1:0:0:0/model
> Modules linked in: netconsole atl1c rtc

To rule out any potential hardware problems, have you run any extensive
memory checks on this machine?

> Pid: 151, comm: pdflush Not tainted (2.6.31.6 #17) G31M-ES2L
> EIP: 0060:[<c1097067>] EFLAGS: 00010246 CPU: 0
> EIP is at bdevname+0x8/0x13
> EAX: df4ddcf0 EBX: 00000000 ECX: df87fd54 EDX: 00000000
> ESI: d5cfa0c0 EDI: 00000000 EBP: 00000001 ESP: df87fd38
>  DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 0068
> Process pdflush (pid: 151, ti=df87e000 task=df8caae0 task.ti=df87e000)
> Stack:
>  c11582ff 0006d250 00000000 fffffffb 00000002 00000246 c1ae7e80 00011200
> <0> 00011210 df83a9e0 c1043b26 df87fd60 00000004 00000101 c101be1c 00000000
> <0> 00000000 d5cfa0c0 00000001 c11583e4 00000001 df83aa00 df83aa00 c107d6db
> Call Trace:
>  [<c11582ff>] ? generic_make_request+0x1cc/0x209
>  [<c1043b26>] ? mempool_alloc+0x1e/0xd6
>  [<c101be1c>] ? __do_softirq+0x9b/0xc8
>  [<c11583e4>] ? submit_bio+0xa8/0xb0
>  [<c107d6db>] ? bio_alloc_bioset+0x3e/0xa4
>  [<c107ce92>] ? submit_bh+0x127/0x152
>  [<c107b117>] ? __block_write_full_page+0x1ff/0x2d8
>  [<c107eafd>] ? blkdev_get_block+0x0/0x46
>  [<c107cc5e>] ? block_write_full_page_endio+0xe2/0xec
>  [<c1079ef7>] ? end_buffer_async_write+0x0/0xd4
>  [<c107eafd>] ? blkdev_get_block+0x0/0x46
>  [<c107cc72>] ? block_write_full_page+0xa/0xc
>  [<c1079ef7>] ? end_buffer_async_write+0x0/0xd4
>  [<c104750c>] ? __writepage+0x8/0x1d
>  [<c1047407>] ? write_cache_pages+0x1bf/0x2bc
>  [<c1047504>] ? __writepage+0x0/0x1d
>  [<c1047521>] ? generic_writepages+0x0/0x1f
>  [<c104753d>] ? generic_writepages+0x1c/0x1f
>  [<c1047562>] ? do_writepages+0x22/0x32
>  [<c1076444>] ? writeback_single_inode+0xad/0x1b2
>  [<c1076672>] ? generic_sync_sb_inodes+0x129/0x26e
>  [<c1047c80>] ? pdflush+0x0/0x2d
>  [<c1076820>] ? writeback_inodes+0x64/0xb4
>  [<c1047040>] ? background_writeout+0x5f/0x91
>  [<c1047bab>] ? __pdflush+0xcf/0x1a4
>  [<c1047ca9>] ? pdflush+0x29/0x2d
>  [<c1046fe1>] ? background_writeout+0x0/0x91
>  [<c1047c80>] ? pdflush+0x0/0x2d
>  [<c1026d72>] ? kthread+0x6b/0x70
>  [<c1026d07>] ? kthread+0x0/0x70
>  [<c1002f93>] ? kernel_thread_helper+0x7/0x10
> Code: 09 56 53 68 f7 09 2e c1 eb 07 56 53 68 90 0a 2e c1 6a 20 55 e8
> f0 01 0d 00 83 c4 14 5b 89 e8 5e 5f 5d c3 89 d1 8b 50 48 8b 40 54 <8b>
> 92 c0 00 00 00 e9 92 ff ff ff 53 89 d3 89 c2 81 e2 ff ff 0f
> EIP: [<c1097067>] bdevname+0x8/0x13 SS:ESP 0068:df87fd38
> CR2: 00000000000000c0

This one is different, it's on the submit path.

-- 
Jens Axboe

Re: Crash during SATA reads

[Glenn Maynard]

On Thu, Nov 12, 2009 at 4:55 AM, Jens Axboe <jens.axboe@oracle.com> wrote:
> To rule out any potential hardware problems, have you run any extensive
> memory checks on this machine?

God damn it.  I ran memtest+ just a week or so ago and it was fine
through several passes; now it's failing badly.  I'm inclined to send
Kingston a bill for a day and a half of wasted time.

I didn't think back to memory since I'm used to memory problems in
userspace, where they cause wildly variable crashes.  Of course, the
kernel's far more likely to stick data in the same spot, so it makes
sense that it doesn't cause as much volatility, leading to a bunch of
related-looking crashes.

Thanks.

-- 
Glenn Maynard

Re: Crash during SATA reads

[Jens Axboe]

On Thu, Nov 12 2009, Glenn Maynard wrote:
> On Thu, Nov 12, 2009 at 4:55 AM, Jens Axboe <jens.axboe@oracle.com> wrote:
> > To rule out any potential hardware problems, have you run any extensive
> > memory checks on this machine?
> 
> God damn it.  I ran memtest+ just a week or so ago and it was fine
> through several passes; now it's failing badly.  I'm inclined to send
> Kingston a bill for a day and a half of wasted time.

Auch, perhaps it's just seated badly? Power problems? Or yes, you just
got crap RAM :/

> I didn't think back to memory since I'm used to memory problems in
> userspace, where they cause wildly variable crashes.  Of course, the
> kernel's far more likely to stick data in the same spot, so it makes
> sense that it doesn't cause as much volatility, leading to a bunch of
> related-looking crashes.

Well, at least it's a relief that it isn't a kernel issue :-)

-- 
Jens Axboe