Why does get_rtc_time_us() truncate the result to uint32_t?

[eyaleb]

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]

Thanks for the report, will get this fixed.

[eyaleb]

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]

Similar?

viewtopic.php?t=1758

[ESP_igrr]

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]

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]

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]

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

Will ponder a bit how to solve this.

[eyaleb]

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]

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.