Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17

[Mathieu Desnoyers <mathieu.desnoyers@efficios.com>]

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

----- On Feb 21, 2016, at 1:15 PM, Ross Green rgkernel@gmail.com wrote:

> On Sun, Feb 21, 2016 at 4:04 PM, Ross Green <rgkernel@gmail.com> wrote:
>> On Sat, Feb 20, 2016 at 5:32 PM, Paul E. McKenney
>> <paulmck@linux.vnet.ibm.com> wrote:
>>> On Sat, Feb 20, 2016 at 03:34:30PM +1100, Ross Green wrote:
>>>> On Sat, Feb 20, 2016 at 4:33 AM, Paul E. McKenney
>>>> <paulmck@linux.vnet.ibm.com> wrote:
>>>> > On Thu, Feb 18, 2016 at 08:13:18PM -0800, John Stultz wrote:
>>>> >> On Thu, Feb 18, 2016 at 7:56 PM, Ross Green <rgkernel@gmail.com> wrote:
>>>> >> > Well a bonus extra!
>>>> >> > Kept everything running and there was another stall.
>>>> >> > So i have included the demsg output for perusal.
>>>> >> >
>>>> >> > Just to clear things up there is no hotplug involved in this system.
>>>> >> > It is a standard Pandaboard ES Ti4460 two processor system.
>>>> >> > I use this for testing as a generic armv7 processor, plus can keep it
>>>> >> > just running along for testing for a long time. the system has a total
>>>> >> > of 23-25 process running on average. Mainly standard daemons. There is
>>>> >> > certainly no heavy processing going on. I run a series of benchmarks
>>>> >> > that are cpu intensive for the first 20 miinutes after boot and then
>>>> >> > just leave it idle away. checking every so often to see how it has
>>>> >> > gone.
>>>> >> > As mentioned I have observed these stalls going back to 3.17 kernel.
>>>> >> > It will often take up to a week to record such a stall. I will
>>>> >> > typically test every new release kernel, so the -rc? series will get
>>>> >> > around a weeks testing.
>>>> >>
>>>> >> Sorry. Kind of hopping in a bit late here. Is this always happening
>>>> >> with just the pandaboard? Or are you seeing this on different
>>>> >> machines?
>>>> >>
>>>> >> Have you tried enabling CONFIG_DEBUG_TIMEKEEPING just in case
>>>> >> something is going awry there?
>>>> >
>>>> > Excellent point -- timekeeping issues have caused this sort of issue
>>>> > in the past.
>>>> >
>>>> > Ross, on your next test, could you please enable CONFIG_DEBUG_TIMEKEEPING
>>>> > as John suggests?
>>>> >
>>>> >                                                         Thanx, Paul
>>>> >
>>>> As John has suggested have already enabled CONFIG_DEBUG_TIMEKEEPING.
>>>>
>>>> So far just on 1 day running.
>>>>
>>>> Sigh...!! Nothing to report as yet, only one day on the clock.
>>>> Its like watching grass grow!
>>>
>>> I hear you!  Though I was thinking in terms of watching paint dry...
>>>
>>>                                                         Thanx, Paul
>>>
>> Yes,
>>
>> but with paint drying there is an end point!
>> Grass just keeps on growing ...
>>
>> More like the children in the back of the car ...
>> Are we there yet? ...
>>
>> Well still nothing .. to report. I have just built a 4.5-rc5, but will
>> wait till I get some outcome from the previous test. That can't be too
>> much longer!
>>
>> In hope,
>>
>> Ross Green
> Patience little ones ...
> 
> Well after 2 days plus running pulled another stall.
> This is with 4.5-rc4 and CONFIG_DEBUG_TIMEKEEPING set.
> 
> Can't see anything related to the TIMEKEEPING.
> 
> Anyway here is the dmesg output for people to look at.
> 
> Paul, I was going to move onto 4.5-rc5 kernel, is there something else
> that you want me to test with that, Anyone else have any suggestions
> or ideas?

Starting from kernel 3.17, if we request a e.g. 1000 jiffies schedule_timeout
on a HZ=1000 kernel, is there an upper bound to the number of jiffies it
can actually take before the timeout happens, especially on idle systems ?
I remember a talk from Thomas Gleixner on the new timer wheel which could
add some imprecision to those timeouts. Not sure in which kernel version it
got in though.

