Re: 2.6.12-mm2

Re: 2.6.12-mm2

[Reuben Farrelly]

Hi,

On 26/06/2005 11:12 a.m., Andrew Morton wrote:
> ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.12/2.6.12-mm2/
> 
> 
> - A reminder that there is a vger mailing list for tracking patches which
>   are added to -mm.  Do
> 
>     `echo subscribe mm-commits | mail majordomo@vger.kernel.org'
> 
> - Lots of merges.  I'm holding off on the 80-odd pcmcia patches until we get
>   the recent PCI breakage sorted out.
> 
> - Big arch/cris update.

Some bad stuff seems to be happening here (this is new to -mm2; -mm1 did not 
have this problem).

It's 100% reproduceable, although seems to happen at slightly different places 
in the bootup, especially at the end.  Did I miss a patch for this?

reuben




Linux version 2.6.12-mm2 (root@tornado) (gcc version 4.0.0 20050622 (Red Hat 
4.0.0-13)) #1 SMP Mon Jun 27 01:19:41 NZST 2005
BIOS-provided physical RAM map:
  BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
  BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
  BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
  BIOS-e820: 0000000000100000 - 000000001fff0000 (usable)
  BIOS-e820: 000000001fff0000 - 000000001fff3000 (ACPI NVS)
  BIOS-e820: 000000001fff3000 - 0000000020000000 (ACPI data)
  BIOS-e820: 00000000fec00000 - 0000000100000000 (reserved)
511MB LOWMEM available.
found SMP MP-table at 000f52e0
DMI 2.3 present.
ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
Processor #0 15:3 APIC version 20
ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] enabled)
Processor #1 15:3 APIC version 20
ACPI: LAPIC_NMI (acpi_id[0x00] dfl dfl lint[0x1])
ACPI: LAPIC_NMI (acpi_id[0x01] dfl dfl 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 20000000 (gap: 20000000:dec00000)
Built 1 zonelists
Initializing CPU#0
Kernel command line: ro root=/dev/md2 console=ttyS1,57600
PID hash table entries: 2048 (order: 11, 32768 bytes)
Detected 2813.906 MHz processor.
Using tsc for high-res timesource
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: 515240k/524224k available (2133k kernel code, 8504k reserved, 920k 
data, 204k init, 0k highmem)
Checking if this processor honours the WP bit even in supervisor mode... Ok.
Calibrating delay using timer specific routine.. 5635.43 BogoMIPS (lpj=11270866)
Mount-cache hash table entries: 512
monitor/mwait feature present.
using mwait in idle threads.
CPU: Trace cache: 12K uops, L1 D cache: 16K
CPU: L2 cache: 1024K
CPU: Physical Processor ID: 0
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.
CPU0: Intel P4/Xeon Extended MCE MSRs (12) available
CPU0: Thermal monitoring enabled
Enabling fast FPU save and restore... done.
Enabling unmasked SIMD FPU exception support... done.
Checking 'hlt' instruction... OK.
CPU0: Intel(R) Pentium(R) 4 CPU 2.80GHz stepping 03
Booting processor 1/1 eip 2000
Initializing CPU#1
Calibrating delay using timer specific routine.. 5627.52 BogoMIPS (lpj=11255052)

monitor/mwait feature present.
CPU: Trace cache: 12K uops, L1 D cache: 16K
CPU: L2 cache: 1024K
CPU: Physical Processor ID: 0
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#1.
CPU1: Intel P4/Xeon Extended MCE MSRs (12) available
CPU1: Thermal monitoring enabled
CPU1: Intel(R) Pentium(R) 4 CPU 2.80GHz stepping 03
Total of 2 processors activated (11262.95 BogoMIPS).
ENABLING IO-APIC IRQs
..TIMER: vector=0x31 pin1=2 pin2=-1
checking TSC synchronization across 2 CPUs: passed.
softlockup thread 0 started up.
Brought up 2 CPUs
softlockup thread 1 started up.
-> [0][1][ 524288]   0.0 [  0.0] (0): (   30446    15223)
-> [0][1][ 551882]   0.0 [  0.0] (0): (   12568    16550)
-> [0][1][ 580928]   0.0 [  0.0] (0): (   -2456    15787)
-> [0][1][ 611503]   0.0 [  0.0] (0): (   -4468     8899)
-> [0][1][ 643687]   0.0 [  0.0] (0): (  -10064     7247)
-> [0][1][ 677565]   0.0 [  0.0] (0): (    6817    12064)
-> [0][1][ 713226]   0.0 [  0.0] (0): (   15269    10258)
-> [0][1][ 750764]   0.0 [  0.0] (0): (   16819     5904)
-> found max.
[0][1] working set size found: 524288, cost: 30446
---------------------
| migration cost matrix (max_cache_size: 1048576, cpu: 2813 MHz):
---------------------
           [00]    [01]
[00]:     -     0.0(0)
[01]:   0.0(0)    -
--------------------------------
| cacheflush times [1]: 0.0 (60892)
| calibration delay: 0 seconds
--------------------------------
NET: Registered protocol family 16
PCI: PCI BIOS revision 2.10 entry at 0xfb440, last bus=3
PCI: Using configuration type 1
mtrr: v2.0 (20020519)
ACPI: Subsystem revision 20050309
ACPI: Interpreter enabled
ACPI: Using IOAPIC for interrupt routing
ACPI: PCI Root Bridge [PCI0] (0000:00)
PCI: Probing PCI hardware (bus 00)
PCI: Ignoring BAR0-3 of IDE controller 0000:00:1f.2
PCI: Transparent bridge - 0000:00:1e.0
ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 *7 9 10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 6 7 9 *10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 *5 6 7 9 10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 7 9 10 *11 12 14 15)
ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 5 6 7 9 10 11 12 14 15) *0,disabled.
ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 5 6 7 9 10 *11 12 14 15)
ACPI: PCI Interrupt Link [LNK0] (IRQs 3 4 5 6 7 9 10 11 12 14 15) *0,disabled.
ACPI: PCI Interrupt Link [LNK1] (IRQs 3 4 5 6 7 *9 10 11 12 14 15)
SCSI subsystem initialized
usbcore: registered new driver usbfs
usbcore: registered new driver hub
PCI: Using ACPI for IRQ routing
PCI: If a device doesn't work, try "pci=routeirq".  If it helps, post a report
Machine check exception polling timer started.
inotify device minor=63
Initializing Cryptographic API
Real Time Clock Driver v1.12
hw_random: RNG not detected
Hangcheck: starting hangcheck timer 0.9.0 (tick is 180 seconds, margin is 60 
seconds).
Hangcheck: Using monotonic_clock().
cn_fork is registered
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 $ 8 ports, IRQ sharing enabled
ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
  [<c0103ad0>] dump_stack+0x17/0x19
  [<c01cab4b>] spin_bug+0x5b/0x67
  [<c01cac9c>] _raw_spin_lock+0x78/0x7a
  [<c0314ad9>] _spin_lock+0x8/0xa
  [<c0313370>] schedule+0x6c0/0xd68
  [<c0100d31>] cpu_idle+0x64/0x66
  [<c01002c5>] rest_init+0x25/0x27
  [<c03fe8af>] start_kernel+0x154/0x167
  [<c010020f>] 0xc010020f
Kernel panic - not syncing: bad locking
  Badness in smp_call_function at arch/i386/kernel/smp.c:553
  [<c0103ad0>] dump_stack+0x17/0x19
  [<c010f980>] smp_call_function+0x137/0x13c
  [<c010fb49>] smp_send_stop+0x1e/0x27
  [<c011c2cf>] panic+0x4c/0x102
  [<c01cab57>] __spin_lock_debug+0x0/0xcd
  [<c01cac9c>] _raw_spin_lock+0x78/0x7a
  [<c0314ad9>] _spin_lock+0x8/0xa
  [<c0313370>] schedule+0x6c0/0xd68
  [<c0100d31>] cpu_idle+0x64/0x66
  [<c01002c5>] rest_init+0x25/0x27
  [<c03fe8af>] start_kernel+0x154/0x167
  [<c010020f>] 0xc010020f

Re: 2.6.12-mm2

[Andrew Morton]

Reuben Farrelly <reuben-lkml@reub.net> wrote:
>
> ...
> 
> Some bad stuff seems to be happening here (this is new to -mm2; -mm1 did not 
> have this problem).
> 
> It's 100% reproduceable, although seems to happen at slightly different places 
> in the bootup, especially at the end.  Did I miss a patch for this?
> 

Why do you keep breaking my kernel?

> ...
> Serial: 8250/16550 driver $Revision: 1.90 $ 8 ports, IRQ sharing enabled
> ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
> ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
>   [<c0103ad0>] dump_stack+0x17/0x19
>   [<c01cab4b>] spin_bug+0x5b/0x67
>   [<c01cac9c>] _raw_spin_lock+0x78/0x7a
>   [<c0314ad9>] _spin_lock+0x8/0xa
>   [<c0313370>] schedule+0x6c0/0xd68
>   [<c0100d31>] cpu_idle+0x64/0x66
>   [<c01002c5>] rest_init+0x25/0x27
>   [<c03fe8af>] start_kernel+0x154/0x167
>   [<c010020f>] 0xc010020f
> Kernel panic - not syncing: bad locking

That's odd - we lost a printk there:

	printk("BUG: spinlock %s on CPU#%d, %s/%d, %p\n", msg,
		smp_processor_id(), current->comm, current->pid, lock);

which is a shame, because it would have told us stuff.  Do you have any
traces which do have that message?

Anyway, scary trace.  It look like some spinlock is thought to be in the
wrong state in schedule().  Send the .config, please.

Re: 2.6.12-mm2

[Reuben Farrelly]

Hi,

On 27/06/2005 7:24 p.m., Andrew Morton wrote:
> Reuben Farrelly <reuben-lkml@reub.net> wrote:
>> ...
>>
>> Some bad stuff seems to be happening here (this is new to -mm2; -mm1 did not 
>> have this problem).
>>
>> It's 100% reproduceable, although seems to happen at slightly different places 
>> in the bootup, especially at the end.  Did I miss a patch for this?
>>
> 
> Why do you keep breaking my kernel?

Sadistic enjoyment ;-)

>> Serial: 8250/16550 driver $Revision: 1.90 $ 8 ports, IRQ sharing enabled
>> ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
>> ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
>>   [<c0103ad0>] dump_stack+0x17/0x19
>>   [<c01cab4b>] spin_bug+0x5b/0x67
>>   [<c01cac9c>] _raw_spin_lock+0x78/0x7a
>>   [<c0314ad9>] _spin_lock+0x8/0xa
>>   [<c0313370>] schedule+0x6c0/0xd68
>>   [<c0100d31>] cpu_idle+0x64/0x66
>>   [<c01002c5>] rest_init+0x25/0x27
>>   [<c03fe8af>] start_kernel+0x154/0x167
>>   [<c010020f>] 0xc010020f
>> Kernel panic - not syncing: bad locking
> 
> That's odd - we lost a printk there:
> 
> 	printk("BUG: spinlock %s on CPU#%d, %s/%d, %p\n", msg,
> 		smp_processor_id(), current->comm, current->pid, lock);
> 
> which is a shame, because it would have told us stuff.  Do you have any
> traces which do have that message?

Uh. Likely got munged within hyperterm.

Here's a better one just created using QVT:

usbcore: registered new driver usblp
drivers/usb/class/usblp.c: v0.13: USB Printer Device Class driver
usb 3-1: new full speed USB device using uhci_hcd and address 2
hub 3-1:1.0: USB hub found
hub 3-1:1.0: 4 ports detected
usbcore: registered new driver hiddev
usb 4-1: new full speed USB device using uhci_hcd and address 2
drivers/usb/class/usblp.c: usblp0: USB Bidirectional printer dev 2 if 0 alt 0 
proto 2 vid 0x03F0 pid 0x6204
usbcore: registered new driver usbhid
drivers/usb/input/hid-core.c: v2.01:USB HID core driver
mice: PS/2 mouse device common for all mice
input: PC Speaker
md: raid1 personality registered as nr 3
md: md driver 0.90.2 MAX_MD_DEVS=256, MD_SB_DISKS=27
md: bitmap version 3.38
NET: Registered protocol family 2
IP: routing cache hash table of 1024 buckets, 24Kbytes
TCP established hash table entries: 32768 (order: 7, 786432 bytes)
TCP bind hash table entries: 32768 (order: 7, 655360 bytes)
TCP: Hash tables configured (established 32768 bind 32768)
TCP reno registered
GRE over IPv4 tunneling driver
ip_conntrack version 2.1 (4095 buckets, 32760 max) - 212 bytes per conntrack
usb 3-1.1: new low speed USB device using uhci_hcd and address 3
BUG: spinlock recursion on CPU#0, swapper/0, c1407160
  [<c0103ad0>] dump_stack+0x17/0x19
  [<c01cab4b>] spin_bug+0x5b/0x67
  [<c01cac9c>] _raw_spin_lock+0x78/0x7a
  [<c0314ad9>] _spin_lock+0x8/0xa
  [<c0117399>] scheduler_tick+0xd0/0x37c
  [<c01256b3>] update_process_times+0x58/0xd7
  [<c0110f50>] smp_apic_timer_interrupt+0xde/0xe0
  [<c0103614>] apic_timer_interrupt+0x1c/0x24
  [<c0100d1e>] cpu_idle+0x51/0x66
  [<c01002c5>] rest_init+0x25/0x27
  [<c03fe8af>] start_kernel+0x154/0x167
  [<c010020f>] 0xc010020f
Kernel panic - not syncing: bad locking
  Badness in smp_call_function at arch/i386/kernel/smp.c:553
  [<c0103ad0>] dump_stack+0x17/0x19
  [<c010f980>] smp_call_function+0x137/0x13c
  [<c010fb49>] smp_send_stop+0x1e/0x27
  [<c011c2cf>] panic+0x4c/0x102
  [<c01cab57>] __spin_lock_debug+0x0/0xcd
  [<c01cac9c>] _raw_spin_lock+0x78/0x7a
  [<c0314ad9>] _spin_lock+0x8/0xa
  [<c0117399>] scheduler_tick+0xd0/0x37c
  [<c01256b3>] update_process_times+0x58/0xd7
  [<c0110f50>] smp_apic_timer_interrupt+0xde/0xe0
  [<c0103614>] apic_timer_interrupt+0x1c/0x24
  [<c0100d1e>] cpu_idle+0x51/0x66
  [<c01002c5>] rest_init+0x25/0x27
  [<c03fe8af>] start_kernel+0x154/0x167
  [<c010020f>] 0xc010020f

> Anyway, scary trace.  It look like some spinlock is thought to be in the
> wrong state in schedule().  Send the .config, please.

Now online at  http://www.reub.net/kernel/.config

Reuben

Re: 2.6.12-mm2

[Andrew Morton]

Reuben Farrelly <reuben-lkml@reub.net> wrote:
>
>  > Anyway, scary trace.  It look like some spinlock is thought to be in the
>  > wrong state in schedule().  Send the .config, please.
> 
>  Now online at  http://www.reub.net/kernel/.config

Me too.

BUG: spinlock recursion on CPU#0, swapper/0, c120d520             
 [<c01039ed>] dump_stack+0x19/0x20                   
 [<c01d9af2>] spin_bug+0x42/0x54  
 [<c01d9bfa>] _raw_spin_lock+0x3e/0x84
 [<c031d0ad>] _spin_lock+0x9/0x10     
 [<c031b9e9>] schedule+0x479/0xbc8
 [<c0100cb4>] cpu_idle+0x88/0x8c  
 [<c01002c1>] rest_init+0x21/0x28
 [<c0442899>] start_kernel+0x151/0x158
 [<c010020f>] 0xc010020f              
Kernel panic - not syncing: bad locking

The bug is in the new spinlock debugging code itself.  Ingo, can you test
that .config please?

Reuben, I guess disabling CONFIG_DEBUG_SPINLOCK will get you going.

Re: 2.6.12-mm2

[Ingo Molnar]

is the fput()/sysfs_release() crash below known?

	Ingo 

Linux version 2.6.12-mm2 (mingo@jupiter) (gcc version 3.4.1 20040831 (Red Hat 3.4.1-10)) #11 SMP Mon Jun 27 11:19:41 CEST 2005
BIOS-provided physical RAM map:
 BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
 BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
 BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
 BIOS-e820: 0000000000100000 - 0000000010000000 (usable)
 BIOS-e820: 00000000fec00000 - 00000000fec01000 (reserved)
 BIOS-e820: 00000000fee00000 - 00000000fee01000 (reserved)
 BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
256MB LOWMEM available.
found SMP MP-table at 000f5b30
On node 0 totalpages: 65536
  DMA zone: 4096 pages, LIFO batch:1
  Normal zone: 61440 pages, LIFO batch:31
  HighMem zone: 0 pages, LIFO batch:1
early console enabled
DMI 2.2 present.
ABIT i440BX-W83977 detected: force use of acpi=ht
ACPI: Unable to locate RSDP
Intel MultiProcessor Specification v1.1
    Virtual Wire compatibility mode.
OEM ID: OEM00000 Product ID: PROD00000000 APIC at: 0xFEE00000
Processor #0 6:6 APIC version 17
Processor #1 6:6 APIC version 17
I/O APIC #2 Version 17 at 0xFEC00000.
Enabling APIC mode:  Flat.  Using 1 I/O APICs
Processors: 2
Allocating PCI resources starting at 10000000 (gap: 10000000:eec00000)
Built 1 zonelists
mapped APIC to ffffd000 (fee00000)
mapped IOAPIC to ffffc000 (fec00000)
Initializing CPU#0
Kernel command line: root=/dev/hda1 debug earlyprintk=serial,ttyS0,115200 console=ttyS0,115200 console=tty0 3 maxcpus=2 nmi_watchdog=1 debug profile=0
kernel profiling enabled (shift: 0)
PID hash table entries: 2048 (order: 11, 32768 bytes)
Detected 467.796 MHz processor.
Using tsc for high-res timesource
disabling early console
Console: colour VGA+ 80x25
Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
Memory: 244664k/262144k available (2592k kernel code, 17052k reserved, 1061k data, 224k init, 0k highmem)
Checking if this processor honours the WP bit even in supervisor mode... Ok.
Calibrating delay using timer specific routine.. 937.21 BogoMIPS (lpj=1874423)
Mount-cache hash table entries: 512
CPU: After generic identify, caps: 0183fbff 00000000 00000000 00000000 00000000 00000000 00000000
CPU: After vendor identify, caps: 0183fbff 00000000 00000000 00000000 00000000 00000000 00000000
CPU: L1 I cache: 16K, L1 D cache: 16K
CPU: L2 cache: 128K
CPU: After all inits, caps: 0183fbff 00000000 00000000 00000040 00000000 00000000 00000000
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.
Enabling fast FPU save and restore... done.
Checking 'hlt' instruction... OK.
CPU0: Intel Celeron (Mendocino) stepping 05
Booting processor 1/1 eip 2000
Initializing CPU#1
Calibrating delay using timer specific routine.. 935.62 BogoMIPS (lpj=1871246)
CPU: After generic identify, caps: 0183fbff 00000000 00000000 00000000 00000000 00000000 00000000
CPU: After vendor identify, caps: 0183fbff 00000000 00000000 00000000 00000000 00000000 00000000
CPU: L1 I cache: 16K, L1 D cache: 16K
CPU: L2 cache: 128K
CPU: After all inits, caps: 0183fbff 00000000 00000000 00000040 00000000 00000000 00000000
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#1.
CPU1: Intel Celeron (Mendocino) stepping 05
Total of 2 processors activated (1872.83 BogoMIPS).
ENABLING IO-APIC IRQs
..TIMER: vector=0x31 pin1=2 pin2=0
checking TSC synchronization across 2 CPUs: passed.
softlockup thread 0 started up.
Brought up 2 CPUs
softlockup thread 1 started up.
-> [0][1][  65536]   0.3 [  0.3] (0): (  357620   178810)
-> [0][1][  68985]   0.3 [  0.3] (0): (  354253    91088)
-> [0][1][  72615]   0.3 [  0.3] (0): (  390935    63885)
-> [0][1][  76436]   0.4 [  0.4] (0): (  415617    44283)
-> [0][1][  80458]   0.4 [  0.4] (0): (  428850    28758)
-> [0][1][  84692]   0.4 [  0.4] (0): (  460558    30233)
-> [0][1][  89149]   0.5 [  0.5] (0): (  501929    35802)
-> [0][1][  93841]   0.5 [  0.5] (0): (  543036    38454)
-> [0][1][  98780]   0.6 [  0.6] (0): (  609270    52344)
-> [0][1][ 103978]   0.5 [  0.6] (0): (  596005    32804)
-> [0][1][ 109450]   0.6 [  0.6] (0): (  607209    22004)
-> [0][1][ 115210]   0.6 [  0.6] (0): (  643212    29003)
-> [0][1][ 121273]   0.7 [  0.7] (0): (  716535    51163)
-> [0][1][ 127655]   0.7 [  0.7] (0): (  795865    65246)
-> [0][1][ 134373]   0.7 [  0.7] (0): (  745335    57888)
-> [0][1][ 141445]   0.7 [  0.7] (0): (  796304    54428)
-> [0][1][ 148889]   0.8 [  0.8] (0): (  820203    39163)
-> [0][1][ 156725]   0.7 [  0.8] (0): (  716504    71431)
-> [0][1][ 164973]   0.6 [  0.8] (0): (  679884    54025)
-> [0][1][ 173655]   0.6 [  0.8] (0): (  662305    35802)
-> [0][1][ 182794]   0.5 [  0.8] (0): (  598857    49625)
-> [0][1][ 192414]   0.6 [  0.8] (0): (  628063    39415)
-> [0][1][ 202541]   0.5 [  0.8] (0): (  577476    45001)
-> found max.
[0][1] working set size found: 148889, cost: 820203
---------------------
| migration cost matrix (max_cache_size: 131072, cpu: 467 MHz):
---------------------
          [00]    [01]
[00]:     -     1.6(0)
[01]:   1.6(0)    -   
--------------------------------
| cacheflush times [1]: 1.6 (1640406)
| calibration delay: 0 seconds
--------------------------------
NET: Registered protocol family 16
PCI: PCI BIOS revision 2.10 entry at 0xfb420, last bus=1
PCI: Using configuration type 1
mtrr: v2.0 (20020519)
mtrr: your CPUs had inconsistent fixed MTRR settings
mtrr: probably your BIOS does not setup all CPUs.
mtrr: corrected configuration.
ACPI: Subsystem revision 20050309
ACPI: Interpreter disabled.
SCSI subsystem initialized
usbcore: registered new driver usbfs
usbcore: registered new driver hub
PCI: Probing PCI hardware
PCI: Probing PCI hardware (bus 00)
Boot video device is 0000:01:00.0
PCI: Using IRQ router PIIX/ICH [8086/7110] at 0000:00:07.0
PCI->APIC IRQ transform: 0000:00:07.2[D] -> IRQ 19
PCI->APIC IRQ transform: 0000:00:0b.0[A] -> IRQ 18
PCI->APIC IRQ transform: 0000:00:0d.0[A] -> IRQ 17
PCI->APIC IRQ transform: 0000:00:0f.0[A] -> IRQ 16
PCI->APIC IRQ transform: 0000:00:13.0[A] -> IRQ 18
PCI->APIC IRQ transform: 0000:00:13.1[B] -> IRQ 18
PCI->APIC IRQ transform: 0000:01:00.0[A] -> IRQ 16
Machine check exception polling timer started.
inotify device minor=63
Initializing Cryptographic API
Limiting direct PCI/PCI transfers.
Real Time Clock Driver v1.12
Hangcheck: starting hangcheck timer 0.9.0 (tick is 180 seconds, margin is 60 seconds).
Hangcheck: Using monotonic_clock().
cn_fork is registered
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 $ 8 ports, IRQ sharing enabled
ÿttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
io scheduler noop registered
io scheduler anticipatory registered
Floppy drive(s): fd0 is 1.44M
FDC 0 is a post-1991 82077
pktcdvd: v0.2.0a 2004-07-14 Jens Axboe (axboe@suse.de) and petero2@telia.com
Intel(R) PRO/1000 Network Driver - version 6.0.54-k2-NAPI
Copyright (c) 1999-2004 Intel Corporation.
e1000: eth0: e1000_probe: Intel(R) PRO/1000 Network Connection
e100: Intel(R) PRO/100 Network Driver, 3.4.8-k2-NAPI
e100: Copyright(c) 1999-2005 Intel Corporation
e100: eth1: e100_probe: addr 0xef140000, irq 16, MAC addr 00:90:27:8C:A0:50
Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
PIIX4: IDE controller at PCI slot 0000:00:07.1
PIIX4: chipset revision 1
PIIX4: not 100% native mode: will probe irqs later
    ide0: BM-DMA at 0xf000-0xf007, BIOS settings: hda:DMA, hdb:pio
    ide1: BM-DMA at 0xf008-0xf00f, BIOS settings: hdc:DMA, hdd:DMA
Probing IDE interface ide0...
hda: QUANTUM FIREBALLP LM20.5, ATA DISK drive
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Probing IDE interface ide1...
hdc: QUANTUM FIREBALL SE4.3A, ATA DISK drive
hdd: LG CD-ROM CRD-8522B, ATAPI CD/DVD-ROM drive
ide1 at 0x170-0x177,0x376 on irq 15
hda: max request size: 128KiB
hda: 40132503 sectors (20547 MB) w/1900KiB Cache, CHS=39813/16/63, UDMA(33)
hda: cache flushes not supported
 hda: hda1
hdc: max request size: 128KiB
hdc: 8418816 sectors (4310 MB) w/80KiB Cache, CHS=14848/9/63, UDMA(33)
hdc: cache flushes not supported
 hdc: hdc1 hdc2
libata version 1.11 loaded.
USB Universal Host Controller Interface driver v2.3
uhci_hcd 0000:00:07.2: Intel Corporation 82371AB/EB/MB PIIX4 USB
uhci_hcd 0000:00:07.2: new USB bus registered, assigned bus number 1
uhci_hcd 0000:00:07.2: irq 19, io base 0x0000b000
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 2 ports detected
usbcore: registered new driver usblp
drivers/usb/class/usblp.c: v0.13: USB Printer Device Class driver
usbcore: registered new driver hiddev
usbcore: registered new driver usbhid
drivers/usb/input/hid-core.c: v2.01:USB HID core driver
mice: PS/2 mouse device common for all mice
input: PC Speaker
md: raid1 personality registered as nr 3
md: md driver 0.90.2 MAX_MD_DEVS=256, MD_SB_DISKS=27
md: bitmap version 3.38
NET: Registered protocol family 2
input: AT Translated Set 2 keyboard on isa0060/serio0
IP: routing cache hash table of 512 buckets, 12Kbytes
TCP established hash table entries: 16384 (order: 6, 393216 bytes)
TCP bind hash table entries: 16384 (order: 6, 327680 bytes)
TCP: Hash tables configured (established 16384 bind 16384)
TCP reno registered
GRE over IPv4 tunneling driver
ip_conntrack version 2.1 (2048 buckets, 16384 max) - 212 bytes per conntrack
ip_tables: (C) 2000-2002 Netfilter core team
NET: Registered protocol family 1
NET: Registered protocol family 17
Testing NMI watchdog ... OK.
Starting balanced_irq
Using IPI Shortcut mode
BIOS EDD facility v0.16 2004-Jun-25, 2 devices found
md: Autodetecting RAID arrays.
md: autorun ...
md: ... autorun DONE.
kjournald starting.  Commit interval 5 seconds
EXT3-fs: mounted filesystem with ordered data mode.
VFS: Mounted root (ext3 filesystem) readonly.
Freeing unused kernel memory: 224k freed
Unable to handle kernel paging request at virtual address 6b6b6ceb
 printing eip:
c018b51c
*pde = 00000000
Oops: 0002 [#1]
SMP 
Modules linked in:
CPU:    1
EIP:    0060:[<c018b51c>]    Not tainted VLI
EFLAGS: 00010206   (2.6.12-mm2) 
EIP is at sysfs_release+0x3f/0x79
eax: 6b6b6beb   ebx: 6b6b6b6b   ecx: ce5b5e64   edx: 00000000
esi: cf266ca4   edi: cfa3a544   ebp: ce635f50   esp: ce635f44
ds: 007b   es: 007b   ss: 0068
Process udev (pid: 1286, threadinfo=ce634000 task=c1fe6040)
Stack: 00000010 c1ca8b78 c1d4656c ce635f74 c01580b2 00000000 cf399e10 cf399e10 
       ce5b5e64 c1d4656c c1cb275c 00000000 ce635f84 c0157f36 c1cb275c c1d4656c 
       ce635f9c c0156873 00000004 00000004 c1cb275c c1cb2760 ce635fb4 c015690a 
Call Trace:
 [<c0103a18>] show_stack+0x7c/0x92
 [<c0103b99>] show_registers+0x152/0x1ca
 [<c0103d96>] die+0xf4/0x16f
 [<c011433f>] do_page_fault+0x466/0x684
 [<c0103683>] error_code+0x4f/0x54
 [<c01580b2>] __fput+0x176/0x1a9
 [<c0157f36>] fput+0x3b/0x41
 [<c0156873>] filp_close+0x36/0x65
 [<c015690a>] sys_close+0x68/0x83
 [<c0102b13>] sysenter_past_esp+0x54/0x75
Code: 58 8b 70 14 8b 41 58 8b 40 14 85 f6 8b 58 04 74 07 89 f0 e8 8b 22 05 00 85 db 74 1a b8 00 e0 ff ff 21 e0 8b 40 10 c1 e0 07 01 d8 <ff> 88 00 01 00 00 83 3b 02 74 22 85 ff 74 0e 8b 47 0c 85 c0 75 
 

Re: 2.6.12-mm2

[Andrew Morton]

Ingo Molnar <mingo@elte.hu> wrote:
>
> is the fput()/sysfs_release() crash below known?

It doesn't ring any bells.

You have a use-after-free error when udev is dinking with a sysfs file.  It
could be anything.  Could you debug it a bit, please, work out which file
caused the crash?

Re: 2.6.12-mm2

[Ingo Molnar]

* Andrew Morton <akpm@osdl.org> wrote:

> Ingo Molnar <mingo@elte.hu> wrote:
> >
> > is the fput()/sysfs_release() crash below known?
> 
> It doesn't ring any bells.
> 
> You have a use-after-free error when udev is dinking with a sysfs 
> file.  It could be anything.  Could you debug it a bit, please, work 
> out which file caused the crash?

unfortunately it's totally unreproducible, it triggered only once during 
hundreds of bootups. Will keep eyes open though.

	Ingo

[patch] spinlock-debug fix

[Ingo Molnar]

* Andrew Morton <akpm@osdl.org> wrote:

> Reuben Farrelly <reuben-lkml@reub.net> wrote:
> >
> >  > Anyway, scary trace.  It look like some spinlock is thought to be in the
> >  > wrong state in schedule().  Send the .config, please.
> > 
> >  Now online at  http://www.reub.net/kernel/.config
> 
> Me too.
> 
> BUG: spinlock recursion on CPU#0, swapper/0, c120d520             
>  [<c01039ed>] dump_stack+0x19/0x20                   
>  [<c01d9af2>] spin_bug+0x42/0x54  
>  [<c01d9bfa>] _raw_spin_lock+0x3e/0x84
>  [<c031d0ad>] _spin_lock+0x9/0x10     
>  [<c031b9e9>] schedule+0x479/0xbc8
>  [<c0100cb4>] cpu_idle+0x88/0x8c  
>  [<c01002c1>] rest_init+0x21/0x28
>  [<c0442899>] start_kernel+0x151/0x158
>  [<c010020f>] 0xc010020f              
> Kernel panic - not syncing: bad locking
> 
> The bug is in the new spinlock debugging code itself.  Ingo, can you 
> test that .config please?

couldnt reproduce it on an UP box, nor on an SMP/HT 2/4-way box, but it 
finally triggered on a 2-way SMP box.

the bug is that current->pid is not a unique identifier on SMP (doh!).  

The patch below fixes the bug - which also happens to be a speedup for 
the debugging code, as the ->pid dereferencing does not have to be done 
anymore. Also, i've disabled the panicing for now.

	Ingo

- change owner_pid to owner, to fix bad pid uniqueness assumption on SMP
- some more debug output printed
- dont panic for now

Signed-off-by: Ingo Molnar <mingo@elte.hu>

 include/linux/spinlock_types.h |   16 ++++++++++------
 kernel/sched.c                 |    2 +-
 lib/spinlock_debug.c           |   30 +++++++++++++++++++-----------
 3 files changed, 30 insertions(+), 18 deletions(-)

Index: linux/include/linux/spinlock_types.h
===================================================================
--- linux.orig/include/linux/spinlock_types.h
+++ linux/include/linux/spinlock_types.h
@@ -21,11 +21,12 @@ typedef struct {
 	unsigned int break_lock;
 #endif
 #ifdef CONFIG_DEBUG_SPINLOCK
-	unsigned int magic, owner_pid, owner_cpu;
+	unsigned int magic, owner_cpu;
+	void *owner;
 #endif
 } spinlock_t;
 
-#define SPINLOCK_MAGIC  0xdead4ead
+#define SPINLOCK_MAGIC		0xdead4ead
 
 typedef struct {
 	raw_rwlock_t raw_lock;
@@ -33,22 +34,25 @@ typedef struct {
 	unsigned int break_lock;
 #endif
 #ifdef CONFIG_DEBUG_SPINLOCK
-	unsigned int magic, owner_pid, owner_cpu;
+	unsigned int magic, owner_cpu;
+	void *owner;
 #endif
 } rwlock_t;
 
-#define RWLOCK_MAGIC	0xdeaf1eed
+#define RWLOCK_MAGIC		0xdeaf1eed
+
+#define SPINLOCK_OWNER_INIT	((void *)-1L)
 
 #ifdef CONFIG_DEBUG_SPINLOCK
 # define SPIN_LOCK_UNLOCKED						\
 	(spinlock_t)	{	.raw_lock = __RAW_SPIN_LOCK_UNLOCKED,	\
 				.magic = SPINLOCK_MAGIC,		\
-				.owner_pid = -1,			\
+				.owner = SPINLOCK_OWNER_INIT,		\
 				.owner_cpu = -1 }
 #define RW_LOCK_UNLOCKED						\
 	(rwlock_t)	{	.raw_lock = __RAW_RW_LOCK_UNLOCKED,	\
 				.magic = RWLOCK_MAGIC,			\
-				.owner_pid = -1,			\
+				.owner = SPINLOCK_OWNER_INIT,		\
 				.owner_cpu = -1 }
 #else
 # define SPIN_LOCK_UNLOCKED \
Index: linux/kernel/sched.c
===================================================================
--- linux.orig/kernel/sched.c
+++ linux/kernel/sched.c
@@ -1604,7 +1604,7 @@ static inline void finish_task_switch(ru
 	prev_task_flags = prev->flags;
 #ifdef CONFIG_DEBUG_SPINLOCK
 	/* this is a valid case when another task releases the spinlock */
-	rq->lock.owner_pid = current->pid;
+	rq->lock.owner = current;
 #endif
 	finish_arch_switch(prev);
 	finish_lock_switch(rq, prev);
Index: linux/lib/spinlock_debug.c
===================================================================
--- linux.orig/lib/spinlock_debug.c
+++ linux/lib/spinlock_debug.c
@@ -14,16 +14,24 @@
 static void spin_bug(spinlock_t *lock, const char *msg)
 {
 	static long print_once = 1;
+	struct task_struct *owner = NULL;
 
 	if (xchg(&print_once, 0)) {
-		printk("BUG: spinlock %s on CPU#%d, %s/%d, %p\n", msg,
-			smp_processor_id(), current->comm, current->pid, lock);
+		if (lock->owner && lock->owner != SPINLOCK_OWNER_INIT)
+			owner = lock->owner;
+		printk("BUG: spinlock %s on CPU#%d, %s/%d\n",
+			msg, smp_processor_id(), current->comm, current->pid);
+		printk(" lock: %p, .magic: %08x, .owner: %s/%d, .owner_cpu: %d\n",
+			lock, lock->magic,
+			owner ? owner->comm : "<none>",
+			owner ? owner->pid : -1,
+			lock->owner_cpu);
 		dump_stack();
 #ifdef CONFIG_SMP
 		/*
 		 * We cannot continue on SMP:
 		 */
-		panic("bad locking");
+//		panic("bad locking");
 #endif
 	}
 }
@@ -33,7 +41,7 @@ static void spin_bug(spinlock_t *lock, c
 static inline void debug_spin_lock_before(spinlock_t *lock)
 {
 	SPIN_BUG_ON(lock->magic != SPINLOCK_MAGIC, lock, "bad magic");
-	SPIN_BUG_ON(lock->owner_pid == current->pid, lock, "recursion");
+	SPIN_BUG_ON(lock->owner == current, lock, "recursion");
 	SPIN_BUG_ON(lock->owner_cpu == raw_smp_processor_id(),
 							lock, "cpu recursion");
 }
@@ -41,17 +49,17 @@ static inline void debug_spin_lock_befor
 static inline void debug_spin_lock_after(spinlock_t *lock)
 {
 	lock->owner_cpu = raw_smp_processor_id();
-	lock->owner_pid = current->pid;
+	lock->owner = current;
 }
 
 static inline void debug_spin_unlock(spinlock_t *lock)
 {
 	SPIN_BUG_ON(lock->magic != SPINLOCK_MAGIC, lock, "bad magic");
 	SPIN_BUG_ON(!spin_is_locked(lock), lock, "already unlocked");
-	SPIN_BUG_ON(lock->owner_pid != current->pid, lock, "wrong owner");
+	SPIN_BUG_ON(lock->owner != current, lock, "wrong owner");
 	SPIN_BUG_ON(lock->owner_cpu != raw_smp_processor_id(),
 							lock, "wrong CPU");
-	lock->owner_pid = -1;
+	lock->owner = SPINLOCK_OWNER_INIT;
 	lock->owner_cpu = -1;
 }
 
@@ -176,7 +184,7 @@ void _raw_read_unlock(rwlock_t *lock)
 static inline void debug_write_lock_before(rwlock_t *lock)
 {
 	RWLOCK_BUG_ON(lock->magic != RWLOCK_MAGIC, lock, "bad magic");
-	RWLOCK_BUG_ON(lock->owner_pid == current->pid, lock, "recursion");
+	RWLOCK_BUG_ON(lock->owner == current, lock, "recursion");
 	RWLOCK_BUG_ON(lock->owner_cpu == raw_smp_processor_id(),
 							lock, "cpu recursion");
 }
@@ -184,16 +192,16 @@ static inline void debug_write_lock_befo
 static inline void debug_write_lock_after(rwlock_t *lock)
 {
 	lock->owner_cpu = raw_smp_processor_id();
-	lock->owner_pid = current->pid;
+	lock->owner = current;
 }
 
 static inline void debug_write_unlock(rwlock_t *lock)
 {
 	RWLOCK_BUG_ON(lock->magic != RWLOCK_MAGIC, lock, "bad magic");
-	RWLOCK_BUG_ON(lock->owner_pid != current->pid, lock, "wrong owner");
+	RWLOCK_BUG_ON(lock->owner != current, lock, "wrong owner");
 	RWLOCK_BUG_ON(lock->owner_cpu != raw_smp_processor_id(),
 							lock, "wrong CPU");
-	lock->owner_pid = -1;
+	lock->owner = SPINLOCK_OWNER_INIT;
 	lock->owner_cpu = -1;
 }
 

Re: [patch] spinlock-debug fix

[Reuben Farrelly]

Hi,

On 27/06/2005 9:48 p.m., Ingo Molnar wrote:
> * Andrew Morton <akpm@osdl.org> wrote:
> 
>> Reuben Farrelly <reuben-lkml@reub.net> wrote:
>>>  > Anyway, scary trace.  It look like some spinlock is thought to be in the
>>>  > wrong state in schedule().  Send the .config, please.
>>>
>>>  Now online at  http://www.reub.net/kernel/.config
>> Me too.
>>
>> BUG: spinlock recursion on CPU#0, swapper/0, c120d520             
>>  [<c01039ed>] dump_stack+0x19/0x20                   
>>  [<c01d9af2>] spin_bug+0x42/0x54  
>>  [<c01d9bfa>] _raw_spin_lock+0x3e/0x84
>>  [<c031d0ad>] _spin_lock+0x9/0x10     
>>  [<c031b9e9>] schedule+0x479/0xbc8
>>  [<c0100cb4>] cpu_idle+0x88/0x8c  
>>  [<c01002c1>] rest_init+0x21/0x28
>>  [<c0442899>] start_kernel+0x151/0x158
>>  [<c010020f>] 0xc010020f              
>> Kernel panic - not syncing: bad locking
>>
>> The bug is in the new spinlock debugging code itself.  Ingo, can you 
>> test that .config please?
> 
> couldnt reproduce it on an UP box, nor on an SMP/HT 2/4-way box, but it 
> finally triggered on a 2-way SMP box.
> 
> the bug is that current->pid is not a unique identifier on SMP (doh!).  
> 
> The patch below fixes the bug - which also happens to be a speedup for 
> the debugging code, as the ->pid dereferencing does not have to be done 
> anymore. Also, i've disabled the panicing for now.
> 
> 	Ingo

This patch fixes it - thanks Ingo.

reuben