Bug 151865

Hardware Environment: IBM x225, 2GB RAM, 2x36GB SCSI disks, 2.66GHz P4 w/ HT

Firmware Environment: 1.43 (9/14/2004)

Software Environment: RHEL3 U5 B1 for i386, kernel 2.4.21-31.ELsmp

Steps to Reproduce:
1. Run our stress test suite (pounder2) for a few hours.

Actual Results: BUG reports, followed by system hanging.

Expected Results: Stress test suite runs to completion.

Additional Information: Here's what I captured on a serial console.
"D11ramsnake" is a shell script that invokes a shared memory stress test.

------------[  cut here  ]--------------
kernel BUG at page_alloc.c:225!
invalid operand: 0000
nfsd nfs lockd sunrpc udf ide-cd cdrom audit usbserial parport_pc lp parport
autofs4 tg3 ipt_REJECT ipt_state ip_conntrack iptable_filter ip_tables floppy sg
CPU: 1
EIP: 0060:[<c0158bf0>] Not tainted
EFLAGS: 00010286

EIP is at __free_pages_ok [kernel] 0x3e0 (2.4.21-31.ELsmp/i686)
eax: 00000033 ebx: c156ff6c ecx: c0383eb4 edx: 0000d53b
esi: de6e0b44 edi: 00115504 ebp: 00000000 esp: e69b1eac
ds: 0068 es: 0068 ss: 0068
Process dd (pid: 22504, stackpage=e69b1000)
Stack: c02bec8c c02499c0 059b1f6c c18fd710 00000001 e69b0000 00000020 00115511
f3c31680 002823f3 c01491a7 00000000 00000000 c156ff6c de6e0b44 00115504
00000800 c01495c6 e69b1f5c c156ff6c 00000000 00001000 00000000 00001000
Call Trace: [<c0249cc0>] ip_rcv_finish [kernel] 0x0 (0xe69b1eb0)
[<c01491a7>] generic_file_readahead [kernel] 0xd7 (0xe69b1ed4)
[<c01495c6>] do_generic_file_read [kernel] 0x1316 (0xe69b1ef0)
[<c014a035>] generic_file_new_read [kernel] 0xc5 (0xe69b1f30)
[<c0149e70>] file_read_actor [kernel] 0x0 (0xe69b1f40)
[<c014a15f>] generic_file_read [kernel] 0x2f (0xe69b1f7c)
[<c01645b7>] sys_read [kernel] 0x97 (0xe69b1f94)

Code: 0f 0b e1 00 0f e5 2b c0 e9 6c fc ff ff 9c 5a fa f0 fe 0d 6c

Kernel panic: fatal exception
------------[  cut here  ]--------------
kernel BUG at page_alloc.c:391!
invalid operand: 0000
nfsd nfs lockd sunrpc udf ide-cd cdrom audit usbserial parport_pc lp parport
autofs4 tg3 ipt_REJECT ipt_state ip_conntrack iptable_filter ip_tables floppy sg
CPU: 1
EIP: 0060:[<c0158f50>] Not tainted
EFLAGS: 00010202

EIP is at rmqueue [kernel] 0x310 (2.4.21-31.ELsmp/i686)
eax: 0104008c ebx: c03a7e00 ecx: 00001000 edx: 00018004
esi: 00037000 edi: c03a7e00 ebp: c15a001c esp: e22b7e38
ds: 0068 es: 0068 ss: 0068
Process D11ramsnake (pid 17218, stackpage=e22b7000)
Stack: 4e4d4c4b 5251504f 00001000 5a595857 00000000 00017004 00017004 00000202
00000000 c03a7e00 c03a7e00 c03aa404 00000003 00000000 c015912d 00000001
c03aa408 00000000 000001f0 00000000 c0159224 c03aa400 00000000 00000003
Call Trace: [<c015912d>] __alloc_pages_limit [kernel] 0x7d (0xe22b7e70)
[<c0159224>] __alloc_pages [kernel] 0xb4 (0xe22b7e88)
[<c01594fc>] __get_free_pages [kernel] 0x1c (0xe22b7ecc)
[<c012170c>] pgd_alloc [kernel] 0x6c (0xe22b7ed0)
[<c0126a9a>] mm_init [kernel] 0xaa (0xe22b7efc)
[<c0126d57>] copy_mm [kernel] 0xc7 (0xe22b7f10)
[<c01277a6>] copy_process [kernel] 0x4d6 (0xe22b7f34)
[<c01725e4>] do_pipe [kernel] 0x184 (0xe22b7f44)
[<c0127eff>] do_fork [kernel] 0x4f (0xe22b7f64)
[<c0109d29>] sys_clone [kernel] 0x49 (0xe22b7fa0)

