Re: 2.6.16-rc6-rt3

From: K.R. Foley
Date: Tue Mar 14 2006 - 11:41:03 EST

Ingo Molnar wrote:
> * K.R. Foley <kr@xxxxxxxxxx> wrote:
>
>> This one doesn't want to boot on the old SMP box. Log and config attached.
>
>> [<c0111e19>] do_page_fault+0x36f/0x48a (88)
>> [<c010357f>] error_code+0x4f/0x54 (76)
>> [<c0132cc6>] resolve_symbol+0x22/0x5d (44)
>> [<c013321c>] simplify_symbols+0x81/0xf4 (40)
>> [<c0133e2d>] load_module+0x637/0x968 (168)
>> [<c01341c1>] sys_init_module+0x3d/0x1d3 (28)
>> [<c0102a1b>] sysenter_past_esp+0x54/0x75 (-8116)
>
> hm, this seems to suggest some module building mismatch. Could you
> double-check that by doing a full rebuild?
>
> Ingo
>

OK. Still having problems. This time I started from scratch with 2.6.15
then patch-2.6.16-rc6 then patch-2.6.16-rc6-rt3. Log and config attached.

--
kr
Linux version 2.6.16-rc6-rt3 (kr@xxxxxxxxxxxxxxxxxxx) (gcc version 3.4.4 20050721 (Red Hat 3.4.4-2)) #1 SMP PREEMPT Tue Mar 14 09:44:24 CST 2006
BIOS-provided physical RAM map:
BIOS-e820: 0000000000000000 - 00000000000a0000 (usable)
BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
BIOS-e820: 0000000000100000 - 000000001ff9e000 (usable)
BIOS-e820: 000000001ff9e000 - 0000000020000000 (reserved)
BIOS-e820: 00000000fec00000 - 00000000fec10000 (reserved)
BIOS-e820: 00000000fee00000 - 00000000fee10000 (reserved)
BIOS-e820: 00000000ffb00000 - 0000000100000000 (reserved)
511MB LOWMEM available.
found SMP MP-table at 000fe710
DMI 2.3 present.
ACPI: PM-Timer IO Port: 0x808
ACPI: LAPIC (acpi_id[0x01] lapic_id[0x00] enabled)
Processor #0 6:8 APIC version 17
ACPI: LAPIC (acpi_id[0x02] lapic_id[0x01] enabled)
Processor #1 6:8 APIC version 17
ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
ACPI: LAPIC_NMI (acpi_id[0x02] high edge lint[0x1])
ACPI: IOAPIC (id[0x02] address[0xfec00000] gsi_base[0])
IOAPIC[0]: apic_id 2, version 32, address 0xfec00000, GSI 0-23
ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
Enabling APIC mode: Flat. Using 1 I/O APICs
Using ACPI (MADT) for SMP configuration information
Allocating PCI resources starting at 30000000 (gap: 20000000:dec00000)
Detected 930.992 MHz processor.
Real-Time Preemption Support (C) 2004-2006 Ingo Molnar
Built 1 zonelists
Kernel command line: ro root=LABEL=/ console=ttyS0,38400 console=tty0 nmi_watchdog=1
Enabling fast FPU save and restore... done.
Enabling unmasked SIMD FPU exception support... done.
Initializing CPU#0
WARNING: experimental RCU implementation.
PID hash table entries: 2048 (order: 11, 32768 bytes)
requested: 50000000 calculated 49992350 ns 50 cyc error: 7650
Event source pit installed with caps set: 01
Console: colour VGA+ 80x25
Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Memory: 506304k/523896k available (1785k kernel code, 17208k reserved, 921k data, 280k init, 0k highmem)
Checking if this processor honours the WP bit even in supervisor mode... Ok.
Calibrating delay using timer specific routine.. 1862.57 BogoMIPS (lpj=931289)
Security Framework v1.0.0 initialized
Capability LSM initialized
Mount-cache hash table entries: 512
CPU: L1 I cache: 16K, L1 D cache: 16K
CPU: L2 cache: 256K
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.
Checking 'hlt' instruction... OK.
CPU0: Intel Pentium III (Coppermine) stepping 06
Booting processor 1/1 eip 2000
Initializing CPU#1
Calibrating delay using timer specific routine.. 1861.67 BogoMIPS (lpj=930836)
CPU: L1 I cache: 16K, L1 D cache: 16K
CPU: L2 cache: 256K
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#1.
CPU1: Intel Pentium III (Coppermine) stepping 06
Total of 2 processors activated (3724.25 BogoMIPS).
ENABLING IO-APIC IRQs
..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1
Event source lapic installed with caps set: 04
checking TSC synchronization across 2 CPUs: passed.
Event source lapic installed with caps set: 04
Brought up 2 CPUs
checking if image is initramfs... it is
Freeing initrd memory: 433k freed
NET: Registered protocol family 16
ACPI: bus type pci registered
PCI: PCI BIOS revision 2.10 entry at 0xfc03e, last bus=4
PCI: Using configuration type 1
ACPI: Subsystem revision 20060127
ACPI: Interpreter enabled
ACPI: Using IOAPIC for interrupt routing
ACPI: PCI Root Bridge [PCI0] (0000:00)
ACPI: Assume root bridge [\_SB_.PCI0] bus is 0
PCI quirk: region 0800-087f claimed by ICH4 ACPI/GPIO/TCO
PCI quirk: region 0880-08bf claimed by ICH4 GPIO
PCI: Transparent bridge - 0000:00:1e.0
ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 7 *9 10 11 12 15)
ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 6 7 9 *10 11 12 15)
ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 *5 6 7 9 10 11 12 15)
ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 7 9 10 *11 12 15)
Linux Plug and Play Support v0.97 (c) Adam Belay
pnp: PnP ACPI init
pnp: PnP ACPI: found 14 devices
PCI: Using ACPI for IRQ routing
PCI: If a device doesn't work, try "pci=routeirq". If it helps, post a report
pnp: 00:0d: ioport range 0x800-0x85f could not be reserved
pnp: 00:0d: ioport range 0xc00-0xc7f has been reserved
pnp: 00:0d: ioport range 0x860-0x8ff could not be reserved
PCI: Bridge: 0000:00:01.0
IO window: disabled.
MEM window: fc000000-fdffffff
PREFETCH window: f4000000-f5ffffff
PCI: Bridge: 0000:02:1f.0
IO window: disabled.
MEM window: fb000000-fb0fffff
PREFETCH window: disabled.
PCI: Bridge: 0000:00:02.0
IO window: disabled.
MEM window: fb000000-fbffffff
PREFETCH window: disabled.
PCI: Bridge: 0000:00:1e.0
IO window: e000-efff
MEM window: f9000000-faffffff
PREFETCH window: 30000000-300fffff
No per-cpu room for modules.
VFS: Disk quotas dquot_6.5.1
Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Initializing Cryptographic API
io scheduler noop registered
io scheduler anticipatory registered (default)
io scheduler deadline registered
io scheduler cfq registered
ACPI: PCI Interrupt 0000:01:00.0[A] -> GSI 16 (level, low) -> IRQ 16
nvidiafb: PCI id - 10de002d
nvidiafb: Actual id - 10de002d
nvidiafb: nVidia device/chipset 10DE002D
nvidiafb: HW is currently programmed for CRT
nvidiafb: Using CRT on CRTC 0
nvidiafb: MTRR set to ON
nvidiafb: PCI nVidia NV2 framebuffer (32MB @ 0xF4000000)
ACPI: Power Button (FF) [PWRF]
ibm_acpi: ec object not found
isapnp: Scanning for PnP cards...
isapnp: No Plug & Play device found
Real Time Clock Driver v1.12ac
PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
serio: i8042 AUX port at 0x60,0x64 irq 12
serio: i8042 KBD port at 0x60,0x64 irq 1
Serial: 8250/16550 driver $Revision: 1.90 $ 4 ports, IRQ sharing disabled
serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
serial8250: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
00:0a: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
00:0b: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
RAMDISK driver initialized: 16 RAM disks of 8192K size 1024 blocksize
Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
ICH: IDE controller at PCI slot 0000:00:1f.1
ICH: chipset revision 2
ICH: not 100% native mode: will probe irqs later
ide0: BM-DMA at 0xffa0-0xffa7, BIOS settings: hda:DMA, hdb:pio
ide1: BM-DMA at 0xffa8-0xffaf, BIOS settings: hdc:DMA, hdd:pio
hda: SAMSUNG CD-R/RW SW-248F, ATAPI CD/DVD-ROM drive
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
hdc: Lite-On LTN483S 48x Max, ATAPI CD/DVD-ROM drive
ide1 at 0x170-0x177,0x376 on irq 15
mice: PS/2 mouse device common for all mice
md: md driver 0.90.3 MAX_MD_DEVS=256, MD_SB_DISKS=27
md: bitmap version 4.39
NET: Registered protocol family 2
input: AT Translated Set 2 keyboard as /class/input/input0
IP route cache hash table entries: 8192 (order: 3, 32768 bytes)
TCP established hash table entries: 32768 (order: 9, 2490368 bytes)
TCP bind hash table entries: 32768 (order: 9, 2359296 bytes)
TCP: Hash tables configured (established 32768 bind 32768)
TCP reno registered
TCP bic registered
NET: Registered protocol family 1
input: ImPS/2 Generic Wheel Mouse as /class/input/input1
NET: Registered protocol family 17
NET: Registered protocol family 8
NET: Registered protocol family 20
Testing NMI watchdog ... OK.
Starting balanced_irq
Using IPI Shortcut mode
*****************************************************************************
* *
requested: 50000000 calculated 49999999 ns 46549597 cyc error: 1
Time: tsc clocksource has been installed.
* REMINDER, the following debugging options are turned on in your .config: *
* *
* CONFIG_DEBUG_RT_MUTEXES *
* CONFIG_DEBUG_PREEMPT *
* *
* they may increase runtime overhead and latencies. *
* *
*****************************************************************************
*****************************************************************************
* *
* REMINDER, the following debugging options are turned on in your .config: *
* *
* CONFIG_DEBUG_RT_MUTEXES *
* CONFIG_DEBUG_PREEMPT *
* *
* they may increase runtime overhead and latencies. *
* *
*****************************************************************************
Freeing unused kernel memory: 280k freed
Could not allocate 8 bytes percpu data
BUG: Unable to handle kernel paging request at virtual address f3010000
printing eip:
c0131c79
*pde = 00000000
Oops: 0000 [#1]
PREEMPT SMP
Modules linked in:
CPU: 1
EIP: 0060:[<c0131c79>] Not tainted VLI
EFLAGS: 00010297 (2.6.16-rc6-rt3 #1)
EIP is at __find_symbol+0x37/0x1da
eax: ffffffff ebx: 000004b0 ecx: c02fe964 edx: c02fab00
esi: f3010000 edi: e08255d0 ebp: c1eafe9c esp: c1eafe8c
ds: 007b es: 007b ss: 0068 preempt: 00000001
Process insmod (pid: 804, threadinfo=c1eae000 task=c1e91150 stack_left=7768 worst_left=-1)
Stack: <0>000004b0 e082adc0 e082bc80 e08255d0 c1eafec8 c0132cc6 e08255d0 c1eafeb4
c1eafeb8 00000001 00000000 e082adc0 e082adc0 00000370 00000032 c1eafef0
c013321c e0824930 0000000b e08255d0 e082bc80 00000000 e0824930 e082bc8d
Call Trace:
[<c01038fb>] show_stack_log_lvl+0xa5/0xad (44)
[<c0103a67>] show_registers+0x137/0x1a0 (44)
[<c0103c3b>] die+0xf3/0x16f (56)
[<c0111e19>] do_page_fault+0x36f/0x48a (88)
[<c010357f>] error_code+0x4f/0x54 (76)
[<c0132cc6>] resolve_symbol+0x22/0x5d (44)
[<c013321c>] simplify_symbols+0x81/0xf4 (40)
[<c0133e2d>] load_module+0x637/0x968 (168)
[<c01341c1>] sys_init_module+0x3d/0x1d3 (28)
[<c0102a1b>] sysenter_past_esp+0x54/0x75 (-8116)
---------------------------
| preempt count: 00000001 ]
| 1-level deep critical section nesting:
----------------------------------------
.. [<c02bd871>] .... _raw_spin_lock_irqsave+0x11/0x33
.....[<c0103b87>] .. ( <= die+0x3f/0x16f)

------------------------------
| showing all locks held by: | (insmod/804 [c1e91150, 119]):
------------------------------

#001: [c0311f24] {module_mutex.lock}
... acquired at: rt_down_interruptible+0x15/0x32

Code: 00 00 00 00 b8 80 85 2f c0 3d 04 cb 2f c0 c7 45 f0 00 00 00 00 73 4a 89 c2 b9 a4 d6 2f c0 8b 5d f0 8b 7d 08 8b 34 dd 84 85 2f c0 <ac> ae 75 08 84 c0 75 f8 31 c0 eb 04 19 c0 0c 01 85 c0 75 11 8b
BUG: nonzero lock count 1 at exit time?
insmod: 804 [c1e91150, 119]
[<c0103854>] show_trace+0x13/0x15 (20)
[<c010392e>] dump_stack+0x16/0x18 (20)
[<c013067f>] rt_mutex_debug_check_no_locks_held+0x60/0x227 (44)
[<c011c837>] do_exit+0x3e3/0x45b (32)
[<c0103cb7>] do_trap+0x0/0x97 (52)
[<c0111e19>] do_page_fault+0x36f/0x48a (88)
[<c010357f>] error_code+0x4f/0x54 (76)
[<c0132cc6>] resolve_symbol+0x22/0x5d (44)
[<c013321c>] simplify_symbols+0x81/0xf4 (40)
[<c0133e2d>] load_module+0x637/0x968 (168)
[<c01341c1>] sys_init_module+0x3d/0x1d3 (28)
[<c0102a1b>] sysenter_past_esp+0x54/0x75 (-8116)
---------------------------
| preempt count: 00000000 ]
| 0-level deep critical section nesting:
----------------------------------------

