esp_timer_get_time() and vTaskDelay() behaviour

[vito576]

Hi, I was trying the example provided by ESPESSIF in this page: https://docs.espressif.com/projects/esp ... speed.html

I wanted to test it in my code while making the following change:

Code: Select all

#include "esp_timer.h"

void measure_important_function(void) {
    const unsigned MEASUREMENTS = 5000;
    uint64_t start = esp_timer_get_time();
    uint64_t retries = 0;
    
    while(retries < MEASUREMENTS) {
        important_function(); 
        retires++;
    }

    uint64_t end = esp_timer_get_time();

    printf("%u iterations took %llu milliseconds (%llu microseconds per invocation)\n",
           MEASUREMENTS, (end - start)/1000, (end - start)/MEASUREMENTS);
}

For my specific function I got 766 microseconds per invocation... But, if I incluide vTaskDelay(pdMS_TO_TICKS(2)) inside the loop:

Code: Select all

while(retries < MEASUREMENTS) {
        vTaskDelay(pdMS_TO_TICKS(2))
        important_function(); 
        retires++;
}

I get 2000 microseconds per invocation... I was expecting something around 2766 microseconds per invocation since I include my function inside the while. Removing the function and leaving only vTaskDelay(pdMS_TO_TICKS(2)) gives the same results -> 2000 microseconds per invocation.

Is this the tipical behaviour?

[MicroController]

By default, you cannot vTaskDelay for less than 10ms (FreeRTOS tick rate=100Hz).
And your function (call) may actually be optimized away by the compiler if gcc sees that it has no visible effects in other code.

[ESP_Sprite]

From the fact that OP gets 2000 microseconds, I imagine he changed the tick frequency to 1000Hz.

OP: The reason is that ticks happen on a fixed schedule, once per MS in your case, seemingly. If you do a vTaskDelay(pdMS_TO_TICKS(2)) you tell FreeRTOS to wait for the tick timer to increase two times. However, because you're already 'halfway' the first tick, it'll effectively wait a tick and a half rather than two ticks.

[vito576]

Yes, I set de clock to 1000 [Hz]

If you do a vTaskDelay(pdMS_TO_TICKS(2)) you tell FreeRTOS to wait for the tick timer to increase two times. However, because you're already 'halfway' the first tick.

Why it's already halfway the first tick? Calling vTaskDelay takes ~ 0.5 [ms]?

I'm just recently dealing with timers but it seems off to me that evaluating the performance of two functions individually and then evaluating the performance of two functions together doesn't add the individual results... for example:

performance(Function1) -> takes 700 [ms] on average
performance(Function2) -> takes 300 [ms] on average

performance(Function2 + Function1) -> takes 800 [ms] on average instead of 700+300 [ms]

[ESP_Sprite]

Why it's already halfway the first tick? Calling vTaskDelay takes ~ 0.5 [ms]?

Because when vTaskDelay exits, the time is on a tick boundary. Immediately after, important_function is called, which uses some time, which I'm rounding to half a tick. (The exact duration doesn't matter, simply that it is less than a whole tick.) When vTaskDelay is called again, it waits for what's left of the tick plus one tick, so 1.5 ticks in this example. That means that the total of (vTaskDelay(2) + important_function) takes exactly 2 ticks, where you would perhaps expect it to take two ticks plus whatever time important_function needs.

I'm just recently dealing with timers but it seems off to me that evaluating the performance of two functions individually and then evaluating the performance of two functions together doesn't add the individual results... for example:

performance(Function1) -> takes 700 [ms] on average
performance(Function2) -> takes 300 [ms] on average

performance(Function2 + Function1) -> takes 800 [ms] on average instead of 700+300 [ms]

I have no idea what that code looks like, but it smells like either your performance evaluation code adds time, or the compiler can optimize by combining something in the calls to both functions so the total takes less.

[vito576]

Code: Select all

#include "esp_timer.h"

void measure_important_function(void) {
    const unsigned MEASUREMENTS = 5000;
    uint64_t start = esp_timer_get_time();
    uint64_t retries = 0;
    
    while(retries < MEASUREMENTS) {
        important_function(); 
        retires++;
    }

    uint64_t end = esp_timer_get_time();

    printf("%u iterations took %llu milliseconds (%llu microseconds per invocation)\n",
           MEASUREMENTS, (end - start)/1000, (end - start)/MEASUREMENTS);
}

As stated in my first post I'm using ESPRESSIF example on evaluating performance, the code I'm using is there...

your performance evaluation code adds time, or the compiler can optimize by combining something in the calls to both functions so the total takes less.

So, I guess is the latter case since I'm using ESPRESSIF example?

To be clear inside my important_function() I'm not interacting with the counter retires

I'm still confused with the behavior on evaluating performance of vTaskDelay with custom functions. Specifically with the actual output I provided where I expected at least the performance to vary a little where I excluded my custom function:

