K64F: LowPowerTimeout: Inaccurate delay after board power up

[fkjagodzinski]

Description

• Type: Bug
• Related issue: LowPowerTimeout: Inconsistent delay when using multilple timeout objects #5150
• Priority: Minor

Bug

Target
K64F

Toolchain
GCC_ARM, ARM, IAR

Toolchain version
GCC_ARM -- 6.3.1,
ARM -- 5.24 (Flex) ARM Compiler 5.06 update 5 (build 528),
IAR -- ANSI C/C++ Compiler V7.80.4.12462/W32 for ARM

mbed-cli version
1.2.0

mbed-os sha
e1090ca

Code

#include "mbed.h"

#define TEST_DELAY_US 30000ULL

int main() {
    Timer timer;
    LowPowerTimeout timeout;

    timer.start();
    timeout.attach_us(mbed::callback(&timer, &Timer::stop), TEST_DELAY_US);

    // Need to wait much longer than TEST_DELAY_US
    Thread::wait(3000);
    printf("%10i\n", timer.read_us());
    return 0;
}

Expected behavior
When the board is powered up the callback is called exactly after TEST_DELAY_US.

Actual behavior
Callback is triggered with a delay different than expected after powerup. When a RESET button is pressed the delay is correct though.
Regular Timeout works as expected.

# board power up
     95670  # not even near 30000 us!
# RESET button pressed
     30013
# RESET button pressed
     30027
# RESET button pressed
     30029

# board power up
     94519
# RESET button pressed
     30014
# RESET button pressed
     30010

# board power up
     94744
# RESET button pressed
     30034

CC @bulislaw @0xc0170 @mmahadevan108

[cmonr]

@fkjagodzinski,

Would you mind trying this again using the latest version of mbed-os? I was not able to reproduce the bug on my end.
[Mirrored to Jira]

[fkjagodzinski]

