AM3352: Low frequency working test

Maciej Kochman

Part Number: AM3352

Hi,

I've created a custom board, based on BeagleBone Black. I'm using am3352.

I'm working on PROCESSOR-SDK-LINUX-AM335X 06_03_00_106.

I'm using the same low frequency RTC as in BBB.

How can I test the oscillator on Arago? For example I want to go to sleep and wake-up using this oscillator.

over 4 years ago

0 Nick Saulnier over 4 years ago

TI__Guru** 103210 points

Hello,

I am not clear on what you are asking about. Are you asking about how to transition power states in Linux on AM335x?

Regards,

Nick

0 Adam Kozlowski over 4 years ago in reply to Nick Saulnier

Expert 1805 points

Hi Nick

I want to clarify what Maciej wrote.
We do have a prototype based on BBB (AM3352).
Before the next round of prototyping, we want to check each circuit to ensure that there are no bugs and that it's properly configured.
Currently, we want to validate the operation of the RTC_SS circuit (with an external 32k crystal).

Assuming we use Uboot and the Linux SDK and have prepared .dts for our custom board, how can we find answers to the following questions?

1) Is the RTC_SS working correctly?
2) Is the RTC_SS appropriately configured in the DTS file (and/or Uboot)?
3) How can we make use of this RTC_SS circuit in Linux? Is there any tool/service that can transit between low power and active modes?

Regards
Adam

0 Nick Saulnier over 4 years ago in reply to Adam Kozlowski

TI__Guru** 103210 points

Hello Adam,

I am sending your question to a member of our hardware team to comment first. Then they can pass you over to the Linux power owner. Please ping the thread if you have not received a reply in a day or so.

Regards,

Nick

0 Adam Kozlowski over 4 years ago in reply to Nick Saulnier

Expert 1805 points

Hi,

Is there any information on this subject?

Regards,
Adam

0 peaves over 4 years ago in reply to Adam Kozlowski

TI__Guru 63175 points

Nick must have assigned this post to me without realizing I was on vacation. I just logged in to check emails and saw this post was assigned to me.

I will be re-assigning this post back to Nick since your verification task is a software function and not sure who supports Linux RTC software.

0 peaves over 4 years ago in reply to peaves

TI__Guru 63175 points

Nick ask me to assign it to someone from our Linux team. Hopefully, they will reply soon.

Regards,
Paul

0 Adam Kozlowski over 4 years ago in reply to peaves

Expert 1805 points

Have a nice break. We'll see who will pick me up.

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

Adam Kozlowski said:
3) How can we make use of this RTC_SS circuit in Linux? Is there any tool/service that can transit between low power and active modes?

You can use rtcwake command. It will put the system to suspend and resume after a given time. For example,

# rtcwake -m standby -s 5

Use 'rtcwake -h' command to get more details.

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin

Would you help me to find answers to the two remaining questions?
1) Is the RTC_SS working correctly?
2) Is the RTC_SS appropriately configured in the DTS file (and/or Uboot)?

My .dts file has the following section:
"
&rtc {
   clocks = <&clk_32768_ck>, <&l4_per_clkctrl AM3_CLKDIV32K_CLKCTRL 0>;
   clock-names = "ext-clk", "int-clk";
   system-power-controller;
};
"
Assuming I want to use an external 32k crystal, is this configuration correct?
In the TRM, I've seen an option to output CLK_32k to the external pin CLKOUT2. How can I set CM_CLKOUT_CTRL register to output 32k_OSC to the CLKOUT2 pin?
How can I check if I use an internal 32k signal or oscillator with an external crystal?
TRM, 20.3.3.2 ClockSource - "
The clock reference for the RTC can be sourced from an external crystal(used with the 32K RTC Oscillator), an external 32KHz oscillator, or from the Peripheral PLL.
...
The oscillator can be enabled or disabled by using the RTC_OSC_REG register."

ad3)
The "rtcwake" command is working but in a strange way. Specifying -s 5 (5 seconds) suspends Linux for about 15s.
Is this the correct operation? What can this cause?

Regards
Adam

0 peaves over 4 years ago in reply to Adam Kozlowski

TI__Guru 63175 points

Why are you needing to verify CLK_32k by sending it to a pin? Is there a reason you can't verify the clock source is operational with a basic functional test of the RTC?

The RTC can be sourced from the Peripheral PLL or RTC oscillator. However, I recommend using the Peripheral PLL as the source if you are not planning to use the RTC to cycle power to the remainder of the SOC. This recommendation is based on several customers experiencing noise coupling into their 32 kHz crystal circuit. You may want to read Advisory 1.0.30 in the silicon errata, where this topic is introduced.

I will let Bin answer your question about Linux configuration required for your specific clock source implementation.

Regards,
Paul

0 Adam Kozlowski over 4 years ago in reply to peaves

Expert 1805 points

peaves said:
Why are you needing to verify CLK_32k by sending it to a pin?

To check the signal quality and start-up time, and adjust RC components accordingly.

peaves said:
You may want to read Advisory 1.0.30 in the silicon errata, where this topic is introduced.

Thanks for the tip. I've read this carefully, and I think our circuits are properly grounded.

peaves said:
However, I recommend using the Peripheral PLL as the source if you are not planning to use the RTC to cycle power to the remainder of the SOC.

In fact, I have a separate power source for the RTC domain. I haven't found all the "puzzles" to make it work yet, but I am trying to gather all the information.

BR
Adam

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

Sorry, I am confused by all your questions/information above, and not sure how to provide support. What is the purpose of the RTC in your system? What issue do you have in the RTC functions?

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin,

We have several people in this thread and too much information.
Let me summarize.

Background:
I want to configure RTC in AM3352 to use an external 32k crystal.
My .dts file has the following section:
"
&rtc {
clocks = <&clk_32768_ck>, <&l4_per_clkctrl AM3_CLKDIV32K_CLKCTRL 0>;
clock-names = "ext-clk", "int-clk";
system-power-controller;
};
"

Questions:
1) Assuming I want to use an external 32k crystal, is this configuration in my .dts file correct?

2) What should I change in my .dts file to output 32k signal to the CLKOUT2 pin? (see TRM 8.1.6.12 CLKOUT Signals)

3) Once I invoke "rtcwake -m standby -s 5" Linux suspends for about 15 seconds (instead of 5s). Is this behavior correct? How to fix it?

Regards
Adam

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

Thanks for the clarification, it helps.

Adam Kozlowski said:
1) Assuming I want to use an external 32k crystal, is this configuration in my .dts file correct?

It looks correct. The kernel RTC driver configures to use the external clock if "ext-clk" is specified in dts, the "int-clk" is ignored. Please see the kernel code below.

 758         rtc->clk = devm_clk_get(&pdev->dev, "ext-clk");                         
 759         if (!IS_ERR(rtc->clk))                                                  
 760                 rtc->has_ext_clk = true;                                        
 761         else                                                                    
 762                 rtc->clk = devm_clk_get(&pdev->dev, "int-clk");                 
 763                                                                                 
 764         if (!IS_ERR(rtc->clk))                                                  
 765                 clk_prepare_enable(rtc->clk);

Adam Kozlowski said:
2) What should I change in my .dts file to output 32k signal to the CLKOUT2 pin? (see TRM 8.1.6.12 CLKOUT Signals)

I am in the mid of a work, and will check on it on this Friday and get you back.

Adam Kozlowski said:
3) Once I invoke "rtcwake -m standby -s 5" Linux suspends for about 15 seconds (instead of 5s). Is this behavior correct? How to fix it?

How did you observe this 15 seconds? Is it the time between the follow two lines in console log or until the entire resume completed? Please note that the RTC will generate wakeup event in 5 seconds but the entire Linux takes longer to wake up.