I get 2000 microseconds per invocation... I was expecting something around 2766 microseconds per invocation since I include my function inside the while. Removing the function and leaving only vTaskDelay(pdMS_TO_TICKS(2)) gives the same results -> 2000 microseconds per invocation.

(I test this with different functions that individually takes less than 766 microseconds and more, and got the same results)

Well, at the end the conclusion(?) seems to be that the performance of individual functions cannot be measure with accuracy (have poor repeatibility is likely a better term) so is wrong to expect the time of execution of different functions to add up. This is not a problem for me right now, but this leads me to the following question for any future use of my esp32:

How can I set an optimal ISR appropriately by using a timer interrupt if the time of execution of the function (that's going to be include in the ISR) that I measure have poor reapeatibility?
Is there a way to get the minimum frequency I can call a function or any good practice (like taking 10x the time of execution that I get by evaluating the performance) to get a function to run every X [seconds]?

[DrMickeyLauer]

The reason is that ticks happen on a fixed schedule, once per MS in your case, seemingly. If you do a vTaskDelay(pdMS_TO_TICKS(2)) you tell FreeRTOS to wait for the tick timer to increase two times. However, because you're already 'halfway' the first tick, it'll effectively wait a tick and a half rather than two ticks.

Wow! Does that mean that using FreeRTOS (w/ CONFIG_HZ=1000), there is no way to exactly specify a sleep shorter than 2 milliseconds? If I specify 1, it could as well sleep any time between 0µs (exaggerated, since it may take a while) and 999µs and if I specify 2, we can only be sure that it sleeps **at least** 1ms, but might be any time between 1 and 2.

This is quite the killer for anything that relies on exact timings, since even if we use a hardware timer it might take a while from the ISR to userland via task notification.

[MicroController]

Yes, FreeRTOS timings are always to be interpreted w.r.t. ticks, with inherent uncertainty of just less than one tick.
Precise timing is not a use case for the FreeRTOS timers. You can use hardware timers or the IDF's 'high resolution timer' to get more accuracy and less uncertainty.

[ESP_Sprite]

As stated in my first post I'm using ESPRESSIF example on evaluating performance, the code I'm using is there...

The performance measurement code is there. Not the code of your important_functions. It could be that the compiler messes with the resulting machine code of that (inlining functions etc) depending on how you invoke them.

your performance evaluation code adds time, or the compiler can optimize by combining something in the calls to both functions so the total takes less.

So, I guess is the latter case since I'm using ESPRESSIF example?

Yes.

I'm still confused with the behavior on evaluating performance of vTaskDelay with custom functions. Specifically with the actual output I provided where I expected at least the performance to vary a little where I excluded my custom function:


(I test this with different functions that individually takes less than 766 microseconds and more, and got the same results)

That doesn't happen because what I explained earlier. To clarify:
- A 'tick' is an unit of 1ms in your case.
- A 'tick boundary' is when FreeRTOS decides a tick ends and starts a new tick.
- Your important_function starts on a tick boundary; the CPU still has 1 ms left before a new tick.
- Your important_function ends 766 ms later; the CPU still has 0.244uS left before a new tick. Total time taken = 766 uS.
- You call vTaskDelay(2). This waits two tick boundaries.
- The first tick boundary arrives 0.244uS later. Total time taken = 1mS.
- The second tick boundary arrives 1mS later. Total time taken = 2mS.
- Your program continues another loop. This loop took exactly 2mS. Note that this is independent of how long the important_function takes exactly; because vTaskDelay 'fills out' the first tick, this will always be 2mS precise.

Well, at the end the conclusion(?) seems to be that the performance of individual functions cannot be measure with accuracy (have poor repeatibility is likely a better term) so is wrong to expect the time of execution of different functions to add up. This is not a problem for me right now, but this leads me to the following question for any future use of my esp32:

I don't think you can conclude that at all. As I said before, the example with vTaskDelay works exactly as you'd imagine it would if you take the quirks of vTaskDelay into account. I think your second example also works fine; if you give the code of the two functions you're trying to measure I can look a bit deeper.

[DrMickeyLauer]

Ok, this thread helped a lot. I think the "quirkiness" of vTaskDelay needs to be described more explicitly in the documentation, as I could imagine many people stumble over it and claim the ESP32 chip family having unreliable timing where it's just a "feature" of FreeRTOS.

Using esp_timer w/ ISR callback and directly waking up a task, you can get a precision in the tens of microseconds, which I think is pretty good. On my ESP32S3 w/ 240MHz and 1000Hz for FreeRTOS, I measured a stable 15µs offset for the ISR and task notification until the task wakes up from xTaskNotifyWait ­–­– pretty much independent of task priority or affinity.

I think that's quite workable. Thanks to all participants.

FWIW: Here's a little component that does it: https://github.com/mickeyl/esp-microsleep