drift (and issues) in esp_timer_get_time and xTaskGetTickCount (GIT8266O-646)

[dsptech]

Environment

• Development Kit : nodemcu
• IDF version : 89a3f25
• Development Env: Eclipse
• Operating System: Windows
• Power Supply: USB

Problem Description

Drift in esp_timer_get_time and xTaskGetTickCount. Not protected access to the timer handle variables in esp_timer_get_time

Expected Behavior

no time drift.

Actual Behavior

see problem description

Steps to reproduce

The snipped below compare the elapsed time by esp_timer_get_time() and xTaskGetTickCount() against the hardware timer WDEVTSF0_TIME_LO. As visible in the attached log, after one minute (with no concurrent task, no wifi etc) esp_timer_get_time() has a drift of 42ms. Also xTaskGetTickCount() show a drift of 68ms (@250Hz Freertos freq.).

After an investigation I seen the below issues in xPortSysTickHandle (port.c):

• 1st drift: ccount timer is read at each handler call and after that it is set to 0. There is no way to take in account the cpu cycles (ticks of ccount timer) lost in the operations. Moreover, a concurrent nmi shot (pwm) might further degrade the operation.
• 2nd drift: us variable is evaluated and the remainder is discarded.
• 3rd drift: ticks variable is evaluated from us variable and the remainder is discarded again.

Furthermore, esp_timer_get_time() read the 64bit g_esp_os_us handler variabile and ccount timer without disabling the interrupts. An invalid "not monotonic" value might be returned.

I need an immediate solution so I've already written a new working handler with 0 drift.
I will send out a pull request today in case my solution is deemed useful for the community.

Regards.

Code to reproduce this issue

#include <stdio.h>
#include <stdint.h>
#include <inttypes.h>
#include <stdbool.h>
#include <freertos/FreeRTOS.h>
#include <freertos/task.h>
#include <esp_timer.h>
#include <esp_system.h>

void app_main()
{
    uint32_t wdev_us,wdevBase_us,elapsedWdev_us;
    uint32_t esp_us, espBase_us, elapsedEsp_us ;
    int32_t wdevVsEsp_us, wdevVsOs_us;
    uint32_t os_tks,osBase_tks,elapsedOs_us;
    bool init=false;
    for (;;) {
        wdev_us = REG_READ(WDEVTSF0_TIME_LO); //first 32 bit only
        esp_us = esp_timer_get_time();        //first 32 bit only
        os_tks = xTaskGetTickCount();
        if (!init){
            init = true;
            wdevBase_us = wdev_us;
            espBase_us = esp_us;
            osBase_tks = os_tks;
        }
        elapsedWdev_us  = wdev_us - wdevBase_us;
        elapsedEsp_us = esp_us - espBase_us;
        elapsedOs_us = 1000000/(configTICK_RATE_HZ) * (os_tks - osBase_tks);
        wdevVsEsp_us = elapsedWdev_us - elapsedEsp_us;
        wdevVsOs_us  = elapsedWdev_us - elapsedOs_us;
        printf("Elapsed Time ms - WDEV: %6" PRIu32 ", ESP : %6" PRIu32 ", OS (freertos) : %6"  PRIu32 "\n",
        	elapsedWdev_us/1000,elapsedEsp_us/1000,elapsedOs_us/1000);
        printf("                     WDEV vs ESP ms : %6" PRIi32", WDEV vs OS ms : %6" PRIi32 "\n\n",
        	wdevVsEsp_us/1000,wdevVsOs_us/1000);
        vTaskDelay(pdMS_TO_TICKS(5000));
    }
}

Debug Logs

Elapsed Time ms - WDEV:      0, ESP :      0, OS (freertos) :      0
                     WDEV vs ESP ms :      0, WDEV vs OS ms :      0

Elapsed Time ms - WDEV:   5010, ESP :   5006, OS (freertos) :   5008
                     WDEV vs ESP ms :      3, WDEV vs OS ms :      2

Elapsed Time ms - WDEV:  10016, ESP :  10009, OS (freertos) :  10008
                     WDEV vs ESP ms :      7, WDEV vs OS ms :      8

Elapsed Time ms - WDEV:  15022, ESP :  15011, OS (freertos) :  15008
                     WDEV vs ESP ms :     10, WDEV vs OS ms :     14

Elapsed Time ms - WDEV:  20028, ESP :  20014, OS (freertos) :  20008
                     WDEV vs ESP ms :     14, WDEV vs OS ms :     20

Elapsed Time ms - WDEV:  25034, ESP :  25016, OS (freertos) :  25008
                     WDEV vs ESP ms :     17, WDEV vs OS ms :     26

Elapsed Time ms - WDEV:  30040, ESP :  30019, OS (freertos) :  30008
                     WDEV vs ESP ms :     21, WDEV vs OS ms :     32

Elapsed Time ms - WDEV:  35046, ESP :  35021, OS (freertos) :  35008
                     WDEV vs ESP ms :     24, WDEV vs OS ms :     38

Elapsed Time ms - WDEV:  40052, ESP :  40024, OS (freertos) :  40008
                     WDEV vs ESP ms :     28, WDEV vs OS ms :     44

Elapsed Time ms - WDEV:  45058, ESP :  45026, OS (freertos) :  45008
                     WDEV vs ESP ms :     31, WDEV vs OS ms :     50

Elapsed Time ms - WDEV:  50064, ESP :  50029, OS (freertos) :  50008
                     WDEV vs ESP ms :     35, WDEV vs OS ms :     56

Elapsed Time ms - WDEV:  55070, ESP :  55031, OS (freertos) :  55008
                     WDEV vs ESP ms :     38, WDEV vs OS ms :     62

Elapsed Time ms - WDEV:  60076, ESP :  60034, OS (freertos) :  60008
                     WDEV vs ESP ms :     42, WDEV vs OS ms :     68

[Ymhr6]

I confirm the presence of a timer drift.
I have a soft timer
TimerHandle_t timer = xTimerCreate("mT", pdMS_TO_TICKS(500), pdTRUE, NULL, timerCicle);
that increment a variable initialized through a call to sntp service.
After 2 hours, with a new call to sntp service, the difference is about 5 seconds, that correspond to 42ms / minute that you noticed.

Same code but with an old SDK (non IDF style) was fine, with a max drift of about 1 second/24 hours.

Now I'm trying with another ESP01 board to see if it's a board problem.
Next I will try your code and will comment results.

[dsptech]

A pair of years ago it work fine. Now I resumed an old project and noticed that.
I think that the issues has been introduced with the update b061230 (19/Ago/19)

[Ymhr6]

With your code no drift! Can I adopt it? When do you think your request will be pull? I don't see much movement on this SDK

[dsptech]

Certainly. Obviously I am using that fix in my projects and so I would be grateful if you would inform me about any discovered problem.
Related the PR, I have no feedback from them at the moment.
Regards.

[dsptech]

Hi @Ymhr6,
I updated the PR

[Ymhr6]

Ok thanks