[  187.507073] Suspending console(s) (use no_console_suspend to debug)                                                                                         
[  187.652104] cpsw 4a100000.ethernet eth0: Link is Down

0 peaves over 4 years ago in reply to Adam Kozlowski

TI__Guru 63175 points

Looking at the 32 kHz reference clock produced by the RTC oscillator via CLKOUT2 provides limited information about oscillator/crystal circuit operation.

The most important thing to verify with the oscillator/crystal circuit is to confirm the internal oscillator has enough gain margin to always begin oscillation when combined with your external crystal circuit. Looking at the output of the oscillator on CLKOUT2 only confirms the specific crystal and SOC combination begins oscillation under the current operating conditions.

There are other techniques that can be used to confirm gain margin of the oscillator/crystal circuit. You can insert resistance in series with the crystal, not the entire crystal circuit, which increases the Effective Series Resistance (ESR) of the crystal as seen by the circuit. To ensure the oscillator/crystal circuit has enough gain margin across multiple crystals, you should insert a resistor that is at least 3x the crystal's ESR and confirm it always starts oscillation across the entire operating range expected for your system. Oscillation can be verified by observing the presence of the 32 kHz clock on CLKOUT2 or simply confirming the RTC is keeping time.

Bin is trying to understand how your system is using the RTC so he can help you configure it for that use case.

Now lets come back to my concern of noise coupling into the 32 kHz crystal circuit. The ESR of the 32 kHz crystal circuit is much higher than the ESR of the high frequency crystal circuit, so it is much easier for noise to couple into it and cause problems. This is why you should seriously consider use the Peripheral PLL source if your system is not planning to use the RTC to cycle power to the remainder of the device. Several customers have experienced their 32 kHz crystal circuit picking up noise and causing problems even after changing the crystal ground as shown in the latest recommendation. If you must use the 32 kHz crystal circuit to source the RTC, you will need to be very careful with your PCB layout and system interconnects to mitigate noise sources and coupling the 32 kHz crystal circuit.

Regards,
Paul

0 Adam Kozlowski over 4 years ago in reply to peaves

Expert 1805 points

Hi Paul,

Thank you for your detailed answer.

I'm not 100% sure if I correctly understand this phrase "... to use the RTC to cycle power to the remainder of the device.".
Do you mean the "RTC only" mode?
So the situation when only the RTC rail is powered, and the rest of the device is powered off.

If so, yes. I would like to use the "RTC only" mode finally.
Unfortunately, I have the AM335x-PMIC configuration based on the BBB, so I use TPS65217C.

According to this
https://e2e.ti.com/support/processors/f/processors-forum/711543/am3351-rtc-only-mode-with-tps65217d
the TPS65217C cannot be used in RTC only mode, but I want to check every configuration to be ready.

peaves said:
Several customers have experienced their 32 kHz crystal circuit picking up noise and causing problems even after changing the crystal ground as shown in the latest recommendation.

Good to know. I can think of an external oscillator (e.g. TCXO) but want to investigate all options. There is no other way to gain this knowledge than by talking to you.

Regards
Adam

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin,

Bin Liu said:
How did you observe this 15 seconds? Is it the time between the follow two lines in console log or until the entire resume completed?

I have the custom board connected to the external power supply. When the board is ACTIVE, I see 170mA. After invoking this command, the current goes down to 40mA and after X seconds back to 170mA.
This X seconds sometimes is equal to 15s or 1 minute and sometimes even more.
Always I can press the spacebar, and the power goes to 170mA immediately, and I see the Linux prompt active.

Regards
Adam

0 peaves over 4 years ago in reply to Adam Kozlowski

TI__Guru 63175 points

Yes. The RTC stays powered while the remainder of the devices is powered off. In this topology, RTC cycles power to the remainder of the device. Once your software boots after first power-on it will configure the RTC. At some point when your OS decides power-down, it will set a wakeup time in the RTC than tell the RTC to power off the remainder portion of the device. When the wakeup time passes, the RTC will turn power on again and your system will reboot again.

When using this topology you must use a crystal circuit or 1.8V LVCMOS reference clock source. I recommend the LVCMOS option to minimize risk associated with noise coupling into the crystal circuit. I also suggest selecting a 1.8V LVCMOS clock source with a fast/rise fall time. If you can find one it may be best if use strong output buffer to source a fast rise/fall signal to the RTC oscillator. This will minimize the chance of noise coupling on this signal as it slowly crosses the input buffer switching threshold.

Regards,
Paul

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

Adam Kozlowski said:
This X seconds sometimes is equal to 15s or 1 minute and sometimes even more.

I didn't hear similar issue before and have to think about how to debug it. Can you please first attach the full Linux boot log?

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin,

Please, find the log attached.

Fullscreen GW4_Log.txt Download

U-Boot SPL 2019.01-gc14892445a-dirty (May 06 2021 - 09:25:37 +0200)
Trying to boot from MMC1


U-Boot 2019.01-gc14892445a-dirty (May 06 2021 - 09:25:37 +0200)

CPU  : AM335X-GP rev 2.1
Model: TI AM335x Gateway4
DRAM:  512 MiB
MMC:   OMAP SD/MMC: 0, OMAP SD/MMC: 1
Loading Environment from FAT... *** Warning - bad CRC, using default environment

