Sergio,
On Wed, Jan 12, 2011 at 02:50, Aguirre, Sergio <saaguirre@xxxxxx> wrote:
> Hi all,
>
> Has anyone been trying to boot w/k.org lately?
>
> I tried with:
> - commit e0e736fc + 2 patches attached I got from patchworks
> - 4430SDP w/ES2.1
> - Busybox FS through NFS.
>
> I see the attached log, which shows a spinlock recursion bug.
>
> I did a git bisect, and found this offending commit:
>
> 34286d6662308d82aed891852d04c7c3a2649b16 is the first bad commit
> commit 34286d6662308d82aed891852d04c7c3a2649b16
> Author: Nick Piggin <npiggin@xxxxxxxxx>
> Date: Fri Jan 7 17:49:57 2011 +1100
>
> fs: rcu-walk aware d_revalidate method
>
> Require filesystems be aware of .d_revalidate being called in rcu-walk
> mode (nd->flags & LOOKUP_RCU). For now do a simple push down, returning
> -ECHILD from all implementations.
>
> Signed-off-by: Nick Piggin <npiggin@xxxxxxxxx>
>
> :040000 040000 409693ac5c32f4daa0c9be786e85b04dea32a24f 1813b382a41b72ccb5d810c282639961e6d81b73 M Documentation
> :040000 040000 a51e00e2f5335f8804e9e5fab10a26b0d67ac302 333fc859d8d1f2badea9023072e1ab356f042215 M drivers
> :040000 040000 53158279a9808c50157dd4b6ec5c35951b3a60af 301c546b257a5b4f3f09289fc5e8f55e66b2b6b9 M fs
> :040000 040000 e68ac1512333db998dc539a40a2b43dcee9cb074 f238839ffc4021e276be9d39d4e9c510575c9f44 M include
>
> And I narrowed it down to this line:
>
> In file fs/namei.c:
>
> ...
> ...
> static int nameidata_dentry_drop_rcu(struct nameidata *nd, struct dentry *dentry)
> {
> struct fs_struct *fs = current->fs;
> struct dentry *parent = nd->path.dentry;
>
> BUG_ON(!(nd->flags & LOOKUP_RCU));
> if (nd->root.mnt) {
> spin_lock(&fs->lock);
> if (nd->root.mnt != fs->root.mnt ||
> nd->root.dentry != fs->root.dentry)
> goto err_root;
> }
> spin_lock(&parent->d_lock);
> spin_lock_nested(&dentry->d_lock, DENTRY_D_LOCK_NESTED); <-- HERE THE RECURSION IS FIRED UP
> ...
> ...
>
> I had been googling around and I just saw Uwe & Santosh reporting the problem in LKML, but nobody has answered.
>
> Has anyone seen this aswell in other platforms? (OMAP3 based boards)
Same issue observed on zoom3 as well. Log attached.
>
> Regards,
> Sergio
>
>
## Booting image at 80300000 ...
Image Name: Linux-2.6.37-05762-gf8b6e81
Image Type: ARM Linux Kernel Image (uncompressed)
Data Size: 2919924 Bytes = 2.8 MB
Load Address: 80008000
Entry Point: 80008000
Verifying Checksum ... OK
OK
Starting kernel ...
[ 0.000000] Linux version 2.6.37-05762-gf8b6e81 (charu@x0084895-pc) (gcc version 4.4.1 (Sourcery G++ Lite 2010q1-202) ) #1
[ 0.000000] CPU: ARMv7 Processor [413fc082] revision 2 (ARMv7), cr=10c53c7f
[ 0.000000] CPU: VIPT nonaliasing data cache, VIPT aliasing instruction cache
[ 0.000000] Machine: OMAP Zoom3 board
[ 0.000000] Memory policy: ECC disabled, Data cache writeback
[ 0.000000] OMAP3630 ES1.0 (l2cache iva sgx neon isp 192mhz_clk )
[ 0.000000] SRAM: Mapped pa 0x40200000 to va 0xfe400000 size: 0x10000
[ 0.000000] PERCPU: Embedded 7 pages/cpu @c0f49000 s6048 r8192 d14432 u32768
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 130048
[ 0.000000] Kernel command line: console=ttyS0,115200n8 noinitrd root=/dev/nfs rw nfsroot=10.24.244.62:/usr/local/NFS/bb,p
[ 0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[ 0.000000] Memory: 512MB = 512MB total
[ 0.000000] Memory: 508212k/508212k available, 16076k reserved, 0K highmem
[ 0.000000] Virtual kernel memory layout:
[ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB)
[ 0.000000] fixmap : 0xfff00000 - 0xfffe0000 ( 896 kB)
[ 0.000000] DMA : 0xffc00000 - 0xffe00000 ( 2 MB)
[ 0.000000] vmalloc : 0xe0800000 - 0xf8000000 ( 376 MB)
[ 0.000000] lowmem : 0xc0000000 - 0xe0000000 ( 512 MB)
[ 0.000000] modules : 0xbf000000 - 0xc0000000 ( 16 MB)
[ 0.000000] .init : 0xc0008000 - 0xc0050000 ( 288 kB)
[ 0.000000] .text : 0xc0050000 - 0xc0573bb8 (5263 kB)
[ 0.000000] .data : 0xc0574000 - 0xc05e8fa0 ( 468 kB)
[ 0.000000] Hierarchical RCU implementation.
[ 0.000000] RCU-based detection of stalled CPUs is disabled.
[ 0.000000] NR_IRQS:402
[ 0.000000] Clocking rate (Crystal/Core/MPU): 26.0/400/600 MHz
[ 0.000000] Reprogramming SDRC clock to 400000000 Hz
[ 0.000000] GPMC revision 5.0
[ 0.000000] IRQ: Found an INTC at 0xfa200000 (revision 4.0) with 96 interrupts
[ 0.000000] Total of 96 interrupts on 1 active controller
[ 0.000000] OMAP clockevent source: GPTIMER1 at 32768 Hz
[ 0.000000] Console: colour dummy device 80x30
[ 0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[ 0.000000] ... MAX_LOCKDEP_SUBCLASSES: 8
[ 0.000000] ... MAX_LOCK_DEPTH: 48
[ 0.000000] ... MAX_LOCKDEP_KEYS: 8191
[ 0.000000] ... CLASSHASH_SIZE: 4096
[ 0.000000] ... MAX_LOCKDEP_ENTRIES: 16384
[ 0.000000] ... MAX_LOCKDEP_CHAINS: 32768
[ 0.000000] ... CHAINHASH_SIZE: 16384
[ 0.000000] memory used by lock dependency info: 3695 kB
[ 0.000000] per task-struct memory footprint: 1152 bytes
[ 0.000000] Calibrating delay loop... 597.64 BogoMIPS (lpj=2334720)
[ 0.000000] pid_max: default: 32768 minimum: 301
[ 0.000000] Security Framework initialized
[ 0.000000] Mount-cache hash table entries: 512
[ 0.000000] CPU: Testing write buffer coherency: ok
[ 0.000000] Brought up 1 CPUs
[ 0.000000] SMP: Total of 1 processors activated (597.64 BogoMIPS).
[ 0.000000] regulator: core version 0.5
[ 0.000000] regulator: dummy:
[ 0.000000] NET: Registered protocol family 16
[ 0.000000] OMAP GPIO hardware version 2.5
[ 0.000000] OMAP GPIO hardware version 2.5
[ 0.000000] OMAP GPIO hardware version 2.5
[ 0.000000] OMAP GPIO hardware version 2.5
[ 0.000000] OMAP GPIO hardware version 2.5
[ 0.000000] OMAP GPIO hardware version 2.5
[ 0.000000] omap_mux_init: Add partition: #1: core, flags: 0
[ 0.000000] error setting wl12xx data
[ 0.000000] hw-breakpoint: debug architecture 0x4 unsupported.
[ 0.000000] OMAP DMA hardware revision 5.0
[ 0.000030] sched_clock: 32 bits at 32kHz, resolution 30517ns, wraps every 131071999ms
[ 0.051635] bio: create slab <bio-0> at 0
[ 0.055541] regulator: vwl1271: 1800 mV
[ 0.061218] SCSI subsystem initialized
[ 0.067565] usbcore: registered new interface driver usbfs
[ 0.068695] usbcore: registered new interface driver hub
[ 0.069335] usbcore: registered new device driver usb
[ 0.071166] omap_device: omap_i2c.1: new worst case activate latency 0: 30517
[ 0.071289] omap_i2c omap_i2c.1: bus 1 rev4.0 at 2400 kHz
[ 0.081604] twl4030: PIH (irq 7) chaining IRQs 368..375
[ 0.081726] twl4030: power (irq 373) chaining IRQs 376..383
[ 0.083587] twl4030: gpio (irq 368) chaining IRQs 384..401
[ 0.096374] regulator: VMMC1: 1850 <--> 3150 mV at 3000 mV normal standby
[ 0.098632] regulator: VMMC2: 1850 mV normal standby
[ 0.100830] regulator: VSIM: 1800 <--> 3000 mV at 1800 mV normal standby
[ 0.101226] omap_device: omap_i2c.1: new worst case deactivate latency 0: 30517
[ 0.101531] omap_i2c omap_i2c.2: bus 2 rev4.0 at 400 kHz
[ 0.111206] omap_i2c omap_i2c.3: bus 3 rev4.0 at 400 kHz
[ 0.119720] Switching to clocksource 32k_counter
[ 0.219970] NET: Registered protocol family 2
[ 0.220764] IP route cache hash table entries: 4096 (order: 2, 16384 bytes)
[ 0.223052] TCP established hash table entries: 16384 (order: 5, 131072 bytes)
[ 0.223846] TCP bind hash table entries: 16384 (order: 7, 589824 bytes)
[ 0.233306] TCP: Hash tables configured (established 16384 bind 16384)
[ 0.233398] TCP reno registered
[ 0.233428] UDP hash table entries: 256 (order: 2, 20480 bytes)
[ 0.233764] UDP-Lite hash table entries: 256 (order: 2, 20480 bytes)
[ 0.234649] NET: Registered protocol family 1
[ 0.235931] RPC: Registered udp transport module.
[ 0.235961] RPC: Registered tcp transport module.
[ 0.235961] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.236938] NetWinder Floating Point Emulator V0.97 (double precision)
[ 0.400970] VFS: Disk quotas dquot_6.5.2
[ 0.401214] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.404083] JFFS2 version 2.2. (NAND) (SUMMARY) Â 2001-2006 Red Hat, Inc.
[ 0.405212] msgmni has been set to 992
[ 0.409454] io scheduler noop registered
[ 0.409484] io scheduler deadline registered
[ 0.409729] io scheduler cfq registered (default)
[ 0.413970] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[ 0.444885] serial8250.0: ttyS0 at MMIO 0x10000000 (irq = 262) is a ST16654
[ 1.024536] console [ttyS0] enabled
[ 1.030639] omap_uart.0: ttyO0 at MMIO 0x4806a000 (irq = 72) is a OMAP UART0
[ 1.039459] omap_uart.1: ttyO1 at MMIO 0x4806c000 (irq = 73) is a OMAP UART1
[ 1.047943] omap_uart.2: ttyO2 at MMIO 0x49020000 (irq = 74) is a OMAP UART2
[ 1.056274] omap_uart.3: ttyO3 at MMIO 0x49042000 (irq = 80) is a OMAP UART3
[ 1.098876] brd: module loaded
[ 1.118774] loop: module loaded
[ 1.123229] omap_device: omap_i2c.1: new worst case activate latency 0: 91552
[ 1.137725] mtdoops: mtd device (mtddev=name/number) must be supplied
[ 1.144531] omap2-nand driver initializing
[ 1.149108] ONFI flash detected
[ 1.152526] NAND device: Manufacturer ID: 0x2c, Chip ID: 0xbc (Micron )
[ 1.159301] Creating 7 MTD partitions on "omap2-nand.0":
[ 1.164642] 0x000000000000-0x000000080000 : "X-Loader-NAND"
[ 1.178466] 0x000000080000-0x0000001c0000 : "U-Boot-NAND"
[ 1.189453] 0x0000001c0000-0x000000200000 : "Boot Env-NAND"
[ 1.200195] 0x000000200000-0x000002000000 : "Kernel-NAND"
[ 1.224304] 0x000002000000-0x00001c000000 : "system"
[ 1.424163] 0x00001c000000-0x00001e000000 : "userdata"
[ 1.449096] 0x00001e000000-0x000020000000 : "cache"
[ 1.474243] OneNAND driver initializing
[ 1.485778] smsc911x: Driver version 2008-10-21.
[ 1.498321] smsc911x-mdio: probed
[ 1.502044] eth0: attached PHY driver [SMSC LAN8700] (mii_bus:phy_addr=ffffffff:01, irq=-1)
[ 1.510955] net eth0: MAC Address: 00:08:ee:03:2a:4a
[ 1.517120] usbcore: registered new interface driver asix
[ 1.523254] usbcore: registered new interface driver cdc_ether
[ 1.529724] usbcore: registered new interface driver net1080
[ 1.536010] usbcore: registered new interface driver cdc_subset
[ 1.542541] usbcore: registered new interface driver zaurus
[ 1.548156] cdc_ncm: 30-Nov-2010
[ 1.551971] usbcore: registered new interface driver cdc_ncm
[ 1.559967] usbcore: registered new interface driver cdc_wdm
[ 1.565765] Initializing USB Mass Storage driver...
[ 1.571228] usbcore: registered new interface driver usb-storage
[ 1.577392] USB Mass Storage support registered.
[ 1.583160] usbcore: registered new interface driver libusual
[ 1.589630] usbcore: registered new interface driver usbtest
[ 1.595306] udc: OMAP UDC driver, version: 4 October 2004 (iso) (dma)
[ 1.605194] mousedev: PS/2 mouse device common for all mice
[ 1.614044] input: TWL4030 Keypad as /devices/platform/omap/omap_i2c.1/i2c-1/1-004a/twl4030_keypad/input/input0
[ 1.633789] input: twl4030_pwrbutton as /devices/platform/omap/omap_i2c.1/i2c-1/1-0049/twl4030_pwrbutton/input/input1
[ 1.647949] twl_rtc twl_rtc: rtc core: registered twl_rtc as rtc0
[ 1.656372] i2c /dev entries driver
[ 1.665069] Driver for 1-wire Dallas network protocol.
[ 1.672210] omap_device: omap_wdt.-1: new worst case activate latency 0: 30517
[ 1.681243] OMAP Watchdog Timer Rev 0x31: initial timeout 60 sec
[ 1.688446] twl4030_wdt twl4030_wdt: Failed to register misc device
[ 1.694946] twl4030_wdt: probe of twl4030_wdt failed with error -16
[ 1.718750] usbcore: registered new interface driver usbhid
[ 1.724487] usbhid: USB HID core driver
[ 1.728332] oprofile: hardware counters not available
[ 1.733428] oprofile: using timer interrupt.
[ 1.738739] TCP cubic registered
[ 1.741973] Initializing XFRM netlink socket
[ 1.746490] NET: Registered protocol family 17
[ 1.751037] NET: Registered protocol family 15
[ 1.756011] Registering the dns_resolver key type
[ 1.761291] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3
[ 1.770812] ThumbEE CPU extension supported.
[ 1.786010] Power Management for TI OMAP3.
[ 1.824157] clock: disabling unused clocks to save power
[ 1.839447] twl_rtc twl_rtc: setting system clock to 2000-01-06 23:06:25 UTC (947199985)
[ 2.065704] mmc1: new high speed MMC card at address 0001
[ 2.073944] mmcblk0: mmc1:0001 STM16G 14.8 GiB
[ 2.085937] mmcblk0:
[ 2.210784] mmc2: card claims to support voltages below the defined range. These will be ignored.
[ 2.239929] mmc2: queuing unknown CIS tuple 0x91 (3 bytes)
[ 2.247650] mmc2: new SDIO card at address 0001
[ 2.356842] net eth0: SMSC911x/921x identified at 0xe0884000, IRQ: 318
[ 3.371124] Sending DHCP requests .., OK
[ 5.792541] IP-Config: Got DHCP answer from 0.0.0.0, my address is 10.24.244.160
[ 5.801330] IP-Config: Complete:
[ 5.804565] device=eth0, addr=10.24.244.160, mask=255.255.255.0, gw=10.24.244.1,
[ 5.812255] host=10.24.244.160, domain=, nis-domain=(none),
[ 5.818298] bootserver=0.0.0.0, rootserver=10.24.244.62, rootpath=
[ 5.828063] Waiting 2sec before mounting root device...
[ 7.868652] VFS: Mounted root (nfs filesystem) on device 0:13.
[ 7.874908] Freeing init memory: 288K
[ 7.880371] Failed to execute /init. Attempting defaults...
[ 8.216583] BUG: spinlock recursion on CPU#0, init/1
[ 8.221588] lock: df584e2c, .magic: dead4ead, .owner: init/1, .owner_cpu: 0
[ 8.228729] [<c0061228>] (unwind_backtrace+0x0/0xe4) from [<c0243860>] (do_raw_spin_lock+0x48/0x158)
[ 8.237945] [<c0243860>] (do_raw_spin_lock+0x48/0x158) from [<c012ab48>] (nameidata_dentry_drop_rcu+0x84/0x17c)
[ 8.248138] [<c012ab48>] (nameidata_dentry_drop_rcu+0x84/0x17c) from [<c012ac70>] (d_revalidate+0x30/0x58)
[ 8.257843] [<c012ac70>] (d_revalidate+0x30/0x58) from [<c012d788>] (link_path_walk+0xb44/0xb64)
[ 8.266693] [<c012d788>] (link_path_walk+0xb44/0xb64) from [<c012d9a0>] (do_path_lookup+0x44/0xcc)
[ 8.275695] [<c012d9a0>] (do_path_lookup+0x44/0xcc) from [<c012e570>] (do_filp_open+0xc8/0x56c)
[ 8.284454] [<c012e570>] (do_filp_open+0xc8/0x56c) from [<c012018c>] (do_sys_open+0x58/0xe4)
[ 8.292938] [<c012018c>] (do_sys_open+0x58/0xe4) from [<c005a240>] (ret_fast_syscall+0x0/0x3c)
[ 19.797027] BUG: spinlock lockup on CPU#0, init/1, df584e2c
[ 19.802673] [<c0061228>] (unwind_backtrace+0x0/0xe4) from [<c0243954>] (do_raw_spin_lock+0x13c/0x158)
[ 19.811950] [<c0243954>] (do_raw_spin_lock+0x13c/0x158) from [<c012ab48>] (nameidata_dentry_drop_rcu+0x84/0x17c)
[ 19.822174] [<c012ab48>] (nameidata_dentry_drop_rcu+0x84/0x17c) from [<c012ac70>] (d_revalidate+0x30/0x58)
[ 19.831939] [<c012ac70>] (d_revalidate+0x30/0x58) from [<c012d788>] (link_path_walk+0xb44/0xb64)
[ 19.840789] [<c012d788>] (link_path_walk+0xb44/0xb64) from [<c012d9a0>] (do_path_lookup+0x44/0xcc)
[ 19.849792] [<c012d9a0>] (do_path_lookup+0x44/0xcc) from [<c012e570>] (do_filp_open+0xc8/0x56c)
[ 19.858551] [<c012e570>] (do_filp_open+0xc8/0x56c) from [<c012018c>] (do_sys_open+0x58/0xe4)
[ 19.867034] [<c012018c>] (do_sys_open+0x58/0xe4) from [<c005a240>] (ret_fast_syscall+0x0/0x3c)
