Understanding the vTaskDelay help

[zazas321]

Hello. I have created a freertos task and I want it to repeat itself precisely every 2 seconds. The pseudo code if my task:

Code: Select all

        static void TIMER_TEST_TASK(void* parameters)
        {       
            for(;;)
            {   
                int64_t task_execution_start = esp_timer_get_time()/1000; // get current time required for the task delay
                ESP_LOGW("MICROSECONDS","time in miliseconds=%lli",task_execution_start);
                

                // HERE BUNCH OF THINHS HAPPENING SUCH AS TOGGLING RELAYS, PRINTING VARIOUS STATES AND ETC.
                // THE TASK EXECUTION CAN TAKE ANYWHERE FROM 1MS TO 50MS 
               
                int64_t task_execution_end = esp_timer_get_time()/1000; 
                int64_t timestamp_difference = (task_execution_end - task_execution_start);
                ESP_LOGW("TEST","task execution end = %lli ms",task_execution_end);
                ESP_LOGW("TEST","timestamp difference = %lli \n",timestamp_difference);

                vTaskDelay((2000-timestamp_difference)/portTICK_PERIOD_MS); 
            }
        }

The task above calculates how long the task took to execute and then performs vTaskDelay including the timestamp_difference. For example, if task execution time is 50ms, then the delay will be 1950ms


Looking at the logs I see:

Code: Select all