<ethaddr> not set. Validating first E-fuse MAC
Net:   eth0: ethernet@4a100000
Hit any key to stop autoboot:  0 
switch to partitions #0, OK
mmc0 is current device
SD/MMC found on device 0
** Unable to read file boot.scr **
** Unable to read file uEnv.txt **
switch to partitions #0, OK
mmc0 is current device
Scanning mmc 0:1...
switch to partitions #0, OK
mmc0 is current device
SD/MMC found on device 0
4280832 bytes read in 363 ms (11.2 MiB/s)
34436 bytes read in 4 ms (8.2 MiB/s)
## Flattened Device Tree blob at 88000000
   Booting using the fdt blob at 0x88000000
   Loading Device Tree to 87ff4000, end 87fff683 ... OK

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.19.94-gbe5389fd85 (oe-user@oe-host) (gcc version 8.3.0 (GNU Toolchain for the A-profile Architecture 8.3-2019.03 (arm-rel-8.36))) #1 PREEMPT Sun Apr 19 03:43:09 UTC 2020
[    0.000000] CPU: ARMv7 Processor [413fc082] revision 2 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: TI AM335x GATEWAY4
[    0.000000] Memory policy: Data cache writeback
[    0.000000] efi: Getting EFI parameters from FDT:
[    0.000000] efi: UEFI not found.
[    0.000000] cma: Reserved 48 MiB at 0x9d000000
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] AM335X ES2.1 (neon)
[    0.000000] random: get_random_bytes called from start_kernel+0xa4/0x434 with crng_init=0
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 129920
[    0.000000] Kernel command line: console=ttyO0,115200n8 root=PARTUUID=998f0e4d-02 rw rootfstype=ext4 rootwait
[    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.000000] Memory: 455964K/524288K available (9216K kernel code, 307K rwdata, 2720K rodata, 1024K init, 252K bss, 19172K reserved, 49152K cma-reserved, 0K highmem)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0xe0800000 - 0xff800000   ( 496 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xe0000000   ( 512 MB)
[    0.000000]     pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
[    0.000000]     modules : 0xbf000000 - 0xbfe00000   (  14 MB)
[    0.000000]       .text : 0x(ptrval) - 0x(ptrval)   (10208 kB)
[    0.000000]       .init : 0x(ptrval) - 0x(ptrval)   (1024 kB)
[    0.000000]       .data : 0x(ptrval) - 0x(ptrval)   ( 308 kB)
[    0.000000]        .bss : 0x(ptrval) - 0x(ptrval)   ( 253 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] rcu: Preemptible hierarchical RCU implementation.
[    0.000000]  Tasks RCU enabled.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] IRQ: Found an INTC at 0x(ptrval) (revision 5.0) with 128 interrupts
[    0.000000] OMAP clockevent source: timer2 at 24000000 Hz
[    0.000021] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 89478484971ns
[    0.000048] clocksource: timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
[    0.000064] OMAP clocksource: timer1 at 24000000 Hz
[    0.000288] timer_probe: no matching timers found
[    0.000531] Console: colour dummy device 80x30
[    0.000568] WARNING: Your 'console=ttyO0' has been replaced by 'ttyS0'
[    0.000577] This ensures that you still see kernel messages. Please
[    0.000585] update your kernel commandline.
[    0.000656] Calibrating delay loop... 597.60 BogoMIPS (lpj=2988032)
[    0.118727] pid_max: default: 32768 minimum: 301
[    0.119009] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.119029] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.120137] CPU: Testing write buffer coherency: ok
[    0.120224] CPU0: Spectre v2: using BPIALL workaround
[    0.121398] Setting up static identity map for 0x80100000 - 0x80100060
[    0.121608] rcu: Hierarchical SRCU implementation.
[    0.122083] EFI services will not be available.
[    0.124048] devtmpfs: initialized
[    0.135019] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3
[    0.135555] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.135589] futex hash table entries: 256 (order: -1, 3072 bytes)
[    0.140596] pinctrl core: initialized pinctrl subsystem
[    0.141605] DMI not present or invalid.
[    0.142166] NET: Registered protocol family 16
[    0.145389] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.175735] l4_wkup_cm:clk:0010:0: failed to disable
[    0.231093] cpuidle: using governor ladder
[    0.231147] cpuidle: using governor menu
[    0.238247] OMAP GPIO hardware version 0.1
[    0.250486] No ATAGs?
[    0.250503] hw-breakpoint: debug architecture 0x4 unsupported.
[    0.270620] edma 49000000.edma: TI EDMA DMA engine driver
[    0.274754] SCSI subsystem initialized
[    0.275381] media: Linux media interface: v0.10
[    0.275448] videodev: Linux video capture interface: v2.00
[    0.275589] pps_core: LinuxPPS API ver. 1 registered
[    0.275602] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.275636] PTP clock support registered
[    0.275686] EDAC MC: Ver: 3.0.0
[    0.277153] omap-mailbox 480c8000.mailbox: omap mailbox rev 0x400
[    0.277923] Advanced Linux Sound Architecture Driver Initialized.
[    0.279843] clocksource: Switched to clocksource timer1
[    0.291900] NET: Registered protocol family 2
[    0.293022] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 4096 bytes)
[    0.293074] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
[    0.293139] TCP bind hash table entries: 4096 (order: 2, 16384 bytes)
[    0.293201] TCP: Hash tables configured (established 4096 bind 4096)
[    0.293343] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.293373] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.293582] NET: Registered protocol family 1
[    0.294370] RPC: Registered named UNIX socket transport module.
[    0.294390] RPC: Registered udp transport module.
[    0.294399] RPC: Registered tcp transport module.
[    0.294409] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.295638] hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available
[    0.297355] Initialise system trusted keyrings
[    0.297784] workingset: timestamp_bits=14 max_order=17 bucket_order=3
[    0.304867] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.305903] NFS: Registering the id_resolver key type
[    0.305962] Key type id_resolver registered
[    0.305974] Key type id_legacy registered
[    0.306035] ntfs: driver 2.1.32 [Flags: R/O].
[    0.309261] Key type asymmetric registered
[    0.309285] Asymmetric key parser 'x509' registered
[    0.309381] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 245)
[    0.309400] io scheduler noop registered
[    0.309411] io scheduler deadline registered
[    0.309754] io scheduler cfq registered (default)
[    0.309771] io scheduler mq-deadline registered
[    0.309783] io scheduler kyber registered
[    0.312373] pinctrl-single 44e10800.pinmux: 142 pins, size 568
[    0.385664] Serial: 8250/16550 driver, 10 ports, IRQ sharing enabled
[    0.391314] 44e09000.serial: ttyS0 at MMIO 0x44e09000 (irq = 30, base_baud = 3000000) is a 8250
[    1.009457] console [ttyS0] enabled
[    1.015643] omap_rng 48310000.rng: Random Number Generator ver. 20
[    1.022082] random: fast init done
[    1.025765] random: crng init done
[    1.047086] brd: module loaded
[    1.059681] loop: module loaded
[    1.068173] libphy: Fixed MDIO Bus: probed
[    1.149934] davinci_mdio 4a101000.mdio: davinci mdio revision 1.6, bus freq 1000000
[    1.157645] davinci_mdio 4a101000.mdio: detected phy mask fffffffd
[    1.165158] libphy: 4a101000.mdio: probed
[    1.169216] davinci_mdio 4a101000.mdio: phy[1]: device 4a101000.mdio:01, driver unknown
[    1.178592] cpsw 4a100000.ethernet: Detected MACID = 14:42:fc:bb:02:83
[    1.185522] cpsw 4a100000.ethernet: initialized cpsw ale version 1.4
[    1.192041] cpsw 4a100000.ethernet: ALE Table size 1024
[    1.197341] cpsw 4a100000.ethernet: cpts: overflow check period 500 (jiffies)
[    1.206532] i2c /dev entries driver
[    1.212824] cpuidle: enable-method property 'ti,am3352' found operations
[    1.220335] sdhci: Secure Digital Host Controller Interface driver
[    1.226557] sdhci: Copyright(c) Pierre Ossman
[    1.232036] omap_gpio 481ae000.gpio: Could not set line 14 debounce to 200000 microseconds (-22)
[    1.240986] omap_hsmmc 48060000.mmc: Got CD GPIO
[    1.246315] omap_hsmmc 48060000.mmc: Linked as a consumer to regulator.1
[    1.280575] omap_hsmmc 481d8000.mmc: Linked as a consumer to regulator.1
[    1.313209] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.321749] ledtrig-cpu: registered to indicate activity on CPUs
[    1.327908] mmc0: host does not support reading read-only switch, assuming write-enable
[    1.342410] NET: Registered protocol family 10
[    1.348992] mmc0: new high speed SDHC card at address 1234
[    1.354870] Segment Routing with IPv6
[    1.358674] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
[    1.366213] mmcblk0: mmc0:1234 SA16G 14.5 GiB 
[    1.372351] NET: Registered protocol family 17
[    1.377222] Key type dns_resolver registered
[    1.383090] omap_voltage_late_init: Voltage driver support not added
[    1.389743]  mmcblk0: p1 p2
[    1.395451] Loading compiled-in X.509 certificates
[    1.406332] mmc1: new high speed MMC card at address 0001
[    1.421744] mmcblk1: mmc1:0001 004GA0 3.69 GiB 
[    1.426979] mmcblk1boot0: mmc1:0001 004GA0 partition 1 2.00 MiB
[    1.435406] mmcblk1boot1: mmc1:0001 004GA0 partition 2 2.00 MiB
[    1.441779] mmcblk1rpmb: mmc1:0001 004GA0 partition 3 512 KiB, chardev (244:0)
[    1.450828]  mmcblk1: p1 p2
[    1.469810] tps65217 0-0024: TPS65217 ID 0xe version 1.2
[    1.475868] omap_i2c 44e0b000.i2c: bus 0 rev0.11 at 400 kHz
[    1.482335] cpu cpu0: Linked as a consumer to regulator.3
[    1.487866] cpu cpu0: Dropping the link to regulator.3
[    1.493544] cpu cpu0: Linked as a consumer to regulator.3
[    1.500831] hctosys: unable to open rtc device (rtc0)
[    1.506627] ALSA device list:
[    1.509618]   No soundcards found.
[    8.992650] EXT4-fs (mmcblk0p2): recovery complete
[    9.000526] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    9.009439] VFS: Mounted root (ext4 filesystem) on device 179:2.
[    9.025619] devtmpfs: mounted
[    9.030041] Freeing unused kernel memory: 1024K
[    9.035024] Run /sbin/init as init process
[    9.400614] systemd[1]: System time before build time, advancing clock.
[    9.453059] systemd[1]: systemd 239 running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKID -ELFUTILS +KMOD -IDN2 -IDN -PCRE2 default-hierarchy=hybrid)
[    9.475344] systemd[1]: Detected architecture arm.

