Why does get_rtc_time_us() truncate the result to uint32_t?

eyaleb
Posts: 31
Joined: Sun May 14, 2017 6:54 am

Why does get_rtc_time_us() truncate the result to uint32_t?

Postby eyaleb » Thu May 18, 2017 12:49 pm

In components/newlib/time.c (master branch) I see

Code: Select all

static uint64_t get_rtc_time_us()
{
    uint64_t ticks = rtc_time_get();
    return (uint32_t) ((ticks * esp_clk_slowclk_cal_get()) >> RTC_CLK_CAL_FRACT);
}
Why the (uint32_t) cast? This causes time (e.g. gettimeofday) to wraparound after just over 1 hour (4294 seconds).
Is there another time function I should use that does better?

TIA

ESP_igrr
Posts: 1689
Joined: Tue Dec 01, 2015 8:37 am

Re: Why does get_rtc_time_us() truncate the result to uint32_t?

Postby ESP_igrr » Fri May 19, 2017 3:41 am

Thanks for the report, will get this fixed.

eyaleb
Posts: 31
Joined: Sun May 14, 2017 6:54 am

Re: Why does get_rtc_time_us() truncate the result to uint32_t?

Postby eyaleb » Fri May 19, 2017 8:17 am

I ran a test where I changed the cast to uint64_t and both gettimeofday() and system_get_rtc_time() behave as expected, no time overflow.

I do not know if the following is related to time measurement, but I see unusual times in my test which deep sleeps for 5 seconds, with WiFi on and one UDP packet sent.

I save the time when esp_deep_sleep() is called, then check it when app_main() is entered. I expect the difference to be about 5.25s (I measured the wakeup around 250-300ms), but I find this to be as low as 200ms (!) and as high as over 8s.

Code: Select all

uint64_t system_get_rtc_time(void);

RTC_DATA_ATTR static uint64_t sleep_start_us = 0;
static uint64_t app_start_us = 0;

void app_main () {
    app_start_us = system_get_rtc_time();
    printf ("sleep_start=%lld app_start=%lld sleep_time=%lld",
                sleep_start_us, app_start_us, app_start_us-sleep_start_us);

// do some work, start WiFi, send UDO oacket

    sleep_start_us = system_get_rtc_time();
    esp_deep_sleep(5*1000000);
}
After some time I see:

Code: Select all

sleep_start=1677693 app_start=6981276 sleep_time=5303583
sleep_start=8266798 app_start=13572686 sleep_time=5305888
sleep_start=14857630 app_start=20172103 sleep_time=5314473
sleep_start=21457409 app_start=26750516 sleep_time=5293107
...
sleep_start=2481611524 app_start=2490039438 sleep_time=8427914
...
sleep_start=4633366874 app_start=4633576764 sleep_time=209890
...
sleep_start=4701616082 app_start=4709967971 sleep_time=8351889
It starts as expected, then strays far from spec.

WiFive
Posts: 2999
Joined: Tue Dec 01, 2015 7:35 am

Re: Why does get_rtc_time_us() truncate the result to uint32_t?

Postby WiFive » Fri May 19, 2017 9:56 am


ESP_igrr
Posts: 1689
Joined: Tue Dec 01, 2015 8:37 am

Re: Why does get_rtc_time_us() truncate the result to uint32_t?

Postby ESP_igrr » Fri May 19, 2017 10:50 am

This actually looks like some kind of precision loss / rounding bug. Would you mind sharing your test code so we can reproduce the issue here?

eyaleb
Posts: 31
Joined: Sun May 14, 2017 6:54 am

Re: Why does get_rtc_time_us() truncate the result to uint32_t?

Postby eyaleb » Fri May 19, 2017 1:10 pm

Sure https://github.com/makehackvoid/ESP8266 ... /esp32/idf
This is my test of an app I will flesh out, not a minimal test of this problem.

BTW, I see this as more that a small precision issue. A few us I can understand, but a few seconds unaccounted in a 5s sleep is rather significant.

I should mention that my board uses a revision 0 module, in case it matters.

[later] Having read topic #1758 (that was pointed above) I should say that I have the device on a table with no motion for hours. At this stage I am getting a significant loss of packets and looking at the reported rssi it is all over the place. Don't know it this is related. Even tried different power sources (no change). No external devices attached to the board yet.

ESP_igrr
Posts: 1689
Joined: Tue Dec 01, 2015 8:37 am

Re: Why does get_rtc_time_us() truncate the result to uint32_t?

Postby ESP_igrr » Fri May 19, 2017 3:51 pm

Thanks for the code; i have so far reproduced variations in the reported sleep time on the range of 4.8-5.2 sec. Note that I say reported time — actual sleep time (measured by external means using a second ESP32) is actually accurate. This variation is due to the fact that we are currently using a different calibration value for the RTC clock on every bootup. This causes the reported microsecond values to exhibit jitter.

i.e. on bootup 1, before sleep:
time_us_1 = rtc_counter * calibration_val
on bootup 2, after sleep
time_us_2 = (rtc_counter + sleep_count) * (calibration_val + epsilon)

time_us_2 - time_us_1 = sleep_count * (calibration_val + epsilon) + rtc_counter * epsilon.

The first term in the right hand side corresponds to the "real" sleep time (which you would measure by external means). The second term corresponds to the error caused by difference in calibration values. The second term will grow over time, as it is proportional to the absolute value of rtc_counter.

I will leave this running for the night to see if the second term grows large enough to cause the degree of sleep time variation you are reporting.

ESP_igrr
Posts: 1689
Joined: Tue Dec 01, 2015 8:37 am

Re: Why does get_rtc_time_us() truncate the result to uint32_t?

Postby ESP_igrr » Sat May 20, 2017 12:51 am

As expected, after a few hours of run time, the reported sleep time varies in the range between -15 and 40 seconds :roll:

Will ponder a bit how to solve this.

eyaleb
Posts: 31
Joined: Sun May 14, 2017 6:54 am

Re: Why does get_rtc_time_us() truncate the result to uint32_t?

Postby eyaleb » Sat May 20, 2017 1:07 am

Just a thought: can we avoid the calibration after a deep sleep wakeup, or do we really expect the rate to change on wakeup?

ESP_igrr
Posts: 1689
Joined: Tue Dec 01, 2015 8:37 am

Re: Why does get_rtc_time_us() truncate the result to uint32_t?

Postby ESP_igrr » Sat May 20, 2017 2:38 am

This is the easiest thing to do, but might be suboptimal if we want to account for frequency change due to changing temperature, for example.
The more comprehensive approach is to update the 'boot time' according to the previous calibration value, on each startup. This way, time error due to calibration coefficient variation will only be proportional to the time since last startup, not the time since the first one.

Who is online

Users browsing this forum: Google [Bot], leenowell and 41 guests