2009-03-11 04:19:18

by Tetsuo Handa

[permalink] [raw]
Subject: KMEMCHECK: linux-next: kernel BUG at arch/x86/mm/kmemcheck/kmemcheck.c:297!

Hello.

I encountered this.

[ 0.004000] ------------[ cut here ]------------
[ 0.004000] kernel BUG at arch/x86/mm/kmemcheck/kmemcheck.c:297!
[ 0.004000] invalid opcode: 0000 [#1] SMP
[ 0.004000] last sysfs file:
[ 0.004000] Modules linked in:
[ 0.004000]
[ 0.004000] Pid: 0, comm: swapper Not tainted (2.6.29-rc7-next-20090310 #1) VMware Virtual Platform
[ 0.004000] EIP: 0060:[<c0122e01>] EFLAGS: 00010202 CPU: 0
[ 0.004000] EIP is at kmemcheck_hide_pages+0x51/0x80
[ 0.004000] EAX: c06d6f70 EBX: f7000000 ECX: 370001e3 EDX: c06d6f70
[ 0.004000] ESI: c17bd000 EDI: 00000000 EBP: c0531ea0 ESP: c0531e8c
[ 0.004000] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 0.004000] Process swapper (pid: 0, ti=c0531000 task=c04f3b60 task.ti=c0531000)
[ 0.004000] Stack:
[ 0.004000] 00000001 00000002 00000000 00000024 c17bd024 c0531ec0 c019c390 00000000
[ 0.004000] 00000001 c17bd000 c17bd000 00000100 c052ee10 c0531ee8 c0198055 ffffffff
[ 0.004000] 21668823 00000001 ffffffff 000000d0 00000010 c052ee10 c052ee10 c0531f08
[ 0.004000] Call Trace:
[ 0.004000] [<c019c390>] ? kmemcheck_alloc_shadow+0x70/0x90
[ 0.004000] [<c0198055>] ? allocate_slab+0xc5/0x130
[ 0.004000] [<c0198112>] ? new_slab+0x22/0x130
[ 0.004000] [<c01987c4>] ? __slab_alloc+0x104/0x1e0
[ 0.004000] [<c0199ce3>] ? __kmalloc+0x113/0x160
[ 0.004000] [<c02672b0>] ? kvasprintf+0x30/0x60
[ 0.004000] [<c02672b0>] ? kvasprintf+0x30/0x60
[ 0.004000] [<c02672b0>] ? kvasprintf+0x30/0x60
[ 0.004000] [<c02672f1>] ? kasprintf+0x11/0x20
[ 0.004000] [<c054ba30>] ? kmem_cache_init+0xc0/0x140
[ 0.004000] [<c03ce3d2>] ? __start_notes+0x0/0xe
[ 0.004000] [<c0535932>] ? start_kernel+0x182/0x280
[ 0.004000] [<c05352b0>] ? unknown_bootoption+0x0/0x150
[ 0.004000] [<c0535080>] ? __init_begin+0x80/0xc0
[ 0.004000] Code: c0 89 c2 74 37 83 7d f0 01 75 20 8b 00 83 e0 fe 0d 00 08 00 00 89 02 0f 01 3b 47 83 c6 24 3b 7d ec 72 cb 83 c4 08 5b 5e 5f 5d c3 <0f> 0b 8d b6 00 00 00 00 8d bc 27 00 00 00 00 eb fe 0f 0b 8d b6
[ 0.004000] EIP: [<c0122e01>] kmemcheck_hide_pages+0x51/0x80 SS:ESP 0068:c0531e8c
[ 0.004000] ---[ end trace 4eaa2a86a8e2da22 ]---

Config is at http://I-love.SAKURA.ne.jp/tmp/config-2.6.29-rc7-next-20090310
Full log is at http://I-love.SAKURA.ne.jp/tmp/dmesg-2.6.29-rc7-next-20090310.txt

Regards.


2009-03-15 17:47:30

by Vegard Nossum

[permalink] [raw]
Subject: Re: KMEMCHECK: linux-next: kernel BUG at arch/x86/mm/kmemcheck/kmemcheck.c:297!

2009/3/11 Tetsuo Handa <[email protected]>:
> Hello.
>
> I encountered this.
>
> [ 0.004000] ------------[ cut here ]------------
> [ 0.004000] kernel BUG at arch/x86/mm/kmemcheck/kmemcheck.c:297!

Hi, thanks for this report!

I have a feeling that the following patch might fix it. Please try it out
only if you have the time. I will also try to reproduce it when I have the
time myself.


Vegard


diff --git a/arch/x86/mm/init.c b/arch/x86/mm/init.c
index 6d63e3d..86f7398 100644
--- a/arch/x86/mm/init.c
+++ b/arch/x86/mm/init.c
@@ -146,7 +146,7 @@ unsigned long __init_refok init_memory_mapping(unsigned long start,
if (!after_bootmem)
init_gbpages();

-#ifdef CONFIG_DEBUG_PAGEALLOC
+#if defined(CONFIG_DEBUG_PAGEALLOC) || defined(CONFIG_KMEMCHECK)
/*
* For CONFIG_DEBUG_PAGEALLOC, identity mapping will use small pages.
* This will simplify cpa(), which otherwise needs to support splitting

2009-03-16 00:54:54

by Tetsuo Handa

[permalink] [raw]
Subject: Re: KMEMCHECK: linux-next: kernel BUG at arch/x86/mm/kmemcheck/kmemcheck.c:297!

Hello.

Vegard Nossum wrote:
> > [ 0.004000] ------------[ cut here ]------------
> > [ 0.004000] kernel BUG at arch/x86/mm/kmemcheck/kmemcheck.c:297!
>
> Hi, thanks for this report!
>
> I have a feeling that the following patch might fix it. Please try it out
> only if you have the time. I will also try to reproduce it when I have the
> time myself.

I tested this patch on linux-next-20090310 and confirmed that this problem was
solved.

By the way, is there a possibility that delays introduced by kmemcheck trigger
false "CPU stalled" warning?
I got below warning message after applying this patch.

[ 14.477987] pci 0000:00:18.7: PCI bridge, secondary bus 0000:22
[ 14.480320] pci 0000:00:18.7: IO window: disabled
[ 14.482590] pci 0000:00:18.7: MEM window: 0xdb200000-0xdb2fffff
[ 14.485180] pci 0000:00:18.7: PREFETCH window: 0x000000dda00000-0x000000ddafffff
[ 14.618875] NET: Registered protocol family 2
[ 14.744525] IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
[ 15.762230] TCP established hash table entries: 131072 (order: 8, 1048576 bytes)
[ 18.989204] TCP bind hash table entries: 65536 (order: 9, 2621440 bytes)
[ 24.007883] INFO: RCU detected CPU 0 stall (t=4294898298/2500 jiffies)
[ 24.007883] Pid: 1, comm: swapper Not tainted 2.6.29-rc7-next-20090310-dirty #2
[ 24.007883] Call Trace:
[ 24.007883] [<c01366d8>] ? printk+0x18/0x20
[ 24.007883] [<c0170254>] print_cpu_stall+0x44/0x90
[ 24.007883] [<c01702dd>] check_cpu_stall+0x3d/0xc0
[ 24.007883] [<c016ccce>] ? __touch_softlockup_watchdog+0xe/0x20
[ 24.007883] [<c016cf69>] ? softlockup_tick+0x169/0x190
[ 24.007883] [<c017091a>] __rcu_pending+0x1a/0xa0
[ 24.007883] [<c01709c9>] rcu_pending+0x29/0x60
[ 24.007883] [<c01401b6>] update_process_times+0x36/0x70
[ 24.007883] [<c0155e25>] tick_periodic+0x25/0x70
[ 24.007883] [<c0155e89>] tick_handle_periodic+0x19/0x80
[ 24.007883] [<c0102f3e>] ? restore_nocheck_notrace+0x0/0xe
[ 24.007883] [<c0115b64>] local_apic_timer_interrupt+0x54/0x60
[ 24.007883] [<c0115b9e>] smp_apic_timer_interrupt+0x2e/0x40
[ 24.007883] [<c01037c7>] apic_timer_interrupt+0x2f/0x34
[ 24.007883] [<c015ba2b>] ? lockdep_init_map+0x5b/0x570
[ 24.007883] [<c0273f02>] __spin_lock_init+0x32/0x60
[ 24.007883] [<c055c241>] tcp_init+0x1c1/0x350
[ 24.007883] [<c033fcca>] ? register_pernet_subsys+0x2a/0x30
[ 24.007883] [<c055cc40>] ? inet_init+0x0/0x1f0
[ 24.007883] [<c055cd40>] inet_init+0x100/0x1f0
[ 24.007883] [<c055cc40>] ? inet_init+0x0/0x1f0
[ 24.007883] [<c010103d>] do_one_initcall+0x2d/0x1a0
[ 24.007883] [<c015a37c>] ? validate_chain+0x3fc/0x540
[ 24.007883] [<c015a37c>] ? validate_chain+0x3fc/0x540
[ 24.007883] [<c012354e>] ? kmemcheck_pte_lookup+0xe/0x30
[ 24.007883] [<c015a37c>] ? validate_chain+0x3fc/0x540
[ 24.007883] [<c012354e>] ? kmemcheck_pte_lookup+0xe/0x30
[ 24.007883] [<c015a37c>] ? validate_chain+0x3fc/0x540
[ 24.007883] [<c015a37c>] ? validate_chain+0x3fc/0x540
[ 24.007883] [<c0157d14>] ? lock_release_holdtime+0x74/0xc0
[ 24.007883] [<c012ecd8>] ? scheduler_tick+0x68/0xb0
[ 24.007883] [<c015d3c7>] ? __lock_release+0x47/0x70
[ 24.007883] [<c012ecd8>] ? scheduler_tick+0x68/0xb0
[ 24.007883] [<c03cd47d>] ? _spin_unlock+0x1d/0x20
[ 24.007883] [<c012ece0>] ? scheduler_tick+0x70/0xb0
[ 24.007883] [<c01401cb>] ? update_process_times+0x4b/0x70
[ 24.007883] [<c0155e25>] ? tick_periodic+0x25/0x70
[ 24.007883] [<c0155e89>] ? tick_handle_periodic+0x19/0x80
[ 24.007883] [<c0102f3e>] ? restore_nocheck_notrace+0x0/0xe
[ 24.007883] [<c015b066>] ? trace_hardirqs_on_caller+0xe6/0x170
[ 24.007883] [<c0535a00>] ? start_kernel+0x250/0x280
[ 24.007883] [<c0265e34>] ? trace_hardirqs_on_thunk+0xc/0x10
[ 24.007883] [<c010590b>] ? do_softirq+0x4b/0xf0
[ 24.007883] [<c0102f3e>] ? restore_nocheck_notrace+0x0/0xe
[ 24.007883] [<c0535ad0>] ? kernel_init+0x0/0x90
[ 24.007883] [<c0535a5a>] do_initcalls+0x2a/0x40
[ 24.007883] [<c0535ad0>] ? kernel_init+0x0/0x90
[ 24.007883] [<c0535a8c>] do_basic_setup+0x1c/0x20
[ 24.007883] [<c0535b20>] kernel_init+0x50/0x90
[ 24.007883] [<c01038e7>] kernel_thread_helper+0x7/0x10
[ 26.314302] TCP: Hash tables configured (established 131072 bind 65536)
[ 26.316703] TCP reno registered
[ 26.423914] NET: Registered protocol family 1
[ 26.498394] checking if image is initramfs...it isn't (junk in compressed archive); looks like an initrd
[ 26.667075] Freeing initrd memory: 1056k freed

I don't see this warning message if I choose CONFIG_KMEMCHECK=n .

Regards.