Welcome to Arago 2019.11!

[    9.534216] systemd[1]: Set hostname to <Gateway4>.
[    9.859632] systemd[1]: File /lib/systemd/system/systemd-journald.service:36 configures an IP firewall (IPAddressDeny=any), but the local system does not support BPF/cgroup based firewalling.
[    9.877077] systemd[1]: Proceeding WITHOUT firewalling in effect! (This warning is only shown for the first loaded unit using IP firewalling.)
[   10.278876] systemd[1]: Listening on initctl Compatibility Named Pipe.
[  OK  ] Listening on initctl Compatibility Named Pipe.
[   10.324400] systemd[1]: Created slice system-serial\x2dgetty.slice.
[  OK  ] Created slice system-serial\x2dgetty.slice.
[   10.360578] systemd[1]: Reached target Remote File Systems.
[  OK  ] Reached target Remote File Systems.
[   10.390941] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[  OK  ] Started Dispatch Password Requests to Console Directory Watch.
[   10.431582] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[  OK  ] Started Forward Password Requests to Wall Directory Watch.
[  OK  ] Reached target Paths.
[  OK  ] Listening on Process Core Dump Socket.
[  OK  ] Listening on Journal Socket.
[  OK  ] Started Hardware RNG Entropy Gatherer Daemon.
         Mounting Kernel Debug File System...
         Starting Load Kernel Modules...
         Mounting POSIX Message Queue File System...
[  OK  ] Listening on udev Kernel Socket.
[   10.784437] cryptodev: loading out-of-tree module taints kernel.
[   10.794066] cryptodev: driver 1.9 loaded.
[  OK  ] Created slice User and Session Slice.
[  OK  ] Reached target Slices.
[   10.843923] usbcore: registered new interface driver usbfs
[   10.849533] usbcore: registered new interface driver hub
[   10.855590] usbcore: registered new device driver usb
[  OK  ] Listening on udev Control Socket.
[   10.886858] usbcore: registered new interface driver ftdi_sio
[   10.900501] usbserial: USB Serial support registered for FTDI USB Serial Device
         Starting udev Coldplug all Devices...
[  OK  ] Listening on Network Service Netlink Socket.
[  OK  ] Listening on Journal Socket (/dev/log).
         Starting Journal Service...
         Starting Remount Root and Kernel File Systems...
[  OK  ] Created slice system-getty.slice.
[  OK  ] Reached target Swap.
[   11.166150] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
         Mounting Temporary Directory (/tmp)...
[  OK  ] Mounted Kernel Debug File System.
[  OK  ] Started Load Kernel Modules.
[  OK  ] Mounted POSIX Message Queue File System.
[  OK  ] Started Remount Root and Kernel File Systems.
[  OK  ] Started Journal Service.
[  OK  ] Mounted Temporary Directory (/tmp).
         Starting Flush Journal to Persistent Storage...
         Starting Create Static Device Nodes in /dev...
         Starting Apply Kernel Variables...
         Mounting Kernel Configuration File System...
[  OK  ] Started Create Static Device Nodes in /dev.
[  OK  ] Started Apply Kernel Variables.
[  OK  ] Mounted Kernel Configuration File System.
[   11.830925] systemd-journald[76]: Received request to flush runtime journal from PID 1
[  OK  ] Reached target Local File Systems (Pre).
         Mounting /media/ram...
[  OK  ] Reached target Containers.
         Mounting /var/volatile...
         Starting udev Kernel Device Manager...
[  OK  ] Started Flush Journal to Persistent Storage.
[  OK  ] Mounted /media/ram.
[  OK  ] Mounted /var/volatile.
         Starting Load/Save Random Seed...
[  OK  ] Reached target Local File Systems.
         Starting Create Volatile Files and Directories...
[  OK  ] Started udev Kernel Device Manager.
[  OK  ] Started Load/Save Random Seed.
[  OK  ] Started Create Volatile Files and Directories.
         Starting Network Time Synchronization...
         Starting Network Service...
         Starting Update UTMP about System Boot/Shutdown...
[  OK  ] Started Update UTMP about System Boot/Shutdown.
[  OK  ] Started Network Service.
         Starting Network Name Resolution...
[  OK  ] Started Network Time Synchronization.
[  OK  ] Reached target System Time Synchronized.
[  OK  ] Started udev Coldplug all Devices.
[  OK  ] Reached target System Initialization.
[  OK  ] Listening on D-Bus System Message Bus Socket.
         Starting Reboot and dump vmcore via kexec...
[  OK  ] Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
[  OK  ] Listening on RPCbind Server Activation Socket.
[  OK  ] Started Daily rotation of log files.
[  OK  ] Listening on dropbear.socket.
[  OK  ] Reached target Sockets.
[  OK  ] Reached target Basic System.
[   14.406909] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec
[  OK  ] Started D-Bus System Message Bus.
[   14.545545] omap_rtc 44e3e000.rtc: registered as rtc0
[   14.782263] at24 0-0050: 256 byte 24c02 EEPROM, writable, 1 bytes/write
[  OK  ] Started strongSwan IPsec IKEv1/IKEv2 daemon using ipsec.conf.
         Starting Print notice about GPLv3 packages...
[  OK  ] Started Job spooling tools.
[  OK  ] Started Periodic Command Scheduler.
[  OK  ] Started Daily Cleanup of Temporary Directories.
[  OK  ] Reached target Timers.
         Starting RPC Bind Service...
         Starting Login Service...
[  OK  ] Started Network Name Resolution.
[  OK  ] Started Reboot and dump vmcore via kexec.
[  OK  ] Found device /dev/ttyS0.
[  OK  ] Reached target Network.
         Starting Lightning Fast Webserver With Light System Requirements...
[   15.899143] omap-sham 53100000.sham: hw accel on OMAP rev 4.3
[   15.962099] omap-aes 53500000.aes: OMAP AES hw accel rev: 3.2
         Starting Simple Network Management Protocol (SNMP) Daemon....
[   16.037178] remoteproc remoteproc0: wkup_m3 is available
[  OK  ] Started Redis In-Memory Data Store.
[   16.190280] omap-aes 53500000.aes: will run requests pump with realtime priority
         Starting Permit User Sessions...
[   16.335732] omap_hwmod: gfx: failed to hardreset
         Starting Avahi mDNS/DNS-SD Stack...
[  OK  ] Reached target Host and Network Name Lookups.
[  OK  ] Started RPC Bind Service.
[   16.761596] pvrsrvkm 56000000.sgx: Unable to reset SGX!
[  OK  ] Started Lightning Fast Webserver With Light System Requirements.
[   16.802843] remoteproc remoteproc0: powering up wkup_m3
[   16.824054] PM: Cannot get wkup_m3_ipc handle
[   16.948615] [drm] Initialized pvr 1.17.4948957 20110701 for 56000000.sgx on minor 0
[   16.966877] remoteproc remoteproc0: Booting fw image am335x-pm-firmware.elf, size 242888
[  OK  ] Started Permit User Sessions.
[   17.109391] PM: Cannot get wkup_m3_ipc handle
[   17.126151] remoteproc remoteproc0: remote processor wkup_m3 is now up
[   17.126176] wkup_m3_ipc 44e11324.wkup_m3_ipc: CM3 Firmware Version = 0x192
[  OK  ] Started Serial Getty on ttyS0.
[   17.311536] NET: Registered protocol family 15
[  OK  ] Started Getty on tty1.
[  OK  ] Started NFS status monitor for NFSv2/3 locking..
[  OK  ] Started Avahi mDNS/DNS-SD Stack.
[   18.597658] net eth0: initializing cpsw version 1.12 (0)
[   18.652851] PM: bootloader does not support rtc-only!
[   18.709983] Generic PHY 4a101000.mdio:01: attached PHY driver [Generic PHY] (mii_bus:phy_addr=4a101000.mdio:01, irq=POLL)
[  OK  ] Found device /dev/ttyS3.
[   19.016359] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   19.234537] Initializing XFRM netlink socket

 _____                    _____           _         _   