[1B][0;33mW (47768) MICROSECONDS: time in miliseconds=47038[1B][0m

[1B][0;33mW (47828) TIMESTAMP: task execution end = 47105 ms[1B][0m
[1B][0;33mW (47838) TIMESTAMP: timestamp difference = 67 


[1B][0;33mW (49768) MICROSECONDS: time in miliseconds=49038[1B][0m

[1B][0;33mW (49828) TIMESTAMP: task execution end = 49105 ms[1B][0m
[1B][0;33mW (49838) TIMESTAMP: timestamp difference = 67 


[1B][0;33mW (51768) MICROSECONDS: time in miliseconds=51038[1B][0m

[1B][0;33mW (51768) TIMESTAMP: task execution end = 51040 ms[1B][0m
[1B][0;33mW (51768) TIMESTAMP: timestamp difference = 2 


[1B][0;33mW (53758) MICROSECONDS: time in miliseconds=53028[1B][0m

[1B][0;33mW (53758) TIMESTAMP: task execution end = 53030 ms[1B][0m
[1B][0;33mW (53758) TIMESTAMP: timestamp difference = 2 


[1B][0;33mW (55748) MICROSECONDS: time in miliseconds=55018[1B][0m

[1B][0;33mW (55748) TIMESTAMP: task execution end = 55020 ms[1B][0m
[1B][0;33mW (55748) TIMESTAMP: timestamp difference = 2 


[1B][0;33mW (57738) MICROSECONDS: time in miliseconds=57008[1B][0m

[1B][0;33mW (57738) TIMESTAMP: task execution end = 57010 ms[1B][0m
[1B][0;33mW (57738) TIMESTAMP: timestamp difference = 2 


[1B][0;33mW (59728) MICROSECONDS: time in miliseconds=58998[1B][0m

[1B][0;33mW (59728) TIMESTAMP: task execution end = 59000 ms[1B][0m
[1B][0;33mW (59728) TIMESTAMP: timestamp difference = 2 


[1B][0;33mW (61718) MICROSECONDS: time in miliseconds=60989[1B][0m

[1B][0;33mW (61718) TIMESTAMP: task execution end = 60990 ms[1B][0m
[1B][0;33mW (61718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (63718) MICROSECONDS: time in miliseconds=62989[1B][0m

[1B][0;33mW (63718) TIMESTAMP: task execution end = 62990 ms[1B][0m
[1B][0;33mW (63718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (65718) MICROSECONDS: time in miliseconds=64989[1B][0m

[1B][0;33mW (65718) TIMESTAMP: task execution end = 64990 ms[1B][0m
[1B][0;33mW (65718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (67718) MICROSECONDS: time in miliseconds=66989[1B][0m

[1B][0;33mW (67718) TIMESTAMP: task execution end = 66990 ms[1B][0m
[1B][0;33mW (67718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (69718) MICROSECONDS: time in miliseconds=68989[1B][0m

[1B][0;33mW (69718) TIMESTAMP: task execution end = 68990 ms[1B][0m
[1B][0;33mW (69718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (71718) MICROSECONDS: time in miliseconds=70989[1B][0m

[1B][0;33mW (71718) TIMESTAMP: task execution end = 70990 ms[1B][0m
[1B][0;33mW (71718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (73718) MICROSECONDS: time in miliseconds=72989[1B][0m

[1B][0;33mW (73718) TIMESTAMP: task execution end = 72990 ms[1B][0m
[1B][0;33mW (73718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (75718) MICROSECONDS: time in miliseconds=74989[1B][0m

[1B][0;33mW (75718) TIMESTAMP: task execution end = 74991 ms[1B][0m
[1B][0;33mW (75718) TIMESTAMP: timestamp difference = 2 


[1B][0;33mW (77718) MICROSECONDS: time in miliseconds=76989[1B][0m

[1B][0;33mW (77718) TIMESTAMP: task execution end = 76990 ms[1B][0m
[1B][0;33mW (77718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (79718) MICROSECONDS: time in miliseconds=78989[1B][0m

[1B][0;33mW (79718) TIMESTAMP: task execution end = 78990 ms[1B][0m
[1B][0;33mW (79718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (81718) MICROSECONDS: time in miliseconds=80989[1B][0m

[1B][0;33mW (81718) TIMESTAMP: task execution end = 80990 ms[1B][0m
[1B][0;33mW (81718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (83718) MICROSECONDS: time in miliseconds=82989[1B][0m

[1B][0;33mW (83718) TIMESTAMP: task execution end = 82990 ms[1B][0m
[1B][0;33mW (83718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (85718) MICROSECONDS: time in miliseconds=84989[1B][0m

[1B][0;33mW (85718) TIMESTAMP: task execution end = 84991 ms[1B][0m
[1B][0;33mW (85718) TIMESTAMP: timestamp difference = 2 


[1B][0;33mW (87718) MICROSECONDS: time in miliseconds=86989[1B][0m

[1B][0;33mW (87718) TIMESTAMP: task execution end = 86990 ms[1B][0m
[1B][0;33mW (87718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (89718) MICROSECONDS: time in miliseconds=88989[1B][0m

[1B][0;33mW (89718) TIMESTAMP: task execution end = 88990 ms[1B][0m
[1B][0;33mW (89718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (91718) MICROSECONDS: time in miliseconds=90989[1B][0m

[1B][0;33mW (91718) TIMESTAMP: task execution end = 90990 ms[1B][0m
[1B][0;33mW (91718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (93718) MICROSECONDS: time in miliseconds=92989[1B][0m

[1B][0;33mW (93718) TIMESTAMP: task execution end = 92990 ms[1B][0m
[1B][0;33mW (93718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (95718) MICROSECONDS: time in miliseconds=94989[1B][0m

[1B][0;33mW (95718) TIMESTAMP: task execution end = 94990 ms[1B][0m
[1B][0;33mW (95718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (97718) MICROSECONDS: time in miliseconds=96989[1B][0m

[1B][0;33mW (97718) TIMESTAMP: task execution end = 96990 ms[1B][0m
[1B][0;33mW (97718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (99718) MICROSECONDS: time in miliseconds=98989[1B][0m

[1B][0;33mW (99718) TIMESTAMP: task execution end = 98990 ms[1B][0m
[1B][0;33mW (99718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (101718) MICROSECONDS: time in miliseconds=100989[1B][0m

[1B][0;33mW (101718) TIMESTAMP: task execution end = 100990 ms[1B][0m
[1B][0;33mW (101718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (103718) MICROSECONDS: time in miliseconds=102989[1B][0m

[1B][0;33mW (103718) TIMESTAMP: task execution end = 102990 ms[1B][0m
[1B][0;33mW (103718) TIMESTAMP: timestamp difference = 1 


[1B][0;33mW (105718) MICROSECONDS: time in miliseconds=104989[1B][0m

[1B][0;33mW (105718) TIMESTAMP: task execution end = 104991 ms[1B][0m
[1B][0;33mW (105718) TIMESTAMP: timestamp difference = 2 


[1B][0;33mW (107738) MICROSECONDS: time in miliseconds=107011[1B][0m

[1B][0;33mW (107818) TIMESTAMP: task execution end = 107091 ms[1B][0m
[1B][0;33mW (107818) TIMESTAMP: timestamp difference = 80 


[1B][0;33mW (109748) MICROSECONDS: time in miliseconds=109018[1B][0m

[1B][0;33mW (109848) TIMESTAMP: task execution end = 109120 ms[1B][0m
[1B][0;33mW (109848) TIMESTAMP: timestamp difference = 102 

As you can see from the logs, the time keeps deviating. Sometimes it delays for exactly 2 seconds but sometimes it misses 10ms.

1. I have ensured that this is the only task with priority 1. There are other tasks running in the background but they have priority 2 or higher.

2. I have disabled all interrupts.

[ESP_Sprite]

If you're using the default settings of ESP-IDF, the tick rate (=minimum granularity to schedule things) is 100Hz, so your 10ms matches exactly a situation where the time to wait would be e.g. 1999.99ms which gets rounded down.

[boarchuz]

• "xTaskDelayUntil() can be used to generate a constant execution frequency." https://freertos.org/xtaskdelayuntiltask-control.html
• FreeRTOS timing is not high resolution and will be limited by the configured tick rate. At the default 100hz, a 1 tick delay could be almost immediate (if the next tick is imminent) right up to 10ms (if immediately after a tick).
• Higher value = higher priority