------------------------------
| showing all locks held by: | (insmod/804 [c1e91150, 120]):
------------------------------

#001: [c0311f24] {module_mutex.lock}
... acquired at: rt_down_interruptible+0x15/0x32

BUG: insmod/804, lock held at task exit time!
[c0311f24] {module_mutex.lock}
.. ->owner: c1e91152
.. held by: insmod: 804 [c1e91150, 120]
... acquired at: rt_down_interruptible+0x15/0x32
hm, PI interest held at exit time? Task:
insmod: 804 [c1e91150, 120]-------------------------
| waiter struct dfd6ff2c:
| w->list_entry: [DP:c0311f2c/c0311f2c|SP:c0311f34/c0311f34|PRI:117]
| w->pi_list_entry: [DP:c1e916a0/c1e916a0|SP:c1e916a8/c1e916a8|PRI:117]

| lock:
[c0311f24] {module_mutex.lock}
.. ->owner: c1e91152
.. held by: insmod: 804 [c1e91150, 120]
... acquired at: rt_down_interruptible+0x15/0x32
| w->ti->task:
insmod: 805 [c1eac070, 117]| blocked at: 0x11111111
-------------------------
softirq-tasklet/8[CPU#0]: BUG in rt_mutex_debug_task_free at kernel/rtmutex-debug.c:387
[<c0103854>] show_trace+0x13/0x15 (20)
[<c010392e>] dump_stack+0x16/0x18 (20)
[<c011ab8e>] __WARN_ON+0x41/0x57 (40)
[<c01309c1>] rt_mutex_debug_task_free+0x29/0x96 (24)
[<c0117227>] free_task+0x15/0x26 (20)
[<c011730e>] __put_task_struct_cb+0xd6/0xdc (16)
[<c013c3ea>] rcu_process_callbacks+0x60/0x75 (20)
[<c011ed93>] __tasklet_action+0xab/0xe1 (24)
[<c011edff>] tasklet_action+0x36/0x3e (28)
[<c011efbb>] ksoftirqd+0xfb/0x18a (32)
[<c012aea8>] kthread+0x7e/0xa7 (40)
[<c01010d1>] kernel_thread_helper+0x5/0xb (1043021852)
---------------------------
| preempt count: 00000001 ]
| 1-level deep critical section nesting:
----------------------------------------
.. [<c02bd871>] .... _raw_spin_lock_irqsave+0x11/0x33
.....[<c011ab5b>] .. ( <= __WARN_ON+0xe/0x57)

Attachment: config.porky.2.6.16-rc6-rt3.gz
Description: GNU Zip compressed data