|  _  |___ ___ ___ ___   |  _  |___ ___  |_|___ ___| |_ 
|     |  _| .'| . | . |  |   __|  _| . | | | -_|  _|  _|
|__|__|_| |__,|_  |___|  |__|  |_| |___|_| |___|___|_|  
              |___|                    |___|            

Arago Project http://arago-project.org Gateway4 ttyS0

Arago 2019.11 Gateway4 ttyS0

Gateway4 login: root
***************************************************************
***************************************************************
NOTICE: This file system contains the following GPLv3 packages:
        autoconf
        bash-dev
        bash
        bc
        binutils
        cifs-utils
        cpio
        cpp-symlinks
        cpp
        dosfstools
        elfutils
        findutils
        g++-symlinks
        g++
        gawk
        gcc-symlinks
        gcc
        gdb
        gdbserver
        gettext
        glmark2
        gstreamer1.0-libav
        gzip
        hidapi
        libbfd
        libcairo-perf-utils
        libdw1
        libelf1
        libgdbm-compat4
        libgdbm-dev
        libgdbm6
        libgettextlib
        libgettextsrc
        libgmp10
        libidn2-0
        libmavconn
        libmpc3
        libmpfr6
        libreadline-dev
        libreadline7
        libunistring2
        m4-dev
        m4
        make
        mavlink
        mavros-extras
        mavros-msgs
        mavros
        nettle
        pdm-anomaly-detection
        socketcan-interface
        swig-dev
        swig
        which

If you do not wish to distribute GPLv3 components please remove
the above packages prior to distribution.  This can be done using
the opkg remove command.  i.e.:
    opkg remove <package>
Where <package> is the name printed in the list above

NOTE: If the package is a dependency of another package you
      will be notified of the dependent packages.  You should
      use the --force-removal-of-dependent-packages option to
      also remove the dependent packages as well
***************************************************************
***************************************************************
[   35.293419] EXT4-fs (mmcblk1p2): mounting ext3 file system using the ext4 subsystem
[   35.368195] EXT4-fs (mmcblk1p2): mounted filesystem with ordered data mode. Opts: (null)
root@Gateway4:~# rtcwake -m standby -s 5
rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "standby" using /dev/rtc0 at Sat Jan  1 00:00:06 2000
[   45.393436] PM: suspend entry (shallow)
[   45.397359] PM: Syncing filesystems ... done.
[   45.420537] Freezing user space processes ... (elapsed 0.002 seconds) done.
[   45.430558] OOM killer disabled.
[   45.433863] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[   45.443351] Suspending console(s) (use no_console_suspend to debug)
[   45.473969] pm33xx pm33xx: PM: Successfully put all powerdomains to target state
[   45.473969] PM: Wakeup source UART
[   45.496450] net eth0: initializing cpsw version 1.12 (0)
[   45.500234] Generic PHY 4a101000.mdio:01: attached PHY driver [Generic PHY] (mii_bus:phy_addr=4a101000.mdio:01, irq=POLL)
[   45.539894] OOM killer enabled.
[   45.543058] Restarting tasks ... done.
[   45.589085] PM: suspend exit
root@Gateway4:~#

Regards
Adam

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

When using RTC to wake up, what is the time difference roughly in second between seeing the following two lines in the log? This is about the time between the UART console is suspended and resumed.

[   45.443351] Suspending console(s) (use no_console_suspend to debug)
[   45.473969] pm33xx pm33xx: PM: Successfully put all powerdomains to target state

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin,

The time interval between these two lines is different each time I invoke the following command

rtcwake -m standby -s 5

The last time it was 6 minutes and 25 seconds.

Regards
Adam

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

The delay is way off. It could be either any issue in RTC wakeup, or any kernel module preventing Linux wakeup sooner. Let me check into this to see how we can debug it.

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

Please run the following commands to check the RTC wakeup time.

First please ensure your kernel has CONFIG_PM_SLEEP_DEBUG enabled.

root@am335x-evm:~# zcat /proc/config.gz | grep PM_SLEEP                                                                                                        
CONFIG_PM_SLEEP=y                                                              
CONFIG_PM_SLEEP_DEBUG=y

Then run the following command to enable PM debug logs.

root@am335x-evm:~# echo 1 > /sys/power/pm_debug_messages
root@am335x-evm:~# echo 8 > /proc/sys/kernel/printk

Then run your rtcwake command and you should see some more PM debug messages in the console log, one of them is the following, which tells the suspend duration. Please check if the number is close to that set in your rtcwake command. If not, is it proportional?

root@am335x-evm:~# rtcwake -m standby -s 2
...
[  725.572371] PM: Timekeeping suspended for 2.140 seconds

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin,

please see the results.

root@Gateway4:~# zcat /proc/config.gz | grep PM_SLEEP
CONFIG_PM_SLEEP=y
CONFIG_PM_SLEEP_DEBUG=y
root@Gateway4:~# echo 1 > /sys/power/pm_debug_messages
root@Gateway4:~# echo 8 > /proc/sys/kernel/printk
root@Gateway4:~# rtcwake -m standby -s 2
rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "standby" using /dev/rtc0 at Sat Jan  1 00:00:03 2000
[  215.998865] PM: suspend entry (shallow)
[  216.003209] PM: Syncing filesystems ... done.
[  216.009133] PM: Preparing system for sleep (shallow)
[  216.019028] Freezing user space processes ... (elapsed 0.002 seconds) done.
[  216.028810] OOM killer disabled.
[  216.032291] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[  216.041333] PM: Suspending system (shallow)
[  216.045560] Suspending console(s) (use no_console_suspend to debug)


----- There was a 6-minute delay between these two adjacent lines  -----


[  216.066750] PM: suspend of devices complete after 13.519 msecs
[  216.071617] PM: late suspend of devices complete after 4.795 msecs
[  216.076271] PM: noirq suspend of devices complete after 4.350 msecs
[  216.076296] pm33xx pm33xx: PM: Successfully put all powerdomains to target state
[  216.076296] PM: Wakeup source RTC Alarm
[  216.094251] PM: noirq resume of devices complete after 17.749 msecs
[  216.097517] PM: early resume of devices complete after 2.975 msecs
[  216.098627] net eth0: initializing cpsw version 1.12 (0)
[  216.102406] Generic PHY 4a101000.mdio:01: attached PHY driver [Generic PHY] (mii_bus:phy_addr=4a101000.mdio:01, irq=POLL)
[  216.110004] PM: Timekeeping suspended for 2.945 seconds
[  216.110154] PM: resume of devices complete after 12.598 msecs
[  216.184621] PM: Finishing wakeup.
[  216.188195] OOM killer enabled.
[  216.191521] Restarting tasks ... done.
[  216.228502] PM: suspend exit

Regards
Adam

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

The following message in the log seems indicating the RTC wakes up the system in time, but maybe something else (a peripheral?) got stuck in resume which prevents the UART console become active.

[ 216.110004] PM: Timekeeping suspended for 2.945 seconds