Code: 0f 0b 87 01 0f e5 2b c0 8b 45 18 a9 00 01 00 00 74 08 0f 0b

Kernel panic: fatal exception

Created an attachment (id=9360)
Serial console output for a second run

Reran the test to make sure this wasn't a fluke.  It wasn't; the machine oopsed
again.

Waiting for reproducer code or vmcores from IBM.

From -31.EL built with slab debugging enabled:

PID: 31730  TASK: cea94000  CPU: 0   COMMAND: "dd"
 #0 [cea95d00] netconsole_netdump at f8aa7703
 #1 [cea95d14] try_crashdump at c0128ed3
 #2 [cea95d24] die at c010c682
 #3 [cea95d38] do_invalid_op at c010c892
 #4 [cea95dd8] error_code (via invalid_op) at c03f61c0
    EAX: 00000020  EBX: c03a8e00  ECX: 00001000  EDX: 000055b1  EBP: c11415a8
    DS:  0068      ESI: 00037000  ES:  0068      EDI: c03a8e00
    CS:  0060      EIP: c015972c  ERR: ffffffff  EFLAGS: 00010202
 #5 [cea95e14] rmqueue at c015972c
 #6 [cea95e50] __alloc_pages_limit at c0159928
 #7 [cea95e68] __alloc_pages at c0159a4b
 #8 [cea95eac] page_cache_read at c0148742
 #9 [cea95ed4] generic_file_readahead at c01491a2
#10 [cea95ef0] do_generic_file_read at c014977f
#11 [cea95f30] generic_file_new_read at c014a030
#12 [cea95f7c] generic_file_read at c014a15a
#13 [cea95f94] sys_read at c0164db5
#14 [cea95fc0] system_call at c03f6068
    EAX: 00000003  EBX: 00000000  ECX: 095ed000  EDX: 00000800
    DS:  002b      ESI: 00000800  ES:  002b      EDI: 095ed000
    SS:  002b      ESP: bfff9918  EBP: bfff9938
    CS:  0023      EIP: 00638f0e  ERR: 00000003  EFLAGS: 0000024



From vanilla 31.EL:

PID: 26230  TASK: ca042000  CPU: 1   COMMAND: "cp"
 #0 [ca043bac] netconsole_netdump at f8aa7703
 #1 [ca043bc0] try_crashdump at c0128ed3
 #2 [ca043bd0] die at c010c682
 #3 [ca043be4] do_invalid_op at c010c892
 #4 [ca043c84] error_code (via invalid_op) at c03f41c0
    EAX: 0104008c  EBX: c03a7e00  ECX: 00001000  EDX: 0000f8b7  EBP: c13a4b10
    DS:  0068      ESI: 00037000  ES:  0068      EDI: c03a7e00
    CS:  0060      EIP: c0158f50  ERR: ffffffff  EFLAGS: 00010202
 #5 [ca043cc0] rmqueue at c0158f50
 #6 [ca043cfc] __alloc_pages_limit at c0159128
 #7 [ca043d14] __alloc_pages at c015921f
 #8 [ca043d58] alloc_bounce_page at c016166e
 #9 [ca043d64] create_bounce at c0161827
