Subject: rcu self-detected stall messages on OMAP3, 4 boards

From: [email-masked] (Paul E. McKenney)
Date: Fri, 21 Sep 2012 14:20:54 -0700

On Fri, Sep 21, 2012 at 05:47:31PM +0000, Paul Walmsley wrote:
> Hi Paul
> 
> On Thu, 20 Sep 2012, Paul Walmsley wrote:
> 
> > On Thu, 20 Sep 2012, Paul E. McKenney wrote:
> >
> > > Paul Walmsley, please let me know if the config below doesn't clear things
> > > up for you or if there is some reason why this config is infeasible.
> > 
> > Will certainly test it here once things settle down.
> 
> I built an OMAP kernel from Linus' commit 
> 4651afbbae968772efd6dc4ba461cba9b49bb9d8 ("Merge branch 'for-3.6-fixes' of 
> git://git.kernel.org/pub/scm/linux/kernel/git/tj/wq").  The config used 
> was 'omap2plus_defconfig', and enabled CONFIG_CPU_IDLE by hand.  Booted it 
> on a Pandaboard (OMAP4430ES2) into a very minimal Debian rootfs.

Did you have the patch at https://lkml.org/lkml/2012/8/30/290 applied?
If not, could you please try it?  (This patch cleared up a similar
problem for Becky, also on OMAP.)

						Thanx, Paul

> Long story short, the rcu_sched stall messages continue to appear.  
> Transcript below.
> 
> The above config should be easy to reproduce from mainline.  Paul, not 
> sure if you're still working with Linaro, but you should be able to get 
> access to a Pandaboard through them to try it yourself, should you wish.
> 
> 
> - Paul
> 
> ## Booting kernel from Legacy Image at 82000000 ...                                                   
>    Image Name:   Linux-3.6.0-rc6-00025-g4651afb                                                       
>    Image Type:   ARM Linux Kernel Image (uncompressed)                                                
>    Data Size:    4061576 Bytes = 3.9 MiB                                                              
>    Load Address: 80008000                                                                             
>    Entry Point:  80008000                                                                             
>    Verifying Checksum ... OK                                                                          
>    Loading Kernel Image ... OK                                                                        
> OK                                                                                                    
>                                                                                                       
> Starting kernel ...                                                                                   
>                                                                                                       
> Uncompressing Linux... done, booting the kernel.                                                      
> [    0.000000] Booting Linux on physical CPU 0                                                        
> [    0.000000] Linux version 3.6.0-rc6-00025-g4651afb (paul at dusk) (gcc version 4.5.1 (Sourcery G++ Lite 2010.09-50) ) #342 SMP Fri Sep 21 11:28:00 MDT 2012                                                                         
> [    0.000000] CPU: ARMv7 Processor [411fc092] revision 2 (ARMv7), cr=10c53c7d                        
> [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache               
> [    0.000000] Machine: OMAP4 Panda board                                                             
> [    0.000000] debug: ignoring loglevel setting.                                                      
> [    0.000000] Reserving 16777216 bytes SDRAM for VRAM                                                
> [    0.000000] Memory policy: ECC disabled, Data cache writealloc
> [    0.000000] On node 0 totalpages: 126720                                                           
> [    0.000000] free_area_init_node: node 0, pgdat c07c6140, node_mem_map c0d23000
> [    0.000000]   Normal zone: 1024 pages used for memmap
> [    0.000000]   Normal zone: 0 pages reserved
> [    0.000000]   Normal zone: 125696 pages, LIFO batch:31
> [    0.000000] OMAP4430 ES2.0
> [    0.000000] PERCPU: Embedded 9 pages/cpu @c112b000 s14016 r8192 d14656 u36864
> [    0.000000] pcpu-alloc: s14016 r8192 d14656 u36864 alloc=9*4096
> [    0.000000] pcpu-alloc: [0] 0 [0] 1 
> [    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 125696
> [    0.000000] Kernel command line: console=ttyO2,230400n8 vram=16M root=/dev/mmcblk0p2 rw rootfstype=ext3 rootwait earlyprintk debug ignore_loglevel
> [    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: 495MB = 495MB total
> [    0.000000] Memory: 488828k/488828k available, 35460k 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]     vmalloc : 0xe0800000 - 0xff000000   ( 488 MB)
> [    0.000000]     lowmem  : 0xc0000000 - 0xe0000000   ( 512 MB)
> [    0.000000]     pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
> [    0.000000]     modules : 0xbf000000 - 0xbfe00000   (  14 MB)
> [    0.000000]       .text : 0xc0008000 - 0xc06dad24   (6988 kB)
> [    0.000000]       .init : 0xc06db000 - 0xc072a6c0   ( 318 kB)
> [    0.000000]       .data : 0xc072c000 - 0xc07c8940   ( 627 kB)
> [    0.000000]        .bss : 0xc07c8964 - 0xc0d22a4c   (5481 kB)
> [    0.000000] Hierarchical RCU implementation.
> [    0.000000]  Additional per-CPU info printed with stalls.
> [    0.000000] NR_IRQS:474
> [    0.000000] omap_hwmod: dpll_mpu_m2_ck: missing clockdomain for dpll_mpu_m2_ck.
> [    0.000000] OMAP clockevent source: GPTIMER1 at 32768 Hz
> [    0.000000] omap_hwmod: sys_32k_ck: missing clockdomain for sys_32k_ck.
> [    0.000000] sched_clock: 32 bits at 32kHz, resolution 30517ns, wraps every 131071999ms
> [    0.000000] OMAP clocksource: 32k_counter 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.001190] Calibrating delay loop... 2007.19 BogoMIPS (lpj=7839744)
> [    0.124725] pid_max: default: 32768 minimum: 301
> [    0.125518] Security Framework initialized
> [    0.125793] Mount-cache hash table entries: 512
> [    0.131286] CPU: Testing write buffer coherency: ok
> [    0.132751] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
> [    0value (unknown osc rate)
> [    0.402343] twl 1-0048: PIH (irq 39) chaining IRQs 352..372
> [    0.403930] VUSB: 3300 mV normal standby
> [    0.404907] vdd_mpu: 500 <--> 1500 mV normal 
> [    0.405792] vdd_iva: 500 <--> 1500 mV normal 
> [    0.406890] vdd_core: 500 <--> 1500 mV normal 
> [    0.408081] V1V8: 1800 mV normal standby
> [    0.408966] V2V1: 2100 mV normal standby
> [    0.409973] VMMC: 1200 <--> 3000 mV at 3000 mV normal standby
> [    0.411132] VPP: 1800 <--> 2500 mV at 1900 mV normal standby
> [    0.412445] VCXIO: 1800 mV normal standby
> [    0.412506] VCXIO: supplied by V2V1
> [    0.414367] VDAC: 1800 mV normal standby
> [    0.414459] VDAC: supplied by V2V1
> [    0.415863] VAUX2_6030: 1200 <--> 2800 mV at 1800 mV normal standby
> [    0.417053] VAUX3_6030: 1000 <--> 3000 mV at 1200 mV normal standby
> [    0.418487] VANA: 2100 mV normal standby
> [    0.430084] omap_i2c omap_i2c.2: bus 2 rev2.4.0 at 400 kHz
> [    0gistered twl_rtc as rtc0
> [    1.241333] i2c /dev entries driver
> [    1.245208] Driver for 1-wire Dallas network protocol.
> [    1.249908] omap_wdt: OMAP Watchdog Timer Rev 0x00: initial timeout 60 sec
> [    1.254272] cpuidle: using governor ladder
> [    1.256530] cpuidle: using governor menu
> [    1.259948] omap_hsmmc omap_hsmmc.0: Failed to get debounce clk
> [    1.263305] omap-dma-engine omap-dma-engine: allocating channel for 62
> [    1.266906] omap-dma-engine omap-dma-engine: allocating channel for 61
> [    1.317443] omap_hsmmc omap_hsmmc.4: Failed to get debounce clk
> [    1.320709] omap-dma-engine omap-dma-engine: allocating channel for 60
> [    1.324279] omap-dma-engine omap-dma-engine: allocating channel for 59
> [    1.444854] usbcore: registered new interface driver usbhid
> [    1.447906] usbhid: USB HID core driver
> [    1.450012] oprofile: hardware counters not available
> [    1.452789] oprofile: using timer interrupt.
> [    1.455657] TCP: cubic registered
> [    1.457489] Initializing XFRM netlink socket
> [    1.459930] NET: Registered protocol family 17
> [    1.462402] NET: Registered protocol family 15
> [    1.465057] Key type dns_resolver registered
> [    1.467559] VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1
> [    1.476593] omap_vc_i2c_init: I2C config for vdd_iva does not match other channels (0).
> [    1.480895] omap_vc_i2c_init: I2C config for vdd_mpu does not match other channels (0).[    1.486236] Power Management for TI OMAP4.
> [    1.489135] ThumbEE CPU extension supported.
> [    1.508178] clock: disabling unused clocks to save power
> [    1.513977] VANA: incomplete constraints, leaving on
> [    1.517669] VDAC: incomplete constraints, leaving on
> [    1.521118] VUSB: incomplete constraints, leaving on
> [    1.525665] twl_rtc twl_rtc: setting system clock to 2000-01-01 00:00:00 UTC (946684800)
> [    1.532409] Waiting for root device /dev/mmcblk0p2...
> [    1.599426] mmc0: host does not support reading read-only switch. assuming write-enable.
> [    1.603942] mmc0: new SD card at address aaaa
> [    1.607849] mmcblk0: mmc0:aaaa SD02G 1.89 GiB 
> [    1.614410]  mmcblk0: p1 p2
> [    3.508514] kjournald starting.  Commit interval 5 seconds
> [    3.668579] EXT3-fs (mmcblk0p2): using internal journal
> [    3.675384] EXT3-fs (mmcblk0p2): recovery complete
> [    3.678039] EXT3-fs (mmcblk0p2): mounted filesystem with ordered data mode
> [    3.682037] VFS: Mounted root (ext3 filesystem) on device 179:2.
> [    3.685607] Freeing init memory: 316K
> modprobe: FATAL: Could not load /lib/modules/3.6.0-rc6-00025-g4651afb/modules.dep: No such file or directory
> 
> INIT: version 2.88 booting
> Using makefile-style concurrent boot in runlevel S.
> Starting the hotplug events dispatcher: udevd.
> Synthesizing the initial hotplug events...done.
> Waiting for /dev to be fully populated...done.
> Activating swap...done.
> Cleaning up ifupdown....
> Setting up networking....
> Loading kernel modules...done.
> Activating lvm and md swap...done.
> Checking file systems...fsck from util-linux 2.19.1
> done.
> Mounting local filesystems...done.
> Activating swapfile swap...done.
> Cleaning up temporary files....
> Configuring network interfaces...done.
> Cleaning up temporary files....
> Setting kernel variables ...done.
> INIT: Entering runlevel: 2
> Using makefile-style concurrent boot in runlevel 2.
> 
> Debian GNU/Linux wheezy/sid armel ttyO2
> 
> armel login: [  305.848632] INFO: rcu_sched self-detected stall on CPU
> [  305.851470]  1: (17 GPs behind) idle=439/1/0 
> [  305.853851]   (t=33915 jiffies)
> [  305.855621] [<c001bcb0>] (unwind_backtrace+0x0/0xf0) from [<c00adcd0>] (rcu_check_callbacks+0x1b0/0x678)
> [  305.860809] [<c00adcd0>] (rcu_check_callbacks+0x1b0/0x678) from [<c00537e8>] (update_process_times+0x38/0x68)
> [  305.866210] [<c00537e8>] (update_process_times+0x38/0x68) from [<c008cf28>] (tick_sched_timer+0x80/0xec)
> [  305.871398] [<c008cf28>] (tick_sched_timer+0x80/0xec) from [<c0069414>] (__run_hrtimer+0x7c/0x1e0)
> [  305.876281] [<c0069414>] (__run_hrtimer+0x7c/0x1e0) from [<c006a1f8>] (hrtimer_interrupt+0x11c/0x2d0)
> [  305.881317] [<c006a1f8>] (hrtimer_interrupt+0x11c/0x2d0) from [<c001a3ec>] (twd_handler+0x30/0x44)
> [  305.886199] [<c001a3ec>] (twd_handler+0x30/0x44) from [<c00a8110>] (handle_percpu_devid_irq+0x90/0x13c)
> [  305.891326] [<c00a8110>] (handle_percpu_devid_irq+0x90/0x13c) from [<c00a4884>] (generic_handle_irq+0x30/0x48)
> [  305.896820] [<c00a4884>] (generic_handle_irq+0x30/0x48) from [<c0014e38>] (handle_IRQ+0x4c/0xac)
> [  305.901611] [<c0014e38>] (handle_IRQ+0x4c/0xac) from [<c00084cc>] (gic_handle_irq+0x28/0x5c)
> [  305.906219] [<c00084cc>] (gic_handle_irq+0x28/0x5c) from [<c04fdf64>] (__irq_svc+0x44/0x5c)
> [  305.910766] Exception stack(0xde86ff08 to 0xde86ff50)
> [  305.913513] ff00:                   0002a80e 00000001 00000000 de8660c0 35b88a9a 00000047
> [  305.917968] ff20: c11345e0 00000002 efc9ba42 00000046 c0509618 00000000 00000001 de86ff50
> [  305.922424] ff40: 0002a80f c03f8f1c 20000113 ffffffff
> [  305.925201] [<c04fdf64>] (__irq_svc+0x44/0x5c) from [<c03f8f1c>] (cpuidle_wrap_enter+0x4c/0xa0)
> [  305.929962] [<c03f8f1c>] (cpuidle_wrap_enter+0x4c/0xa0) from [<c03f8a10>] (cpuidle_enter_state+0x14/0x68)
> [  305.935180] [<c03f8a10>] (cpuidle_enter_state+0x14/0x68) from [<c03fab34>] (cpuidle_enter_state_coupled+0x240/0x2e8)
> [  305.940917] [<c03fab34>] (cpuidle_enter_state_coupled+0x240/0x2e8) from [<c03f8b48>] (cpuidle_idle_call+0xe4/0x2e0)
> [  305.946594] [<c03f8b48>] (cpuidle_idle_call+0xe4/0x2e0) from [<c0015358>] (cpu_idle+0x98/0x124)
> [  305.951324] [<c0015358>] (cpu_idle+0x98/0x124) from [<804f6df4>] (0x804f6df4)
> root
> [  375.629669] INFO: rcu_sched self-detected stall on CPU
> [  375.632476]  0: (2 GPs behind) idle=c1b/1/0 
> [  375.634796]   (t=8914 jiffies)
> [  375.636505] [<c001bcb0>] (unwind_backtrace+0x0/0xf0) from [<c00adcd0>] (rcu_check_callbacks+0x1b0/0x678)
> [  375.641693] [<c00adcd0>] (rcu_check_callbacks+0x1b0/0x678) from [<c00537e8>] (update_process_times+0x38/0x68)
> [  375.647094] [<c00537e8>] (update_process_times+0x38/0x68) from [<c008cf28>] (tick_sched_timer+0x80/0xec)
> [  375.652252] [<c008cf28>] (tick_sched_timer+0x80/0xec) from [<c0069414>] (__run_hrtimer+0x7c/0x1e0)
> [  375.657135] [<c0069414>] (__run_hrtimer+0x7c/0x1e0) from [<c006a1f8>] (hrtimer_interrupt+0x11c/0x2d0)
> [  375.662170] [<c006a1f8>] (hrtimer_interrupt+0x11c/0x2d0) from [<c001a3ec>] (twd_handler+0x30/0x44)
> [  375.667053] [<c001a3ec>] (twd_handler+0x30/0x44) from [<c00a8110>] (handle_percpu_devid_irq+0x90/0x13c)
> [  375.672180] [<c00a8110>] (handle_percpu_devid_irq+0x90/0x13c) from [<c00a4884>] (generic_handle_irq+0x30/0x48)
> [  375.677642] [<c00a4884>] (generic_handle_irq+0x30/0x48) from [<c0014e38>] (handle_IRQ+0x4c/0xac)
> [  375.682434] [<c0014e38>] (handle_IRQ+0x4c/0xac) from [<c00084cc>] (gic_handle_irq+0x28/0x5c)
> [  375.687042] [<c00084cc>] (gic_handle_irq+0x28/0x5c) from [<c04fdf64>] (__irq_svc+0x44/0x5c)
> [  375.691589] Exception stack(0xc072df08 to 0xc072df50)
> [  375.694366] df00:                   0002fb7e 00000001 00000000 c074e8e8 74fea80e 00000057
> [  375.698822] df20: c112b5e0 00000000 74fc5402 00000057 c0d1c94c 00000000 00000001 c072df50
> [  375.703277] df40: 0002fb7f c03f8f1c 20000013 ffffffff
> [  375.706024] [<c04fdf64>] (__irq_svc+0x44/0x5c) from [<c03f8f1c>] (cpuidle_wrap_enter+0x4c/0xa0)
> [  375.710784] [<c03f8f1c>] (cpuidle_wrap_enter+0x4c/0xa0) from [<c03f8ba8>] (cpuidle_idle_call+0x144/0x2e0)
> [  375.716003] [<c03f8ba8>] (cpuidle_idle_call+0x144/0x2e0) from [<c0015358>] (cpu_idle+0x98/0x124)
> [  375.720794] [<c0015358>] (cpu_idle+0x98/0x124) from [<c06db7b0>] (start_kernel+0x2b4/0x304)
> Last login: Sat Jan  1 00:09:14 UTC 2000 on ttyO2
> Linux armel 3.6.0-rc6-00025-g4651afb #342 SMP Fri Sep 21 11:28:00 MDT 2012 armv7l
> 
> The programs included with the Debian GNU/Linux system are free software;
> the exact distribution terms for each program are described in the
> individual files in /usr/share/doc/*/copyright.
> 
> Debian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent
> permitted by applicable law.
> root at armel:~# cat /sys/devices/system/cpu/cpuidle/*
> omap4_idle
> menu
> root at armel:~# 
> 
> 
> 
> 
>