I will look into this to figure out how to debug next.

Meanwhile, can you please attached /proc/config.gz file from your board, and the DTS file for your board?

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin,

Please, find files attached.

config_files.zip

Regards
Adam

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

Please do the following to get a ftrace debug log, maybe it will show which module delays in resume.

- enable ftrace in kernel config:

Kernel hacking --->
    [*] Tracers --->
        [*] Kernel Function Tracer
        ...
        [*] enable/disable function tracing dynamically

- Rebuild the kernel and use it to boot the board;

- After booted into Linux, run the following commands to capture a log:

cd /sys/kernel/debug/tracing/
echo '*resume*' > set_ftrace_filter                                             
echo '!*runtime_resume' >> set_ftrace_filter                                    
echo '!*rpm_resume' >> set_ftrace_filter                                        
echo '!*dpm_resume*' >> set_ftrace_filter                                       
echo '!device_resume*' >> set_ftrace_filter                                     
echo '!platform_pm_resume' >> set_ftrace_filter                                 
echo '!*resume_early*' >> set_ftrace_filter                                     
echo '!*resume_noirq*' >> set_ftrace_filter                                     
echo '!*regulator_resume' >> set_ftrace_filter                                  
echo function > current_tracer
rtcwake -m standby -s 2
cat trace > resume_delay_ftrace.log

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin

I invoked the following commands to compile zImage and modules.

make ARCH=arm CROSS_COMPILE=arm-linux-gnueabihf- tisdk_am335x-evm_defconfig
make ARCH=arm CROSS_COMPILE=arm-linux-gnueabihf- menuconfig
Kernel hacking --->
    [*] Tracers --->
        [*] Kernel Function Tracer
        ...
        [*] enable/disable function tracing dynamically 

make ARCH=arm CROSS_COMPILE=arm-linux-gnueabihf- zImage
make ARCH=arm CROSS_COMPILE=arm-linux-gnueabihf- modules
sudo make ARCH=arm INSTALL_MOD_PATH=/media/tronix/rootfs modules_install

I got the following results.

Fullscreen resume_delay_ftrace.log Download

# tracer: function
#
# entries-in-buffer/entries-written: 78/78   #P:1
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
    kworker/0:1H-54    [000] ....   148.791211: _mmc_resume <-mmc_runtime_resume
         rtcwake-947   [000] ....   148.876470: pm_qos_sysfs_remove_resume_latency <-dev_pm_qos_constraints_destroy
         rtcwake-947   [000] d...   148.890574: syscore_resume <-suspend_devices_and_enter
         rtcwake-947   [000] d...   148.890574: cpu_pm_resume <-syscore_resume
         rtcwake-947   [000] d...   148.890574: irq_gc_resume <-syscore_resume
         rtcwake-947   [000] d...   148.890574: irq_pm_syscore_resume <-syscore_resume
         rtcwake-947   [000] d...   148.890574: resume_irqs <-irq_pm_syscore_resume
         rtcwake-947   [000] d...   148.890574: timekeeping_resume <-syscore_resume
         rtcwake-947   [000] d...   148.890574: clockevents_resume <-timekeeping_resume
         rtcwake-947   [000] d...   148.890574: clocksource_resume <-timekeeping_resume
         rtcwake-947   [000] d...   148.890574: tick_resume <-timekeeping_resume
         rtcwake-947   [000] d...   148.890574: tick_resume_local <-tick_resume
         rtcwake-947   [000] d...   148.890574: clockevents_tick_resume <-tick_resume_local
         rtcwake-947   [000] d...   148.890574: tick_resume_oneshot <-tick_resume_local
         rtcwake-947   [000] d...   148.890574: hrtimers_resume <-timekeeping_resume
         rtcwake-947   [000] dn..   148.890574: sched_clock_resume <-syscore_resume
         rtcwake-947   [000] dn..   148.890585: ledtrig_cpu_syscore_resume <-syscore_resume
         rtcwake-947   [000] ....   148.890753: dpm_noirq_resume_devices <-dpm_resume_noirq
         rtcwake-947   [000] ....   148.909193: pm_runtime_force_resume <-pm_generic_resume_noirq
         rtcwake-947   [000] ....   148.909372: resume_device_irqs <-dpm_resume_noirq
         rtcwake-947   [000] ....   148.909376: resume_irqs <-resume_device_irqs
         rtcwake-947   [000] ....   148.909483: cpuidle_resume <-dpm_resume_noirq
         rtcwake-947   [000] ....   148.910069: edma_pm_resume <-dpm_run_callback
         rtcwake-947   [000] ....   148.912316: davinci_mdio_resume <-dpm_run_callback
         rtcwake-947   [000] ....   148.912358: pm_runtime_force_resume <-davinci_mdio_resume
    kworker/u2:1-45    [000] ....   148.913100: async_resume <-async_run_entry_fn
    kworker/u2:2-88    [000] ....   148.913160: async_resume <-async_run_entry_fn
    kworker/u2:0-7     [000] ....   148.913206: async_resume <-async_run_entry_fn
    kworker/u2:3-951   [000] ....   148.913271: async_resume <-async_run_entry_fn
         rtcwake-947   [000] ....   148.913401: pinctrl_single_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.913483: omap8250_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.913487: serial8250_resume_port <-omap8250_resume
         rtcwake-947   [000] ....   148.913492: uart_resume_port <-serial8250_resume_port
         rtcwake-947   [000] ....   148.913861: omap_wdt_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.913873: omap_mbox_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.913900: omap_rtc_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.913919: omap2_mcspi_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.913925: spi_controller_resume <-omap2_mcspi_resume
         rtcwake-947   [000] ....   148.913986: pm_runtime_force_resume <-omap2_mcspi_resume
         rtcwake-947   [000] ....   148.913998: cpsw_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.917501: phy_resume <-phy_attach_direct
         rtcwake-947   [000] ....   148.917512: __phy_resume <-phy_resume
         rtcwake-947   [000] ....   148.917516: genphy_resume <-__phy_resume
         rtcwake-947   [000] ....   148.922333: ti_emif_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.922358: omap_sham_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.922429: omap_aes_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.922466: omap_rng_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.923003: alarmtimer_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.924834: serial8250_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.925047: mdio_bus_phy_resume <-dpm_run_callback
         rtcwake-947   [000] ....   148.925054: phy_resume <-mdio_bus_phy_resume
         rtcwake-947   [000] ....   148.925057: __phy_resume <-phy_resume
         rtcwake-947   [000] ....   148.925061: genphy_resume <-__phy_resume
         rtcwake-947   [000] ....   148.925622: omap_hsmmc_resume <-platform_pm_resume
    kworker/u2:0-7     [000] ....   148.925725: mmc_bus_resume <-dpm_run_callback
    kworker/u2:0-7     [000] ....   148.925730: mmc_sd_resume <-mmc_bus_resume
    kworker/u2:0-7     [000] ....   148.925736: pm_generic_resume <-mmc_bus_resume
    kworker/u2:0-7     [000] ....   148.925740: mmc_blk_resume <-pm_generic_resume
    kworker/u2:0-7     [000] ....   148.925744: mmc_queue_resume <-mmc_blk_resume
         rtcwake-947   [000] ....   148.925791: omap_hsmmc_resume <-platform_pm_resume
    kworker/u2:3-951   [000] ....   148.925862: mmc_bus_resume <-dpm_run_callback
    kworker/u2:3-951   [000] ....   148.925868: mmc_resume <-mmc_bus_resume
    kworker/u2:3-951   [000] ....   148.925873: pm_generic_resume <-mmc_bus_resume
    kworker/u2:3-951   [000] ....   148.925876: mmc_blk_resume <-pm_generic_resume
    kworker/u2:3-951   [000] ....   148.925879: mmc_queue_resume <-mmc_blk_resume
    kworker/u2:3-951   [000] ....   148.925889: mmc_queue_resume <-mmc_blk_resume
    kworker/u2:3-951   [000] ....   148.925898: mmc_queue_resume <-mmc_blk_resume
         rtcwake-947   [000] ....   148.925935: led_resume <-dpm_run_callback
         rtcwake-947   [000] ....   148.925940: led_classdev_resume <-led_resume
         rtcwake-947   [000] ....   148.925960: led_resume <-dpm_run_callback
         rtcwake-947   [000] ....   148.925963: led_classdev_resume <-led_resume
         rtcwake-947   [000] ....   148.926199: rtc_resume <-dpm_run_callback
         rtcwake-947   [000] ....   148.926202: timekeeping_rtc_skipresume <-rtc_resume
         rtcwake-947   [000] ....   148.926208: rtc_resume.part.2 <-rtc_resume
         rtcwake-947   [000] ....   148.926258: wkup_m3_ipc_resume <-platform_pm_resume
         rtcwake-947   [000] ....   148.926333: cpufreq_resume <-dpm_resume
         rtcwake-947   [000] .n..   148.929097: resume_console <-suspend_devices_and_enter
     kworker/0:3-50    [000] ....   149.033747: _mmc_resume <-mmc_runtime_resume

