Hi Tony, we have observed that the OMAP5 isn't properly rebooting. I.e. if we boot and then type "reboot", everything works fine until:
## Booting kernel from Legacy Image at 82000000 ... Image Name: Linux-4.18.6-letux-lpae+ Image Type: ARM Linux Kernel Image (uncompressed) Data Size: 4863832 Bytes = 4.6 MiB Load Address: 80008000 Entry Point: 80008000 Verifying Checksum ... OK ## Flattened Device Tree blob at 88000000 Booting using the fdt blob at 0x88000000 Loading Kernel Image ... OK Loading Device Tree to 8ffee000, end 8ffff88e ... OK
Starting kernel ...
Then the kernel hangs.
On some boards we can then boot with activating the RESET but on some others we have to (force) poweroff and power on again until the kernel starts. So I think either some PLL or some SMPS or LDO is stuck or not initialized the same with power-on or by reboot.
But it does not seem to be a Palmas issue since I have added i2cdump to report all Palmas registers in U-Boot and there is no (significant) difference between poweroff+on and reboot. So I have not found a bit that can be used to predict if the kernel will boot or not.
Next I have digged out an old technique I had used once for OMAP3 to read out the kernel log *before* the UARTs were initialized:
https://www.denx.de/wiki/DULG/LinuxPostMortemAnalysis
but it seems to no longer work. The log buffer isn't at a fixed address any more. I hacked a logbuf scanner into U-Boot and it reports randomly changing addresses where it finds logbuf entries but they appear to be incomplete.
Then I remembered printascii() which is no longer available.
So what is the canonical way to debug such issues with modern kernels? Is it possible to get something like printascii()? Or make the kernel log go to a fixed address? Or should I hack printk() to write a copy to a private buffer at a static address?
BR and thanks, Nikolaus
* H. Nikolaus Schaller hns@goldelico.com [180909 08:46]:
So what is the canonical way to debug such issues with modern kernels? Is it possible to get something like printascii()? Or make the kernel log go to a fixed address? Or should I hack printk() to write a copy to a private buffer at a static address?
First try adding debug earlycon to your kernel command line. This assumes you have stdout-path in the dts file, see patch "ARM: dts: Add chosen for earlycon UART" I sent for pyra last year at some point.
If that does not get you output early enough, there's the DEBUG_LL option but that's rarely needed nowadays.
And then there's the pstore console support which is really nice as you have the buffer available after a warm reset on watchdog reboot etc. But sounds like that may not help here if you're having trouble with reboot :)
Regards,
Tony
Hi Tony,
Am 10.09.2018 um 19:09 schrieb Tony Lindgren tony@atomide.com:
- H. Nikolaus Schaller hns@goldelico.com [180909 08:46]:
So what is the canonical way to debug such issues with modern kernels? Is it possible to get something like printascii()? Or make the kernel log go to a fixed address? Or should I hack printk() to write a copy to a private buffer at a static address?
First try adding debug earlycon to your kernel command line. This assumes you have stdout-path in the dts file, see patch "ARM: dts: Add chosen for earlycon UART" I sent for pyra last year at some point.
Ah, yes. This was missing in my testing tree.
If that does not get you output early enough, there's the DEBUG_LL option but that's rarely needed nowadays.
And then there's the pstore console support which is really nice as you have the buffer available after a warm reset on watchdog reboot etc. But sounds like that may not help here if you're having trouble with reboot :)
Indeed.
Now, I get something for further analysis, which indicates how the kernel is stumbling...
root@letux:~# dmesg|fgrep early [ 0.000000] Malformed early option 'console' [ 0.000000] earlycon: omapserial0 at MMIO 0x48020000 (options '')
^^^ ok, earlycon is working :)
[ 0.000000] Kernel command line: console= root=PARTUUID=7d45bc20-02 rw rootfstype=ext4 rootwait console=ttyO2,115200n8 vram=12M omapfb.vram=0:8M,1:4M omapfb.rotate_type=0 omapdss.def_disp=lcd rootwait twl4030_charger.allow_usb=1 log_buf_len=8M ignore_loglevel earlyprintk earlycon [ 0.000000] early log buf free: 63696(97%) root@letux:~# reboot
Broadcast message from root@letux (console) (Mon Sep 10 20:05:16 2018):
The system is going down for reboot NOW!
....
[ 164.453708] reboot: Restarting system
U-Boot SPL 2016.11-00292-g12720df (Aug 12 2018 - 18:32:51) OMAP5432-GP ES2.0
....
## Booting kernel from Legacy Image at 82000000 ... Image Name: Linux-4.18.0-letux+ Image Type: ARM Linux Kernel Image (uncompressed) Data Size: 4901632 Bytes = 4.7 MiB Load Address: 80008000 Entry Point: 80008000 Verifying Checksum ... OK ## Flattened Device Tree blob at 88000000 Booting using the fdt blob at 0x88000000 Loading Kernel Image ... OK Loading Device Tree to 8ffed000, end 8fffff57 ... OK
Starting kernel ...
[ 0.000000] Booting Linux on physical CPU 0x0 [ 0.000000] Linux version 4.18.0-letux+ (hns@iMac.fritz.box) (gcc version 4.9.2 (GCC)) #2664 SMP PREEMPT Mon Sep 10 20:46:49 CEST 2018 [ 0.000000] CPU: ARMv7 Processor [412fc0f2] revision 2 (ARMv7), cr=10c5387d [ 0.000000] CPU: div instructions available: patching division code [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache [ 0.000000] OF: fdt: Machine model: Pyra-Handheld-V5.1.2ff [ 0.000000] Malformed early option 'console' [ 0.000000] debug: ignoring loglevel setting. [ 0.000000] earlycon: omapserial0 at MMIO 0x48020000 (options '') [ 0.000000] bootconsole [omapserial0] enabled [ 0.000000] Memory policy: Data cache writealloc [ 0.000000] cma: Reserved 16 MiB at 0xfd800000 [ 0.000000] OMAP4: Map 0xfee00000 to (ptrval) for dram barrier [ 0.000000] On node 0 totalpages: 519680 [ 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: 323072 pages, LIFO batch:31 [ 0.000000] OMAP5432 ES2.0 [ 0.000000] random: get_random_bytes called from start_kernel+0x80/0x470 with crng_init=0 [ 0.000000] percpu: Embedded 17 pages/cpu @(ptrval) s40320 r8192 d21120 u69632 [ 0.000000] pcpu-alloc: s40320 r8192 d21120 u69632 alloc=17*4096 [ 0.000000] pcpu-alloc: [0] 0 [0] 1 [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 518144 [ 0.000000] Kernel command line: console= root=PARTUUID=7d45bc20-02 rw rootfstype=ext4 rootwait console=ttyO2,115200n8 vram=12M omapfb.vram=0:8M,1:4M omapfb.rotate_type=0 omapdss.def_disp=lcd rootwait twl4030_charger.allow_usb=1 log_buf_len=8M ignore_loglevel earlyprintk earlycon [ 0.000000] log_buf_len: 8388608 bytes [ 0.000000] early log buf free: 63696(97%) [ 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: 2025568K/2078720K available (6823K kernel code, 653K rwdata, 1824K rodata, 1024K init, 221K bss, 36768K reserved, 16384K cma-reserved, 1275904K highmem) [ 0.000000] Virtual kernel memory layout: [ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB) [ 0.000000] fixmap : 0xffc00000 - 0xfff00000 (3072 kB) [ 0.000000] vmalloc : 0xf0800000 - 0xff800000 ( 240 MB) [ 0.000000] lowmem : 0xc0000000 - 0xf0000000 ( 768 MB) [ 0.000000] pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB) [ 0.000000] modules : 0xbf000000 - 0xbfe00000 ( 14 MB) [ 0.000000] .text : 0x(ptrval) - 0x(ptrval) (7816 kB) [ 0.000000] .init : 0x(ptrval) - 0x(ptrval) (1024 kB) [ 0.000000] .data : 0x(ptrval) - 0x(ptrval) ( 654 kB) [ 0.000000] .bss : 0x(ptrval) - 0x(ptrval) ( 222 kB) [ 0.000000] Preemptible hierarchical RCU implementation. [ 0.000000] RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=2. [ 0.000000] Tasks RCU enabled. [ 0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2 [ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16 [ 0.000000] GIC: Using split EOI/Deactivate mode [ 0.000000] clock: dpll_abe_ck failed transition to 'locked' [ 0.000000] OMAP clockevent source: timer1 at 32768 Hz [ 0.000000] arch_timer: cp15 timer(s) running at 6.14MHz (phys). [ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x16ac02862, max_idle_ns: 440795202218 ns [ 0.000005] sched_clock: 56 bits at 6MHz, resolution 162ns, wraps every 4398046511085ns [ 0.008218] Switching to timer-based delay loop, resolution 162ns [ 0.015171] clocksource: 32k_counter: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 58327039986419 ns [ 0.025273] OMAP clocksource: 32k_counter at 32768 Hz [ 0.031722] Console: colour dummy device 80x30 [ 0.036209] Calibrating delay loop (skipped), value calculated using timer frequency.. 12.28 BogoMIPS (lpj=61440) [ 0.046753] pid_max: default: 32768 minimum: 301 [ 0.051557] Security Framework initialized [ 0.055723] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.062482] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.070125] CPU: Testing write buffer coherency: ok [ 0.075087] CPU0: Spectre v2: firmware did not set auxiliary control register IBE bit, system vulnerable [ 0.084971] /cpus/cpu@0 missing clock-frequency property [ 0.090363] /cpus/cpu@1 missing clock-frequency property [ 0.095794] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 [ 0.101610] smp: CPU1 parked within kernel, needs reset (0x0 0x801248a0) [ 0.161732] Setting up static identity map for 0x80100000 - 0x80100060 [ 0.168443] Hierarchical SRCU implementation. [ 0.212907] smp: Bringing up secondary CPUs ... [ 0.273213] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 [ 0.273219] CPU1: Spectre v2: using ICIALLU workaround [ 0.284313] smp: Brought up 1 node, 2 CPUs [ 0.288434] SMP: Total of 2 processors activated (24.57 BogoMIPS). [ 0.294807] CPU: All CPU(s) started in HYP mode. [ 0.299509] CPU: Virtualization extensions available. [ 0.305759] devtmpfs: initialized [ 0.319718] VFP support v0.3: implementor 41 architecture 4 part 30 variant f rev 0 [ 0.327882] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns [ 0.337934] futex hash table entries: 512 (order: 3, 32768 bytes) [ 0.344594] pinctrl core: initialized pinctrl subsystem [ 0.350243] really_probe: driver reg-dummy for reg-dummy bus platform [ 0.357023] really_probe: driver reg-dummy for reg-dummy bus platform ok (1) [ 0.364644] NET: Registered protocol family 16 [ 0.370796] DMA: preallocated 256 KiB pool for atomic coherent allocations [ 0.378566] omap_hwmod: l3_main_3 using broken dt data from ocp [ 0.385175] omap_hwmod: l3_main_2 using broken dt data from ocp [ 1.723766] clock: dpll_abe_ck failed transition to 'locked'
^^^ this seems to be different
[ 3.028640] clock: dpll_abe_ck failed transition to 'locked' [ 4.333541] clock: dpll_abe_ck failed transition to 'locked' [ 5.638412] clock: dpll_abe_ck failed transition to 'locked' [ 6.939455] clock: dpll_abe_ck failed transition to 'locked' [ 6.947796] ------------[ cut here ]------------ [ 6.952460] WARNING: CPU: 0 PID: 1 at drivers/clk/clk.c:814 clk_core_disable_lock+0x18/0x24 [ 6.961024] aess_fclk already disabled [ 6.964864] Modules linked in: [ 6.967995] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-letux+ #2664 [ 6.974954] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 6.981136] [<c01112c8>] (unwind_backtrace) from [<c010c87c>] (show_stack+0x10/0x14) [ 6.989075] [<c010c87c>] (show_stack) from [<c078f894>] (dump_stack+0x7c/0x9c) [ 6.996489] [<c078f894>] (dump_stack) from [<c0132848>] (__warn+0xd8/0x108) [ 7.003632] [<c0132848>] (__warn) from [<c01328bc>] (warn_slowpath_fmt+0x44/0x6c) [ 7.011313] [<c01328bc>] (warn_slowpath_fmt) from [<c049d44c>] (clk_core_disable_lock+0x18/0x24) [ 7.020335] [<c049d44c>] (clk_core_disable_lock) from [<c01200b8>] (_disable_clocks+0x18/0x70) [ 7.029177] [<c01200b8>] (_disable_clocks) from [<c012116c>] (_enable+0x1ec/0x230) [ 7.036947] [<c012116c>] (_enable) from [<c012259c>] (_setup.part.16+0xc8/0x404) [ 7.044537] [<c012259c>] (_setup.part.16) from [<c01215c8>] (_setup+0x14/0x1c) [ 7.051949] [<c01215c8>] (_setup) from [<c01216b4>] (omap_hwmod_for_each+0x3c/0x64) [ 7.059810] [<c01216b4>] (omap_hwmod_for_each) from [<c0a0db90>] (__omap_hwmod_setup_all+0xa4/0xc0) [ 7.069099] [<c0a0db90>] (__omap_hwmod_setup_all) from [<c0102eb4>] (do_one_initcall+0xc0/0x268) [ 7.078121] [<c0102eb4>] (do_one_initcall) from [<c0a01050>] (kernel_init_freeable+0x220/0x36c) [ 7.087050] [<c0a01050>] (kernel_init_freeable) from [<c07a25dc>] (kernel_init+0x8/0x110) [ 7.095443] [<c07a25dc>] (kernel_init) from [<c01010e8>] (ret_from_fork+0x14/0x2c) [ 7.103207] Exception stack(0xed8adfb0 to 0xed8adff8) [ 7.108390] dfa0: 00000000 00000000 00000000 00000000 [ 7.116786] dfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 7.125180] dfe0: 00000000 00000000 00000000 00000000 00000013 00000000 [ 7.131971] ---[ end trace 02345015e7dc8e1f ]--- [ 7.136720] omap_hwmod: aess: _wait_target_ready failed: -16 [ 7.142511] omap_hwmod: aess: cannot be enabled for reset (3) [ 8.447580] clock: dpll_abe_ck failed transition to 'locked' [ 9.752444] clock: dpll_abe_ck failed transition to 'locked'
--- and then everything hangs
If I enforce a warm RESET, the Pyra boots again up to the same point of failure. I have to power-off and on again through Palmas to get it booting again.
Searching for "clock: dpll_abe_ck failed transition to 'locked'" leads to:
https://e2e.ti.com/support/omap/f/885/t/328485?dpll-abe-ck-failed-transition...
And:
https://www.pyra-handheld.com/pipermail/kernel/2016-May/000877.html
So we had discussed this already a while ago but did not find a solution...
Maybe I should try to disable ABE/AESS for the next experiment (not today). An try the same on OMAP5EVM (to find out if there are hardware dependencies involved).
BR and thanks, Nikolaus
Hi,
* H. Nikolaus Schaller hns@goldelico.com [180910 20:31]:
Now, I get something for further analysis, which indicates how the kernel is stumbling...
Oh that same old omap5 reboot clock issue. Adding Tero and Peter to Cc.
Can you please also set this up as a bug at bugzilla.kernel.org? We've already seen this before but I don't think there was any solution.
Regards,
Tony
root@letux:~# dmesg|fgrep early [ 0.000000] Malformed early option 'console' [ 0.000000] earlycon: omapserial0 at MMIO 0x48020000 (options '')
^^^ ok, earlycon is working :)
[ 0.000000] Kernel command line: console= root=PARTUUID=7d45bc20-02 rw rootfstype=ext4 rootwait console=ttyO2,115200n8 vram=12M omapfb.vram=0:8M,1:4M omapfb.rotate_type=0 omapdss.def_disp=lcd rootwait twl4030_charger.allow_usb=1 log_buf_len=8M ignore_loglevel earlyprintk earlycon [ 0.000000] early log buf free: 63696(97%) root@letux:~# reboot
Broadcast message from root@letux (console) (Mon Sep 10 20:05:16 2018):
The system is going down for reboot NOW!
....
[ 164.453708] reboot: Restarting system
U-Boot SPL 2016.11-00292-g12720df (Aug 12 2018 - 18:32:51) OMAP5432-GP ES2.0
....
## Booting kernel from Legacy Image at 82000000 ... Image Name: Linux-4.18.0-letux+ Image Type: ARM Linux Kernel Image (uncompressed) Data Size: 4901632 Bytes = 4.7 MiB Load Address: 80008000 Entry Point: 80008000 Verifying Checksum ... OK ## Flattened Device Tree blob at 88000000 Booting using the fdt blob at 0x88000000 Loading Kernel Image ... OK Loading Device Tree to 8ffed000, end 8fffff57 ... OK
Starting kernel ...
[ 0.000000] Booting Linux on physical CPU 0x0 [ 0.000000] Linux version 4.18.0-letux+ (hns@iMac.fritz.box) (gcc version 4.9.2 (GCC)) #2664 SMP PREEMPT Mon Sep 10 20:46:49 CEST 2018 [ 0.000000] CPU: ARMv7 Processor [412fc0f2] revision 2 (ARMv7), cr=10c5387d [ 0.000000] CPU: div instructions available: patching division code [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache [ 0.000000] OF: fdt: Machine model: Pyra-Handheld-V5.1.2ff [ 0.000000] Malformed early option 'console' [ 0.000000] debug: ignoring loglevel setting. [ 0.000000] earlycon: omapserial0 at MMIO 0x48020000 (options '') [ 0.000000] bootconsole [omapserial0] enabled [ 0.000000] Memory policy: Data cache writealloc [ 0.000000] cma: Reserved 16 MiB at 0xfd800000 [ 0.000000] OMAP4: Map 0xfee00000 to (ptrval) for dram barrier [ 0.000000] On node 0 totalpages: 519680 [ 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: 323072 pages, LIFO batch:31 [ 0.000000] OMAP5432 ES2.0 [ 0.000000] random: get_random_bytes called from start_kernel+0x80/0x470 with crng_init=0 [ 0.000000] percpu: Embedded 17 pages/cpu @(ptrval) s40320 r8192 d21120 u69632 [ 0.000000] pcpu-alloc: s40320 r8192 d21120 u69632 alloc=17*4096 [ 0.000000] pcpu-alloc: [0] 0 [0] 1 [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 518144 [ 0.000000] Kernel command line: console= root=PARTUUID=7d45bc20-02 rw rootfstype=ext4 rootwait console=ttyO2,115200n8 vram=12M omapfb.vram=0:8M,1:4M omapfb.rotate_type=0 omapdss.def_disp=lcd rootwait twl4030_charger.allow_usb=1 log_buf_len=8M ignore_loglevel earlyprintk earlycon [ 0.000000] log_buf_len: 8388608 bytes [ 0.000000] early log buf free: 63696(97%) [ 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: 2025568K/2078720K available (6823K kernel code, 653K rwdata, 1824K rodata, 1024K init, 221K bss, 36768K reserved, 16384K cma-reserved, 1275904K highmem) [ 0.000000] Virtual kernel memory layout: [ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB) [ 0.000000] fixmap : 0xffc00000 - 0xfff00000 (3072 kB) [ 0.000000] vmalloc : 0xf0800000 - 0xff800000 ( 240 MB) [ 0.000000] lowmem : 0xc0000000 - 0xf0000000 ( 768 MB) [ 0.000000] pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB) [ 0.000000] modules : 0xbf000000 - 0xbfe00000 ( 14 MB) [ 0.000000] .text : 0x(ptrval) - 0x(ptrval) (7816 kB) [ 0.000000] .init : 0x(ptrval) - 0x(ptrval) (1024 kB) [ 0.000000] .data : 0x(ptrval) - 0x(ptrval) ( 654 kB) [ 0.000000] .bss : 0x(ptrval) - 0x(ptrval) ( 222 kB) [ 0.000000] Preemptible hierarchical RCU implementation. [ 0.000000] RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=2. [ 0.000000] Tasks RCU enabled. [ 0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2 [ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16 [ 0.000000] GIC: Using split EOI/Deactivate mode [ 0.000000] clock: dpll_abe_ck failed transition to 'locked' [ 0.000000] OMAP clockevent source: timer1 at 32768 Hz [ 0.000000] arch_timer: cp15 timer(s) running at 6.14MHz (phys). [ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x16ac02862, max_idle_ns: 440795202218 ns [ 0.000005] sched_clock: 56 bits at 6MHz, resolution 162ns, wraps every 4398046511085ns [ 0.008218] Switching to timer-based delay loop, resolution 162ns [ 0.015171] clocksource: 32k_counter: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 58327039986419 ns [ 0.025273] OMAP clocksource: 32k_counter at 32768 Hz [ 0.031722] Console: colour dummy device 80x30 [ 0.036209] Calibrating delay loop (skipped), value calculated using timer frequency.. 12.28 BogoMIPS (lpj=61440) [ 0.046753] pid_max: default: 32768 minimum: 301 [ 0.051557] Security Framework initialized [ 0.055723] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.062482] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.070125] CPU: Testing write buffer coherency: ok [ 0.075087] CPU0: Spectre v2: firmware did not set auxiliary control register IBE bit, system vulnerable [ 0.084971] /cpus/cpu@0 missing clock-frequency property [ 0.090363] /cpus/cpu@1 missing clock-frequency property [ 0.095794] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 [ 0.101610] smp: CPU1 parked within kernel, needs reset (0x0 0x801248a0) [ 0.161732] Setting up static identity map for 0x80100000 - 0x80100060 [ 0.168443] Hierarchical SRCU implementation. [ 0.212907] smp: Bringing up secondary CPUs ... [ 0.273213] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 [ 0.273219] CPU1: Spectre v2: using ICIALLU workaround [ 0.284313] smp: Brought up 1 node, 2 CPUs [ 0.288434] SMP: Total of 2 processors activated (24.57 BogoMIPS). [ 0.294807] CPU: All CPU(s) started in HYP mode. [ 0.299509] CPU: Virtualization extensions available. [ 0.305759] devtmpfs: initialized [ 0.319718] VFP support v0.3: implementor 41 architecture 4 part 30 variant f rev 0 [ 0.327882] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns [ 0.337934] futex hash table entries: 512 (order: 3, 32768 bytes) [ 0.344594] pinctrl core: initialized pinctrl subsystem [ 0.350243] really_probe: driver reg-dummy for reg-dummy bus platform [ 0.357023] really_probe: driver reg-dummy for reg-dummy bus platform ok (1) [ 0.364644] NET: Registered protocol family 16 [ 0.370796] DMA: preallocated 256 KiB pool for atomic coherent allocations [ 0.378566] omap_hwmod: l3_main_3 using broken dt data from ocp [ 0.385175] omap_hwmod: l3_main_2 using broken dt data from ocp [ 1.723766] clock: dpll_abe_ck failed transition to 'locked'
^^^ this seems to be different
[ 3.028640] clock: dpll_abe_ck failed transition to 'locked' [ 4.333541] clock: dpll_abe_ck failed transition to 'locked' [ 5.638412] clock: dpll_abe_ck failed transition to 'locked' [ 6.939455] clock: dpll_abe_ck failed transition to 'locked' [ 6.947796] ------------[ cut here ]------------ [ 6.952460] WARNING: CPU: 0 PID: 1 at drivers/clk/clk.c:814 clk_core_disable_lock+0x18/0x24 [ 6.961024] aess_fclk already disabled [ 6.964864] Modules linked in: [ 6.967995] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-letux+ #2664 [ 6.974954] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 6.981136] [<c01112c8>] (unwind_backtrace) from [<c010c87c>] (show_stack+0x10/0x14) [ 6.989075] [<c010c87c>] (show_stack) from [<c078f894>] (dump_stack+0x7c/0x9c) [ 6.996489] [<c078f894>] (dump_stack) from [<c0132848>] (__warn+0xd8/0x108) [ 7.003632] [<c0132848>] (__warn) from [<c01328bc>] (warn_slowpath_fmt+0x44/0x6c) [ 7.011313] [<c01328bc>] (warn_slowpath_fmt) from [<c049d44c>] (clk_core_disable_lock+0x18/0x24) [ 7.020335] [<c049d44c>] (clk_core_disable_lock) from [<c01200b8>] (_disable_clocks+0x18/0x70) [ 7.029177] [<c01200b8>] (_disable_clocks) from [<c012116c>] (_enable+0x1ec/0x230) [ 7.036947] [<c012116c>] (_enable) from [<c012259c>] (_setup.part.16+0xc8/0x404) [ 7.044537] [<c012259c>] (_setup.part.16) from [<c01215c8>] (_setup+0x14/0x1c) [ 7.051949] [<c01215c8>] (_setup) from [<c01216b4>] (omap_hwmod_for_each+0x3c/0x64) [ 7.059810] [<c01216b4>] (omap_hwmod_for_each) from [<c0a0db90>] (__omap_hwmod_setup_all+0xa4/0xc0) [ 7.069099] [<c0a0db90>] (__omap_hwmod_setup_all) from [<c0102eb4>] (do_one_initcall+0xc0/0x268) [ 7.078121] [<c0102eb4>] (do_one_initcall) from [<c0a01050>] (kernel_init_freeable+0x220/0x36c) [ 7.087050] [<c0a01050>] (kernel_init_freeable) from [<c07a25dc>] (kernel_init+0x8/0x110) [ 7.095443] [<c07a25dc>] (kernel_init) from [<c01010e8>] (ret_from_fork+0x14/0x2c) [ 7.103207] Exception stack(0xed8adfb0 to 0xed8adff8) [ 7.108390] dfa0: 00000000 00000000 00000000 00000000 [ 7.116786] dfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 7.125180] dfe0: 00000000 00000000 00000000 00000000 00000013 00000000 [ 7.131971] ---[ end trace 02345015e7dc8e1f ]--- [ 7.136720] omap_hwmod: aess: _wait_target_ready failed: -16 [ 7.142511] omap_hwmod: aess: cannot be enabled for reset (3) [ 8.447580] clock: dpll_abe_ck failed transition to 'locked' [ 9.752444] clock: dpll_abe_ck failed transition to 'locked'
--- and then everything hangs
If I enforce a warm RESET, the Pyra boots again up to the same point of failure. I have to power-off and on again through Palmas to get it booting again.
Searching for "clock: dpll_abe_ck failed transition to 'locked'" leads to:
https://e2e.ti.com/support/omap/f/885/t/328485?dpll-abe-ck-failed-transition...
And:
https://www.pyra-handheld.com/pipermail/kernel/2016-May/000877.html
So we had discussed this already a while ago but did not find a solution...
Maybe I should try to disable ABE/AESS for the next experiment (not today). An try the same on OMAP5EVM (to find out if there are hardware dependencies involved).
BR and thanks, Nikolaus
On 10/09/18 23:50, Tony Lindgren wrote:
Hi,
- H. Nikolaus Schaller hns@goldelico.com [180910 20:31]:
Now, I get something for further analysis, which indicates how the kernel is stumbling...
Oh that same old omap5 reboot clock issue. Adding Tero and Peter to Cc.
Can you please also set this up as a bug at bugzilla.kernel.org? We've already seen this before but I don't think there was any solution.
You should try to reproduce the issue on omap5uevm. Nothing much I can do if this issue is only present on Pyra HW.
-Tero
Regards,
Tony
root@letux:~# dmesg|fgrep early [ 0.000000] Malformed early option 'console' [ 0.000000] earlycon: omapserial0 at MMIO 0x48020000 (options '')
^^^ ok, earlycon is working :)
[ 0.000000] Kernel command line: console= root=PARTUUID=7d45bc20-02 rw rootfstype=ext4 rootwait console=ttyO2,115200n8 vram=12M omapfb.vram=0:8M,1:4M omapfb.rotate_type=0 omapdss.def_disp=lcd rootwait twl4030_charger.allow_usb=1 log_buf_len=8M ignore_loglevel earlyprintk earlycon [ 0.000000] early log buf free: 63696(97%) root@letux:~# reboot
Broadcast message from root@letux (console) (Mon Sep 10 20:05:16 2018):
The system is going down for reboot NOW!
....
[ 164.453708] reboot: Restarting system
U-Boot SPL 2016.11-00292-g12720df (Aug 12 2018 - 18:32:51) OMAP5432-GP ES2.0
....
## Booting kernel from Legacy Image at 82000000 ... Image Name: Linux-4.18.0-letux+ Image Type: ARM Linux Kernel Image (uncompressed) Data Size: 4901632 Bytes = 4.7 MiB Load Address: 80008000 Entry Point: 80008000 Verifying Checksum ... OK ## Flattened Device Tree blob at 88000000 Booting using the fdt blob at 0x88000000 Loading Kernel Image ... OK Loading Device Tree to 8ffed000, end 8fffff57 ... OK
Starting kernel ...
[ 0.000000] Booting Linux on physical CPU 0x0 [ 0.000000] Linux version 4.18.0-letux+ (hns@iMac.fritz.box) (gcc version 4.9.2 (GCC)) #2664 SMP PREEMPT Mon Sep 10 20:46:49 CEST 2018 [ 0.000000] CPU: ARMv7 Processor [412fc0f2] revision 2 (ARMv7), cr=10c5387d [ 0.000000] CPU: div instructions available: patching division code [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache [ 0.000000] OF: fdt: Machine model: Pyra-Handheld-V5.1.2ff [ 0.000000] Malformed early option 'console' [ 0.000000] debug: ignoring loglevel setting. [ 0.000000] earlycon: omapserial0 at MMIO 0x48020000 (options '') [ 0.000000] bootconsole [omapserial0] enabled [ 0.000000] Memory policy: Data cache writealloc [ 0.000000] cma: Reserved 16 MiB at 0xfd800000 [ 0.000000] OMAP4: Map 0xfee00000 to (ptrval) for dram barrier [ 0.000000] On node 0 totalpages: 519680 [ 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: 323072 pages, LIFO batch:31 [ 0.000000] OMAP5432 ES2.0 [ 0.000000] random: get_random_bytes called from start_kernel+0x80/0x470 with crng_init=0 [ 0.000000] percpu: Embedded 17 pages/cpu @(ptrval) s40320 r8192 d21120 u69632 [ 0.000000] pcpu-alloc: s40320 r8192 d21120 u69632 alloc=17*4096 [ 0.000000] pcpu-alloc: [0] 0 [0] 1 [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 518144 [ 0.000000] Kernel command line: console= root=PARTUUID=7d45bc20-02 rw rootfstype=ext4 rootwait console=ttyO2,115200n8 vram=12M omapfb.vram=0:8M,1:4M omapfb.rotate_type=0 omapdss.def_disp=lcd rootwait twl4030_charger.allow_usb=1 log_buf_len=8M ignore_loglevel earlyprintk earlycon [ 0.000000] log_buf_len: 8388608 bytes [ 0.000000] early log buf free: 63696(97%) [ 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: 2025568K/2078720K available (6823K kernel code, 653K rwdata, 1824K rodata, 1024K init, 221K bss, 36768K reserved, 16384K cma-reserved, 1275904K highmem) [ 0.000000] Virtual kernel memory layout: [ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB) [ 0.000000] fixmap : 0xffc00000 - 0xfff00000 (3072 kB) [ 0.000000] vmalloc : 0xf0800000 - 0xff800000 ( 240 MB) [ 0.000000] lowmem : 0xc0000000 - 0xf0000000 ( 768 MB) [ 0.000000] pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB) [ 0.000000] modules : 0xbf000000 - 0xbfe00000 ( 14 MB) [ 0.000000] .text : 0x(ptrval) - 0x(ptrval) (7816 kB) [ 0.000000] .init : 0x(ptrval) - 0x(ptrval) (1024 kB) [ 0.000000] .data : 0x(ptrval) - 0x(ptrval) ( 654 kB) [ 0.000000] .bss : 0x(ptrval) - 0x(ptrval) ( 222 kB) [ 0.000000] Preemptible hierarchical RCU implementation. [ 0.000000] RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=2. [ 0.000000] Tasks RCU enabled. [ 0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2 [ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16 [ 0.000000] GIC: Using split EOI/Deactivate mode [ 0.000000] clock: dpll_abe_ck failed transition to 'locked' [ 0.000000] OMAP clockevent source: timer1 at 32768 Hz [ 0.000000] arch_timer: cp15 timer(s) running at 6.14MHz (phys). [ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x16ac02862, max_idle_ns: 440795202218 ns [ 0.000005] sched_clock: 56 bits at 6MHz, resolution 162ns, wraps every 4398046511085ns [ 0.008218] Switching to timer-based delay loop, resolution 162ns [ 0.015171] clocksource: 32k_counter: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 58327039986419 ns [ 0.025273] OMAP clocksource: 32k_counter at 32768 Hz [ 0.031722] Console: colour dummy device 80x30 [ 0.036209] Calibrating delay loop (skipped), value calculated using timer frequency.. 12.28 BogoMIPS (lpj=61440) [ 0.046753] pid_max: default: 32768 minimum: 301 [ 0.051557] Security Framework initialized [ 0.055723] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.062482] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.070125] CPU: Testing write buffer coherency: ok [ 0.075087] CPU0: Spectre v2: firmware did not set auxiliary control register IBE bit, system vulnerable [ 0.084971] /cpus/cpu@0 missing clock-frequency property [ 0.090363] /cpus/cpu@1 missing clock-frequency property [ 0.095794] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 [ 0.101610] smp: CPU1 parked within kernel, needs reset (0x0 0x801248a0) [ 0.161732] Setting up static identity map for 0x80100000 - 0x80100060 [ 0.168443] Hierarchical SRCU implementation. [ 0.212907] smp: Bringing up secondary CPUs ... [ 0.273213] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 [ 0.273219] CPU1: Spectre v2: using ICIALLU workaround [ 0.284313] smp: Brought up 1 node, 2 CPUs [ 0.288434] SMP: Total of 2 processors activated (24.57 BogoMIPS). [ 0.294807] CPU: All CPU(s) started in HYP mode. [ 0.299509] CPU: Virtualization extensions available. [ 0.305759] devtmpfs: initialized [ 0.319718] VFP support v0.3: implementor 41 architecture 4 part 30 variant f rev 0 [ 0.327882] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns [ 0.337934] futex hash table entries: 512 (order: 3, 32768 bytes) [ 0.344594] pinctrl core: initialized pinctrl subsystem [ 0.350243] really_probe: driver reg-dummy for reg-dummy bus platform [ 0.357023] really_probe: driver reg-dummy for reg-dummy bus platform ok (1) [ 0.364644] NET: Registered protocol family 16 [ 0.370796] DMA: preallocated 256 KiB pool for atomic coherent allocations [ 0.378566] omap_hwmod: l3_main_3 using broken dt data from ocp [ 0.385175] omap_hwmod: l3_main_2 using broken dt data from ocp [ 1.723766] clock: dpll_abe_ck failed transition to 'locked'
^^^ this seems to be different
[ 3.028640] clock: dpll_abe_ck failed transition to 'locked' [ 4.333541] clock: dpll_abe_ck failed transition to 'locked' [ 5.638412] clock: dpll_abe_ck failed transition to 'locked' [ 6.939455] clock: dpll_abe_ck failed transition to 'locked' [ 6.947796] ------------[ cut here ]------------ [ 6.952460] WARNING: CPU: 0 PID: 1 at drivers/clk/clk.c:814 clk_core_disable_lock+0x18/0x24 [ 6.961024] aess_fclk already disabled [ 6.964864] Modules linked in: [ 6.967995] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-letux+ #2664 [ 6.974954] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 6.981136] [<c01112c8>] (unwind_backtrace) from [<c010c87c>] (show_stack+0x10/0x14) [ 6.989075] [<c010c87c>] (show_stack) from [<c078f894>] (dump_stack+0x7c/0x9c) [ 6.996489] [<c078f894>] (dump_stack) from [<c0132848>] (__warn+0xd8/0x108) [ 7.003632] [<c0132848>] (__warn) from [<c01328bc>] (warn_slowpath_fmt+0x44/0x6c) [ 7.011313] [<c01328bc>] (warn_slowpath_fmt) from [<c049d44c>] (clk_core_disable_lock+0x18/0x24) [ 7.020335] [<c049d44c>] (clk_core_disable_lock) from [<c01200b8>] (_disable_clocks+0x18/0x70) [ 7.029177] [<c01200b8>] (_disable_clocks) from [<c012116c>] (_enable+0x1ec/0x230) [ 7.036947] [<c012116c>] (_enable) from [<c012259c>] (_setup.part.16+0xc8/0x404) [ 7.044537] [<c012259c>] (_setup.part.16) from [<c01215c8>] (_setup+0x14/0x1c) [ 7.051949] [<c01215c8>] (_setup) from [<c01216b4>] (omap_hwmod_for_each+0x3c/0x64) [ 7.059810] [<c01216b4>] (omap_hwmod_for_each) from [<c0a0db90>] (__omap_hwmod_setup_all+0xa4/0xc0) [ 7.069099] [<c0a0db90>] (__omap_hwmod_setup_all) from [<c0102eb4>] (do_one_initcall+0xc0/0x268) [ 7.078121] [<c0102eb4>] (do_one_initcall) from [<c0a01050>] (kernel_init_freeable+0x220/0x36c) [ 7.087050] [<c0a01050>] (kernel_init_freeable) from [<c07a25dc>] (kernel_init+0x8/0x110) [ 7.095443] [<c07a25dc>] (kernel_init) from [<c01010e8>] (ret_from_fork+0x14/0x2c) [ 7.103207] Exception stack(0xed8adfb0 to 0xed8adff8) [ 7.108390] dfa0: 00000000 00000000 00000000 00000000 [ 7.116786] dfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 7.125180] dfe0: 00000000 00000000 00000000 00000000 00000013 00000000 [ 7.131971] ---[ end trace 02345015e7dc8e1f ]--- [ 7.136720] omap_hwmod: aess: _wait_target_ready failed: -16 [ 7.142511] omap_hwmod: aess: cannot be enabled for reset (3) [ 8.447580] clock: dpll_abe_ck failed transition to 'locked' [ 9.752444] clock: dpll_abe_ck failed transition to 'locked'
--- and then everything hangs
If I enforce a warm RESET, the Pyra boots again up to the same point of failure. I have to power-off and on again through Palmas to get it booting again.
Searching for "clock: dpll_abe_ck failed transition to 'locked'" leads to:
https://e2e.ti.com/support/omap/f/885/t/328485?dpll-abe-ck-failed-transition...
And:
https://www.pyra-handheld.com/pipermail/kernel/2016-May/000877.html
So we had discussed this already a while ago but did not find a solution...
Maybe I should try to disable ABE/AESS for the next experiment (not today). An try the same on OMAP5EVM (to find out if there are hardware dependencies involved).
BR and thanks, Nikolaus
-- Texas Instruments Finland Oy, Porkkalankatu 22, 00180 Helsinki. Y-tunnus/Business ID: 0615521-4. Kotipaikka/Domicile: Helsinki
Hi Tero,
Am 11.09.2018 um 08:02 schrieb Tero Kristo t-kristo@ti.com:
On 10/09/18 23:50, Tony Lindgren wrote:
Hi,
- H. Nikolaus Schaller hns@goldelico.com [180910 20:31]:
Now, I get something for further analysis, which indicates how the kernel is stumbling...
Oh that same old omap5 reboot clock issue. Adding Tero and Peter to Cc. Can you please also set this up as a bug at bugzilla.kernel.org? We've already seen this before but I don't think there was any solution.
You should try to reproduce the issue on omap5uevm. Nothing much I can do if this issue is only present on Pyra HW.
Strangely it is not reproducible on OMAP5EVM. With the same kernel uImage, defconfig and user-space.
Differences are of course DTBs and some u-boot specialities, but both are derived from standard omap5 files from mainline.
I have digged through the old discussion on e2e and the gitorius code gave some hints about which registers are interesting and should be checked.
I did hack some code into U-Boot to print their values in misc_init_r() after "power-on" and "reboot". Ans wrote a shell script wrapper for devmem2 to read the same registers after successful boot.
Here are the values of interesting registers on the Pyra:
Pyra before boot (printed from U-Boot)
4a0041e4 00000002: CM_IDLEST_DPLL_ABE 4a0041e8 00000000: CM_AUTOIDLE_DPLL_ABE 4a0041f0 00000001: CM_DIV_M2_DPLL_ABE 4a0041f4 00000001: CM_DIV_M3_DPLL_ABE 4a004500 00000003: CM_ABE_CLKSTCTRL 4ae06108 00000000: CM_CLKSEL_WKUPAON 4ae0610c 00000001: CM_CLKSEL_ABE_PLL_REF
Pyra after boot in Linux
Value at address 0x4A0041E4 (0xb6fe71e4): 0x12 Value at address 0x4A0041E8 (0xb6f681e8): 0x1 Value at address 0x4A0041F0 (0xb6fc01f0): 0x1 Value at address 0x4A0041F4 (0xb6f901f4): 0x2 Value at address 0x4A004500 (0xb6f6f500): 0x803 Value at address 0x4AE06108 (0xb6fa1108): 0x0 Value at address 0x4AE0610C (0xb6fa910c): 0x1
Pyra in U-Boot after "reboot" (printed from U-Boot)
4a0041e4 00000012: CM_IDLEST_DPLL_ABE 4a0041e8 00000000: CM_AUTOIDLE_DPLL_ABE 4a0041f0 00000001: CM_DIV_M2_DPLL_ABE 4a0041f4 00000001: CM_DIV_M3_DPLL_ABE 4a004500 00000003: CM_ABE_CLKSTCTRL 4ae06108 00000000: CM_CLKSEL_WKUPAON 4ae0610c 00000001: CM_CLKSEL_ABE_PLL_REF
Pyra kernel does not boot (clock: dpll_abe_ck failed transition to 'locked')
and the same on OMAP5EVM:
EVM before boot (printed from U-Boot)
4a0041e4 00000002: CM_IDLEST_DPLL_ABE 4a0041e8 00000000: CM_AUTOIDLE_DPLL_ABE 4a0041f0 00000001: CM_DIV_M2_DPLL_ABE 4a0041f4 00000001: CM_DIV_M3_DPLL_ABE 4a004500 00000003: CM_ABE_CLKSTCTRL 4ae06108 00000000: CM_CLKSEL_WKUPAON 4ae0610c 00000001: CM_CLKSEL_ABE_PLL_REF
EVM after boot in Linux
Value at address 0x4A0041E4 (0xb6fae1e4): 0x12 Value at address 0x4A0041E8 (0xb6fb91e8): 0x1 Value at address 0x4A0041F0 (0xb6f251f0): 0x1 Value at address 0x4A0041F4 (0xb6f961f4): 0x2 Value at address 0x4A004500 (0xb6fcf500): 0x3 Value at address 0x4AE06108 (0xb6f9b108): 0x0 Value at address 0x4AE0610C (0xb6f5310c): 0x1
EVM in U-Boot after "reboot"
4a0041e4 00000002: CM_IDLEST_DPLL_ABE 4a0041e8 00000000: CM_AUTOIDLE_DPLL_ABE 4a0041f0 00000001: CM_DIV_M2_DPLL_ABE 4a0041f4 00000001: CM_DIV_M3_DPLL_ABE 4a004500 00000003: CM_ABE_CLKSTCTRL 4ae06108 00000000: CM_CLKSEL_WKUPAON 4ae0610c 00000001: CM_CLKSEL_ABE_PLL_REF
EVM in Kernel after successful reboot
Value at address 0x4A0041E4 (0xb6fe81e4): 0x12 Value at address 0x4A0041E8 (0xb6f7a1e8): 0x1 Value at address 0x4A0041F0 (0xb6f4c1f0): 0x1 Value at address 0x4A0041F4 (0xb6f2c1f4): 0x2 Value at address 0x4A004500 (0xb6f1f500): 0x3 Value at address 0x4AE06108 (0xb6f63108): 0x0 Value at address 0x4AE0610C (0xb6fca10c): 0x1
So there is no diff in U-Boot after power-on between EVM and Pyra and before the kernel starts.
After kernel has booted, there is a single difference in CM_ABE_CLKSTCTRL.
The relevant bit is: CLKACTIVITY_DPLL_ABE_X2_ CLK
After reboot, there are bigger differences not wiped out by u-boot.
So the question is what disturbs this clock, especially as CLKACTIVITY_DPLL_ABE_X2_ seems to say that the clock is active (on Pyra) but not on EVM (I had expected the reverse to be more likely).
And why things are not cleaned up before reboot.
I have not yet analysed in detail and carefully all differences between u-boot code and device tree source, but I currently only aware that there are some additional audio subsystems enabled on the Pyra, e.g. vibramotor, handsfree speakers. Maybe one of these keeps the clock active?
So I'll continue there and report if I find something which I can disable...
BR, Nikolaus
-Tero
Regards, Tony
root@letux:~# dmesg|fgrep early [ 0.000000] Malformed early option 'console' [ 0.000000] earlycon: omapserial0 at MMIO 0x48020000 (options '')
^^^ ok, earlycon is working :)
[ 0.000000] Kernel command line: console= root=PARTUUID=7d45bc20-02 rw rootfstype=ext4 rootwait console=ttyO2,115200n8 vram=12M omapfb.vram=0:8M,1:4M omapfb.rotate_type=0 omapdss.def_disp=lcd rootwait twl4030_charger.allow_usb=1 log_buf_len=8M ignore_loglevel earlyprintk earlycon [ 0.000000] early log buf free: 63696(97%) root@letux:~# reboot
Broadcast message from root@letux (console) (Mon Sep 10 20:05:16 2018):
The system is going down for reboot NOW!
....
[ 164.453708] reboot: Restarting system
U-Boot SPL 2016.11-00292-g12720df (Aug 12 2018 - 18:32:51) OMAP5432-GP ES2.0
....
## Booting kernel from Legacy Image at 82000000 ... Image Name: Linux-4.18.0-letux+ Image Type: ARM Linux Kernel Image (uncompressed) Data Size: 4901632 Bytes = 4.7 MiB Load Address: 80008000 Entry Point: 80008000 Verifying Checksum ... OK ## Flattened Device Tree blob at 88000000 Booting using the fdt blob at 0x88000000 Loading Kernel Image ... OK Loading Device Tree to 8ffed000, end 8fffff57 ... OK
Starting kernel ...
[ 0.000000] Booting Linux on physical CPU 0x0 [ 0.000000] Linux version 4.18.0-letux+ (hns@iMac.fritz.box) (gcc version 4.9.2 (GCC)) #2664 SMP PREEMPT Mon Sep 10 20:46:49 CEST 2018 [ 0.000000] CPU: ARMv7 Processor [412fc0f2] revision 2 (ARMv7), cr=10c5387d [ 0.000000] CPU: div instructions available: patching division code [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache [ 0.000000] OF: fdt: Machine model: Pyra-Handheld-V5.1.2ff [ 0.000000] Malformed early option 'console' [ 0.000000] debug: ignoring loglevel setting. [ 0.000000] earlycon: omapserial0 at MMIO 0x48020000 (options '') [ 0.000000] bootconsole [omapserial0] enabled [ 0.000000] Memory policy: Data cache writealloc [ 0.000000] cma: Reserved 16 MiB at 0xfd800000 [ 0.000000] OMAP4: Map 0xfee00000 to (ptrval) for dram barrier [ 0.000000] On node 0 totalpages: 519680 [ 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: 323072 pages, LIFO batch:31 [ 0.000000] OMAP5432 ES2.0 [ 0.000000] random: get_random_bytes called from start_kernel+0x80/0x470 with crng_init=0 [ 0.000000] percpu: Embedded 17 pages/cpu @(ptrval) s40320 r8192 d21120 u69632 [ 0.000000] pcpu-alloc: s40320 r8192 d21120 u69632 alloc=17*4096 [ 0.000000] pcpu-alloc: [0] 0 [0] 1 [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 518144 [ 0.000000] Kernel command line: console= root=PARTUUID=7d45bc20-02 rw rootfstype=ext4 rootwait console=ttyO2,115200n8 vram=12M omapfb.vram=0:8M,1:4M omapfb.rotate_type=0 omapdss.def_disp=lcd rootwait twl4030_charger.allow_usb=1 log_buf_len=8M ignore_loglevel earlyprintk earlycon [ 0.000000] log_buf_len: 8388608 bytes [ 0.000000] early log buf free: 63696(97%) [ 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: 2025568K/2078720K available (6823K kernel code, 653K rwdata, 1824K rodata, 1024K init, 221K bss, 36768K reserved, 16384K cma-reserved, 1275904K highmem) [ 0.000000] Virtual kernel memory layout: [ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB) [ 0.000000] fixmap : 0xffc00000 - 0xfff00000 (3072 kB) [ 0.000000] vmalloc : 0xf0800000 - 0xff800000 ( 240 MB) [ 0.000000] lowmem : 0xc0000000 - 0xf0000000 ( 768 MB) [ 0.000000] pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB) [ 0.000000] modules : 0xbf000000 - 0xbfe00000 ( 14 MB) [ 0.000000] .text : 0x(ptrval) - 0x(ptrval) (7816 kB) [ 0.000000] .init : 0x(ptrval) - 0x(ptrval) (1024 kB) [ 0.000000] .data : 0x(ptrval) - 0x(ptrval) ( 654 kB) [ 0.000000] .bss : 0x(ptrval) - 0x(ptrval) ( 222 kB) [ 0.000000] Preemptible hierarchical RCU implementation. [ 0.000000] RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=2. [ 0.000000] Tasks RCU enabled. [ 0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2 [ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16 [ 0.000000] GIC: Using split EOI/Deactivate mode [ 0.000000] clock: dpll_abe_ck failed transition to 'locked' [ 0.000000] OMAP clockevent source: timer1 at 32768 Hz [ 0.000000] arch_timer: cp15 timer(s) running at 6.14MHz (phys). [ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x16ac02862, max_idle_ns: 440795202218 ns [ 0.000005] sched_clock: 56 bits at 6MHz, resolution 162ns, wraps every 4398046511085ns [ 0.008218] Switching to timer-based delay loop, resolution 162ns [ 0.015171] clocksource: 32k_counter: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 58327039986419 ns [ 0.025273] OMAP clocksource: 32k_counter at 32768 Hz [ 0.031722] Console: colour dummy device 80x30 [ 0.036209] Calibrating delay loop (skipped), value calculated using timer frequency.. 12.28 BogoMIPS (lpj=61440) [ 0.046753] pid_max: default: 32768 minimum: 301 [ 0.051557] Security Framework initialized [ 0.055723] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.062482] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.070125] CPU: Testing write buffer coherency: ok [ 0.075087] CPU0: Spectre v2: firmware did not set auxiliary control register IBE bit, system vulnerable [ 0.084971] /cpus/cpu@0 missing clock-frequency property [ 0.090363] /cpus/cpu@1 missing clock-frequency property [ 0.095794] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 [ 0.101610] smp: CPU1 parked within kernel, needs reset (0x0 0x801248a0) [ 0.161732] Setting up static identity map for 0x80100000 - 0x80100060 [ 0.168443] Hierarchical SRCU implementation. [ 0.212907] smp: Bringing up secondary CPUs ... [ 0.273213] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 [ 0.273219] CPU1: Spectre v2: using ICIALLU workaround [ 0.284313] smp: Brought up 1 node, 2 CPUs [ 0.288434] SMP: Total of 2 processors activated (24.57 BogoMIPS). [ 0.294807] CPU: All CPU(s) started in HYP mode. [ 0.299509] CPU: Virtualization extensions available. [ 0.305759] devtmpfs: initialized [ 0.319718] VFP support v0.3: implementor 41 architecture 4 part 30 variant f rev 0 [ 0.327882] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns [ 0.337934] futex hash table entries: 512 (order: 3, 32768 bytes) [ 0.344594] pinctrl core: initialized pinctrl subsystem [ 0.350243] really_probe: driver reg-dummy for reg-dummy bus platform [ 0.357023] really_probe: driver reg-dummy for reg-dummy bus platform ok (1) [ 0.364644] NET: Registered protocol family 16 [ 0.370796] DMA: preallocated 256 KiB pool for atomic coherent allocations [ 0.378566] omap_hwmod: l3_main_3 using broken dt data from ocp [ 0.385175] omap_hwmod: l3_main_2 using broken dt data from ocp [ 1.723766] clock: dpll_abe_ck failed transition to 'locked'
^^^ this seems to be different
[ 3.028640] clock: dpll_abe_ck failed transition to 'locked' [ 4.333541] clock: dpll_abe_ck failed transition to 'locked' [ 5.638412] clock: dpll_abe_ck failed transition to 'locked' [ 6.939455] clock: dpll_abe_ck failed transition to 'locked' [ 6.947796] ------------[ cut here ]------------ [ 6.952460] WARNING: CPU: 0 PID: 1 at drivers/clk/clk.c:814 clk_core_disable_lock+0x18/0x24 [ 6.961024] aess_fclk already disabled [ 6.964864] Modules linked in: [ 6.967995] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-letux+ #2664 [ 6.974954] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 6.981136] [<c01112c8>] (unwind_backtrace) from [<c010c87c>] (show_stack+0x10/0x14) [ 6.989075] [<c010c87c>] (show_stack) from [<c078f894>] (dump_stack+0x7c/0x9c) [ 6.996489] [<c078f894>] (dump_stack) from [<c0132848>] (__warn+0xd8/0x108) [ 7.003632] [<c0132848>] (__warn) from [<c01328bc>] (warn_slowpath_fmt+0x44/0x6c) [ 7.011313] [<c01328bc>] (warn_slowpath_fmt) from [<c049d44c>] (clk_core_disable_lock+0x18/0x24) [ 7.020335] [<c049d44c>] (clk_core_disable_lock) from [<c01200b8>] (_disable_clocks+0x18/0x70) [ 7.029177] [<c01200b8>] (_disable_clocks) from [<c012116c>] (_enable+0x1ec/0x230) [ 7.036947] [<c012116c>] (_enable) from [<c012259c>] (_setup.part.16+0xc8/0x404) [ 7.044537] [<c012259c>] (_setup.part.16) from [<c01215c8>] (_setup+0x14/0x1c) [ 7.051949] [<c01215c8>] (_setup) from [<c01216b4>] (omap_hwmod_for_each+0x3c/0x64) [ 7.059810] [<c01216b4>] (omap_hwmod_for_each) from [<c0a0db90>] (__omap_hwmod_setup_all+0xa4/0xc0) [ 7.069099] [<c0a0db90>] (__omap_hwmod_setup_all) from [<c0102eb4>] (do_one_initcall+0xc0/0x268) [ 7.078121] [<c0102eb4>] (do_one_initcall) from [<c0a01050>] (kernel_init_freeable+0x220/0x36c) [ 7.087050] [<c0a01050>] (kernel_init_freeable) from [<c07a25dc>] (kernel_init+0x8/0x110) [ 7.095443] [<c07a25dc>] (kernel_init) from [<c01010e8>] (ret_from_fork+0x14/0x2c) [ 7.103207] Exception stack(0xed8adfb0 to 0xed8adff8) [ 7.108390] dfa0: 00000000 00000000 00000000 00000000 [ 7.116786] dfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 7.125180] dfe0: 00000000 00000000 00000000 00000000 00000013 00000000 [ 7.131971] ---[ end trace 02345015e7dc8e1f ]--- [ 7.136720] omap_hwmod: aess: _wait_target_ready failed: -16 [ 7.142511] omap_hwmod: aess: cannot be enabled for reset (3) [ 8.447580] clock: dpll_abe_ck failed transition to 'locked' [ 9.752444] clock: dpll_abe_ck failed transition to 'locked'
--- and then everything hangs
If I enforce a warm RESET, the Pyra boots again up to the same point of failure. I have to power-off and on again through Palmas to get it booting again.
Searching for "clock: dpll_abe_ck failed transition to 'locked'" leads to:
https://e2e.ti.com/support/omap/f/885/t/328485?dpll-abe-ck-failed-transition...
And:
https://www.pyra-handheld.com/pipermail/kernel/2016-May/000877.html
So we had discussed this already a while ago but did not find a solution...
Maybe I should try to disable ABE/AESS for the next experiment (not today). An try the same on OMAP5EVM (to find out if there are hardware dependencies involved).
BR and thanks, Nikolaus
-- Texas Instruments Finland Oy, Porkkalankatu 22, 00180 Helsinki. Y-tunnus/Business ID: 0615521-4. Kotipaikka/Domicile: Helsinki
Hi,
Am 11.09.2018 um 15:07 schrieb H. Nikolaus Schaller hns@goldelico.com:
Hi Tero,
After kernel has booted, there is a single difference in CM_ABE_CLKSTCTRL.
The relevant bit is: CLKACTIVITY_DPLL_ABE_X2_CLK
After reboot, there are bigger differences not wiped out by u-boot.
So the question is what disturbs this clock, especially as CLKACTIVITY_DPLL_ABE_X2_ seems to say that the clock is active (on Pyra) but not on EVM (I had expected the reverse to be more likely).
CM_ABE_CLKSTCTRL remains 0x803 on Pyra and 0x3 on EVM
Well, if we see the same setup by U-Boot after power-on it must be kernel + DTS. Or is this a false conclusion?
So I started to deconfigure kernel subsystems completely:
1. all twl6040 / abe / aess 2. all OMAP3 & OMAP4 3. all wireless (wl1837 uses some external functional clocks) 4. all sound
And I have checked U-Boot and DTS sources but did not find Pyra specific overwrites for any system clock or abe or dpll related registers.
Then I did rm /lib/modules (the most critical ones are configured into the kernel so that I can still boot), and interestingly the CLKACTIVITY_DPLL_ABE_X2_CLK is now the same (0x3) on Pyra and OMAP5EVM. And "reboot" works.
So I can now simply modprobe blacklist them one after the other to find out which one is conflicting.
BR, Nikolaus
Am 11.09.2018 um 18:26 schrieb H. Nikolaus Schaller hns@goldelico.com:
Hi,
Am 11.09.2018 um 15:07 schrieb H. Nikolaus Schaller hns@goldelico.com:
Hi Tero,
After kernel has booted, there is a single difference in CM_ABE_CLKSTCTRL.
The relevant bit is: CLKACTIVITY_DPLL_ABE_X2_CLK
After reboot, there are bigger differences not wiped out by u-boot.
So the question is what disturbs this clock, especially as CLKACTIVITY_DPLL_ABE_X2_ seems to say that the clock is active (on Pyra) but not on EVM (I had expected the reverse to be more likely).
CM_ABE_CLKSTCTRL remains 0x803 on Pyra and 0x3 on EVM
Well, if we see the same setup by U-Boot after power-on it must be kernel + DTS. Or is this a false conclusion?
So I started to deconfigure kernel subsystems completely:
- all twl6040 / abe / aess
- all OMAP3 & OMAP4
- all wireless (wl1837 uses some external functional clocks)
- all sound
And I have checked U-Boot and DTS sources but did not find Pyra specific overwrites for any system clock or abe or dpll related registers.
Then I did rm /lib/modules (the most critical ones are configured into the kernel so that I can still boot), and interestingly the CLKACTIVITY_DPLL_ABE_X2_CLK is now the same (0x3) on Pyra and OMAP5EVM. And "reboot" works.
So I can now simply modprobe blacklist them one after the other to find out which one is conflicting.
Bingo!
root@letux:~# more /etc/modprobe.d/blacklist.conf blacklist pwm_omap_dmtimer root@letux:~#
makes the problem go away.
BTW: blacklisting pwm_bl makes CLKACTIVITY_DPLL_ABE_X2_CLK show the right value but reboot still can't transition dpll_abe_ck to 'locked'.
Why don't you see this on omap5uevm even if these modules are loaded? I assume there is usually no panel connected that makes use of pwm_bl and pwm_omap_dmtimer. And there is no compatible = "ti,omap-dmtimer-pwm"; in omap5-board-common.dtsi or omap5-uevm.dts. This is a hardware difference between Pyra and OMAP5EVM.
So I think it is now up to you to help me to find out why pwm_omap_dmtimer can influence the dpll_abe_ck...
BR and thanks, Nikolaus
Hi, small addendum - there must be another factor involved.
Am 11.09.2018 um 20:20 schrieb H. Nikolaus Schaller hns@goldelico.com:
Am 11.09.2018 um 18:26 schrieb H. Nikolaus Schaller hns@goldelico.com:
Hi,
Am 11.09.2018 um 15:07 schrieb H. Nikolaus Schaller hns@goldelico.com:
Hi Tero,
After kernel has booted, there is a single difference in CM_ABE_CLKSTCTRL.
The relevant bit is: CLKACTIVITY_DPLL_ABE_X2_CLK
After reboot, there are bigger differences not wiped out by u-boot.
So the question is what disturbs this clock, especially as CLKACTIVITY_DPLL_ABE_X2_ seems to say that the clock is active (on Pyra) but not on EVM (I had expected the reverse to be more likely).
CM_ABE_CLKSTCTRL remains 0x803 on Pyra and 0x3 on EVM
Well, if we see the same setup by U-Boot after power-on it must be kernel + DTS. Or is this a false conclusion?
So I started to deconfigure kernel subsystems completely:
- all twl6040 / abe / aess
- all OMAP3 & OMAP4
- all wireless (wl1837 uses some external functional clocks)
- all sound
And I have checked U-Boot and DTS sources but did not find Pyra specific overwrites for any system clock or abe or dpll related registers.
Then I did rm /lib/modules (the most critical ones are configured into the kernel so that I can still boot), and interestingly the CLKACTIVITY_DPLL_ABE_X2_CLK is now the same (0x3) on Pyra and OMAP5EVM. And "reboot" works.
So I can now simply modprobe blacklist them one after the other to find out which one is conflicting.
Bingo!
root@letux:~# more /etc/modprobe.d/blacklist.conf blacklist pwm_omap_dmtimer root@letux:~#
makes the problem go away.
BTW: blacklisting pwm_bl makes CLKACTIVITY_DPLL_ABE_X2_CLK show the right value but reboot still can't transition dpll_abe_ck to 'locked'.
After adding back all modules except pwm_omap_dmtimer the problem comes back to the Pyra. And adding a omap-dmtimer-pwm to the omap5-uevm.dts does make CLKACTIVITY_DPLL_ABE_X2_CLK become 0x803 as I see on the Pyra, but it still handles reboots properly.
More test results to come tomorrow.
Why don't you see this on omap5uevm even if these modules are loaded? I assume there is usually no panel connected that makes use of pwm_bl and pwm_omap_dmtimer. And there is no compatible = "ti,omap-dmtimer-pwm"; in omap5-board-common.dtsi or omap5-uevm.dts. This is a hardware difference between Pyra and OMAP5EVM.
So I think it is now up to you to help me to find out why pwm_omap_dmtimer can influence the dpll_abe_ck...
BR and thanks, Nikolaus
Kernel mailing list Kernel@pyra-handheld.com http://pyra-handheld.com/cgi-bin/mailman/listinfo/kernel
* H. Nikolaus Schaller hns@goldelico.com [180911 18:28]:
BTW: blacklisting pwm_bl makes CLKACTIVITY_DPLL_ABE_X2_CLK show the right value but reboot still can't transition dpll_abe_ck to 'locked'.
After adding back all modules except pwm_omap_dmtimer the problem comes back to the Pyra. And adding a omap-dmtimer-pwm to the omap5-uevm.dts does make CLKACTIVITY_DPLL_ABE_X2_CLK become 0x803 as I see on the Pyra, but it still handles reboots properly.
More test results to come tomorrow.
OK good to hear you got it narrowed down. Sounds like it's time to get minimal pyra support merged to mainline too :)
Regards,
Tony
Hi Tony,
Am 12.09.2018 um 02:03 schrieb Tony Lindgren tony@atomide.com:
- H. Nikolaus Schaller hns@goldelico.com [180911 18:28]:
BTW: blacklisting pwm_bl makes CLKACTIVITY_DPLL_ABE_X2_CLK show the right value but reboot still can't transition dpll_abe_ck to 'locked'.
After adding back all modules except pwm_omap_dmtimer the problem comes back to the Pyra. And adding a omap-dmtimer-pwm to the omap5-uevm.dts does make CLKACTIVITY_DPLL_ABE_X2_CLK become 0x803 as I see on the Pyra, but it still handles reboots properly.
More test results to come tomorrow.
OK good to hear you got it narrowed down.
I have further narrowed it down to
root@letux:~# more /etc/modprobe.d/pwm.conf blacklist pwm_omap_dmtimer blacklist snd_soc_omap_abe_twl6040 root@letux:~#
which always reboots fine (tested with letux-4.18.7 and 4.19-rc1 and 4.14.58).
Either
modprobe pwm_omap_dmtimer
OR (!)
modprobe snd_soc_omap_abe_twl6040
before "reboot" makes the Pyra boot hang with the dpll_abe_ck failure.
Generally it reminds me a little of the pinctrl and generic-adc-battery drivers problem where it turned out that the main problem was a write-out-of-bounds in generic-adc-battery so that it did occur only if drivers were loaded in a specifc sequence.
But this here is more reproducible. On the Pyra.
I am still trying to reproduce the effect on the omap5evm by amending the mainline DTS. It does reboot with these modules loaded...
What I alread wonder is what
- dpll_abe_ck setup - pwm_omap_dmtimer - snd_soc_omap_abe_twl6040
have in common so that they can influence each other?
hwmods? clock setup? dividers? plls?
BR, Nikolaus
On 12/09/18 19:17, H. Nikolaus Schaller wrote:
Hi Tony,
Am 12.09.2018 um 02:03 schrieb Tony Lindgren tony@atomide.com:
- H. Nikolaus Schaller hns@goldelico.com [180911 18:28]:
BTW: blacklisting pwm_bl makes CLKACTIVITY_DPLL_ABE_X2_CLK show the right value but reboot still can't transition dpll_abe_ck to 'locked'.
After adding back all modules except pwm_omap_dmtimer the problem comes back to the Pyra. And adding a omap-dmtimer-pwm to the omap5-uevm.dts does make CLKACTIVITY_DPLL_ABE_X2_CLK become 0x803 as I see on the Pyra, but it still handles reboots properly.
More test results to come tomorrow.
OK good to hear you got it narrowed down.
I have further narrowed it down to
root@letux:~# more /etc/modprobe.d/pwm.conf blacklist pwm_omap_dmtimer blacklist snd_soc_omap_abe_twl6040 root@letux:~#
which always reboots fine (tested with letux-4.18.7 and 4.19-rc1 and 4.14.58).
Either
modprobe pwm_omap_dmtimer
OR (!)
modprobe snd_soc_omap_abe_twl6040
before "reboot" makes the Pyra boot hang with the dpll_abe_ck failure.
Generally it reminds me a little of the pinctrl and generic-adc-battery drivers problem where it turned out that the main problem was a write-out-of-bounds in generic-adc-battery so that it did occur only if drivers were loaded in a specifc sequence.
But this here is more reproducible. On the Pyra.
I am still trying to reproduce the effect on the omap5evm by amending the mainline DTS. It does reboot with these modules loaded...
What I alread wonder is what
- dpll_abe_ck setup
- pwm_omap_dmtimer
- snd_soc_omap_abe_twl6040
They are most likely using the same source clock (dpll_abe_ck.)
- Some PWMs (GPtimers) use ABE as clock source, depending on DT config you might be using a PWM which uses ABE clocks - Also TWL6040 uses ABE clock as source, as it is used for audio
-Tero
have in common so that they can influence each other?
hwmods? clock setup? dividers? plls?
BR, Nikolaus
-- Texas Instruments Finland Oy, Porkkalankatu 22, 00180 Helsinki. Y-tunnus/Business ID: 0615521-4. Kotipaikka/Domicile: Helsinki
Hi Tero,
Am 12.09.2018 um 19:19 schrieb Tero Kristo t-kristo@ti.com:
On 12/09/18 19:17, H. Nikolaus Schaller wrote:
Hi Tony,
Am 12.09.2018 um 02:03 schrieb Tony Lindgren tony@atomide.com:
- H. Nikolaus Schaller hns@goldelico.com [180911 18:28]:
BTW: blacklisting pwm_bl makes CLKACTIVITY_DPLL_ABE_X2_CLK show the right value but reboot still can't transition dpll_abe_ck to 'locked'.
After adding back all modules except pwm_omap_dmtimer the problem comes back to the Pyra. And adding a omap-dmtimer-pwm to the omap5-uevm.dts does make CLKACTIVITY_DPLL_ABE_X2_CLK become 0x803 as I see on the Pyra, but it still handles reboots properly.
More test results to come tomorrow.
OK good to hear you got it narrowed down.
I have further narrowed it down to root@letux:~# more /etc/modprobe.d/pwm.conf blacklist pwm_omap_dmtimer blacklist snd_soc_omap_abe_twl6040 root@letux:~# which always reboots fine (tested with letux-4.18.7 and 4.19-rc1 and 4.14.58). Either modprobe pwm_omap_dmtimer OR (!) modprobe snd_soc_omap_abe_twl6040 before "reboot" makes the Pyra boot hang with the dpll_abe_ck failure. Generally it reminds me a little of the pinctrl and generic-adc-battery drivers problem where it turned out that the main problem was a write-out-of-bounds in generic-adc-battery so that it did occur only if drivers were loaded in a specifc sequence. But this here is more reproducible. On the Pyra. I am still trying to reproduce the effect on the omap5evm by amending the mainline DTS. It does reboot with these modules loaded... What I alread wonder is what
- dpll_abe_ck setup
- pwm_omap_dmtimer
- snd_soc_omap_abe_twl6040
They are most likely using the same source clock (dpll_abe_ck.)
- Some PWMs (GPtimers) use ABE as clock source, depending on DT config you might be using a PWM which uses ABE clocks
Intersting!
Pyra uses timer9 for display backlight PWM and timer8 for keyboard backlight PWM.
Table 23-3: timer8 (and 5-7) gets ICLK and RST from ABE while timer9 (and others) gets them from L4_PER.
And Table 3-242 also lists McBSP which are not activated on the evm. This makes another difference. Figure 3-37 is also informative.
- Also TWL6040 uses ABE clock as source, as it is used for audio
So as a working hypothesis, these drivers might do conflicting clock enable/reset activities or prevent them from being disabled during preparation for reboot.
I have done further tests on the Pyra and
a) the problem with pwm_bl goes away if I comment out the keyboard backlight (timer8) from DT and keep timer9 only. It can still independently be triggered by modprobing snd_soc_omap_abe_twl6040
b) it appears that the problem is already triggered by modprobe and does not go away by modprobe -r, so it is unlikely a cleanup problem before reboot.
All this indicates that some clock dividers or switches are not properly controlled.
But I have still not found what makes the significant difference between Pyra and uevm setup.
BR and thanks, Nikolaus
Hi,
Am 13.09.2018 um 12:16 schrieb H. Nikolaus Schaller hns@goldelico.com:
I have done further tests on the Pyra and
a) the problem with pwm_bl goes away if I comment out the keyboard backlight (timer8) from DT and keep timer9 only. It can still independently be triggered by modprobing snd_soc_omap_abe_twl6040
b) it appears that the problem is already triggered by modprobe and does not go away by modprobe -r, so it is unlikely a cleanup problem before reboot.
All this indicates that some clock dividers or switches are not properly controlled.
But I have still not found what makes the significant difference between Pyra and uevm setup.
Having done more experiments, I found the following.
I see the problem on Pyra even when only modprobing pwm_omap_dmtimer but not pwm_bl. So the problem is indeed in omap timer/pwm management and not outside.
This means the backlight pwm isn't even active and I have checked that there are no calls to pwm_omap_dmtimer_config() or pwm_omap_dmtimer_enable() because pwm_bl isn't loaded.
A simple run through pwm_omap_dmtimer_probe() by modprobe pwm_omap_dmtimer suffices to trigger the reboot problem afterwards.
Next, I tried to inject printk() into pwm_omap_dmtimer_probe() to isolate where the problem starts.
It turns out that disabling the call
dm_timer = pdata->request_by_node(timer);
in drivers/pwm/pwm-omap-dmtimer.c suffices to make the problem go away. Of course without working PWM even if I modprobe pwm_bl.
This seems to call _omap_dm_timer_request().
The deepest level I could identify is the call to
pm_runtime_get_sync(&timer->pdev->dev);
in omap_dm_timer_enable().
If I make omap_dm_timer_enable() return 0 before this call, I can reboot without problems.
The call sequence known to trigger the problem is so far:
pwm_omap_dmtimer_probe() dm_timer = pdata->request_by_node(timer); omap_dm_timer_request_by_node(); _omap_dm_timer_request(); omap_dm_timer_enable() pm_runtime_get_sync(&timer->pdev->dev);
So it is a pm_runtime problem for timer8 (and others).
But not really in the pwm-omap-dmtimer and timer-ti-dm drivers but it collides with something else (which is on the Pyra but not on the OMAP5EVM).
I had thought about adding printk into pm_runtime_get_sync but this is no longer specific to the dm-timers. The same would be for printk in the hwmods for timers.
Any suggestions how to find out what the second factor could be?
BR and thanks, Nikolaus
On 15/09/18 18:50, H. Nikolaus Schaller wrote:
Hi,
Am 13.09.2018 um 12:16 schrieb H. Nikolaus Schaller hns@goldelico.com:
I have done further tests on the Pyra and
a) the problem with pwm_bl goes away if I comment out the keyboard backlight (timer8) from DT and keep timer9 only. It can still independently be triggered by modprobing snd_soc_omap_abe_twl6040
b) it appears that the problem is already triggered by modprobe and does not go away by modprobe -r, so it is unlikely a cleanup problem before reboot.
All this indicates that some clock dividers or switches are not properly controlled.
But I have still not found what makes the significant difference between Pyra and uevm setup.
Having done more experiments, I found the following.
I see the problem on Pyra even when only modprobing pwm_omap_dmtimer but not pwm_bl. So the problem is indeed in omap timer/pwm management and not outside.
This means the backlight pwm isn't even active and I have checked that there are no calls to pwm_omap_dmtimer_config() or pwm_omap_dmtimer_enable() because pwm_bl isn't loaded.
A simple run through pwm_omap_dmtimer_probe() by modprobe pwm_omap_dmtimer suffices to trigger the reboot problem afterwards.
Next, I tried to inject printk() into pwm_omap_dmtimer_probe() to isolate where the problem starts.
It turns out that disabling the call
dm_timer = pdata->request_by_node(timer);
in drivers/pwm/pwm-omap-dmtimer.c suffices to make the problem go away. Of course without working PWM even if I modprobe pwm_bl.
This seems to call _omap_dm_timer_request().
The deepest level I could identify is the call to
pm_runtime_get_sync(&timer->pdev->dev);
in omap_dm_timer_enable().
If I make omap_dm_timer_enable() return 0 before this call, I can reboot without problems.
The call sequence known to trigger the problem is so far:
pwm_omap_dmtimer_probe() dm_timer = pdata->request_by_node(timer); omap_dm_timer_request_by_node(); _omap_dm_timer_request(); omap_dm_timer_enable() pm_runtime_get_sync(&timer->pdev->dev);
So it is a pm_runtime problem for timer8 (and others).
But not really in the pwm-omap-dmtimer and timer-ti-dm drivers but it collides with something else (which is on the Pyra but not on the OMAP5EVM).
I had thought about adding printk into pm_runtime_get_sync but this is no longer specific to the dm-timers. The same would be for printk in the hwmods for timers.
Any suggestions how to find out what the second factor could be?
Have you traced the reset signals on your board? How is sys_nreswarm connected for example compared to omap5uevm board? What happens if you replace the warm reset with a cold reset? Try replacing the warm reset from omap4_prminst_global_warm_sw_reset() with cold reset (just change the bit used to reset the device.)
It looks like in case of pyra, the resets are not passed in properly, leaving some pieces of HW (like ABE) in bad state. None of the register level settings should impact the result of warm reset in ideal world, however there are some warm reset erratas in place for the device which call for proper routing of reset signals on the board itself, and might have impact.
Have you looked at the errata documents whether any of those apply to your design?
-Tero -- Texas Instruments Finland Oy, Porkkalankatu 22, 00180 Helsinki. Y-tunnus/Business ID: 0615521-4. Kotipaikka/Domicile: Helsinki
Hi Tero, sorry for the delayed response.
Am 17.09.2018 um 09:30 schrieb Tero Kristo t-kristo@ti.com:
On 15/09/18 18:50, H. Nikolaus Schaller wrote:
Hi,
Am 13.09.2018 um 12:16 schrieb H. Nikolaus Schaller hns@goldelico.com:
I have done further tests on the Pyra and
a) the problem with pwm_bl goes away if I comment out the keyboard backlight (timer8) from DT and keep timer9 only. It can still independently be triggered by modprobing snd_soc_omap_abe_twl6040
b) it appears that the problem is already triggered by modprobe and does not go away by modprobe -r, so it is unlikely a cleanup problem before reboot.
All this indicates that some clock dividers or switches are not properly controlled.
But I have still not found what makes the significant difference between Pyra and uevm setup.
Having done more experiments, I found the following. I see the problem on Pyra even when only modprobing pwm_omap_dmtimer but not pwm_bl. So the problem is indeed in omap timer/pwm management and not outside. This means the backlight pwm isn't even active and I have checked that there are no calls to pwm_omap_dmtimer_config() or pwm_omap_dmtimer_enable() because pwm_bl isn't loaded. A simple run through pwm_omap_dmtimer_probe() by modprobe pwm_omap_dmtimer suffices to trigger the reboot problem afterwards. Next, I tried to inject printk() into pwm_omap_dmtimer_probe() to isolate where the problem starts. It turns out that disabling the call dm_timer = pdata->request_by_node(timer); in drivers/pwm/pwm-omap-dmtimer.c suffices to make the problem go away. Of course without working PWM even if I modprobe pwm_bl. This seems to call _omap_dm_timer_request(). The deepest level I could identify is the call to pm_runtime_get_sync(&timer->pdev->dev); in omap_dm_timer_enable(). If I make omap_dm_timer_enable() return 0 before this call, I can reboot without problems. The call sequence known to trigger the problem is so far: pwm_omap_dmtimer_probe() dm_timer = pdata->request_by_node(timer); omap_dm_timer_request_by_node(); _omap_dm_timer_request(); omap_dm_timer_enable() pm_runtime_get_sync(&timer->pdev->dev); So it is a pm_runtime problem for timer8 (and others). But not really in the pwm-omap-dmtimer and timer-ti-dm drivers but it collides with something else (which is on the Pyra but not on the OMAP5EVM). I had thought about adding printk into pm_runtime_get_sync but this is no longer specific to the dm-timers. The same would be for printk in the hwmods for timers. Any suggestions how to find out what the second factor could be?
Have you traced the reset signals on your board? How is sys_nreswarm connected for example compared to omap5uevm board?
I have done this comparison and we have indeed differences. The tca6424 is not connected to nreswarm on the Pyra (but to a separate gpio which is activated by u-boot). And there is a potentially very significant one: we have added an 1nF capacitor to GND.
The reason is that the nreswarm line was found to be extremely sensitive to external noise in nanosecond time frame. It suffices to tap the nreswarm pad of the RESET button with a 30 cm long measurement cable with nothing connected to the other end, to to trigger a reboot. So the tiny capacitive energy of the cable seems to trigger a reset. And this happens although the nreswarm has a 10 kOhm pull-up to 1.8V so that it should be sufficiently protected for ESD. I noticed that effect when trying to oscilloscope the nreswarm signal on the Pyra two years ago.
But before we draw the conclusion that this is the reason of the problem: I have this capacitor also installed on one EVM as well. And a second one without. Both do the "reboot" fine, while the Pyra doesn't. I have not yet tried to reboot a Pyra with this capacitor removed.
And tonight I received a private message through the openpandora forum that someone tried this on the igep5 and has the same reboot problem:
Blacklisting snd_soc_omap_abe_twl6040 also solves the reboot issue on the igep.
I asked for config and setup:
I used the 4.19-rc5 mainline with only the omap2plus_defconfig, no option changed, GCC-8.2.0.
So if you happen to own an igep5, please check if you can reproduce it there with mainline kernel.
What happens if you replace the warm reset with a cold reset? Try replacing the warm reset from omap4_prminst_global_warm_sw_reset() with cold reset (just change the bit used to reset the device.)
I have this on my to-do list.
As a first look, there seems to be a delay constant MAX_MODULE_HARDRESET_WAIT for 10µs. Well, 10 kOhm and 1 nF is a time constant of 10 µs. So the reset impulse and wait time may be too short for the Pyra (and long enough for the EVM by pure chance)...
It looks like in case of pyra, the resets are not passed in properly, leaving some pieces of HW (like ABE) in bad state. None of the register level settings should impact the result of warm reset in ideal world, however there are some warm reset erratas in place for the device which call for proper routing of reset signals on the board itself, and might have impact.
Have you looked at the errata documents whether any of those apply to your design?
Have this on my to-do as well.
BR and thanks, Nikolaus
Hi Tero,
Am 25.09.2018 um 08:47 schrieb H. Nikolaus Schaller hns@goldelico.com:
Hi Tero, sorry for the delayed response.
Am 17.09.2018 um 09:30 schrieb Tero Kristo t-kristo@ti.com:
On 15/09/18 18:50, H. Nikolaus Schaller wrote:
Hi,
Am 13.09.2018 um 12:16 schrieb H. Nikolaus Schaller hns@goldelico.com:
I have done further tests on the Pyra and
a) the problem with pwm_bl goes away if I comment out the keyboard backlight (timer8) from DT and keep timer9 only. It can still independently be triggered by modprobing snd_soc_omap_abe_twl6040
b) it appears that the problem is already triggered by modprobe and does not go away by modprobe -r, so it is unlikely a cleanup problem before reboot.
All this indicates that some clock dividers or switches are not properly controlled.
But I have still not found what makes the significant difference between Pyra and uevm setup.
Having done more experiments, I found the following. I see the problem on Pyra even when only modprobing pwm_omap_dmtimer but not pwm_bl. So the problem is indeed in omap timer/pwm management and not outside. This means the backlight pwm isn't even active and I have checked that there are no calls to pwm_omap_dmtimer_config() or pwm_omap_dmtimer_enable() because pwm_bl isn't loaded. A simple run through pwm_omap_dmtimer_probe() by modprobe pwm_omap_dmtimer suffices to trigger the reboot problem afterwards. Next, I tried to inject printk() into pwm_omap_dmtimer_probe() to isolate where the problem starts. It turns out that disabling the call dm_timer = pdata->request_by_node(timer); in drivers/pwm/pwm-omap-dmtimer.c suffices to make the problem go away. Of course without working PWM even if I modprobe pwm_bl. This seems to call _omap_dm_timer_request(). The deepest level I could identify is the call to pm_runtime_get_sync(&timer->pdev->dev); in omap_dm_timer_enable(). If I make omap_dm_timer_enable() return 0 before this call, I can reboot without problems. The call sequence known to trigger the problem is so far: pwm_omap_dmtimer_probe() dm_timer = pdata->request_by_node(timer); omap_dm_timer_request_by_node(); _omap_dm_timer_request(); omap_dm_timer_enable() pm_runtime_get_sync(&timer->pdev->dev); So it is a pm_runtime problem for timer8 (and others). But not really in the pwm-omap-dmtimer and timer-ti-dm drivers but it collides with something else (which is on the Pyra but not on the OMAP5EVM). I had thought about adding printk into pm_runtime_get_sync but this is no longer specific to the dm-timers. The same would be for printk in the hwmods for timers. Any suggestions how to find out what the second factor could be?
Have you traced the reset signals on your board? How is sys_nreswarm connected for example compared to omap5uevm board?
I have done this comparison and we have indeed differences. The tca6424 is not connected to nreswarm on the Pyra (but to a separate gpio which is activated by u-boot). And there is a potentially very significant one: we have added an 1nF capacitor to GND.
The reason is that the nreswarm line was found to be extremely sensitive to external noise in nanosecond time frame. It suffices to tap the nreswarm pad of the RESET button with a 30 cm long measurement cable with nothing connected to the other end, to to trigger a reboot. So the tiny capacitive energy of the cable seems to trigger a reset. And this happens although the nreswarm has a 10 kOhm pull-up to 1.8V so that it should be sufficiently protected for ESD. I noticed that effect when trying to oscilloscope the nreswarm signal on the Pyra two years ago.
But before we draw the conclusion that this is the reason of the problem: I have this capacitor also installed on one EVM as well. And a second one without. Both do the "reboot" fine, while the Pyra doesn't. I have not yet tried to reboot a Pyra with this capacitor removed.
And tonight I received a private message through the openpandora forum that someone tried this on the igep5 and has the same reboot problem:
Blacklisting snd_soc_omap_abe_twl6040 also solves the reboot issue on the igep.
I asked for config and setup:
I used the 4.19-rc5 mainline with only the omap2plus_defconfig, no option changed, GCC-8.2.0.
So if you happen to own an igep5, please check if you can reproduce it there with mainline kernel.
What happens if you replace the warm reset with a cold reset? Try replacing the warm reset from omap4_prminst_global_warm_sw_reset() with cold reset (just change the bit used to reset the device.)
I have this on my to-do list.
As a first look, there seems to be a delay constant MAX_MODULE_HARDRESET_WAIT for 10µs. Well, 10 kOhm and 1 nF is a time constant of 10 µs. So the reset impulse and wait time may be too short for the Pyra (and long enough for the EVM by pure chance)...
It looks like in case of pyra, the resets are not passed in properly, leaving some pieces of HW (like ABE) in bad state. None of the register level settings should impact the result of warm reset in ideal world, however there are some warm reset erratas in place for the device which call for proper routing of reset signals on the board itself, and might have impact.
Have you looked at the errata documents whether any of those apply to your design?
Have this on my to-do as well.
I have now checked with SWPZ018O and SWPZ037D. The first one talks about an erratum (ID: i744) with ES1.0 but we have ES2.0 chips. The second document doesn't mention NRES errata at all.
There is only ID: i831 which says that the ABE firmware can only be loaded after a cold reset. But we are not even at the point of trying to load firmware after a warm reset (or cold reset)...
BR, Nikolaus
-
H. Nikolaus Schaller -
Tero Kristo -
Tony Lindgren