Next May 11 : BUG during scsi initialization

Next May 11 : BUG during scsi initialization

[Sachin Sant]

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

Today's Next tree failed to boot on a Power6 box with following BUG :

BUG: spinlock bad magic on CPU#1, modprobe/63
Unable to handle kernel paging request for data at address 0xffffc994838
Faulting instruction address: 0xc00000000035f5a8
Oops: Kernel access of bad area, sig: 11 [#1]
SMP NR_CPUS=1024 DEBUG_PAGEALLOC NUMA pSeries
Modules linked in: scsi_mod(+)
NIP: c00000000035f5a8 LR: c00000000035f58c CTR: 0000000000136f8c
REGS: c0000000c7d03500 TRAP: 0300   Not tainted  (2.6.30-rc5-autotest-next-20090511)
MSR: 8000000000009032 <EE,ME,IR,DR>  CR: 28222484  XER: 0000000f
DAR: 00000ffffc994838, DSISR: 0000000040000000
TASK = c0000000c7cf0a80[63] 'modprobe' THREAD: c0000000c7d00000 CPU: 1
GPR00: c00000000035f58c c0000000c7d03780 c000000000aaeed8 0000000000000031 
GPR04: 0000000000000000 00000000585cf4e0 0000000000673580 80000000565a6cc0 
GPR08: 0000000000000000 c0000000009ebf50 0000000000000000 c0000000009ebf38 
GPR12: 0000000028222482 c000000000b82600 0000000000000000 0000000000000000 
GPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 
GPR20: 0000000000000018 ffffffffffffffff c0000000009bbe40 0000000000000010 
GPR24: 0000000000210d00 c0000000c6caff80 c0000000dfc732a0 c000000000f61380 
GPR28: c0000000007c8350 c0000000008a4280 c000000000a2f928 00000ffffc994550 
NIP [c00000000035f5a8] .spin_bug+0x90/0xd4
LR [c00000000035f58c] .spin_bug+0x74/0xd4
Call Trace:
[c0000000c7d03780] [c00000000035f58c] .spin_bug+0x74/0xd4 (unreliable)
[c0000000c7d03810] [c00000000035f890] ._raw_spin_lock+0x48/0x184
[c0000000c7d038b0] [c0000000005d67d8] ._spin_lock+0x10/0x24
[c0000000c7d03920] [c00000000013fbdc] .__slab_alloc_page+0x344/0x3cc
[c0000000c7d039e0] [c000000000141168] .kmem_cache_alloc+0x13c/0x21c
[c0000000c7d03aa0] [c000000000141b04] .kmem_cache_create+0x294/0x2a8
[c0000000c7d03b90] [d000000000ea14cc] .scsi_init_queue+0x38/0x170 [scsi_mod]
[c0000000c7d03c20] [d000000000ea13c8] .init_scsi+0x1c/0xe8 [scsi_mod]
[c0000000c7d03ca0] [c0000000000092c0] .do_one_initcall+0x80/0x19c
[c0000000c7d03d90] [c0000000000c0540] .SyS_init_module+0xe0/0x244
[c0000000c7d03e30] [c000000000008534] syscall_exit+0x0/0x40
Instruction dump:
7f84e378 e87e8020 38c604d0 e8e902ea 4827fced 60000000 2fbf0000 80bd0004 
409e0010 e8de8028 38e0ffff 4800000c <e8ff02ea> 38df04d0 7fa4eb78 811d0008 
---[ end trace f725820a6fa9dbb7 ]---
/init: line 21:    63 Segmentation fault      modprobe $file

I have attached the dmesg log here. Let me know if any other information 
is required.

Thanks
-Sachin

-- 

---------------------------------
Sachin Sant
IBM Linux Technology Center
India Systems and Technology Labs
Bangalore, India
---------------------------------


[-- Attachment #2: next11-boot --]
[-- Type: text/plain, Size: 9024 bytes --]

Using 007bc904 bytes for initrd buffer
Please wait, loading kernel...
Allocated 01100000 bytes for kernel @ 02300000
   Elf64 kernel loaded...
Loading ramdisk...
ramdisk loaded 007bc904 @ 03400000
OF stdout device is: /vdevice/vty@30000000
Preparing to boot Linux version 2.6.30-rc5-autotest-next-20090511 (root@mpower6lp5) (gcc version 4.3.2 [gcc-4_3-branch revision 141291] (SUSE Linux) ) #1 SMP Mon May 11 16:01:58 IST 2009
Calling ibm,client-architecture... done
command line: root=/dev/sda3 sysrq=1 insmod=sym53c8xx insmod=ipr crashkernel=512M-:256M IDENT=1242039097 
memory layout at init:
  alloc_bottom : 0000000003bc0000
  alloc_top    : 0000000008000000
  alloc_top_hi : 0000000008000000
  rmo_top      : 0000000008000000
  ram_top      : 0000000008000000
instantiating rtas at 0x00000000074e0000... done
boot cpu hw idx 0000000000000000
copying OF device tree...
Building dt strings...
Building dt structure...
Device tree strings 0x0000000003bd0000 -> 0x0000000003bd15c2
Device tree struct  0x0000000003be0000 -> 0x0000000003c00000
Calling quiesce...
returning from prom_init
Crash kernel location must be 0x2000000
Reserving 256MB of memory at 32MB for crashkernel (System RAM: 4096MB)
Phyp-dump disabled at boot time
Using pSeries machine description
Using 1TB segments
Found initrd at 0xc000000003400000:0xc000000003bbc904
console [udbg0] enabled
Partition configured for 2 cpus.
CPU maps initialized for 2 threads per core
Starting Linux PPC64 #1 SMP Mon May 11 16:01:58 IST 2009
-----------------------------------------------------
ppc64_pft_size                = 0x1a
physicalMemorySize            = 0x100000000
htab_hash_mask                = 0x7ffff
-----------------------------------------------------
Initializing cgroup subsys cpuset
Initializing cgroup subsys cpu
Linux version 2.6.30-rc5-autotest-next-20090511 (root@mpower6lp5) (gcc version 4.3.2 [gcc-4_3-branch revision 141291] (SUSE Linux) ) #1 SMP Mon May 11 16:01:58 IST 2009
[boot]0012 Setup Arch
EEH: No capable adapters found
PPC64 nvram contains 15360 bytes
Zone PFN ranges:
  DMA      0x00000000 -> 0x00010000
  Normal   0x00010000 -> 0x00010000
Movable zone start PFN for each node
early_node_map[2] active PFN ranges
    2: 0x00000000 -> 0x0000e000
    3: 0x0000e000 -> 0x00010000
Could not find start_pfn for node 0
[boot]0015 Setup Done
Built 3 zonelists in Node order, mobility grouping on.  Total pages: 65472
Policy zone: DMA
Kernel command line: root=/dev/sda3 sysrq=1 insmod=sym53c8xx insmod=ipr crashkernel=512M-:256M IDENT=1242039097 
Experimental hierarchical RCU implementation.
RCU-based detection of stalled CPUs is enabled.
Experimental hierarchical RCU init done.
NR_IRQS:512
[boot]0020 XICS Init
[boot]0021 XICS Done
PID hash table entries: 4096 (order: 12, 32768 bytes)
clocksource: timebase mult[7d0000] shift[22] registered
Console: colour dummy device 80x25
console handover: boot [udbg0] -> real [hvc0]
allocated 2621440 bytes of page_cgroup
please try cgroup_disable=memory option if you don't want
freeing bootmem node 2
freeing bootmem node 3
Memory: 3881920k/4194304k available (8896k kernel code, 312384k reserved, 2048k data, 4287k bss, 448k init)
Calibrating delay loop... 1022.36 BogoMIPS (lpj=5111808)
Security Framework initialized
SELinux:  Disabled at boot.
Dentry cache hash table entries: 524288 (order: 6, 4194304 bytes)
Inode-cache hash table entries: 262144 (order: 5, 2097152 bytes)
Mount-cache hash table entries: 4096
Initializing cgroup subsys ns
Initializing cgroup subsys cpuacct
Initializing cgroup subsys memory
Initializing cgroup subsys devices
Initializing cgroup subsys freezer
Processor 1 found.
Brought up 2 CPUs
net_namespace: 1936 bytes
NET: Registered protocol family 16
IBM eBus Device Driver
PCI: Probing PCI hardware
bio: create slab <bio-0> at 0
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
Failed to register trace events module notifier
NET: Registered protocol family 2
IP route cache hash table entries: 32768 (order: 2, 262144 bytes)
TCP established hash table entries: 131072 (order: 5, 2097152 bytes)
TCP bind hash table entries: 65536 (order: 5, 2097152 bytes)
TCP: Hash tables configured (established 131072 bind 65536)
TCP reno registered
NET: Registered protocol family 1
Unpacking initramfs...
IOMMU table initialized, virtual merging enabled
audit: initializing netlink socket (disabled)
type=2000 audit(1242039145.533:1): initialized
Kprobe smoke test started
Kprobe smoke test passed successfully
HugeTLB registered 16 MB page size, pre-allocated 0 pages
HugeTLB registered 16 GB page size, pre-allocated 0 pages
VFS: Disk quotas dquot_6.5.2
Dquot-cache hash table entries: 8192 (order 0, 65536 bytes)
Btrfs loaded
msgmni has been set to 7580
alg: No test for stdrng (krng)
Block layer SCSI generic (bsg) driver version 0.4 loaded (major 254)
io scheduler noop registered
io scheduler anticipatory registered
io scheduler deadline registered
io scheduler cfq registered (default)
pci_hotplug: PCI Hot Plug PCI Core version: 0.5
rpaphp: RPA HOT Plug PCI Controller Driver version: 0.1
Generic RTC Driver v1.07
Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
pmac_zilog: 0.6 (Benjamin Herrenschmidt <benh@kernel.crashing.org>)
input: Macintosh mouse button emulation as /devices/virtual/input/input0
Uniform Multi-Platform E-IDE driver
ide-gd driver 1.18
IBM eHEA ethernet device driver (Release EHEA_0101)
ehea: eth0: Jumbo frames are disabled
ehea: eth0 -> logical port id #2
ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
mice: PS/2 mouse device common for all mice
EDAC MC: Ver: 2.1.0 May 11 2009
usbcore: registered new interface driver hiddev
usbcore: registered new interface driver usbhid
usbhid: v2.6:USB HID core driver
TCP cubic registered
NET: Registered protocol family 15
registered taskstats version 1
Freeing unused kernel memory: 448k freed
doing fast boot
SysRq : Changing Loglevel
Loglevel set to 1
BUG: spinlock bad magic on CPU#1, modprobe/63
Unable to handle kernel paging request for data at address 0xffffc994838
Faulting instruction address: 0xc00000000035f5a8
Oops: Kernel access of bad area, sig: 11 [#1]
SMP NR_CPUS=1024 DEBUG_PAGEALLOC NUMA pSeries
Modules linked in: scsi_mod(+)
NIP: c00000000035f5a8 LR: c00000000035f58c CTR: 0000000000136f8c
REGS: c0000000c7d03500 TRAP: 0300   Not tainted  (2.6.30-rc5-autotest-next-20090511)
MSR: 8000000000009032 <EE,ME,IR,DR>  CR: 28222484  XER: 0000000f
DAR: 00000ffffc994838, DSISR: 0000000040000000
TASK = c0000000c7cf0a80[63] 'modprobe' THREAD: c0000000c7d00000 CPU: 1
GPR00: c00000000035f58c c0000000c7d03780 c000000000aaeed8 0000000000000031 
GPR04: 0000000000000000 00000000585cf4e0 0000000000673580 80000000565a6cc0 
GPR08: 0000000000000000 c0000000009ebf50 0000000000000000 c0000000009ebf38 
GPR12: 0000000028222482 c000000000b82600 0000000000000000 0000000000000000 
GPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 
GPR20: 0000000000000018 ffffffffffffffff c0000000009bbe40 0000000000000010 
GPR24: 0000000000210d00 c0000000c6caff80 c0000000dfc732a0 c000000000f61380 
GPR28: c0000000007c8350 c0000000008a4280 c000000000a2f928 00000ffffc994550 
NIP [c00000000035f5a8] .spin_bug+0x90/0xd4
LR [c00000000035f58c] .spin_bug+0x74/0xd4
Call Trace:
[c0000000c7d03780] [c00000000035f58c] .spin_bug+0x74/0xd4 (unreliable)
[c0000000c7d03810] [c00000000035f890] ._raw_spin_lock+0x48/0x184
[c0000000c7d038b0] [c0000000005d67d8] ._spin_lock+0x10/0x24
[c0000000c7d03920] [c00000000013fbdc] .__slab_alloc_page+0x344/0x3cc
[c0000000c7d039e0] [c000000000141168] .kmem_cache_alloc+0x13c/0x21c
[c0000000c7d03aa0] [c000000000141b04] .kmem_cache_create+0x294/0x2a8
[c0000000c7d03b90] [d000000000ea14cc] .scsi_init_queue+0x38/0x170 [scsi_mod]
[c0000000c7d03c20] [d000000000ea13c8] .init_scsi+0x1c/0xe8 [scsi_mod]
[c0000000c7d03ca0] [c0000000000092c0] .do_one_initcall+0x80/0x19c
[c0000000c7d03d90] [c0000000000c0540] .SyS_init_module+0xe0/0x244
[c0000000c7d03e30] [c000000000008534] syscall_exit+0x0/0x40
Instruction dump:
7f84e378 e87e8020 38c604d0 e8e902ea 4827fced 60000000 2fbf0000 80bd0004 
409e0010 e8de8028 38e0ffff 4800000c <e8ff02ea> 38df04d0 7fa4eb78 811d0008 
---[ end trace f725820a6fa9dbb7 ]---
/init: line 21:    63 Segmentation fault      modprobe $file
Creating device nodes with udev
udevd version 128 started


After the udevadm settle timeout, the events queue contains:

632: /devices/vio/30000007


Boot logging started on /dev/hvc0(/dev/console) at Mon May 11 10:52:56 2009


After the udevadm settle timeout, the events queue contains:

632: /devices/vio/30000007




After the udevadm settle timeout, the events queue contains:

632: /devices/vio/30000007




After the udevadm settle timeout, the events queue contains:

632: /devices/vio/30000007


Waiting for device /dev/sda3 to appear: ..............................Could not find /dev/sda3.
Want me to fall back to /dev/sda3? (Y/n) 

Re: Next May 11 : BUG during scsi initialization

[Matthew Wilcox]

On Mon, May 11, 2009 at 05:16:10PM +0530, Sachin Sant wrote:
> Today's Next tree failed to boot on a Power6 box with following BUG :

This doesn't actually appear to be a SCSI bug ... it looks like SCSI tried
to allocate memory and things went wrong in the memory allocator:

[c0000000c7d038b0] [c0000000005d67d8] ._spin_lock+0x10/0x24
[c0000000c7d03920] [c00000000013fbdc] .__slab_alloc_page+0x344/0x3cc
[c0000000c7d039e0] [c000000000141168] .kmem_cache_alloc+0x13c/0x21c
[c0000000c7d03aa0] [c000000000141b04] .kmem_cache_create+0x294/0x2a8
[c0000000c7d03b90] [d000000000ea14cc] .scsi_init_queue+0x38/0x170 [scsi_mod]

Which memory allocator did you have selected (SLAB, SLUB, SLOB, SLQB)?

> BUG: spinlock bad magic on CPU#1, modprobe/63
> Unable to handle kernel paging request for data at address 0xffffc994838
> Faulting instruction address: 0xc00000000035f5a8
> Oops: Kernel access of bad area, sig: 11 [#1]
> SMP NR_CPUS=1024 DEBUG_PAGEALLOC NUMA pSeries
> Modules linked in: scsi_mod(+)
> NIP: c00000000035f5a8 LR: c00000000035f58c CTR: 0000000000136f8c
> REGS: c0000000c7d03500 TRAP: 0300   Not tainted  (2.6.30-rc5-autotest-next-20090511)
> MSR: 8000000000009032 <EE,ME,IR,DR>  CR: 28222484  XER: 0000000f
> DAR: 00000ffffc994838, DSISR: 0000000040000000
> TASK = c0000000c7cf0a80[63] 'modprobe' THREAD: c0000000c7d00000 CPU: 1
> GPR00: c00000000035f58c c0000000c7d03780 c000000000aaeed8 
> 0000000000000031 GPR04: 0000000000000000 00000000585cf4e0 
> 0000000000673580 80000000565a6cc0 GPR08: 0000000000000000 
> c0000000009ebf50 0000000000000000 c0000000009ebf38 GPR12: 
> 0000000028222482 c000000000b82600 0000000000000000 0000000000000000  
> GPR16: 0000000000000000 0000000000000000 0000000000000000 
> 0000000000000000 GPR20: 0000000000000018 ffffffffffffffff 
> c0000000009bbe40 0000000000000010 GPR24: 0000000000210d00 
> c0000000c6caff80 c0000000dfc732a0 c000000000f61380 GPR28: 
> c0000000007c8350 c0000000008a4280 c000000000a2f928 00000ffffc994550 NIP 
> [c00000000035f5a8] .spin_bug+0x90/0xd4
> LR [c00000000035f58c] .spin_bug+0x74/0xd4
> Call Trace:
> [c0000000c7d03780] [c00000000035f58c] .spin_bug+0x74/0xd4 (unreliable)
> [c0000000c7d03810] [c00000000035f890] ._raw_spin_lock+0x48/0x184
> [c0000000c7d038b0] [c0000000005d67d8] ._spin_lock+0x10/0x24
> [c0000000c7d03920] [c00000000013fbdc] .__slab_alloc_page+0x344/0x3cc
> [c0000000c7d039e0] [c000000000141168] .kmem_cache_alloc+0x13c/0x21c
> [c0000000c7d03aa0] [c000000000141b04] .kmem_cache_create+0x294/0x2a8
> [c0000000c7d03b90] [d000000000ea14cc] .scsi_init_queue+0x38/0x170 [scsi_mod]
> [c0000000c7d03c20] [d000000000ea13c8] .init_scsi+0x1c/0xe8 [scsi_mod]
> [c0000000c7d03ca0] [c0000000000092c0] .do_one_initcall+0x80/0x19c
> [c0000000c7d03d90] [c0000000000c0540] .SyS_init_module+0xe0/0x244
> [c0000000c7d03e30] [c000000000008534] syscall_exit+0x0/0x40
> Instruction dump:
> 7f84e378 e87e8020 38c604d0 e8e902ea 4827fced 60000000 2fbf0000 80bd0004  
> 409e0010 e8de8028 38e0ffff 4800000c <e8ff02ea> 38df04d0 7fa4eb78 811d0008 
> ---[ end trace f725820a6fa9dbb7 ]---
> /init: line 21:    63 Segmentation fault      modprobe $file
>
> I have attached the dmesg log here. Let me know if any other information  
> is required.
>
> Thanks
> -Sachin
>
> -- 
>
> ---------------------------------
> Sachin Sant
> IBM Linux Technology Center
> India Systems and Technology Labs
> Bangalore, India
> ---------------------------------
>

> Using 007bc904 bytes for initrd buffer
> Please wait, loading kernel...
> Allocated 01100000 bytes for kernel @ 02300000
>    Elf64 kernel loaded...
> Loading ramdisk...
> ramdisk loaded 007bc904 @ 03400000
> OF stdout device is: /vdevice/vty@30000000
> Preparing to boot Linux version 2.6.30-rc5-autotest-next-20090511 (root@mpower6lp5) (gcc version 4.3.2 [gcc-4_3-branch revision 141291] (SUSE Linux) ) #1 SMP Mon May 11 16:01:58 IST 2009
> Calling ibm,client-architecture... done
> command line: root=/dev/sda3 sysrq=1 insmod=sym53c8xx insmod=ipr crashkernel=512M-:256M IDENT=1242039097 
> memory layout at init:
>   alloc_bottom : 0000000003bc0000
>   alloc_top    : 0000000008000000
>   alloc_top_hi : 0000000008000000
>   rmo_top      : 0000000008000000
>   ram_top      : 0000000008000000
> instantiating rtas at 0x00000000074e0000... done
> boot cpu hw idx 0000000000000000
> copying OF device tree...
> Building dt strings...
> Building dt structure...
> Device tree strings 0x0000000003bd0000 -> 0x0000000003bd15c2
> Device tree struct  0x0000000003be0000 -> 0x0000000003c00000
> Calling quiesce...
> returning from prom_init
> Crash kernel location must be 0x2000000
> Reserving 256MB of memory at 32MB for crashkernel (System RAM: 4096MB)
> Phyp-dump disabled at boot time
> Using pSeries machine description
> Using 1TB segments
> Found initrd at 0xc000000003400000:0xc000000003bbc904
> console [udbg0] enabled
> Partition configured for 2 cpus.
> CPU maps initialized for 2 threads per core
> Starting Linux PPC64 #1 SMP Mon May 11 16:01:58 IST 2009
> -----------------------------------------------------
> ppc64_pft_size                = 0x1a
> physicalMemorySize            = 0x100000000
> htab_hash_mask                = 0x7ffff
> -----------------------------------------------------
> Initializing cgroup subsys cpuset
> Initializing cgroup subsys cpu
> Linux version 2.6.30-rc5-autotest-next-20090511 (root@mpower6lp5) (gcc version 4.3.2 [gcc-4_3-branch revision 141291] (SUSE Linux) ) #1 SMP Mon May 11 16:01:58 IST 2009
> [boot]0012 Setup Arch
> EEH: No capable adapters found
> PPC64 nvram contains 15360 bytes
> Zone PFN ranges:
>   DMA      0x00000000 -> 0x00010000
>   Normal   0x00010000 -> 0x00010000
> Movable zone start PFN for each node
> early_node_map[2] active PFN ranges
>     2: 0x00000000 -> 0x0000e000
>     3: 0x0000e000 -> 0x00010000
> Could not find start_pfn for node 0
> [boot]0015 Setup Done
> Built 3 zonelists in Node order, mobility grouping on.  Total pages: 65472
> Policy zone: DMA
> Kernel command line: root=/dev/sda3 sysrq=1 insmod=sym53c8xx insmod=ipr crashkernel=512M-:256M IDENT=1242039097 
> Experimental hierarchical RCU implementation.
> RCU-based detection of stalled CPUs is enabled.
> Experimental hierarchical RCU init done.
> NR_IRQS:512
> [boot]0020 XICS Init
> [boot]0021 XICS Done
> PID hash table entries: 4096 (order: 12, 32768 bytes)
> clocksource: timebase mult[7d0000] shift[22] registered
> Console: colour dummy device 80x25
> console handover: boot [udbg0] -> real [hvc0]
> allocated 2621440 bytes of page_cgroup
> please try cgroup_disable=memory option if you don't want
> freeing bootmem node 2
> freeing bootmem node 3
> Memory: 3881920k/4194304k available (8896k kernel code, 312384k reserved, 2048k data, 4287k bss, 448k init)
> Calibrating delay loop... 1022.36 BogoMIPS (lpj=5111808)
> Security Framework initialized
> SELinux:  Disabled at boot.
> Dentry cache hash table entries: 524288 (order: 6, 4194304 bytes)
> Inode-cache hash table entries: 262144 (order: 5, 2097152 bytes)
> Mount-cache hash table entries: 4096
> Initializing cgroup subsys ns
> Initializing cgroup subsys cpuacct
> Initializing cgroup subsys memory
> Initializing cgroup subsys devices
> Initializing cgroup subsys freezer
> Processor 1 found.
> Brought up 2 CPUs
> net_namespace: 1936 bytes
> NET: Registered protocol family 16
> IBM eBus Device Driver
> PCI: Probing PCI hardware
> bio: create slab <bio-0> at 0
> usbcore: registered new interface driver usbfs
> usbcore: registered new interface driver hub
> usbcore: registered new device driver usb
> Failed to register trace events module notifier
> NET: Registered protocol family 2
> IP route cache hash table entries: 32768 (order: 2, 262144 bytes)
> TCP established hash table entries: 131072 (order: 5, 2097152 bytes)
> TCP bind hash table entries: 65536 (order: 5, 2097152 bytes)
> TCP: Hash tables configured (established 131072 bind 65536)
> TCP reno registered
> NET: Registered protocol family 1
> Unpacking initramfs...
> IOMMU table initialized, virtual merging enabled
> audit: initializing netlink socket (disabled)
> type=2000 audit(1242039145.533:1): initialized
> Kprobe smoke test started
> Kprobe smoke test passed successfully
> HugeTLB registered 16 MB page size, pre-allocated 0 pages
> HugeTLB registered 16 GB page size, pre-allocated 0 pages
> VFS: Disk quotas dquot_6.5.2
> Dquot-cache hash table entries: 8192 (order 0, 65536 bytes)
> Btrfs loaded
> msgmni has been set to 7580
> alg: No test for stdrng (krng)
> Block layer SCSI generic (bsg) driver version 0.4 loaded (major 254)
> io scheduler noop registered
> io scheduler anticipatory registered
> io scheduler deadline registered
> io scheduler cfq registered (default)
> pci_hotplug: PCI Hot Plug PCI Core version: 0.5
> rpaphp: RPA HOT Plug PCI Controller Driver version: 0.1
> Generic RTC Driver v1.07
> Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
> pmac_zilog: 0.6 (Benjamin Herrenschmidt <benh@kernel.crashing.org>)
> input: Macintosh mouse button emulation as /devices/virtual/input/input0
> Uniform Multi-Platform E-IDE driver
> ide-gd driver 1.18
> IBM eHEA ethernet device driver (Release EHEA_0101)
> ehea: eth0: Jumbo frames are disabled
> ehea: eth0 -> logical port id #2
> ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
> ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
> mice: PS/2 mouse device common for all mice
> EDAC MC: Ver: 2.1.0 May 11 2009
> usbcore: registered new interface driver hiddev
> usbcore: registered new interface driver usbhid
> usbhid: v2.6:USB HID core driver
> TCP cubic registered
> NET: Registered protocol family 15
> registered taskstats version 1
> Freeing unused kernel memory: 448k freed
> doing fast boot
> SysRq : Changing Loglevel
> Loglevel set to 1
> BUG: spinlock bad magic on CPU#1, modprobe/63
> Unable to handle kernel paging request for data at address 0xffffc994838
> Faulting instruction address: 0xc00000000035f5a8
> Oops: Kernel access of bad area, sig: 11 [#1]
> SMP NR_CPUS=1024 DEBUG_PAGEALLOC NUMA pSeries
> Modules linked in: scsi_mod(+)
> NIP: c00000000035f5a8 LR: c00000000035f58c CTR: 0000000000136f8c
> REGS: c0000000c7d03500 TRAP: 0300   Not tainted  (2.6.30-rc5-autotest-next-20090511)
> MSR: 8000000000009032 <EE,ME,IR,DR>  CR: 28222484  XER: 0000000f
> DAR: 00000ffffc994838, DSISR: 0000000040000000
> TASK = c0000000c7cf0a80[63] 'modprobe' THREAD: c0000000c7d00000 CPU: 1
> GPR00: c00000000035f58c c0000000c7d03780 c000000000aaeed8 0000000000000031 
> GPR04: 0000000000000000 00000000585cf4e0 0000000000673580 80000000565a6cc0 
> GPR08: 0000000000000000 c0000000009ebf50 0000000000000000 c0000000009ebf38 
> GPR12: 0000000028222482 c000000000b82600 0000000000000000 0000000000000000 
> GPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 
> GPR20: 0000000000000018 ffffffffffffffff c0000000009bbe40 0000000000000010 
> GPR24: 0000000000210d00 c0000000c6caff80 c0000000dfc732a0 c000000000f61380 
> GPR28: c0000000007c8350 c0000000008a4280 c000000000a2f928 00000ffffc994550 
> NIP [c00000000035f5a8] .spin_bug+0x90/0xd4
> LR [c00000000035f58c] .spin_bug+0x74/0xd4
> Call Trace:
> [c0000000c7d03780] [c00000000035f58c] .spin_bug+0x74/0xd4 (unreliable)
> [c0000000c7d03810] [c00000000035f890] ._raw_spin_lock+0x48/0x184
> [c0000000c7d038b0] [c0000000005d67d8] ._spin_lock+0x10/0x24
> [c0000000c7d03920] [c00000000013fbdc] .__slab_alloc_page+0x344/0x3cc
> [c0000000c7d039e0] [c000000000141168] .kmem_cache_alloc+0x13c/0x21c
> [c0000000c7d03aa0] [c000000000141b04] .kmem_cache_create+0x294/0x2a8
> [c0000000c7d03b90] [d000000000ea14cc] .scsi_init_queue+0x38/0x170 [scsi_mod]
> [c0000000c7d03c20] [d000000000ea13c8] .init_scsi+0x1c/0xe8 [scsi_mod]
> [c0000000c7d03ca0] [c0000000000092c0] .do_one_initcall+0x80/0x19c
> [c0000000c7d03d90] [c0000000000c0540] .SyS_init_module+0xe0/0x244
> [c0000000c7d03e30] [c000000000008534] syscall_exit+0x0/0x40
> Instruction dump:
> 7f84e378 e87e8020 38c604d0 e8e902ea 4827fced 60000000 2fbf0000 80bd0004 
> 409e0010 e8de8028 38e0ffff 4800000c <e8ff02ea> 38df04d0 7fa4eb78 811d0008 
> ---[ end trace f725820a6fa9dbb7 ]---
> /init: line 21:    63 Segmentation fault      modprobe $file
> Creating device nodes with udev
> udevd version 128 started
> 
> 
> After the udevadm settle timeout, the events queue contains:
> 
> 632: /devices/vio/30000007
> 
> 
> Boot logging started on /dev/hvc0(/dev/console) at Mon May 11 10:52:56 2009
> 
> 
> After the udevadm settle timeout, the events queue contains:
> 
> 632: /devices/vio/30000007
> 
> 
> 
> 
> After the udevadm settle timeout, the events queue contains:
> 
> 632: /devices/vio/30000007
> 
> 
> 
> 
> After the udevadm settle timeout, the events queue contains:
> 
> 632: /devices/vio/30000007
> 
> 
> Waiting for device /dev/sda3 to appear: ..............................Could not find /dev/sda3.
> Want me to fall back to /dev/sda3? (Y/n) 
> 


-- 
Matthew Wilcox				Intel Open Source Technology Centre
"Bill, look, we understand that you're interested in selling us this
operating system, but compare it to ours.  We can't possibly take such
a retrograde step."

Re: Next May 11 : BUG during scsi initialization

[Sachin Sant]

Matthew Wilcox wrote:
> On Mon, May 11, 2009 at 05:16:10PM +0530, Sachin Sant wrote:
>   
>> Today's Next tree failed to boot on a Power6 box with following BUG :
>>     
>
> This doesn't actually appear to be a SCSI bug ... it looks like SCSI tried
> to allocate memory and things went wrong in the memory allocator:
>
> [c0000000c7d038b0] [c0000000005d67d8] ._spin_lock+0x10/0x24
> [c0000000c7d03920] [c00000000013fbdc] .__slab_alloc_page+0x344/0x3cc
> [c0000000c7d039e0] [c000000000141168] .kmem_cache_alloc+0x13c/0x21c
> [c0000000c7d03aa0] [c000000000141b04] .kmem_cache_create+0x294/0x2a8
> [c0000000c7d03b90] [d000000000ea14cc] .scsi_init_queue+0x38/0x170 [scsi_mod]
>
> Which memory allocator did you have selected (SLAB, SLUB, SLOB, SLQB)?
>   
Default one. SLQB

CONFIG_SLQB_ALLOCATOR=y
CONFIG_SLQB=y

Page size is 64K with Config DEBUG_PAGEALLOC set.

CONFIG_PPC_HAS_HASH_64K=y
CONFIG_PPC_64K_PAGES=y
CONFIG_DEBUG_PAGEALLOC=y

Thanks
-Sachin


-- 

---------------------------------
Sachin Sant
IBM Linux Technology Center
India Systems and Technology Labs
Bangalore, India
---------------------------------

Re: Next May 11 : BUG during scsi initialization

[Matthew Wilcox]

On Mon, May 11, 2009 at 05:34:07PM +0530, Sachin Sant wrote:
> Matthew Wilcox wrote:
>> On Mon, May 11, 2009 at 05:16:10PM +0530, Sachin Sant wrote:
>>   
>>> Today's Next tree failed to boot on a Power6 box with following BUG :
>>
>> This doesn't actually appear to be a SCSI bug ... it looks like SCSI tried
>> to allocate memory and things went wrong in the memory allocator:
>>
>> [c0000000c7d038b0] [c0000000005d67d8] ._spin_lock+0x10/0x24
>> [c0000000c7d03920] [c00000000013fbdc] .__slab_alloc_page+0x344/0x3cc
>> [c0000000c7d039e0] [c000000000141168] .kmem_cache_alloc+0x13c/0x21c
>> [c0000000c7d03aa0] [c000000000141b04] .kmem_cache_create+0x294/0x2a8
>> [c0000000c7d03b90] [d000000000ea14cc] .scsi_init_queue+0x38/0x170 [scsi_mod]
>>
>> Which memory allocator did you have selected (SLAB, SLUB, SLOB, SLQB)?
>>   
> Default one. SLQB
>
> CONFIG_SLQB_ALLOCATOR=y
> CONFIG_SLQB=y
>
> Page size is 64K with Config DEBUG_PAGEALLOC set.
>
> CONFIG_PPC_HAS_HASH_64K=y
> CONFIG_PPC_64K_PAGES=y
> CONFIG_DEBUG_PAGEALLOC=y

Hm.  We've seen some similar problems at Intel while doing database
performance tests with SLQB.  Any ideas, Nick?

-- 
Matthew Wilcox				Intel Open Source Technology Centre
"Bill, look, we understand that you're interested in selling us this
operating system, but compare it to ours.  We can't possibly take such
a retrograde step."

Re: Next May 11 : BUG during scsi initialization

[Sachin Sant]

Matthew Wilcox wrote:
>> Default one. SLQB
>>
>> CONFIG_SLQB_ALLOCATOR=y
>> CONFIG_SLQB=y
>>
>> Page size is 64K with Config DEBUG_PAGEALLOC set.
>>
>> CONFIG_PPC_HAS_HASH_64K=y
>> CONFIG_PPC_64K_PAGES=y
>> CONFIG_DEBUG_PAGEALLOC=y
>>     
>
> Hm.  We've seen some similar problems at Intel while doing database
> performance tests with SLQB.  Any ideas, Nick?
>   
Yeah so the problem seems to be with SLQB. I was able to boot Next 11 with
SLUB on the same machine.

Thanks
-Sachin

-- 

---------------------------------
Sachin Sant
IBM Linux Technology Center
India Systems and Technology Labs
Bangalore, India
---------------------------------

Re: Next May 11 : BUG during scsi initialization

[Matthew Wilcox]

On Mon, May 11, 2009 at 09:49:55PM +0530, Sachin Sant wrote:
> Yeah so the problem seems to be with SLQB. I was able to boot Next 11 with
> SLUB on the same machine.

Is it 100% reproducable with SLQB?  Our errors were fairly hard to tickle
on demand.

-- 
Matthew Wilcox				Intel Open Source Technology Centre
"Bill, look, we understand that you're interested in selling us this
operating system, but compare it to ours.  We can't possibly take such
a retrograde step."

Re: Next May 11 : BUG during scsi initialization

[Sachin Sant]

Matthew Wilcox wrote:
> On Mon, May 11, 2009 at 09:49:55PM +0530, Sachin Sant wrote:
>   
>> Yeah so the problem seems to be with SLQB. I was able to boot Next 11 with
>> SLUB on the same machine.
>>     
>
> Is it 100% reproducable with SLQB?  Our errors were fairly hard to tickle
> on demand.
>
>   
Yes. I am able to recreate this during every single reboot. I just 
tested few older next
releases (May 6th, 7th and 8th)as well and was able to recreate this 
issue with every release.

Thanks
-Sachin

-- 

---------------------------------
Sachin Sant
IBM Linux Technology Center
India Systems and Technology Labs
Bangalore, India
---------------------------------

Re: Next May 11 : BUG during scsi initialization

[Nick Piggin]

On Mon, May 11, 2009 at 06:21:35AM -0600, Matthew Wilcox wrote:
> On Mon, May 11, 2009 at 05:34:07PM +0530, Sachin Sant wrote:
> > Matthew Wilcox wrote:
> >> On Mon, May 11, 2009 at 05:16:10PM +0530, Sachin Sant wrote:
> >>   
> >>> Today's Next tree failed to boot on a Power6 box with following BUG :
> >>
> >> This doesn't actually appear to be a SCSI bug ... it looks like SCSI tried
> >> to allocate memory and things went wrong in the memory allocator:
> >>
> >> [c0000000c7d038b0] [c0000000005d67d8] ._spin_lock+0x10/0x24
> >> [c0000000c7d03920] [c00000000013fbdc] .__slab_alloc_page+0x344/0x3cc
> >> [c0000000c7d039e0] [c000000000141168] .kmem_cache_alloc+0x13c/0x21c
> >> [c0000000c7d03aa0] [c000000000141b04] .kmem_cache_create+0x294/0x2a8
> >> [c0000000c7d03b90] [d000000000ea14cc] .scsi_init_queue+0x38/0x170 [scsi_mod]
> >>
> >> Which memory allocator did you have selected (SLAB, SLUB, SLOB, SLQB)?
> >>   
> > Default one. SLQB
> >
> > CONFIG_SLQB_ALLOCATOR=y
> > CONFIG_SLQB=y
> >
> > Page size is 64K with Config DEBUG_PAGEALLOC set.
> >
> > CONFIG_PPC_HAS_HASH_64K=y
> > CONFIG_PPC_64K_PAGES=y
> > CONFIG_DEBUG_PAGEALLOC=y
> 
> Hm.  We've seen some similar problems at Intel while doing database
> performance tests with SLQB.  Any ideas, Nick?

Hmm, I think (hope) your problems were fixed with the recent memory
coruption bug fix for SLQB. (if not, let me know)

This one possibly looks like a problem with remote memory allocation
or memory hotplug or something like that. I'll do a bit of code
review....

Re: Next May 11 : BUG during scsi initialization

[Stephen Rothwell]

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

Hi Nick,

On Tue, 12 May 2009 06:57:16 +0200 Nick Piggin <npiggin@suse.de> wrote:
>
> Hmm, I think (hope) your problems were fixed with the recent memory
> coruption bug fix for SLQB. (if not, let me know)
> 
> This one possibly looks like a problem with remote memory allocation
> or memory hotplug or something like that. I'll do a bit of code
> review....

These are -next kernels which include the two fixes you posted recently
(I am pretty sure).  I am also getting the network failures that Sachin
is seeing on several of my machines here.  The previously reported
problems have gone away.

-- 
Cheers,
Stephen Rothwell                    sfr@canb.auug.org.au
http://www.canb.auug.org.au/~sfr/

[-- Attachment #2: Type: application/pgp-signature, Size: 197 bytes --]

Re: Next May 11 : BUG during scsi initialization

[Nick Piggin]

On Tue, May 12, 2009 at 03:56:13PM +1000, Stephen Rothwell wrote:
> Hi Nick,
> 
> On Tue, 12 May 2009 06:57:16 +0200 Nick Piggin <npiggin@suse.de> wrote:
> >
> > Hmm, I think (hope) your problems were fixed with the recent memory
> > coruption bug fix for SLQB. (if not, let me know)
> > 
> > This one possibly looks like a problem with remote memory allocation
> > or memory hotplug or something like that. I'll do a bit of code
> > review....
> 
> These are -next kernels which include the two fixes you posted recently
> (I am pretty sure).

Yes they should do.


>  I am also getting the network failures that Sachin
> is seeing on several of my machines here.  The previously reported
> problems have gone away.

This one is a SCSI failure... was there also a network one reported?
At any rate, I'm fairly sure this is a problem with SLQB, so it could
easily happen in any early driver setup.

Re: Next May 11 : BUG during scsi initialization

[Stephen Rothwell]

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

On Tue, 12 May 2009 07:59:18 +0200 Nick Piggin <npiggin@suse.de> wrote:
>
> On Tue, May 12, 2009 at 03:56:13PM +1000, Stephen Rothwell wrote:
> > Hi Nick,
> > 
> > On Tue, 12 May 2009 06:57:16 +0200 Nick Piggin <npiggin@suse.de> wrote:
> > >
> > > Hmm, I think (hope) your problems were fixed with the recent memory
> > > coruption bug fix for SLQB. (if not, let me know)
> > > 
> > > This one possibly looks like a problem with remote memory allocation
> > > or memory hotplug or something like that. I'll do a bit of code
> > > review....
> > 
> > These are -next kernels which include the two fixes you posted recently
> > (I am pretty sure).
> 
> Yes they should do.
> 
> 
> >  I am also getting the network failures that Sachin
> > is seeing on several of my machines here.  The previously reported
> > problems have gone away.
> 
> This one is a SCSI failure... was there also a network one reported?
> At any rate, I'm fairly sure this is a problem with SLQB, so it could
> easily happen in any early driver setup.

This is what I have been getting for the last few days:

calling  .ibmveth_module_init+0x0/0x80 @ 1
Unable to handle kernel paging request for data at address 0x22640004002d310
Faulting instruction address: 0xc000000000038840
cpu 0x0: Vector: 300 (Data Access) at [c0000000be67ef50]
    pc: c000000000038840: .memcpy+0x240/0x280
    lr: c0000000002a7860: .__nla_put+0x30/0x50
    sp: c0000000be67f1d0
   msr: 8000000000009032
   dar: 22640004002d310
 dsisr: 40000000
  current = 0xc0000000be67a000
  paca    = 0xc000000000913280
    pid   = 1, comm = swapper
enter ? for help
[link register   ] c0000000002a7860 .__nla_put+0x30/0x50
[c0000000be67f1d0] c0000000002a7850 .__nla_put+0x20/0x50 (unreliable)
[c0000000be67f260] c0000000002a7bb8 .nla_put+0x48/0x60
[c0000000be67f2e0] c0000000004a50b0 .rtnl_fill_ifinfo+0x320/0x740
[c0000000be67f3e0] c0000000004a586c .rtmsg_ifinfo+0x7c/0x110
[c0000000be67f480] c0000000004a59f0 .rtnetlink_event+0xf0/0x110
[c0000000be67f500] c00000000008a848 .notifier_call_chain+0x78/0x100
[c0000000be67f5a0] c0000000004964b8 .call_netdevice_notifiers+0x28/0x40
[c0000000be67f620] c000000000497a40 .register_netdevice+0x340/0x400
[c0000000be67f700] c000000000497b58 .register_netdev+0x58/0x80
[c0000000be67f790] c000000000574b4c .ibmveth_probe+0x2ec/0x400
[c0000000be67f8a0] c0000000000248b0 .vio_bus_probe+0xa0/0xb0
[c0000000be67f930] c000000000328b30 .driver_probe_device+0xf0/0x210
[c0000000be67f9d0] c000000000328d28 .__driver_attach+0xd8/0xe0
[c0000000be67fa60] c000000000327c78 .bus_for_each_dev+0x98/0xf0
[c0000000be67fb10] c000000000328898 .driver_attach+0x28/0x40
[c0000000be67fb90] c00000000032849c .bus_add_driver+0xdc/0x2d0
[c0000000be67fc30] c000000000329314 .driver_register+0x84/0x1d0
[c0000000be67fcd0] c0000000000247f0 .vio_register_driver+0x40/0x60
[c0000000be67fd60] c00000000077c5ac .ibmveth_module_init+0x5c/0x80
[c0000000be67fde0] c00000000000901c .do_one_initcall+0x6c/0x1e0
[c0000000be67fee0] c00000000074ed1c .kernel_init+0x1fc/0x280
[c0000000be67ff90] c00000000002a4c0 .kernel_thread+0x54/0x70

-- 
Cheers,
Stephen Rothwell                    sfr@canb.auug.org.au
http://www.canb.auug.org.au/~sfr/

[-- Attachment #2: Type: application/pgp-signature, Size: 197 bytes --]

Re: Next May 11 : BUG during scsi initialization

[Stephen Rothwell]

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

Hi Nick,

On Tue, 12 May 2009 16:03:52 +1000 Stephen Rothwell <sfr@canb.auug.org.au> wrote:
>
> This is what I have been getting for the last few days:

bisected into the net changes, I will follow up there, sorry.

-- 
Cheers,
Stephen Rothwell                    sfr@canb.auug.org.au
http://www.canb.auug.org.au/~sfr/

[-- Attachment #2: Type: application/pgp-signature, Size: 197 bytes --]

Re: Next May 11 : BUG during scsi initialization

[Nick Piggin]

On Tue, May 12, 2009 at 04:52:45PM +1000, Stephen Rothwell wrote:
> Hi Nick,
> 
> On Tue, 12 May 2009 16:03:52 +1000 Stephen Rothwell <sfr@canb.auug.org.au> wrote:
> >
> > This is what I have been getting for the last few days:
> 
> bisected into the net changes, I will follow up there, sorry.

No problem. Phew, yours was looking like a nasty one if it was indeed
an SLQB bug ;) 

Thanks,
Nick