Regards
Adam

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

The ftrace log only lasts for a few hundreds of ms, it doesn't show the time when resume got stuck.

Can you please also provide the console resume log along with the ftrace log? I want to see the timestamp in the kernel log to know if the ftrace log happens after the stuck point is passed.

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin

root@Gateway4:~# cd /sys/kernel/debug/tracing/
root@Gateway4:/sys/kernel/debug/tracing# echo '*resume*' > set_ftrace_filter
root@Gateway4:/sys/kernel/debug/tracing# echo '!*runtime_resume' >> set_ftrace_filter 
root@Gateway4:/sys/kernel/debug/tracing# echo '!*rpm_resume' >> set_ftrace_filter 
root@Gateway4:/sys/kernel/debug/tracing# echo '!*dpm_resume*' >> set_ftrace_filter
root@Gateway4:/sys/kernel/debug/tracing# echo '!device_resume*' >> set_ftrace_filter
root@Gateway4:/sys/kernel/debug/tracing# echo '!platform_pm_resume' >> set_ftrace_filter 
root@Gateway4:/sys/kernel/debug/tracing# echo '!*resume_early*' >> set_ftrace_filter
root@Gateway4:/sys/kernel/debug/tracing# echo '!*resume_noirq*' >> set_ftrace_filter 
root@Gateway4:/sys/kernel/debug/tracing# echo '!*regulator_resume' >> set_ftrace_filter
root@Gateway4:/sys/kernel/debug/tracing# echo function > current_tracer
root@Gateway4:/sys/kernel/debug/tracing# rtcwake -m standby -s 2
rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "standby" using /dev/rtc0 at Sat Jan  1 00:00:03 2000
[   87.484645] PM: suspend entry (shallow)
[   87.488537] PM: Syncing filesystems ... done.
[   87.515180] Freezing user space processes ... (elapsed 0.002 seconds) done.
[   87.525279] OOM killer disabled.
[   87.528593] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[   87.537987] Suspending console(s) (use no_console_suspend to debug)

----- There was a long... delay between these two adjacent lines  -----

[   87.569694] pm33xx pm33xx: PM: Successfully put all powerdomains to target state
[   87.569694] PM: Wakeup source UART
[   87.593223] net eth0: initializing cpsw version 1.12 (0)
[   87.597190] Generic PHY 4a101000.mdio:01: attached PHY driver [Generic PHY] (mii_bus:phy_addr=4a101000.mdio:01, irq=POLL)
[   87.637065] OOM killer enabled.
[   87.640372] Restarting tasks ... done.
[   87.682249] PM: suspend exit
root@Gateway4:/sys/kernel/debug/tracing#

31034fac832d29ed8584666c901086445_code-editor-fs">Fullscreen om/cfs-filesystemfile/__key/communityserver-discussions-components-files/791/5430.resume_5F00_delay_5F00_ftrace.log?_=637571139280000000" 5430.resume_delay_ftrace.log">5430.resume_delay_ftrace.log om/cfs-filesystemfile/__key/communityserver-discussions-components-files/791/5430.resume_5F00_delay_5F00_ftrace.log?_=637571139280000000" 5430.resume_delay_ftrace.log">Download 4fac832d29ed8584666c901086445_code-editor" idth:320px;margin:0px;" tracer: function #P:1 _-----=> irqs-off / _----=> need-resched | / _---=> hardirq/softirq || / _--=> preempt-depth ||| / delay TIMESTAMP FUNCTION | | 87.473133: _mmc_resume <-mmc_runtime_resume 87.556102: pm_qos_sysfs_remove_resume_latency <-dev_pm_qos_constraints_destroy 87.569694: syscore_resume <-suspend_devices_and_enter 87.569694: cpu_pm_resume <-syscore_resume 87.569694: irq_gc_resume <-syscore_resume 87.569694: irq_pm_syscore_resume <-syscore_resume 87.569694: resume_irqs <-irq_pm_syscore_resume 87.569694: timekeeping_resume <-syscore_resume 87.569694: clockevents_resume <-timekeeping_resume 87.569694: clocksource_resume <-timekeeping_resume 87.569694: tick_resume <-timekeeping_resume 87.569694: tick_resume_local <-tick_resume 87.569694: clockevents_tick_resume <-tick_resume_local 87.569694: tick_resume_oneshot <-tick_resume_local 87.569694: hrtimers_resume <-timekeeping_resume 87.569694: sched_clock_resume <-syscore_resume 87.569706: ledtrig_cpu_syscore_resume <-syscore_resume 87.569872: dpm_noirq_resume_devices <-dpm_resume_noirq 87.588305: pm_runtime_force_resume <-pm_generic_resume_noirq 87.588484: resume_device_irqs <-dpm_resume_noirq 87.588489: resume_irqs <-resume_device_irqs 87.588596: cpuidle_resume <-dpm_resume_noirq 87.589167: edma_pm_resume <-dpm_run_callback 87.591422: davinci_mdio_resume <-dpm_run_callback 87.591465: pm_runtime_force_resume <-davinci_mdio_resume 87.592208: async_resume <-async_run_entry_fn 87.592268: async_resume <-async_run_entry_fn 87.592315: async_resume <-async_run_entry_fn 87.592382: async_resume <-async_run_entry_fn 87.592513: pinctrl_single_resume <-platform_pm_resume 87.592597: omap8250_resume <-platform_pm_resume 87.592601: serial8250_resume_port <-omap8250_resume 87.592606: uart_resume_port <-serial8250_resume_port 87.592980: omap_wdt_resume <-platform_pm_resume 87.592993: omap_mbox_resume <-platform_pm_resume 87.593020: omap_rtc_resume <-platform_pm_resume 87.593038: omap2_mcspi_resume <-platform_pm_resume 87.593043: spi_controller_resume <-omap2_mcspi_resume 87.593107: pm_runtime_force_resume <-omap2_mcspi_resume 87.593119: cpsw_resume <-platform_pm_resume 87.596637: phy_resume <-phy_attach_direct 87.596649: __phy_resume <-phy_resume 87.596653: genphy_resume <-__phy_resume 87.601467: ti_emif_resume <-platform_pm_resume 87.601489: omap_sham_resume <-platform_pm_resume 87.601558: omap_aes_resume <-platform_pm_resume 87.601596: omap_rng_resume <-platform_pm_resume 87.602104: alarmtimer_resume <-platform_pm_resume 87.603615: serial8250_resume <-platform_pm_resume 87.604156: mdio_bus_phy_resume <-dpm_run_callback 87.604171: phy_resume <-mdio_bus_phy_resume 87.604175: __phy_resume <-phy_resume 87.604178: genphy_resume <-__phy_resume 87.604729: omap_hsmmc_resume <-platform_pm_resume 87.604834: mmc_bus_resume <-dpm_run_callback 87.604839: mmc_sd_resume <-mmc_bus_resume 87.604845: pm_generic_resume <-mmc_bus_resume 87.604849: mmc_blk_resume <-pm_generic_resume 87.604853: mmc_queue_resume <-mmc_blk_resume 87.604899: omap_hsmmc_resume <-platform_pm_resume 87.604972: mmc_bus_resume <-dpm_run_callback 87.604978: mmc_resume <-mmc_bus_resume 87.604982: pm_generic_resume <-mmc_bus_resume 87.604985: mmc_blk_resume <-pm_generic_resume 87.604988: mmc_queue_resume <-mmc_blk_resume 87.604998: mmc_queue_resume <-mmc_blk_resume 87.605007: mmc_queue_resume <-mmc_blk_resume 87.605045: led_resume <-dpm_run_callback 87.605050: led_classdev_resume <-led_resume 87.605069: led_resume <-dpm_run_callback 87.605072: led_classdev_resume <-led_resume 87.605306: rtc_resume <-dpm_run_callback 87.605310: timekeeping_rtc_skipresume <-rtc_resume 87.605316: rtc_resume.part.2 <-rtc_resume 87.605368: wkup_m3_ipc_resume <-platform_pm_resume 87.605444: cpufreq_resume <-dpm_resume 87.608210: resume_console <-suspend_devices_and_enter 87.681689: _mmc_resume <-mmc_runtime_resume = j('#fragment-1a84591e31034fac832d29ed8584666c901086445_code-editor-fs'); -1a84591e31034fac832d29ed8584666c901086445_code-editor'); function(){ odeEditor('fullscreen')) { odeEditor('fullscreen', false); odeEditor('fullscreen', true);