#10 [ca043da8] __make_request at c01d2444
#11 [ca043e04] generic_make_request at c01d2b87
#12 [ca043e2c] submit_bh_rsector at c01d2c24
#13 [ca043e48] block_read_full_page at c0168161
#14 [ca043eac] page_cache_read at c014877e
#15 [ca043ed4] generic_file_readahead at c01491a2
#16 [ca043ef0] do_generic_file_read at c014977f
#17 [ca043f30] generic_file_new_read at c014a030
#18 [ca043f7c] generic_file_read at c014a15a
#19 [ca043f94] sys_read at c01645b5
#20 [ca043fc0] system_call at c03f4068
    EAX: 00000003  EBX: 00000004  ECX: bfffa3c0  EDX: 00001000
    DS:  002b      ESI: 00001000  ES:  002b      EDI: bfffa3c0
    SS:  002b      ESP: bfffa3a8  EBP: bfffb4c8
    CS:  0023      EIP: 001dff0e  ERR: 00000003  EFLAGS: 00000246

The above crashes occur at different points in the DEBUG_LRU_PAGE() macro.

I was able to reproduce this on 2.4.21-27.0.2 last night.
I'll test U3 kernels today.

Don, how did you reproduce it?

Larry

I reproduced the panic using the pounder test suite provided by IBM (see IT68975).
Run the test suite for a few hours.  Kill/restart it.  The panic usually occurs
a few hours into the second run.

Reproduceable on -15.EL.

> crash> kmem -s d4eabf80
> CACHE    NAME                 OBJSIZE  ALLOCATED     TOTAL  SLABS  SSIZE
> c3a96a08 kioctx                   128          0        30      1     4k
> SLAB      MEMORY    TOTAL  ALLOCATED  FREE
> d4eab000  d4eab100     30          0    30
> FREE / [ALLOCATED]
>   d4eabf80  (cpu 0 cache)
>
> Looks like this object is being freed a second time.

Most definitely -- it's sitting right there on the kmem_cache's per-cpu list.


> crash>  kmem d4eab000
> CACHE    NAME                 OBJSIZE  ALLOCATED     TOTAL  SLABS  SSIZE
> c3a96a08 kioctx                   128          0        30      1     4k
> SLAB      MEMORY    TOTAL  ALLOCATED  FREE
> d4eab000  d4eab100     30        -30    60
>   d4eab000 (slab_s)
>
> Hmm, has the *slab* has been freed twice?

Nope...

This output is searching the slab infrastructure for d4eab000 usage,
and finds that in the kioctx slab cache, that d4eab000 is the address
of a slab_s page.  The "-30" and "60" in the ALLOCATED column is a
miscalculation in the crash code when the search results in a slab_s
pointer instead of a slab object address inside that slab_s page.
(I can reproduce that -- my bad...)  Note that when it found that slab_s
in the first output from "kmem -s d4eabf80" that it printed the proper values.

Anyway, yes, there's most definitely a double-free in this case.

Created attachment 114222 [details]
Patch to fix random RHEL3 memory corruption

Don, please try out the latest official patch that fixes the RHEL3 memory
corruption problems.

IBM's pounder testsuite has run overnight on -32.EL + Larry's pte patch above.
I also restarted the test this morning and it has run past it's usual crashpoint
of a couple hours.

I believe this issue is corrected. 

A fix for this problem has just been committed to the RHEL3 U6
patch pool this evening (in kernel version 2.4.21-32.4.EL).

A fix for this problem has also been committed to the RHEL3 E6
patch pool this evening (in kernel version 2.4.21-32.0.1.EL).

An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on the solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHSA-2005-472.html

IBM has 2 new independent reports of this.  Reopening.

Neil/Don, IT 77541 does *not* relate to this bug, which was limited to x86
systems.  The new issue occurred on ia64, so please open a new bug.  I'm
reclosing this one.

Ernie, I think I'm missing something here.  Everying in IT 77541 (the two new
independent reports), appear to me to all be occuring under x86, just as this
bug indicates.  Where are you seeing that the new issue occured under ia64?