My thinking is that it might be a good idea to try using hrtimers rather than
a jiffies-based timeout to awaken the RCU thread if it's really important to
run in a bounded amount of jiffies. Or else the jiffies-based sanity check
that triggers the warning is perhaps too strict.

Thoughts ?

Thanks,

Mathieu


> 
> Regards,
> 
> Ross Green

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

[-- Attachment #2: dmesg-4.5-rc4-3 --]
[-- Type: application/octet-stream, Size: 25170 bytes --]

$ uptime
 04:44:22 up 2 days,  8:33,  load average: 0.07, 0.09, 0.09
$ dmesg
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.5.0-rc4-panda (rfg@red.dwarf) (gcc version 5.3.0 (Buildroot 2016.02-git-00183-g1682aee) ) #2 SMP PREEMPT Fri Feb 19 19:33:54 AEDT 2016
[    0.000000] CPU: ARMv7 Processor [412fc09a] revision 10 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] Machine model: TI OMAP4 PandaBoard-ES
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] OMAP4: Map 0xbfe00000 to fe600000 for dram barrier
[    0.000000] On node 0 totalpages: 261632
[    0.000000] free_area_init_node: node 0, pgdat c09662c0, node_mem_map ef7f9000
[    0.000000]   Normal zone: 1536 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 196608 pages, LIFO batch:31
[    0.000000]   HighMem zone: 65024 pages, LIFO batch:15
[    0.000000] OMAP4460 ES1.1
[    0.000000] PERCPU: Embedded 12 pages/cpu @ef7ab000 s17984 r8192 d22976 u49152
[    0.000000] pcpu-alloc: s17984 r8192 d22976 u49152 alloc=12*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 260096
[    0.000000] Kernel command line: root=/dev/mmcblk0p2 rootwait console=ttyO2,115200
[    0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Memory: 1027232K/1046528K available (6879K kernel code, 252K rwdata, 2156K rodata, 304K init, 298K bss, 19296K reserved, 0K cma-reserved, 260096K highmem)
[    0.000000] Virtual kernel memory layout:
                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                   vmalloc : 0xf0800000 - 0xff800000   ( 240 MB)
                   lowmem  : 0xc0000000 - 0xf0000000   ( 768 MB)
                   pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
                   modules : 0xbf000000 - 0xbfe00000   (  14 MB)
                     .text : 0xc0008000 - 0xc08db0d4   (9037 kB)
                     .init : 0xc08dc000 - 0xc0928000   ( 304 kB)
                     .data : 0xc0928000 - 0xc09672c0   ( 253 kB)
                      .bss : 0xc096a000 - 0xc09b48b8   ( 299 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[    0.000000] Preemptible hierarchical RCU implementation.
[    0.000000]  Build-time adjustment of leaf fanout to 32.
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] L2C: platform modifies aux control register: 0x0e070000 -> 0x3e470000
[    0.000000] L2C: DT/platform modifies aux control register: 0x0e070000 -> 0x3e470000
[    0.000000] L2C-310 enabling early BRESP for Cortex-A9
[    0.000000] OMAP L2C310: ROM does not support power control setting
[    0.000000] L2C-310 dynamic clock gating disabled, standby mode disabled
[    0.000000] L2C-310 cache controller enabled, 16 ways, 1024 kB
[    0.000000] L2C-310: CACHE_ID 0x410000c7, AUX_CTRL 0x4e470000
[    0.000000] ti_dt_clocks_register: failed to lookup clock node dss_fck
[    0.000000] ti_dt_clocks_register: failed to lookup clock node dss_fck
[    0.000000] ti_dt_clocks_register: failed to lookup clock node bandgap_fclk
[    0.000000] OMAP clockevent source: timer1 at 32768 Hz
[    0.000000] clocksource: 32k_counter: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 58327039986419 ns
[    0.000000] sched_clock: 32 bits at 32kHz, resolution 30517ns, wraps every 65535999984741ns
[    0.000030] OMAP clocksource: 32k_counter at 32768 Hz
[    0.000885] Console: colour dummy device 80x30
[    0.000885] Calibrating delay loop... 1397.55 BogoMIPS (lpj=6987776)
[    0.089202] pid_max: default: 32768 minimum: 301
[    0.089263] Security Framework initialized
[    0.089324] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.089324] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.089935] CPU: Testing write buffer coherency: ok
[    0.090179] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.090240] Setting up static identity map for 0x80008280 - 0x800082d8
[    0.209197] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.209259] Brought up 2 CPUs
[    0.209289] SMP: Total of 2 processors activated (2795.11 BogoMIPS).
[    0.209289] CPU: All CPU(s) started in SVC mode.
[    0.210083] devtmpfs: initialized
[    0.227081] VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 4
[    0.227569] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.227722] xor: measuring software checksum speed
[    0.319183]    arm4regs  :  1006.000 MB/sec
[    0.419189]    8regs     :   803.600 MB/sec
[    0.519165]    32regs    :   761.200 MB/sec
[    0.519195] xor: using function: arm4regs (1006.000 MB/sec)
[    0.519439] pinctrl core: initialized pinctrl subsystem
[    0.521331] NET: Registered protocol family 16
[    0.522338] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.524078] omap_hwmod: l3_main_3 using broken dt data from ocp
[    0.525604] omap_hwmod: l3_main_2 using broken dt data from ocp
[    0.631103] OMAP GPIO hardware version 0.1
[    0.636413] omap-gpmc 50000000.gpmc: GPMC revision 6.0
[    0.636444] gpmc_mem_init: disabling cs 0 mapped at 0x0-0x1000000
[    0.636962] irq: no irq domain found for /ocp/l4@4a000000/scm@100000/pinmux@40 !
[    0.637359] irq: no irq domain found for /ocp/l4@4a000000/scm@100000/pinmux@40 !
[    0.637725] irq: no irq domain found for /ocp/l4@4a000000/scm@100000/pinmux@40 !
[    0.649597] platform 4b501000.aes: Cannot lookup hwmod 'aes'
[    0.649902] platform 480a5000.des: Cannot lookup hwmod 'des'
[    0.655883] hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers.
[    0.655883] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.656524] omap4_sram_init:Unable to get sram pool needed to handle errata I688
[    0.656738] OMAP DMA hardware revision 0.0
[    0.909423] raid6: int32x1  gen()   103 MB/s
[    1.079498] raid6: int32x1  xor()    82 MB/s
[    1.249267] raid6: int32x2  gen()   134 MB/s
[    1.419372] raid6: int32x2  xor()    99 MB/s
[    1.589385] raid6: int32x4  gen()   145 MB/s
[    1.759307] raid6: int32x4  xor()    98 MB/s
[    1.929260] raid6: int32x8  gen()   160 MB/s
[    2.099365] raid6: int32x8  xor()    94 MB/s
[    2.099365] raid6: using algorithm int32x8 gen() 160 MB/s
[    2.099365] raid6: .... xor() 94 MB/s, rmw enabled
[    2.099395] raid6: using intx1 recovery algorithm
[    2.105468] omap-dma-engine 4a056000.dma-controller: OMAP DMA engine driver
[    2.179321] reg-fixed-voltage wl12xx_vmmc: could not find pctldev for node /ocp/l4@4a000000/scm@100000/pinmux@40/pinmux_wl12xx_gpio, deferring probe
[    2.183593] omap-iommu 4a066000.mmu: 4a066000.mmu registered
[    2.183715] omap-iommu 55082000.mmu: 55082000.mmu registered
[    2.185821] SCSI subsystem initialized
[    2.186096] usbcore: registered new interface driver usbfs
[    2.186248] usbcore: registered new interface driver hub
[    2.186401] usbcore: registered new device driver usb
[    2.187347] omap_i2c 48070000.i2c: could not find pctldev for node /ocp/l4@4a000000/scm@100000/pinmux@40/pinmux_i2c1_pins, deferring probe
[    2.187408] omap_i2c 48072000.i2c: could not find pctldev for node /ocp/l4@4a000000/scm@100000/pinmux@40/pinmux_i2c2_pins, deferring probe
[    2.187438] omap_i2c 48060000.i2c: could not find pctldev for node /ocp/l4@4a000000/scm@100000/pinmux@40/pinmux_i2c3_pins, deferring probe
[    2.187469] omap_i2c 48350000.i2c: could not find pctldev for node /ocp/l4@4a000000/scm@100000/pinmux@40/pinmux_i2c4_pins, deferring probe
[    2.187744] Linux video capture interface: v2.00
[    2.188507] Advanced Linux Sound Architecture Driver Initialized.
[    2.189971] clocksource: Switched to clocksource 32k_counter
[    2.204315] NET: Registered protocol family 2
[    2.204864] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    2.204956] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    2.205108] TCP: Hash tables configured (established 8192 bind 8192)
[    2.205169] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    2.205230] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    2.205413] NET: Registered protocol family 1
[    2.205810] RPC: Registered named UNIX socket transport module.
[    2.205841] RPC: Registered udp transport module.
[    2.205841] RPC: Registered tcp transport module.
[    2.205841] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    2.208007] hw perfevents: enabled with armv7_cortex_a9 PMU driver, 7 counters available
[    2.210235] futex hash table entries: 512 (order: 3, 32768 bytes)
[    2.239166] NFS: Registering the id_resolver key type
[    2.239196] Key type id_resolver registered
[    2.239196] Key type id_legacy registered
[    2.239227] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    2.239257] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
[    2.250488] ntfs: driver 2.1.32 [Flags: R/O].
[    2.250762] fuse init (API version 7.24)
[    2.253631] jitterentropy: Initialization failed with host not compliant with requirements: 2
[    2.253692] bounce: pool size: 64 pages
[    2.253723] io scheduler noop registered
[    2.253753] io scheduler deadline registered
[    2.253784] io scheduler cfq registered (default)
[    2.254669] pinctrl-single 4a100040.pinmux: 203 pins at pa fc100040 size 406
[    2.254882] pinctrl-single 4a31e040.pinmux: 28 pins at pa fc31e040 size 56
[    2.257873] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    2.259490] omap_uart 4806a000.serial: no wakeirq for uart0
[    2.259643] 4806a000.serial: ttyO0 at MMIO 0x4806a000 (irq = 226, base_baud = 3000000) is a OMAP UART0
[    2.260192] 4806c000.serial: ttyO1 at MMIO 0x4806c000 (irq = 227, base_baud = 3000000) is a OMAP UART1
[    2.260681] 48020000.serial: ttyO2 at MMIO 0x48020000 (irq = 228, base_baud = 3000000) is a OMAP UART2
[    3.157531] console [ttyO2] enabled
[    3.161712] 4806e000.serial: ttyO3 at MMIO 0x4806e000 (irq = 229, base_baud = 3000000) is a OMAP UART3
[    3.172424] [drm] Initialized drm 1.1.0 20060810
[    3.178955] 58000000.dss supply vdda_video not found, using dummy regulator
[    3.186340] OMAP DSS rev 4.0
[    3.189514] omapdss_dss 58000000.dss: bound 58001000.dispc (ops dispc_component_ops)
[    3.197875] omapdss_dss 58000000.dss: bound 58005000.encoder (ops dsi_component_ops)
[    3.206481] omapdss_dss 58000000.dss: bound 58006000.encoder (ops hdmi4_component_ops)
[    3.258361] loop: module loaded
[    3.264434] usbcore: registered new interface driver smsc95xx
[    3.270599] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    3.277404] ehci-omap: OMAP-EHCI Host Controller driver
[    3.299987] ehci-omap 4a064c00.ehci: EHCI Host Controller
[    3.305664] ehci-omap 4a064c00.ehci: new USB bus registered, assigned bus number 1
[    3.313720] ehci-omap 4a064c00.ehci: irq 336, io mem 0x4a064c00
[    3.339996] ehci-omap 4a064c00.ehci: USB 2.0 started, EHCI 1.00
[    3.346374] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    3.353515] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    3.361083] usb usb1: Product: EHCI Host Controller
[    3.366180] usb usb1: Manufacturer: Linux 4.5.0-rc4-panda ehci_hcd
[    3.372650] usb usb1: SerialNumber: 4a064c00.ehci
[    3.378234] hub 1-0:1.0: USB hub found
[    3.382232] hub 1-0:1.0: 3 ports detected
[    3.387145] usbcore: registered new interface driver cdc_wdm
[    3.393218] usbcore: registered new interface driver usb-storage
[    3.399932] i2c /dev entries driver
[    3.403747] usbcore: registered new interface driver uvcvideo
[    3.409729] USB Video Class driver (1.1.1)
[    3.415252] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec
[    3.422821] device-mapper: uevent: version 1.0.3
[    3.427978] device-mapper: ioctl: 4.34.0-ioctl (2015-10-28) initialised: dm-devel@redhat.com
[    3.491424] hidraw: raw HID events driver (C) Jiri Kosina
[    3.497497] usbcore: registered new interface driver usbhid
[    3.503356] usbhid: USB HID core driver
[    3.507904] emif 4c000000.emif: emif_probe: device configured with addr = f08a8000 and IRQ247
[    3.517242] emif 4d000000.emif: emif_probe: device configured with addr = f08aa000 and IRQ248
[    3.528778] omap-abe-twl6040 sound: ASoC: CODEC DAI twl6040-legacy not registered
[    3.536743] omap-abe-twl6040 sound: snd_soc_register_card() failed: -517
[    3.544311] ip_tables: (C) 2000-2006 Netfilter Core Team
[    3.550048] Initializing XFRM netlink socket
[    3.554595] NET: Registered protocol family 17
[    3.559570] Key type dns_resolver registered
[    3.564270] twl: not initialized
[    3.567687] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1375000 Vs max 1316660
[    3.576171] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1375000 Vs max 1316660
[    3.584686] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1375000 Vs max 1316660
[    3.593170] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1375000 Vs max 1316660
[    3.601684] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1375000 Vs max 1316660
[    3.610168] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1375000 Vs max 1316660
[    3.618652] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1410000 Vs max 1316660
[    3.627136] omap2_set_init_voltage: unable to find boot up OPP for vdd_mpu
[    3.634429] omap2_set_init_voltage: unable to set vdd_mpu
[    3.640197] omap2_set_init_voltage: unable to find boot up OPP for vdd_core
[    3.647552] omap2_set_init_voltage: unable to set vdd_core
[    3.653381] omap2_set_init_voltage: unable to find boot up OPP for vdd_iva
[    3.660675] omap2_set_init_voltage: unable to set vdd_iva
[    3.667602] Power Management for TI OMAP4+ devices.
[    3.672790] OMAP4 PM: u-boot >= v2012.07 is required for full PM support
[    3.680023] ThumbEE CPU extension supported.
[    3.680023] Registering SWP/SWPB emulation handler
[    3.684631] SmartReflex Class3 initialized
[    3.714111] Btrfs loaded
[    3.719268] dmm 4e000000.dmm: initialized all PAT entries
[    3.719726] usb 1-1: new high-speed USB device number 2 using ehci-omap
[    3.744720] Skipping twl internal clock init and using bootloader value (unknown osc rate)
[    3.770660] twl 0-0048: PIH (irq 340) nested IRQs
[    3.777099] twl_rtc 48070000.i2c:twl@48:rtc: Enabling TWL-RTC
[    3.785766] twl_rtc 48070000.i2c:twl@48:rtc: rtc core: registered 48070000.i2c:twl@48 as rtc0
[    3.805755] twl6040 0-004b: clk32k is not handled
[    3.813476] omap_i2c 48070000.i2c: bus 0 rev0.11 at 400 kHz
[    3.820220] omap_i2c 48072000.i2c: bus 1 rev0.11 at 400 kHz
[    3.827056] omap_i2c 48060000.i2c: bus 2 rev0.11 at 100 kHz
[    3.833801] omap_i2c 48350000.i2c: bus 3 rev0.11 at 400 kHz
[    3.840087] omap_hsmmc 4809c000.mmc: omap_device: omap_device_enable() called from invalid state 1
[    3.870208] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[    3.877380] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.885742] hub 1-1:1.0: USB hub found
[    3.889831] hub 1-1:1.0: 5 ports detected
[    3.900604] omap_hsmmc 480d5000.mmc: omap_device: omap_device_enable() called from invalid state 1
[    4.035125] omap_hsmmc 480d5000.mmc: card claims to support voltages below defined range
[    4.048919] omap-abe-twl6040 sound: twl6040-legacy <-> 40132000.mcpdm mapping ok
[    4.060760] twl_rtc 48070000.i2c:twl@48:rtc: setting system clock to 2016-02-19 09:11:01 UTC (1455873061)
[    4.071014] sr_init: No PMIC hook to init smartreflex
[    4.076599] smartreflex smartreflex.0: omap_sr_probe: SmartReflex driver initialized
[    4.084991] smartreflex smartreflex.1: omap_sr_probe: SmartReflex driver initialized
[    4.093353] smartreflex smartreflex.2: omap_sr_probe: SmartReflex driver initialized
[    4.105468] mmc1: new SDIO card at address 0001
[    4.114013] mmc0: host does not support reading read-only switch, assuming write-enable
[    4.114013] vwl1271: disabling
[    4.120666] VDAC: disabling
[    4.121124] VANA: disabling
[    4.121551] VUSB: disabling
[    4.121765] ALSA device list:
[    4.121765]   #0: PandaBoardES
[    4.141418] Waiting for root device /dev/mmcblk0p2...
[    4.146911] mmc0: new high speed SDHC card at address e624
[    4.153320] mmcblk0: mmc0:e624 SL32G 28.8 GiB
[    4.187683]  mmcblk0: p1 p2 p3 p4
[    4.229980] usb 1-1.1: new high-speed USB device number 3 using ehci-omap
[    4.264984] EXT4-fs (mmcblk0p2): couldn't mount as ext3 due to feature incompatibilities
[    4.274322] EXT4-fs (mmcblk0p2): mounting ext2 file system using the ext4 subsystem
[    4.316009] EXT4-fs (mmcblk0p2): mounted filesystem without journal. Opts: (null)
[    4.324005] VFS: Mounted root (ext2 filesystem) readonly on device 179:2.
[    4.340850] devtmpfs: mounted
[    4.344329] Freeing unused kernel memory: 304K (c08dc000 - c0928000)
[    4.361633] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[    4.368896] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    4.379486] smsc95xx v1.0.4
[    4.467376] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-4a064c00.ehci-1.1, smsc95xx USB 2.0 Ethernet, 6e:35:2b:90:2e:10
[    4.703063] EXT4-fs (mmcblk0p2): warning: mounting unchecked fs, running e2fsck is recommended
[    4.758605] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    4.895751] random: dd urandom read with 31 bits of entropy available
[    8.906768] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[   18.698944] Bluetooth: Core ver 2.21
[   18.703186] NET: Registered protocol family 31
[   18.708099] Bluetooth: HCI device and connection manager initialized
[   18.715240] Bluetooth: HCI socket layer initialized
[   18.720825] Bluetooth: L2CAP socket layer initialized
[   18.726287] Bluetooth: SCO socket layer initialized
[   26.347351] NFSD: the nfsdcld client tracking upcall will be removed in 3.10. Please transition to using nfsdcltrack.
[   26.358642] NFSD: starting 90-second grace period (net c09607c0)
[   48.742340] random: nonblocking pool is initialized
[  146.720031] NFSD: Unable to end grace period: -110
[  179.328674] wlcore: loaded
[  189.669311] wlcore: firmware booted (Rev 6.3.10.0.133)
[  193.170959] wlan0: authenticate with 90:f6:52:81:ee:70
[  193.185272] wlan0: send auth to 90:f6:52:81:ee:70 (try 1/3)
[  193.192993] wlan0: send auth to 90:f6:52:81:ee:70 (try 2/3)
[  193.200256] wlan0: send auth to 90:f6:52:81:ee:70 (try 3/3)
[  193.207519] wlan0: authentication with 90:f6:52:81:ee:70 timed out
[  196.753845] wlan0: authenticate with 90:f6:52:81:ee:70
[  196.767944] wlan0: send auth to 90:f6:52:81:ee:70 (try 1/3)
[  196.775329] wlan0: send auth to 90:f6:52:81:ee:70 (try 2/3)
[  196.782440] wlan0: send auth to 90:f6:52:81:ee:70 (try 3/3)
[  196.789764] wlan0: authentication with 90:f6:52:81:ee:70 timed out
[  200.636230] wlan0: authenticate with 90:f6:52:81:ee:70
[  200.680450] wlan0: send auth to 90:f6:52:81:ee:70 (try 1/3)
[  200.688446] wlan0: authenticated
[  200.711700] wlan0: associate with 90:f6:52:81:ee:70 (try 1/3)
[  200.722381] wlan0: RX AssocResp from 90:f6:52:81:ee:70 (capab=0x431 status=0 aid=1)
[  200.737976] wlan0: associated
[  200.798187] wlcore: Association completed.
[  785.829315] Adding 2097148k swap on /dev/mmcblk0p3.  Priority:-1 extents:1 across:2097148k SS
[197112.778137] INFO: rcu_preempt self-detected stall on CPU
[197112.781707]         0-...: (1 GPs behind) idle=ff5/1/0 softirq=1813827/1813828 fqs=1
[197112.784942] INFO: rcu_preempt detected stalls on CPUs/tasks:
[197112.784942]         0-...: (1 GPs behind) idle=ff5/1/0 softirq=1813827/1813828 fqs=1
[197112.784973]         (detected by 1, t=11981 jiffies, g=613144, c=613143, q=188)
[197112.784973] Task dump for CPU 0:
[197112.784973] swapper/0       R running      0     0      0 0x00000000
[197112.785003] Backtrace:
[197112.785003] Backtrace aborted due to bad frame pointer <c0929f54>
[197112.824920]          (t=11981 jiffies g=613144 c=613143 q=188)
[197112.834930] Task dump for CPU 0:
[197112.834930] swapper/0       R running      0     0      0 0x00000002
[197112.834930] Backtrace:
[197112.834930] [<c0013f80>] (dump_backtrace) from [<c001417c>] (show_stack+0x18/0x1c)
[197112.858886]  r7:c092a518 r6:800c0193 r5:00000000 r4:c092d180
[197112.858886] [<c0014164>] (show_stack) from [<c005ac68>] (sched_show_task+0xbc/0x110)
[197112.870941] [<c005abac>] (sched_show_task) from [<c005d0f8>] (dump_cpu_task+0x40/0x48)
[197112.878906]  r5:c093a080 r4:00000000
[197112.884918] [<c005d0b8>] (dump_cpu_task) from [<c00828c4>] (rcu_dump_cpu_stacks+0x9c/0xdc)
[197112.894500]  r5:c093a080 r4:00000001
[197112.895751] [<c0082828>] (rcu_dump_cpu_stacks) from [<c0086d28>] (rcu_check_callbacks+0x500/0x8e4)
[197112.904937]  r9:c093a080 r8:c092a628 r7:2ee89000 r6:c0926340 r5:c093a080 r4:ef7af340
[197112.904937] [<c0086828>] (rcu_check_callbacks) from [<c0089f58>] (update_process_times+0x40/0x6c)
[197112.904937]  r10:c009b9bc r9:00000001 r8:ef7abc4c r7:0000b346 r6:194762c0 r5:00000000
[197112.934173]  r4:c092d180
[197112.935089] [<c0089f18>] (update_process_times) from [<c009b9b8>] (tick_sched_handle+0x50/0x54)
[197112.944946]  r5:c0929f10 r4:ef7abe40
[197112.944946] [<c009b968>] (tick_sched_handle) from [<c009ba0c>] (tick_sched_timer+0x50/0x94)
[197112.959075] [<c009b9bc>] (tick_sched_timer) from [<c008a99c>] (__hrtimer_run_queues+0x110/0x1a4)
[197112.968475]  r7:00000000 r6:ef7abc40 r5:ef7abe40 r4:ef7abc00
[197112.974578] [<c008a88c>] (__hrtimer_run_queues) from [<c008b030>] (hrtimer_interrupt+0xac/0x1fc)
[197112.978240]  r10:ef7abc78 r9:ef7abc98 r8:ef7abc14 r7:ef7abcb8 r6:ffffffff r5:00000003
[197112.984924]  r4:ef7abc00
[197112.995147] [<c008af84>] (hrtimer_interrupt) from [<c001720c>] (twd_handler+0x38/0x48)
[197112.995147]  r10:c092a4ec r9:fa241100 r8:00000011 r7:ef0287c0 r6:c092a7a8 r5:ef005cc0
[197113.012023]  r4:00000001
[197113.012023] [<c00171d4>] (twd_handler) from [<c007d02c>] (handle_percpu_devid_irq+0x74/0x8c)
[197113.023834]  r5:ef005cc0 r4:ef7b1780
[197113.027099] [<c007cfb8>] (handle_percpu_devid_irq) from [<c0078ab4>] (generic_handle_irq+0x2c/0x3c)
[197113.037384]  r9:fa241100 r8:ef008000 r7:00000001 r6:00000000 r5:00000000 r4:c092341c
[197113.037384] [<c0078a88>] (generic_handle_irq) from [<c0078dac>] (__handle_domain_irq+0x64/0xbc)
[197113.037384] [<c0078d48>] (__handle_domain_irq) from [<c00094d4>] (gic_handle_irq+0x50/0x90)
[197113.059997]  r9:fa241100 r8:fa240100 r7:c0929f10 r6:fa24010c r5:c092a7a8 r4:c0947f48
[197113.059997] [<c0009484>] (gic_handle_irq) from [<c0014cd4>] (__irq_svc+0x54/0x90)
[197113.075073] Exception stack(0xc0929f10 to 0xc0929f58)
[197113.075073] 9f00:                                     00000000 ef7ab390 fe600000 00000000
[197113.094451] 9f20: c0928000 c092a49c c092236c c0929f80 c0967065 c0967065 c092a4ec c0929f6c
[197113.095703] 9f40: c0929f4c c0929f60 c0028a30 c0010ca0 600c0113 ffffffff
[197113.095703]  r9:c0967065 r8:c0967065 r7:c0929f44 r6:ffffffff r5:600c0113 r4:c0010ca0
[197113.095703] [<c0010c78>] (arch_cpu_idle) from [<c006f720>] (default_idle_call+0x28/0x34)
[197113.095703] [<c006f6f8>] (default_idle_call) from [<c006f844>] (cpu_startup_entry+0x118/0x188)
[197113.095703] [<c006f72c>] (cpu_startup_entry) from [<c06b9e68>] (rest_init+0x90/0x94)
[197113.095703]  r7:ffffffff r4:00000002
[197113.095703] [<c06b9dd8>] (rest_init) from [<c08dcd0c>] (start_kernel+0x390/0x39c)
[197113.151000]  r5:c096a000 r4:00000000
[197113.158843] [<c08dc97c>] (start_kernel) from [<8000807c>] (0x8000807c)
$ zcat /proc/config.gz | grep TIME
CONFIG_BUILDTIME_EXTABLE_SORT=y
CONFIG_GENERIC_TIME_VSYSCALL=y
CONFIG_HIGH_RES_TIMERS=y
# CONFIG_IRQ_TIME_ACCOUNTING is not set
CONFIG_TIMERFD=y
CONFIG_HAVE_IRQ_TIME_ACCOUNTING=y
CONFIG_OMAP_32K_TIMER=y
CONFIG_OMAP_DM_TIMER=y
CONFIG_HAVE_ARM_ARCH_TIMER=y
# CONFIG_PARAVIRT_TIME_ACCOUNTING is not set
# CONFIG_NETWORK_PHY_TIMESTAMPING is not set
# CONFIG_NETFILTER_XT_TARGET_IDLETIMER is not set
# CONFIG_NETFILTER_XT_MATCH_TIME is not set
CONFIG_SERIAL_8250_RUNTIME_UARTS=4
# CONFIG_HW_RANDOM_TIMERIOMEM is not set
# Enable PHYLIB and NETWORK_PHY_TIMESTAMPING to see the additional clocks.
CONFIG_SND_TIMER=y
CONFIG_SND_PCM_TIMER=y
CONFIG_SND_HRTIMER=y
CONFIG_SND_SEQ_HRTIMER_DEFAULT=y
CONFIG_LEDS_TRIGGER_TIMER=y
# CONFIG_RTC_DRV_HID_SENSOR_TIME is not set
CONFIG_ARM_ARCH_TIMER=y
CONFIG_ARM_ARCH_TIMER_EVTSTREAM=y
CONFIG_ARM_GLOBAL_TIMER=y
CONFIG_ARM_TIMER_SP804=y
CONFIG_CLKSRC_ARM_GLOBAL_TIMER_SCHED_CLOCK=y
# CONFIG_SH_TIMER_CMT is not set
# CONFIG_SH_TIMER_MTU2 is not set
# CONFIG_SH_TIMER_TMU is not set
# CONFIG_EM_TIMER_STI is not set
# CONFIG_PWM_OMAP_DMTIMER is not set
CONFIG_PRINTK_TIME=y
CONFIG_PANIC_TIMEOUT=0
CONFIG_DEBUG_TIMEKEEPING=y
# CONFIG_TIMER_STATS is not set
CONFIG_RCU_CPU_STALL_TIMEOUT=60
$