Regards
Adam

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

Comparing the timestamps in the two logs, it seems the long delay happens after all the kernel modules are resumed.

I think there are a couple ways to debug further.

- If the JTAG header is available on your board, connect an emulator, and halt the CPU while the delay happens and check where it got stuck in the code. If you can load the kernel symbol files with kernel debug info enable, you could see where the the PC stops in the kernel source code.

- If JTAG header is not available, I think you would have to disable kernel modules in kernel menuconfig one by one to figure out which module causes the delay.

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

Can you please run a quick test similar to the last one which captures the console log and ftrace log? but this time add the following command before running "rtcwake -m standby -s 2", it disables uart suspend, so that we can get more accurate console logs.

# echo no > /sys/module/printk/parameters/console_suspend

and please attach the console log and ftrace log.

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin,
I had a few days off. I'll come back to you on Monday. Sorry for the delay.

Regards
Adam

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin,

Bin Liu said:
- If the JTAG header is available on your board, connect an emulator, and halt the CPU while the delay happens and check where it got stuck in the code. If you can load the kernel symbol files with kernel debug info enable, you could see where the the PC stops in the kernel source code.

I tried to do this using two different debuggers: XDS110 and Jlink Ultra+.
To be able to debug Kernal, I added flags according to this thread:
e2e.ti.com/.../cortxa8-error-connecting-to-the-target-error--1204-0x3d5b-unable-to-access-the-dap

I can connect the debugger and walk through the code...

Unfortunately, once I invoke the

rtcwake -m standby -s 5

I get the following error:

On XDS110

CortxA8: Error: (Error -1170 @ 0x0) Unable to access the DAP. Reset the device, and retry the operation. If error persists, confirm configuration, power-cycle the board, and/or try more reliable JTAG settings (e.g. lower TCLK). (Emulation package 9.3.0.00032)

On Jlink

CortxA8: Error: Stat [ JLINKARM_IsHalted() call ] failed!
CortxA8: Trouble Halting Target CPU: Halt failed!

Do I miss anything? How exactly do I need to attach a debugger to see where the code is stuck?
I wonder if it is possible, to debug "through" the standby state. After calling rtcwake, JTAG disconnects.

Regards
Adam

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

Can you connect the JTAG after a few seconds, for example about 10-20 seconds, after run 'rtcwake ...' command, then halt the CPU?

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin,

Bin Liu said:
Can you connect the JTAG after a few seconds, for example about 10-20 seconds, after run 'rtcwake ...' command, then halt the CPU?

I can't connect after 10s, 20s and 60s from calling the rtcwake command.

CortxA8: Error: (Error -1170 @ 0x0) Unable to access the DAP. Reset the device, and retry the operation. If error persists, confirm configuration, power-cycle the board, and/or try more reliable JTAG settings (e.g. lower TCLK). (Emulation package 9.3.0.00032)

I can reconnect to the CPU after the rtcwake command has completely resumed (depends 5-10 min later), so after a moment we try to catch.

Going back to this clue...

Bin Liu said:
Can you please run a quick test similar to the last one which captures the console log and ftrace log? but this time add the following command before running "rtcwake -m standby -s 2", it disables uart suspend, so that we can get more accurate console logs.

Fullscreen

After adding this additional command, Kernel stays in standby mode forever.
I can only resume by pressing the spacebar.
I did this several times waiting many hours for any response...

Regards
Adam

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

I noticed one more thing...

There is one additional line on the console after this flag is added

# echo no > /sys/module/printk/parameters/console_suspend

root@Gateway4:/sys/kernel/debug/tracing# rtcwake -m standby -s 2
rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "standby" using /dev/rtc0 at Tue Jun  1 13:29:35 2021
[  126.789319] PM: suspend entry (shallow)
[  126.793374] PM: Syncing filesystems ... done.
[  126.801530] Freezing user space processes ... (elapsed 0.002 seconds) done.
[  126.811203] OOM killer disabled.
[  126.814642] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[  126.839698] cpsw 4a100000.ethernet eth0: Link is Down
[  126.861620] l4_wkup_cm:clk:0010:0: failed to disable

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

Sorry for the late response. I was trying to discuss this issue with our sw dev team to come out with some ideas on how to debug it, but we haven't got much progress yet.

Meanwhile, instead of connecting JTAG to A8 which was failed, can you please try to connect JTAG to M3 during the resume delay to see if it succeeds?

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin,

Thank you for your persistence...

Bin Liu said:
Meanwhile, instead of connecting JTAG to A8 which was failed, can you please try to connect JTAG to M3 during the resume delay to see if it succeeds?

After invoking rtcwake command, I can connect JTAG to M3 (but not to A8).

Regards
Adam

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

Once you connected to M3, can you halt M3 then check its PC location, and de-assembly the code to tell where it is?

You might also want to quickly resume and halt M3 multiple times to see if the PC stuck in M3?

0 Adam Kozlowski over 4 years ago in reply to Bin Liu

Expert 1805 points

Hi Bin,

Bin Liu said:
Once you connected to M3, can you halt M3 then check its PC location, and de-assembly the code to tell where it is?

It moves between 0x235A and 0x235C

Bin Liu said:
You might also want to quickly resume and halt M3 multiple times to see if the PC stuck in M3?

It moves between 0x235A and 0x235C

Moreover, I found that this extra delay only happens on the first rtcwake invocation after the board reset.

Below I enclose some numbers for the first and subsequent invocations.

First invocation after reset (rtcwake -m standby -s 5)

First try - 18s
Second try - 29s

Subsequent invocations
First try - 5s
Second try - 5s

Regards
Adam

0 Bin Liu over 4 years ago in reply to Adam Kozlowski

TI__Guru**** 171001 points

Hi Adam,

The info is helpful.

I will look into it and get you back.

Processors

Processors forum

AM3352: Low frequency working test