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

[Ross Green <rgkernel@gmail.com>]

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

On Wed, Feb 24, 2016 at 7:55 AM, Paul E. McKenney
<paulmck@linux.vnet.ibm.com> wrote:
> On Tue, Feb 23, 2016 at 08:34:11PM +0000, Mathieu Desnoyers wrote:
>> ----- 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.
>
> Some imprecision I could well understand.  21 seconds of imprecision
> on a three-millisecond timeout I am having somewhat more difficulty
> understanding.  ;-)
>
> But I would rather avoid hrtimers for the RCU grace-period kthread
> because a few milliseconds of adjustment for energy-efficiency
> reasons is a very good thing.
>
> Still working on getting decent traces...
>
>                                                         Thanx, Paul
>

G'day all,

Here is another dmesg output for 4.5-rc5 showing another rcu_preempt stall.
This one appeared after only a day of running. CONFIG_DEBUG_TIMING is
turned on, but can't see any output that shows from this.

Again testing as before,

Boot, run a series of small benchmarks, then just let the system be
and idle away.

I notice in the stack trace there is mention of hrtimer_run_queues and
hrtimer_interrupt.

Anyway, leave this for a few more eyes to look at.

Open to any other suggestions of things to test.

Regards,

Ross Green

[-- Attachment #2: dmesg-4.5-rc5 --]
[-- Type: application/octet-stream, Size: 30999 bytes --]

$ uptime
 07:41:55 up 1 day,  6:27,  load average: 0.01, 0.05, 0.10
$ dmesg
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.5.0-rc5-panda (rfg@red.dwarf) (gcc version 5.3.0 (Buildroot 2016.02-git-00183-g1682aee) ) #2 SMP PREEMPT Mon Feb 22 23:28:57 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 c0966300, 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 (6883K kernel code, 252K rwdata, 2156K rodata, 300K 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 - 0xc08dc0d4   (9041 kB)
                     .init : 0xc08dd000 - 0xc0928000   ( 300 kB)
                     .data : 0xc0928000 - 0xc0967300   ( 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.000000] OMAP clocksource: 32k_counter at 32768 Hz
[    0.000854] 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.089965] 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.226806] VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 4
[    0.227294] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.227447] xor: measuring software checksum speed
[    0.319183]    arm4regs  :  1000.000 MB/sec
[    0.419158]    8regs     :   804.000 MB/sec
[    0.519165]    32regs    :   760.800 MB/sec
[    0.519195] xor: using function: arm4regs (1000.000 MB/sec)
[    0.519439] pinctrl core: initialized pinctrl subsystem
[    0.521331] NET: Registered protocol family 16
[    0.522186] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.523864] omap_hwmod: l3_main_3 using broken dt data from ocp
[    0.525390] omap_hwmod: l3_main_2 using broken dt data from ocp
[    0.630828] OMAP GPIO hardware version 0.1
[    0.636108] omap-gpmc 50000000.gpmc: GPMC revision 6.0
[    0.636108] gpmc_mem_init: disabling cs 0 mapped at 0x0-0x1000000
[    0.636657] irq: no irq domain found for /ocp/l4@4a000000/scm@100000/pinmux@40 !
[    0.637023] irq: no irq domain found for /ocp/l4@4a000000/scm@100000/pinmux@40 !
[    0.637420] irq: no irq domain found for /ocp/l4@4a000000/scm@100000/pinmux@40 !
[    0.649230] platform 4b501000.aes: Cannot lookup hwmod 'aes'
[    0.649536] platform 480a5000.des: Cannot lookup hwmod 'des'                                                                       
[    0.655517] hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers.
[    0.655517] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.656158] omap4_sram_init:Unable to get sram pool needed to handle errata I688
[    0.656372] OMAP DMA hardware revision 0.0
[    0.909423] raid6: int32x1  gen()   103 MB/s
[    1.079467] raid6: int32x1  xor()    82 MB/s
[    1.249237] raid6: int32x2  gen()   134 MB/s
[    1.419403] raid6: int32x2  xor()    98 MB/s
[    1.589385] raid6: int32x4  gen()   145 MB/s
[    1.759429] raid6: int32x4  xor()    97 MB/s
[    1.929260] raid6: int32x8  gen()   160 MB/s
[    2.099487] raid6: int32x8  xor()    94 MB/s
[    2.099487] raid6: using algorithm int32x8 gen() 160 MB/s
[    2.099487] raid6: .... xor() 94 MB/s, rmw enabled
[    2.099517] raid6: using intx1 recovery algorithm
[    2.105529] 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.183563] omap-iommu 4a066000.mmu: 4a066000.mmu registered
[    2.183685] omap-iommu 55082000.mmu: 55082000.mmu registered
[    2.185760] SCSI subsystem initialized
[    2.186065] usbcore: registered new interface driver usbfs
[    2.186187] usbcore: registered new interface driver hub
[    2.186340] usbcore: registered new device driver usb
[    2.187286] omap_i2c 48070000.i2c: could not find pctldev for node /ocp/l4@4a000000/scm@100000/pinmux@40/pinmux_i2c1_pins, deferring probe
[    2.187347] omap_i2c 48072000.i2c: could not find pctldev for node /ocp/l4@4a000000/scm@100000/pinmux@40/pinmux_i2c2_pins, deferring probe
[    2.187377] omap_i2c 48060000.i2c: could not find pctldev for node /ocp/l4@4a000000/scm@100000/pinmux@40/pinmux_i2c3_pins, deferring probe
[    2.187408] omap_i2c 48350000.i2c: could not find pctldev for node /ocp/l4@4a000000/scm@100000/pinmux@40/pinmux_i2c4_pins, deferring probe
[    2.187683] Linux video capture interface: v2.00
[    2.188415] Advanced Linux Sound Architecture Driver Initialized.
[    2.189880] clocksource: Switched to clocksource 32k_counter
[    2.204132] NET: Registered protocol family 2
[    2.204803] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    2.204925] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    2.205047] TCP: Hash tables configured (established 8192 bind 8192)
[    2.205139] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    2.205169] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    2.205383] NET: Registered protocol family 1
[    2.205749] RPC: Registered named UNIX socket transport module.
[    2.205780] RPC: Registered udp transport module.
[    2.205780] RPC: Registered tcp transport module.
[    2.205780] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    2.208068] hw perfevents: enabled with armv7_cortex_a9 PMU driver, 7 counters available
[    2.211242] futex hash table entries: 512 (order: 3, 32768 bytes)
[    2.233947] NFS: Registering the id_resolver key type
[    2.233978] Key type id_resolver registered
[    2.234008] Key type id_legacy registered
[    2.234008] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    2.234039] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
[    2.235382] ntfs: driver 2.1.32 [Flags: R/O].
[    2.235687] fuse init (API version 7.24)
[    2.238464] jitterentropy: Initialization failed with host not compliant with requirements: 2
[    2.238555] bounce: pool size: 64 pages
[    2.238555] io scheduler noop registered
[    2.238586] io scheduler deadline registered
[    2.238616] io scheduler cfq registered (default)
[    2.239501] pinctrl-single 4a100040.pinmux: 203 pins at pa fc100040 size 406
[    2.239715] pinctrl-single 4a31e040.pinmux: 28 pins at pa fc31e040 size 56
[    2.242767] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    2.244354] omap_uart 4806a000.serial: no wakeirq for uart0
[    2.244476] 4806a000.serial: ttyO0 at MMIO 0x4806a000 (irq = 226, base_baud = 3000000) is a OMAP UART0
[    2.244995] 4806c000.serial: ttyO1 at MMIO 0x4806c000 (irq = 227, base_baud = 3000000) is a OMAP UART1
[    2.245452] 48020000.serial: ttyO2 at MMIO 0x48020000 (irq = 228, base_baud = 3000000) is a OMAP UART2
[    3.142425] console [ttyO2] enabled
[    3.146545] 4806e000.serial: ttyO3 at MMIO 0x4806e000 (irq = 229, base_baud = 3000000) is a OMAP UART3
[    3.157287] [drm] Initialized drm 1.1.0 20060810
[    3.163757] 58000000.dss supply vdda_video not found, using dummy regulator
[    3.171142] OMAP DSS rev 4.0
[    3.174316] omapdss_dss 58000000.dss: bound 58001000.dispc (ops dispc_component_ops)
[    3.182647] omapdss_dss 58000000.dss: bound 58005000.encoder (ops dsi_component_ops)
[    3.191192] omapdss_dss 58000000.dss: bound 58006000.encoder (ops hdmi4_component_ops)
[    3.243072] loop: module loaded
[    3.249145] usbcore: registered new interface driver smsc95xx
[    3.255279] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    3.262115] ehci-omap: OMAP-EHCI Host Controller driver
[    3.279907] ehci-omap 4a064c00.ehci: EHCI Host Controller
[    3.285614] ehci-omap 4a064c00.ehci: new USB bus registered, assigned bus number 1
[    3.293670] ehci-omap 4a064c00.ehci: irq 336, io mem 0x4a064c00
[    3.319885] ehci-omap 4a064c00.ehci: USB 2.0 started, EHCI 1.00
[    3.326263] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    3.333374] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    3.340942] usb usb1: Product: EHCI Host Controller
[    3.346069] usb usb1: Manufacturer: Linux 4.5.0-rc5-panda ehci_hcd
[    3.352539] usb usb1: SerialNumber: 4a064c00.ehci
[    3.358123] hub 1-0:1.0: USB hub found
[    3.362091] hub 1-0:1.0: 3 ports detected
[    3.367004] usbcore: registered new interface driver cdc_wdm
[    3.373077] usbcore: registered new interface driver usb-storage
[    3.379791] i2c /dev entries driver
[    3.383605] usbcore: registered new interface driver uvcvideo
[    3.389617] USB Video Class driver (1.1.1)
[    3.395111] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec
[    3.402679] device-mapper: uevent: version 1.0.3
[    3.407836] device-mapper: ioctl: 4.34.0-ioctl (2015-10-28) initialised: dm-devel@redhat.com
[    3.480865] hidraw: raw HID events driver (C) Jiri Kosina
[    3.486755] usbcore: registered new interface driver usbhid
[    3.492584] usbhid: USB HID core driver
[    3.497100] emif 4c000000.emif: emif_probe: device configured with addr = f08a8000 and IRQ247
[    3.506408] emif 4d000000.emif: emif_probe: device configured with addr = f08aa000 and IRQ248
[    3.517333] omap-abe-twl6040 sound: ASoC: CODEC DAI twl6040-legacy not registered
[    3.525299] omap-abe-twl6040 sound: snd_soc_register_card() failed: -517                                                           
[    3.532775] ip_tables: (C) 2000-2006 Netfilter Core Team
[    3.538482] Initializing XFRM netlink socket
[    3.543029] NET: Registered protocol family 17
[    3.547973] Key type dns_resolver registered
[    3.552673] twl: not initialized
[    3.556091] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1375000 Vs max 1316660
[    3.564697] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1375000 Vs max 1316660
[    3.573211] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1375000 Vs max 1316660
[    3.581695] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1375000 Vs max 1316660
[    3.590179] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1375000 Vs max 1316660
[    3.598663] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1375000 Vs max 1316660
[    3.607147] twl6030_uv_to_vsel:OUT OF RANGE! non mapped vsel for 1410000 Vs max 1316660
[    3.615661] omap2_set_init_voltage: unable to find boot up OPP for vdd_mpu
[    3.623199] omap2_set_init_voltage: unable to set vdd_mpu
[    3.628936] omap2_set_init_voltage: unable to find boot up OPP for vdd_core
[    3.636322] omap2_set_init_voltage: unable to set vdd_core
[    3.642150] omap2_set_init_voltage: unable to find boot up OPP for vdd_iva
[    3.649414] omap2_set_init_voltage: unable to set vdd_iva
[    3.656066] Power Management for TI OMAP4+ devices.
[    3.661254] OMAP4 PM: u-boot >= v2012.07 is required for full PM support
[    3.668487] ThumbEE CPU extension supported.
[    3.673034] Registering SWP/SWPB emulation handler
[    3.673065] SmartReflex Class3 initialized
[    3.682525] usb 1-1: new high-speed USB device number 2 using ehci-omap
[    3.707427] Btrfs loaded
[    3.712707] dmm 4e000000.dmm: initialized all PAT entries
[    3.730163] Skipping twl internal clock init and using bootloader value (unknown osc rate)
[    3.760406] twl 0-0048: PIH (irq 340) nested IRQs
[    3.766815] twl_rtc 48070000.i2c:twl@48:rtc: Enabling TWL-RTC
[    3.775482] twl_rtc 48070000.i2c:twl@48:rtc: rtc core: registered 48070000.i2c:twl@48 as rtc0
[    3.797241] twl6040 0-004b: clk32k is not handled
[    3.804412] omap_i2c 48070000.i2c: bus 0 rev0.11 at 400 kHz
[    3.811981] omap_i2c 48072000.i2c: bus 1 rev0.11 at 400 kHz
[    3.819000] omap_i2c 48060000.i2c: bus 2 rev0.11 at 100 kHz
[    3.825622] omap_i2c 48350000.i2c: bus 3 rev0.11 at 400 kHz
[    3.832000] omap_hsmmc 4809c000.mmc: omap_device: omap_device_enable() called from invalid state 1
[    3.850494] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[    3.857666] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.865997] hub 1-1:1.0: USB hub found
[    3.870147] hub 1-1:1.0: 5 ports detected
[    3.885772] omap_hsmmc 480d5000.mmc: omap_device: omap_device_enable() called from invalid state 1
[    4.026062] omap_hsmmc 480d5000.mmc: card claims to support voltages below defined range
[    4.041259] omap-abe-twl6040 sound: twl6040-legacy <-> 40132000.mcpdm mapping ok
[    4.053192] twl_rtc 48070000.i2c:twl@48:rtc: setting system clock to 2016-02-22 14:14:55 UTC (1456150495)
[    4.063568] sr_init: No PMIC hook to init smartreflex
[    4.069244] smartreflex smartreflex.0: omap_sr_probe: SmartReflex driver initialized
[    4.077728] mmc1: new SDIO card at address 0001
[    4.077728] smartreflex smartreflex.1: omap_sr_probe: SmartReflex driver initialized
[    4.077941] smartreflex smartreflex.2: omap_sr_probe: SmartReflex driver initialized
[    4.088684] VDAC: disabling
[    4.089141] VANA: disabling
[    4.089599] VUSB: disabling
[    4.089965] ALSA device list:
[    4.089965]   #0: PandaBoardES
[    4.114654] Waiting for root device /dev/mmcblk0p2...
[    4.129089] mmc0: host does not support reading read-only switch, assuming write-enable
[    4.140960] mmc0: new high speed SDHC card at address e624
[    4.161804] mmcblk0: mmc0:e624 SL32G 28.8 GiB 
[    4.179931] usb 1-1.1: new high-speed USB device number 3 using ehci-omap
[    4.196685]  mmcblk0: p1 p2 p3 p4
[    4.241821] EXT4-fs (mmcblk0p2): couldn't mount as ext3 due to feature incompatibilities
[    4.251098] EXT4-fs (mmcblk0p2): mounting ext2 file system using the ext4 subsystem
[    4.281799] EXT4-fs (mmcblk0p2): mounted filesystem without journal. Opts: (null)
[    4.283599] VFS: Mounted root (ext2 filesystem) readonly on device 179:2.
[    4.304168] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[    4.311523] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    4.322143] smsc95xx v1.0.4
[    4.325714] devtmpfs: mounted
[    4.328979] Freeing unused kernel memory: 300K (c08dd000 - c0928000)
[    4.410034] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-4a064c00.ehci-1.1, smsc95xx USB 2.0 Ethernet, c2:03:46:11:42:fc
[    4.672088] EXT4-fs (mmcblk0p2): warning: mounting unchecked fs, running e2fsck is recommended
[    4.720947] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    4.859893] random: dd urandom read with 31 bits of entropy available
[    9.680908] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[   19.578399] Bluetooth: Core ver 2.21
[   19.582489] NET: Registered protocol family 31
[   19.587188] Bluetooth: HCI device and connection manager initialized
[   19.594635] Bluetooth: HCI socket layer initialized
[   19.599731] Bluetooth: L2CAP socket layer initialized
[   19.605316] Bluetooth: SCO socket layer initialized
[   27.174468] NFSD: the nfsdcld client tracking upcall will be removed in 3.10. Please transition to using nfsdcltrack.
[   27.185882] NFSD: starting 90-second grace period (net c0960800)
[   30.303527] random: nonblocking pool is initialized
[   56.984252] wlcore: loaded
[   65.072265] wlcore: firmware booted (Rev 6.3.10.0.133)
[   65.807983] wlcore: ERROR ELP wakeup timeout!
[   65.812622] ------------[ cut here ]------------
[   65.817535] WARNING: CPU: 1 PID: 1116 at drivers/net/wireless/ti/wlcore/main.c:787 wl1271_op_cancel_hw_scan+0x838/0x83c [wlcore]()
[   65.830047] Modules linked in: btwilink st_drv wl12xx wlcore_sdio wlcore mac80211 cfg80211 bluetooth
[   65.830047] CPU: 1 PID: 1116 Comm: wpa_supplicant Not tainted 4.5.0-rc5-panda #2
[   65.839874] Hardware name: Generic OMAP4 (Flattened Device Tree)
[   65.853942] Backtrace: 
[   65.853942] [<c0013f80>] (dump_backtrace) from [<c001417c>] (show_stack+0x18/0x1c)
[   65.864562]  r7:bf0e6bf4 r6:60030113 r5:c0947d74 r4:00000000
[   65.869873] [<c0014164>] (show_stack) from [<c03a2364>] (dump_stack+0x94/0xa8)
[   65.878265] [<c03a22d0>] (dump_stack) from [<c0034c98>] (warn_slowpath_common+0x88/0xb8)
[   65.886810]  r7:bf0e6bf4 r6:00000313 r5:00000009 r4:00000000
[   65.890624] [<c0034c10>] (warn_slowpath_common) from [<c0034d6c>] (warn_slowpath_null+0x24/0x2c)
[   65.899871]  r8:bf103540 r7:ee9a8d94 r6:00000000 r5:c092a100 r4:ee9a8d40
[   65.899871] [<c0034d48>] (warn_slowpath_null) from [<bf0e6bf4>] (wl1271_op_cancel_hw_scan+0x838/0x83c [wlcore])
[   65.919952] [<bf0e6b94>] (wl1271_op_cancel_hw_scan [wlcore]) from [<bf0e8e98>] (wl12xx_queue_recovery_work+0x1c/0x20 [wlcore])
[   65.929870]  r5:c092a100 r4:ee9a8d40
[   65.929870] [<bf0e8e7c>] (wl12xx_queue_recovery_work [wlcore]) from [<bf0f26d4>] (wl1271_ps_elp_wakeup+0x200/0x208 [wlcore])
[   65.947723] [<bf0f24d4>] (wl1271_ps_elp_wakeup [wlcore]) from [<bf0e4114>] (wl1271_op_hw_scan+0x68/0xe0 [wlcore])
[   65.951965]  r10:ef0034f8 r9:ee9a83e0 r8:00000000 r7:ef355e00 r6:ee9a8d7c r5:00000000
[   65.959869]  r4:ee9a8d40
[   65.959869] [<bf0e40ac>] (wl1271_op_hw_scan [wlcore]) from [<bf0938a0>] (ieee80211_sched_scan_stopped+0x294/0x4dc [mac80211])
[   65.959869]  r10:00000000 r9:ee9ffcf0 r8:00000000 r7:ee9a8ab0 r6:ef003400 r5:eebeb4c0
[   65.989868]  r4:ee9a83e0
[   65.989868] [<bf0936a0>] (ieee80211_sched_scan_stopped [mac80211]) from [<bf09456c>] (ieee80211_request_scan+0x30/0x48 [mac80211])
[   65.999877]  r9:ee9ffcf0 r8:00000112 r7:ee9a8000 r6:ef003400 r5:0000064c r4:eebeb4c0
[   66.009857] [<bf09453c>] (ieee80211_request_scan [mac80211]) from [<bf0a3184>] (ieee80211_scan+0x8c/0xc8 [mac80211])
[   66.024505]  r7:ee9a8000 r6:ef003400 r5:00000000 r4:eebeb4c0
[   66.030609] [<bf0a30f8>] (ieee80211_scan [mac80211]) from [<bf072770>] (nl80211_trigger_scan+0x600/0x65c [cfg80211])
[   66.039855]  r5:00000000 r4:ee863924
[   66.039855] [<bf072170>] (nl80211_trigger_scan [cfg80211]) from [<c06141e4>] (genl_rcv_msg+0x264/0x400)
[   66.055511]  r10:edc58400 r9:c0960800 r8:00000000 r7:ef377a80 r6:ee863914 r5:bf07a158
[   66.055511]  r4:bf07ba48
[   66.064208] [<c0613f80>] (genl_rcv_msg) from [<c0613430>] (netlink_rcv_skb+0xa8/0xc4)
[   66.068542]  r10:ef377a80 r9:00000000 r8:00000000 r7:ef377a80 r6:ef377a80 r5:c0613f80
[   66.083099]  r4:ee863900
[   66.083099] [<c0613388>] (netlink_rcv_skb) from [<c0613f70>] (genl_rcv+0x2c/0x3c)
[   66.089874]  r7:ef377a80 r6:00000024 r5:ef377a80 r4:c09620a4
[   66.093719] [<c0613f44>] (genl_rcv) from [<c0612d48>] (netlink_unicast+0x170/0x258)
[   66.093719]  r5:ee86b800 r4:ef153800
[   66.111633] [<c0612bd8>] (netlink_unicast) from [<c06131f8>] (netlink_sendmsg+0x2f8/0x360)
[   66.120361]  r8:00000000 r7:00000024 r6:ee86b800 r5:00000000 r4:ee9fff4c
[   66.120361] [<c0612f00>] (netlink_sendmsg) from [<c05d43c0>] (sock_sendmsg+0x1c/0x2c)
[   66.135772]  r10:00000000 r9:ee9ffe28 r8:00000000 r7:eed4dc80 r6:00000000 r5:00000000
[   66.135772]  r4:ee9fff4c
[   66.135772] [<c05d43a4>] (sock_sendmsg) from [<c05d4a60>] (___sys_sendmsg+0x1f4/0x1fc)
[   66.152099] [<c05d486c>] (___sys_sendmsg) from [<c05d5824>] (__sys_sendmsg+0x44/0x70)
[   66.152099]  r10:00000000 r9:ee9fe000 r8:c000fce8 r7:00000128 r6:eed4dc80 r5:00000000
[   66.171752]  r4:bed4aa34
[   66.174438] [<c05d57e0>] (__sys_sendmsg) from [<c05d5860>] (SyS_sendmsg+0x10/0x14)
[   66.180175]  r6:0008d9d8 r5:0008e188 r4:0008da50
[   66.180175] [<c05d5850>] (SyS_sendmsg) from [<c000fae0>] (ret_fast_syscall+0x0/0x3c)
[   66.195648] ---[ end trace 0a879fbe88a91723 ]---
[   66.200653] wlcore: Hardware recovery in progress. FW ver: Rev 6.3.10.0.133
[   66.200653] ------------[ cut here ]------------
[   66.217193] WARNING: CPU: 1 PID: 17 at drivers/net/wireless/ti/wlcore/io.h:64 wlcore_set_partition+0xa8/0x450 [wlcore]()
[   66.228729] Modules linked in: btwilink st_drv wl12xx wlcore_sdio wlcore mac80211 cfg80211 bluetooth
[   66.231811] CPU: 1 PID: 17 Comm: kworker/u4:1 Tainted: G        W       4.5.0-rc5-panda #2
[   66.246429] Hardware name: Generic OMAP4 (Flattened Device Tree)
[   66.246429] Workqueue: phy0 wl1271_recovery_work [wlcore]
[   66.253631] Backtrace: 
[   66.259918] [<c0013f80>] (dump_backtrace) from [<c001417c>] (show_stack+0x18/0x1c)
[   66.269958]  r7:bf0ee8b0 r6:600c0113 r5:c0947d74 r4:00000000
[   66.269958] [<c0014164>] (show_stack) from [<c03a2364>] (dump_stack+0x94/0xa8)
[   66.269958] [<c03a22d0>] (dump_stack) from [<c0034c98>] (warn_slowpath_common+0x88/0xb8)
[   66.269958]  r7:bf0ee8b0 r6:00000040 r5:00000009 r4:00000000
[   66.296539] [<c0034c10>] (warn_slowpath_common) from [<c0034d6c>] (warn_slowpath_null+0x24/0x2c)
[   66.296539]  r8:ee9a8d7c r7:ee878200 r6:fffffffb r5:bf1212cc r4:ee9a8d40
[   66.296539] [<c0034d48>] (warn_slowpath_null) from [<bf0ee8b0>] (wlcore_set_partition+0xa8/0x450 [wlcore])
[   66.324890] [<bf0ee808>] (wlcore_set_partition [wlcore]) from [<bf0e60fc>] (wl1271_recovery_work+0x74/0x334 [wlcore])
[   66.324890]  r6:ee9a8d40 r5:ef043f80 r4:ee9a8fec
[   66.324890] [<bf0e6088>] (wl1271_recovery_work [wlcore]) from [<c004a6f4>] (process_one_work+0x128/0x400)
[   66.346649]  r8:00000000 r7:ee878200 r6:ef00b000 r5:ef043f80 r4:ee9a8fec
[   66.346649] [<c004a5cc>] (process_one_work) from [<c004aa20>] (worker_thread+0x54/0x58c)
[   66.366851]  r10:ef043f80 r9:ef14a020 r8:ef00b018 r7:c092a100 r6:00000088 r5:ef043f98
[   66.366851]  r4:ef00b000
[   66.366851] [<c004a9cc>] (worker_thread) from [<c005053c>] (kthread+0xe4/0xfc)
[   66.385498]  r10:00000000 r9:00000000 r8:00000000 r7:c004a9cc r6:ef043f80 r5:ef1404c0
[   66.385498]  r4:00000000
[   66.385498] [<c0050458>] (kthread) from [<c000fb98>] (ret_from_fork+0x14/0x3c)
[   66.404144]  r7:00000000 r6:00000000 r5:c0050458 r4:ef1404c0
[   66.410247] ---[ end trace 0a879fbe88a91724 ]---
[   66.411651] wlcore: down
[   66.418945] ieee80211 phy0: Hardware restart was requested
[   66.997100] wlcore: firmware booted (Rev 6.3.10.0.133)
[   70.594848] wlan0: authenticate with 90:f6:52:81:ee:70
[   70.609497] wlan0: send auth to 90:f6:52:81:ee:70 (try 1/3)
[   70.616821] wlan0: send auth to 90:f6:52:81:ee:70 (try 2/3)
[   70.623901] wlan0: send auth to 90:f6:52:81:ee:70 (try 3/3)
[   70.631286] wlan0: authentication with 90:f6:52:81:ee:70 timed out
[   74.182769] wlan0: authenticate with 90:f6:52:81:ee:70
[   74.196655] wlan0: send auth to 90:f6:52:81:ee:70 (try 1/3)
[   74.203765] wlan0: send auth to 90:f6:52:81:ee:70 (try 2/3)
[   74.210845] wlan0: send auth to 90:f6:52:81:ee:70 (try 3/3)
[   74.217895] wlan0: authentication with 90:f6:52:81:ee:70 timed out
[   78.127929] wlan0: authenticate with 90:f6:52:81:ee:70
[   78.180389] wlan0: send auth to 90:f6:52:81:ee:70 (try 1/3)
[   78.188415] wlan0: authenticated
[   78.204956] wlan0: associate with 90:f6:52:81:ee:70 (try 1/3)
[   78.215667] wlan0: RX AssocResp from 90:f6:52:81:ee:70 (capab=0x431 status=0 aid=1)
[   78.230895] wlan0: associated
[   78.291473] wlcore: Association completed.
[  147.359924] NFSD: Unable to end grace period: -110
[  251.135437] Adding 2097148k swap on /dev/mmcblk0p3.  Priority:-1 extents:1 across:2097148k SS
[91494.584503] INFO: rcu_preempt detected stalls on CPUs/tasks:
[91494.587402]  (detected by 1, t=7368 jiffies, g=283842, c=283841, q=103)
[91494.597412] All QSes seen, last rcu_preempt kthread activity 7367 (9119441-9112074), jiffies_till_next_fqs=1, root ->qsmask 0x0
[91494.609649] swapper/1       R running      0     0      1 0x00000000
[91494.616394] Backtrace: 
[91494.618408] [<c0013f80>] (dump_backtrace) from [<c001417c>] (show_stack+0x18/0x1c)
[91494.619018]  r7:2ee94000 r6:c0927340 r5:00000001 r4:ef077480
[91494.619018] [<c0014164>] (show_stack) from [<c005ac70>] (sched_show_task+0xbc/0x110)
[91494.638977] [<c005abb4>] (sched_show_task) from [<c0087100>] (rcu_check_callbacks+0x8d0/0x8e4)
[91494.641265]  r5:c093a080 r4:ef7bb340
[91494.653533] [<c0086830>] (rcu_check_callbacks) from [<c0089f60>] (update_process_times+0x40/0x6c)
[91494.659667]  r10:c009b9c4 r9:00000001 r8:ef7b7c4c r7:00005336 r6:b43a3541 r5:00000000
[91494.671874]  r4:ef077480
[91494.671874] [<c0089f20>] (update_process_times) from [<c009b9c0>] (tick_sched_handle+0x50/0x54)
[91494.678985]  r5:ef09ff58 r4:ef7b7e40
[91494.687561] [<c009b970>] (tick_sched_handle) from [<c009ba14>] (tick_sched_timer+0x50/0x94)
[91494.696411] [<c009b9c4>] (tick_sched_timer) from [<c008a9a4>] (__hrtimer_run_queues+0x110/0x1a4)
[91494.700347]  r7:00000000 r6:ef7b7c40 r5:ef7b7e40 r4:ef7b7c00
[91494.708374] [<c008a894>] (__hrtimer_run_queues) from [<c008b038>] (hrtimer_interrupt+0xac/0x1fc)
[91494.717407]  r10:ef7b7c78 r9:ef7b7c98 r8:ef7b7c14 r7:ef7b7cb8 r6:ffffffff r5:00000003
[91494.727416]  r4:ef7b7c00
[91494.732025] [<c008af8c>] (hrtimer_interrupt) from [<c001720c>] (twd_handler+0x38/0x48)
[91494.732025]  r10:c092a4ec r9:fa241100 r8:00000011 r7:ef0287c0 r6:c092a7a8 r5:ef005cc0
[91494.748199]  r4:00000001
[91494.751403] [<c00171d4>] (twd_handler) from [<c007d034>] (handle_percpu_devid_irq+0x74/0x8c)
[91494.757415]  r5:ef005cc0 r4:ef7bd780
[91494.764129] [<c007cfc0>] (handle_percpu_devid_irq) from [<c0078abc>] (generic_handle_irq+0x2c/0x3c)
[91494.767395]  r9:fa241100 r8:ef008000 r7:00000001 r6:00000000 r5:00000000 r4:c092441c
[91494.781097] [<c0078a90>] (generic_handle_irq) from [<c0078db4>] (__handle_domain_irq+0x64/0xbc)
[91494.791137] [<c0078d50>] (__handle_domain_irq) from [<c00094d4>] (gic_handle_irq+0x50/0x90)
[91494.791137]  r9:fa241100 r8:fa240100 r7:ef09ff58 r6:fa24010c r5:c092a7a8 r4:c0947f88
[91494.808197] [<c0009484>] (gic_handle_irq) from [<c0014cd4>] (__irq_svc+0x54/0x90)
[91494.814727] Exception stack(0xef09ff58 to 0xef09ffa0)
[91494.818664] ff40:                                                       00000000 ef7b7390
[91494.818664] ff60: fe600000 00000000 ef09e000 c092a49c c092336c ef09ffc8 c09670a5 c09670a5
[91494.837402] ff80: c092a4ec ef09ffb4 ef09ff94 ef09ffa8 c0028a30 c0010ca0 60010113 ffffffff
[91494.837402]  r9:c09670a5 r8:c09670a5 r7:ef09ff8c r6:ffffffff r5:60010113 r4:c0010ca0
[91494.837402] [<c0010c78>] (arch_cpu_idle) from [<c006f728>] (default_idle_call+0x28/0x34)
[91494.857452] [<c006f700>] (default_idle_call) from [<c006f84c>] (cpu_startup_entry+0x118/0x188)
[91494.873352] [<c006f734>] (cpu_startup_entry) from [<c001627c>] (secondary_start_kernel+0x178/0x184)
[91494.877410]  r7:c096a288 r4:c093d140
[91494.882934] [<c0016104>] (secondary_start_kernel) from [<800095ac>] (0x800095ac)
[91494.882934]  r5:00000051 r4:af08406a
[91494.898345] rcu_preempt kthread starved for 7367 jiffies! g283842 c283841 f0x2 RCU_GP_WAIT_FQS(3) ->state=0x100
[91494.900360] rcu_preempt     W c06bab48     0     7      2 0x00000000
[91494.914428] Backtrace: 
[91494.914428] [<c06ba97c>] (__schedule) from [<c06baed8>] (schedule+0x54/0xc4)
[91494.921508]  r10:c092a518 r9:00000001 r8:008b0a0b r7:c092a100 r6:ef097ed4 r5:ef7b73c0
[91494.934112]  r4:ef096000
[91494.934112] [<c06bae84>] (schedule) from [<c06bdcd8>] (schedule_timeout+0x118/0x1ac)
[91494.945007]  r5:ef7b73c0 r4:ef7b73c0
[91494.945007] [<c06bdbc0>] (schedule_timeout) from [<c00860f4>] (rcu_gp_kthread+0x64c/0x99c)
[91494.957397]  r8:c092a100 r7:c093a210 r6:c093a21c r5:c093a080 r4:00000000
[91494.957397] [<c0085aa8>] (rcu_gp_kthread) from [<c005053c>] (kthread+0xe4/0xfc)
[91494.972412]  r7:c0085aa8
[91494.972412] [<c0050458>] (kthread) from [<c000fb98>] (ret_from_fork+0x14/0x3c)
[91494.982391]  r7:00000000 r6:00000000 r5:c0050458 r4:ef0407c0
$ zcat /proc/config.gz | fgrep CONFIG_DEBUG_TIM
CONFIG_DEBUG_TIMEKEEPING=y
$ 
$ 
$ 
$ cat /proc/version 
Linux version 4.5.0-rc5-panda (rfg@red.dwarf) (gcc version 5.3.0 (Buildroot 2016.02-git-00183-g1682aee) ) #2 SMP PREEMPT Mon Feb 22 23:28:57 AEDT 2016
$