Hi, Neil.  The "Cpu type" at the top of IT 77541 was listed as "IA-64",
but I now see that the trace was from an i686.  At any rate, the problem
reported in this bugzilla is different and was fixed in 2.4.21-32.0.1.EL,
so I've removed this BZ from the IT and am reclosing this bug.

Please open a new bug for IT 77541.  Thanks in advance.

Moving all associated Issue Trackers to bug 168681.

A customer has hit a BUG() in the same page_alloc.c file.  Although it is a
different BUG() then the one in this report (page_alloc.c:328 opposed to
page_alloc.c:391) it fails for the same condition "if (BAD_RANGE(zone, page))
BUG();".  I am not sure if these to issues are related but they seem
suspiciously similar.

What was the cause of the initial corruption and the fix?

Thanks,

Alexis

In case it helps, here is a truncated stack trace from the customer:

 invalid operand: 0000
netconsole audit autofs4 nfs lockd sunrpc tg3 bonding sg sr_mod microcode
ide-scsi ide-cd cdrom keybdev mous
edev hid input ehci-hcd usb-ohci usbcore ext3 jbd 
CPU:    3
EIP:    0060:[<02159f7d>]    Tainted: PF
EFLAGS: 00210006

EIP is at rmqueue [kernel] 0x1fd (2.4.21-47.ELhugemem/i686)
eax: 00000070   ebx: 00000008   ecx: 000f6000   edx: 0015b068
esi: 023a93fc   edi: 023a8200   ebp: 0815588c   esp: dbe47da0
ds: 0068   es: 0068   ss: 0068
Process java (pid: 3857, stackpage=dbe47000)
Stack: 0211e1f0 00000001 000f6000 00001dc0 00000003 00065068 00065060 00200202 
       00000000 023a8200 023a8200 023a9524 00000003 00000000 0215a26d 02000068 
       023a952c 00000000 000001d2 00000000 0215a374 023a9520 00000000 00000003 
Call Trace:   [<0211e1f0>] smp_apic_timer_interrupt [kernel] 0x70 (0xdbe47da0)
[<0215a26d>] __alloc_pages_limit [kernel] 0x7d (0xdbe47dd8)
[<0215a374>] __alloc_pages [kernel] 0xc4 (0xdbe47df0)
[<02143bad>] do_anonymous_page [kernel] 0x16d (0xdbe47e34)
[<021449e1>] handle_mm_fault [kernel] 0xe1 (0xdbe47eb8)
[<021209bc>] do_page_fault [kernel] 0x15c (0xdbe47ef4)
[<02146ff3>] do_mmap_pgoff [kernel] 0x4d3 (0xdbe47f38)
[<021142a8>] sys_mmap2 [kernel] 0x78 (0xdbe47f94)
[<02120860>] do_page_fault [kernel] 0x0 (0xdbe47fb0)

Code: Bad EIP value.

> What was the cause of the initial corruption and the fix?

It was associated with the modification of 64-bit pte's used by
PAE kernels, where the modification of the two 32-bit halves
of a pte was not being done atomically, potentially leading
to the corruption of a pte's contents, which in turn would
lead to various memory corruption issues.

But, as you can see, that hole was closed in 2.4.21-32.0.1.EL.

(In reply to comment #42)
> > What was the cause of the initial corruption and the fix?
> 
> It was associated with the modification of 64-bit pte's used by
> PAE kernels, where the modification of the two 32-bit halves
> of a pte was not being done atomically, potentially leading
> to the corruption of a pte's contents, which in turn would
> lead to various memory corruption issues.
> 
> But, as you can see, that hole was closed in 2.4.21-32.0.1.EL.
> 
Is this the same issue as what was seen in the RedHat bug 168681?
> 

No, BZ #168681 one had to do with the pounter suite's "randasys" 
program passing a bogus user address into sys_futex(), which in turn
caused page structure corruption.  (fixed in 2.4.21-37.9.EL)