@cmonr I checked the code on current master (6811c9f) and it behaves same way as before. :(
I even tested two K64F boards -- both fail.

It might be more convenient to use some non-default UART:

#include "mbed.h"
#define TEST_DELAY_US 30000ULL

int main() {
    Serial ser(PTC17, PTC16); // tx, rx
    Timer timer;
    LowPowerTimeout timeout;

    timer.start();
    timeout.attach_us(mbed::callback(&timer, &Timer::stop), TEST_DELAY_US);

    // Need to wait much longer than TEST_DELAY_US
    Thread::wait(3000);
    ser.printf("%10i\n", timer.read_us());
    return 0;
}

[Mirrored to Jira]

[cmonr]

@fkjagodzinski ,

I changed the serial pins, updated the GCC_ARM compiler, and manually checked out mbed-os to your SHA, but was still not able to see the issue.

A couple of things:

• How exactly are you powering on your K64F dev board? On my system, I installed a jumper on J20 to power cycle the board.
• What OS is this test running in? At the moment, I'm doing my work inside of an Ubuntu 16.04 LTS VM.
• I'm not sure it would make a difference, but I would suggest doing an mbed update to update your mbed-os project instance to 5.6.
• For reference, mbed-cli is at version 1.2.2.

[Mirrored to Jira]

[fkjagodzinski]

Initially I compiled this code on a Windows 10 machine, but have same results on my Linux laptop (native Ubuntu 16.04.3 LTS) on GCC_ARM, all mbed stuff up to date:

$ ./arm-none-eabi-gcc --version
arm-none-eabi-gcc (GNU Tools for ARM Embedded Processors 6-2017-q2-update) 6.3.1 20170620 (release) [ARM/embedded-6-branch revision 249437]
$ pip list | grep mbed
mbed-cli (1.2.2)
mbed-greentea (1.3.2)
mbed-host-tests (1.3.0)
mbed-ls (1.3.4)

Regarding the power method I initially just used USB cable connected to OpenSDA port on K64F. I have J20 shorted (as it was by default) but I checked powering the board though VIN pin (J3/16) -- same results -- first data immediately after power on is always incorrect. Here is a dump from the serial:

# Power applied to OpenSDA port 
     94782

# Power applied to OpenSDA port
     94769

# Reset button pressed
     30038

# Reset button pressed
     30010

# Power applied to OpenSDA port
     46868

# J25 switched from 1-2 to 2-3 for reset button to work
# 5 V applied to VIN (J3/16)
    254543

# Reset button pressed
     30010

# Reset button pressed
     30047

# Power applied to VIN pin
    254001

# Power applied to VIN pin
    194409

# Power applied to VIN pin
    255824

# Reset button pressed
     30024

These results are from latest master 4d81ead.

The K64F I have is marked as follows:
170-28163 REV F etched on PCB,
700-28163 REV E SCH-28163 REV F on a sticker.
[Mirrored to Jira]

[0xc0170]

@fkjagodzinski I think this can be closed. Latest ticker specs for 5.9 should have resolved this.
[Mirrored to Jira]

[fkjagodzinski]

Good point. I'll retry on current master and report here.
[Mirrored to Jira]

[fkjagodzinski]

I checked the code with current master (65abff9). Here is an UART dump:

# Power applied to OpenSDA port
    89420
# Reset button pressed
    30028
# Reset button pressed
    30041

# Power applied to VIN pin
    250316
# Reset button pressed
    30036
# Reset button pressed
    30049

# Power applied to VIN pin
    250377
# Reset button pressed
    30039
# Reset button pressed
    30035

# Power applied to OpenSDA port
    90224
# Reset button pressed
    30043
# Reset button pressed
    30055

# Power applied to OpenSDA port
    90075
# Reset button pressed
    30034

As you can see, the results are pretty much the same, 39852f7 didn't fix this issue.
[Mirrored to Jira]

[MateuszMaz]

with @maciejbocianski help, I did some investigation here, which probably show what gone wrong.

Let's begin with the list of devices, on that I checked this case:

1. NUCLEO F070RB
2. FRDM K64F
3. NRF52832
4. NUCLEO -F429ZI
5. NUCLEO -L476RG
6. FRDM K22F
7. FRDM K82F

The problem occurs only for Freedom devices K22F, K64F, K82F.

Secondly, I want to present the list of components that has similiar problem:

1. LowPowerTimer
2. LowPowerTicker
3. LowPowerTimeout

They are all based on LP ticker.
All timer function based on us_ticker are correct. (Timer, Ticker)
I have also tested it with logic level analyzer, and the result was the same.

What the problem is?
When we create an object related to lp_ticker, it enable RTC clock, then it writes values to LPTRM0 registers, to start the timer. The problem is that after powering the device, timer start to count 75 ms after its first initialization. After this time, if we i.e add some code that uses any other thing based on lp_ticker like, LowPowerTimer it will work without any problems.
So i.e if we add some Thread::wait(80) after LowPowerTimer timeout in @fkjagodzinski code,
then the time result will always be ok.

I have checked the LPTMR0 registers, after initialization, and after timer start. The values are ok.
So the timer is ready to count after initialization, but it doesn't get clock pulses.

Finally, documentation of K64F says that after enabling RTC we should wait "oscilator startup time" before enabling the time counter to allow the 32.768 kHz clock time to stabilize. (I couldn't find what exactly value is this time).
Now let's look at lp_ticker_init (which is used by K64F and K22F)
We don't wait any time after rtc_setup_oscillator(RTC); line 57.
When I added very time hungry operation (around 80 ms) after L57, then it fixed the problem for K64F, K22F, K82F. (If we add this operation line above L57 it will not change anything).

To conclude, problem is related to RTC oscilator. It starts to generate pulses around 75 ms after writing the values to its registers. This behaviour occurs after powering up the device

Standard timers are based on other clock source.

If you want to ask me how does logic level analyzer test looks like, then:

1. Before timeout.attach write 1 on D8
2. In callback write 1 on D7
3. Measure time between D8 and D7

[Mirrored to Jira]

[fkjagodzinski]

Good job @MateuszMaz! Thanks for sharing your findings. Will you be able to provide a fix for this issue?
[Mirrored to Jira]

[fkjagodzinski]

After a short discussion with @MateuszMaz we came to a conclusion that help from @ARMmbed/team-nxp may be needed. Could you guys take a look?
[Mirrored to Jira]

[maclobdell]

@mmahadevan108 - Any update on this one? Can you analyze the issue and fix if possible?
[Mirrored to Jira]