diff --git a/components/esp_timer/include/esp_timer.h b/components/esp_timer/include/esp_timer.h index a1c63d1a45..f77222bf8e 100644 --- a/components/esp_timer/include/esp_timer.h +++ b/components/esp_timer/include/esp_timer.h @@ -41,6 +41,7 @@ #include #include +#include #include "esp_err.h" #ifdef __cplusplus @@ -81,6 +82,7 @@ typedef struct { void* arg; //!< Argument to pass to the callback esp_timer_dispatch_t dispatch_method; //!< Call the callback from task or from ISR const char* name; //!< Timer name, used in esp_timer_dump function + bool skip_unhandled_events; //!< Skip unhandled events for periodic timers } esp_timer_create_args_t; /** diff --git a/components/esp_timer/src/esp_timer.c b/components/esp_timer/src/esp_timer.c index 3ce7399ddc..a636c14590 100644 --- a/components/esp_timer/src/esp_timer.c +++ b/components/esp_timer/src/esp_timer.c @@ -55,9 +55,15 @@ #define EVENT_ID_DELETE_TIMER 0xF0DE1E1E +typedef enum { + FL_DISPATCH_METHOD = (1 << 0), //!< 0=Callback is called from timer task, 1=Callback is called from timer ISR + FL_SKIP_UNHANDLED_EVENTS = (1 << 1), //!< 0=NOT skip unhandled events for periodic timers, 1=Skip unhandled events for periodic timers +} flags_t; + struct esp_timer { uint64_t alarm; - uint64_t period; + uint64_t period:56; + flags_t flags:8; union { esp_timer_cb_t callback; uint32_t event_id; @@ -67,6 +73,7 @@ struct esp_timer { const char* name; size_t times_triggered; size_t times_armed; + size_t times_skipped; uint64_t total_callback_run_time; #endif // WITH_PROFILING LIST_ENTRY(esp_timer) list_entry; @@ -117,6 +124,8 @@ esp_err_t esp_timer_create(const esp_timer_create_args_t* args, } result->callback = args->callback; result->arg = args->arg; + result->flags = (args->dispatch_method ? FL_DISPATCH_METHOD : 0) | + (args->skip_unhandled_events ? FL_SKIP_UNHANDLED_EVENTS : 0); #if WITH_PROFILING result->name = args->name; timer_insert_inactive(result); @@ -158,6 +167,7 @@ esp_err_t IRAM_ATTR esp_timer_start_periodic(esp_timer_handle_t timer, uint64_t timer->period = period_us; #if WITH_PROFILING timer->times_armed++; + timer->times_skipped = 0; #endif esp_err_t err = timer_insert(timer); timer_list_unlock(); @@ -282,47 +292,51 @@ static void timer_process_alarm(esp_timer_dispatch_t dispatch_method) (void) dispatch_method; timer_list_lock(); - int64_t now = esp_timer_impl_get_time(); - esp_timer_handle_t it = LIST_FIRST(&s_timers); - while (it != NULL && - it->alarm < now) { // NOLINT(clang-analyzer-unix.Malloc) - // Static analyser reports "Use of memory after it is freed" since the "it" variable - // is freed below (if EVENT_ID_DELETE_TIMER) and assigned to the (new) LIST_FIRST() - // so possibly (if the "it" hasn't been removed from the list) it might keep the same ptr. - // Ignoring this warning, as this couldn't happen if queue.h used to populate the list + esp_timer_handle_t it; + while (1) { + it = LIST_FIRST(&s_timers); + int64_t now = esp_timer_impl_get_time(); + if (it == NULL || it->alarm > now) { + break; + } LIST_REMOVE(it, list_entry); if (it->event_id == EVENT_ID_DELETE_TIMER) { free(it); - it = LIST_FIRST(&s_timers); - continue; - } - if (it->period > 0) { - it->alarm += it->period; - timer_insert(it); + it = NULL; } else { - it->alarm = 0; + if (it->period > 0) { + int skipped = (now - it->alarm) / it->period; + if ((it->flags & FL_SKIP_UNHANDLED_EVENTS) && (skipped > 1)) { + it->alarm = now + it->period; #if WITH_PROFILING - timer_insert_inactive(it); + it->times_skipped += skipped; +#endif + } else { + it->alarm += it->period; + } + timer_insert(it); + } else { + it->alarm = 0; +#if WITH_PROFILING + timer_insert_inactive(it); +#endif + } +#if WITH_PROFILING + uint64_t callback_start = now; +#endif + esp_timer_cb_t callback = it->callback; + void* arg = it->arg; + timer_list_unlock(); + (*callback)(arg); + timer_list_lock(); +#if WITH_PROFILING + it->times_triggered++; + it->total_callback_run_time += esp_timer_impl_get_time() - callback_start; #endif } -#if WITH_PROFILING - uint64_t callback_start = now; -#endif - esp_timer_cb_t callback = it->callback; - void* arg = it->arg; - timer_list_unlock(); - (*callback)(arg); - timer_list_lock(); - now = esp_timer_impl_get_time(); -#if WITH_PROFILING - it->times_triggered++; - it->total_callback_run_time += now - callback_start; -#endif - it = LIST_FIRST(&s_timers); } - esp_timer_handle_t first = LIST_FIRST(&s_timers); - if (first) { - esp_timer_impl_set_alarm(first->alarm); + if (it) { + esp_timer_impl_set_alarm(it->alarm); } timer_list_unlock(); } @@ -415,15 +429,21 @@ esp_err_t esp_timer_deinit(void) static void print_timer_info(esp_timer_handle_t t, char** dst, size_t* dst_size) { - size_t cb = snprintf(*dst, *dst_size, #if WITH_PROFILING - "%-12s %12lld %12lld %9d %9d %12lld\n", - t->name, t->period, t->alarm, - t->times_armed, t->times_triggered, t->total_callback_run_time); + size_t cb; + // name is optional, might be missed. + if (t->name) { + cb = snprintf(*dst, *dst_size, "%-12s ", t->name); + } else { + cb = snprintf(*dst, *dst_size, "timer@%p ", t); + } + cb += snprintf(*dst + cb, *dst_size + cb, "%12lld %12lld %9d %9d %6d %12lld\n", + (uint64_t)t->period, t->alarm, t->times_armed, + t->times_triggered, t->times_skipped, t->total_callback_run_time); /* keep this in sync with the format string, used in esp_timer_dump */ -#define TIMER_INFO_LINE_LEN 78 +#define TIMER_INFO_LINE_LEN 90 #else - "timer@%p %12lld %12lld\n", t, t->period, t->alarm); + size_t cb = snprintf(*dst, *dst_size, "timer@%p %12lld %12lld\n", t, (uint64_t)t->period, t->alarm); #define TIMER_INFO_LINE_LEN 46 #endif *dst += cb; diff --git a/components/esp_timer/test/test_esp_timer.c b/components/esp_timer/test/test_esp_timer.c index 3ef7b3a879..e3a9b31da6 100644 --- a/components/esp_timer/test/test_esp_timer.c +++ b/components/esp_timer/test/test_esp_timer.c @@ -413,6 +413,8 @@ TEST_CASE("esp_timer for very short intervals", "[esp_timer]") teardown_overflow(); vSemaphoreDelete(semaphore); + TEST_ESP_OK(esp_timer_delete(timer1)); + TEST_ESP_OK(esp_timer_delete(timer2)); } @@ -665,6 +667,7 @@ TEST_CASE("after esp_timer_impl_advance, timers run when expected", "[esp_timer] TEST_ASSERT(state.cb_time > t_start); ref_clock_deinit(); + TEST_ESP_OK(esp_timer_delete(timer)); } static esp_timer_handle_t timer1; @@ -824,6 +827,8 @@ TEST_CASE("esp_timer_impl_set_alarm and using start_once do not lead that the Sy esp_timer_stop(oneshot_timer); esp_timer_delete(oneshot_timer); + esp_timer_stop(periodic_timer); + esp_timer_delete(periodic_timer); printf("timers deleted\n"); vTaskDelay(1000 / portTICK_PERIOD_MS); @@ -869,3 +874,45 @@ TEST_CASE("Test esp_timer_impl_set_alarm when the counter is near an overflow va } } #endif + +static void timer_callback5(void* arg) +{ + *(int64_t *)arg = esp_timer_get_time(); +} + +TEST_CASE("Test a latency between a call of callback and real event", "[esp_timer]") +{ + + int64_t callback_time = 0; + const esp_timer_create_args_t periodic_timer_args = { + .arg = &callback_time, + .callback = &timer_callback5, + }; + + esp_timer_handle_t periodic_timer; + + TEST_ESP_OK(esp_timer_create(&periodic_timer_args, &periodic_timer)); + int interval_ms = 50; + TEST_ESP_OK(esp_timer_start_periodic(periodic_timer, interval_ms * 1000)); + + for (int i = 0; i < 5; ++i) { + int64_t expected_time = esp_timer_get_next_alarm(); + int64_t saved_callback_time = callback_time; + while (saved_callback_time == callback_time) { + vTaskDelay(10 / portTICK_PERIOD_MS); + } + int diff = callback_time - expected_time; + printf("%d us\n", diff); +#ifndef CONFIG_IDF_ENV_FPGA + if (i != 0) { + // skip the first measurement + // if CPU_FREQ = 240MHz. 14 - 16us + TEST_ASSERT_LESS_OR_EQUAL(50, diff); + } +#endif // not CONFIG_IDF_ENV_FPGA + } + + TEST_ESP_OK(esp_timer_dump(stdout)); + TEST_ESP_OK(esp_timer_stop(periodic_timer)); + TEST_ESP_OK(esp_timer_delete(periodic_timer)); +} diff --git a/components/esp_timer/test/test_esp_timer_light_sleep.c b/components/esp_timer/test/test_esp_timer_light_sleep.c new file mode 100644 index 0000000000..e6ef48e5c9 --- /dev/null +++ b/components/esp_timer/test/test_esp_timer_light_sleep.c @@ -0,0 +1,52 @@ +#include +#include +#include +#include +#include +#include "esp_timer.h" +#include "unity.h" +#include "esp_rom_sys.h" +#include "esp_sleep.h" + + +#if !TEMPORARY_DISABLED_FOR_TARGETS(ESP32S3) // IDF-1780 ESP32-S3 Deep sleep and light sleep + +static void timer_cb1(void *arg) +{ + ++*((int*) arg); +} + +TEST_CASE("Test the periodic timer does not handle lost events during light sleep", "[esp_timer][timeout=20]") +{ + + int count_calls; + const esp_timer_create_args_t timer_args = { + .name = "timer_cb1", + .arg = &count_calls, + .callback = &timer_cb1, + .skip_unhandled_events = true, + }; + esp_timer_handle_t periodic_timer; + esp_timer_create(&timer_args, &periodic_timer); + + int period_cb_ms = 10; + int interval_ms = 50; + TEST_ESP_OK(esp_timer_start_periodic(periodic_timer, period_cb_ms * 1000)); + TEST_ESP_OK(esp_sleep_enable_timer_wakeup(interval_ms * 1000)); + printf("Run light sleep\n"); + printf("count_calls should be around = %d\n", interval_ms / period_cb_ms); + for (int i = 0; i < 3; i++) { + count_calls = 0; + TEST_ESP_OK(esp_light_sleep_start()); + esp_rom_delay_us(interval_ms * 1000); + printf("count_calls = %d\n", count_calls); + TEST_ASSERT_INT_WITHIN(2, interval_ms / period_cb_ms, count_calls); + TEST_ESP_OK(esp_timer_dump(stdout)); + } + TEST_ESP_OK(esp_timer_stop(periodic_timer)); + // times_skipped is about 12 (4 from each sleep time). + TEST_ESP_OK(esp_timer_dump(stdout)); + TEST_ESP_OK(esp_timer_delete(periodic_timer)); +} + +#endif // !TEMPORARY_DISABLED_FOR_TARGETS(ESP32S3) diff --git a/components/esp_timer/test/test_ets_timer.c b/components/esp_timer/test/test_ets_timer.c index a17add857f..4725027095 100644 --- a/components/esp_timer/test/test_ets_timer.c +++ b/components/esp_timer/test/test_ets_timer.c @@ -49,6 +49,7 @@ TEST_CASE("ets_timer produces correct delay", "[ets_timer]") } ets_timer_disarm(&timer1); + ets_timer_done(&timer1); } TEST_CASE("periodic ets_timer produces correct delays", "[ets_timer]") @@ -94,6 +95,7 @@ TEST_CASE("periodic ets_timer produces correct delays", "[ets_timer]") for (size_t i = 0; i < NUM_INTERVALS; ++i) { TEST_ASSERT_INT32_WITHIN(portTICK_PERIOD_MS, (i + 1) * delay_ms, args.intervals[i]); } + ets_timer_done(&timer1); #undef NUM_INTERVALS } @@ -197,7 +199,9 @@ TEST_CASE("multiple ETSTimers are ordered correctly", "[ets_timer]") TEST_ASSERT_TRUE(args1.pass); TEST_ASSERT_TRUE(args2.pass); TEST_ASSERT_TRUE(args3.pass); - + ets_timer_done(&timer1); + ets_timer_done(&timer2); + ets_timer_done(&timer3); #undef N } @@ -243,4 +247,5 @@ IRAM_ATTR TEST_CASE("ETSTimers arm & disarm run from IRAM", "[ets_timer]") spi_flash_guard_get()->start(); ets_timer_disarm(&timer1); spi_flash_guard_get()->end(); + ets_timer_done(&timer1); } diff --git a/docs/en/api-reference/system/esp_timer.rst b/docs/en/api-reference/system/esp_timer.rst index 58d1ce5782..3987f304bd 100644 --- a/docs/en/api-reference/system/esp_timer.rst +++ b/docs/en/api-reference/system/esp_timer.rst @@ -47,6 +47,33 @@ The timer can be started in one-shot mode or in periodic mode. Note that the timer must not be running when :cpp:func:`esp_timer_start_once` or :cpp:func:`esp_timer_start_periodic` is called. To restart a running timer, call :cpp:func:`esp_timer_stop` first, then call one of the start functions. +esp_timer during the light sleep +-------------------------------- + +During light sleep, the esp_timer counter stops and no callback functions are called. +Instead, the time is counted by the RTC counter. Upon waking up, the system gets the difference +between the counters and calls a function that advances the esp_timer counter. +Since the counter has been advanced, the system starts calling callbacks that were not called during sleep. +The number of callbacks depends on the duration of the sleep and the period of the timers. It can lead to overflow of some queues. +This only applies to periodic timers, one-shot timers will be called once. + +This behavior can be changed by calling :cpp:func:`esp_timer_stop` before sleeping. +In some cases, this can be inconvenient, and instead of the stop function, +you can use the `skip_unhandled_events` option during :cpp:func:`esp_timer_create`. +When the `skip_unhandled_events` is true, if a periodic timer expires one or more times during light sleep +then only one callback is called on wake. + +Handling callbacks +------------------ + +esp_timer is designed to achieve a high-resolution low latency timer and the ability to handle delayed events. +If the timer is late then the callback will be called as soon as possible, it will not be lost. +In the worst case, when the timer has not been processed for more than one period (for periodic timers), +in this case the callbacks will be called one after the other without waiting for the set period. +This can be bad for some applications, and the `skip_unhandled_events` option was introduced to eliminate this behavior. +If `skip_unhandled_events` is set then a periodic timer that has expired multiple times without being able to call +the callback will still result in only one callback event once processing is possible. + Obtaining Current Time ---------------------- diff --git a/examples/cxx/experimental/experimental_cpp_component/esp_event_cxx.cpp b/examples/cxx/experimental/experimental_cpp_component/esp_event_cxx.cpp index 83f40949bc..e363861e2e 100644 --- a/examples/cxx/experimental/experimental_cpp_component/esp_event_cxx.cpp +++ b/examples/cxx/experimental/experimental_cpp_component/esp_event_cxx.cpp @@ -73,7 +73,8 @@ ESPEventRegTimed::ESPEventRegTimed(std::function timer_cb_hook, static_cast(this), ESP_TIMER_TASK, - "event" + "event", + false // skip_unhandled_events }; esp_err_t res = esp_timer_create(&oneshot_timer_args, &timer); diff --git a/examples/system/esp_timer/README.md b/examples/system/esp_timer/README.md index 69a789d6b4..1814c75f25 100644 --- a/examples/system/esp_timer/README.md +++ b/examples/system/esp_timer/README.md @@ -49,31 +49,31 @@ The example should have the following log output: ``` ... I (294) example: Started timers, time since boot: 9662 us -periodic 500000 509644 1 0 0 -one-shot 0 5009654 1 0 0 +periodic 500000 509644 1 0 0 0 +one-shot 0 5009654 1 0 0 0 I (794) example: Periodic timer called, time since boot: 509694 us I (1294) example: Periodic timer called, time since boot: 1009671 us I (1794) example: Periodic timer called, time since boot: 1509671 us I (2294) example: Periodic timer called, time since boot: 2009671 us -periodic 500000 2509644 1 4 542 -one-shot 0 5009654 1 0 0 +periodic 500000 2509644 1 4 0 542 +one-shot 0 5009654 1 0 0 0 I (2794) example: Periodic timer called, time since boot: 2509671 us I (3294) example: Periodic timer called, time since boot: 3009671 us I (3794) example: Periodic timer called, time since boot: 3509671 us I (4294) example: Periodic timer called, time since boot: 4009671 us -periodic 500000 4509644 1 8 1026 -one-shot 0 5009654 1 0 0 +periodic 500000 4509644 1 8 0 1026 +one-shot 0 5009654 1 0 0 0 I (4794) example: Periodic timer called, time since boot: 4509671 us I (5294) example: Periodic timer called, time since boot: 5009669 us I (5294) example: One-shot timer called, time since boot: 5009788 us I (5294) example: Restarted periodic timer with 1s period, time since boot: 5012675 us I (6294) example: Periodic timer called, time since boot: 6012692 us -periodic 1000000 7012666 2 11 1391 -one-shot 0 0 1 1 11472 +periodic 1000000 7012666 2 11 0 1391 +one-shot 0 0 1 1 0 11472 I (7294) example: Periodic timer called, time since boot: 7012692 us I (8294) example: Periodic timer called, time since boot: 8012692 us -periodic 1000000 9012666 2 13 1639 -one-shot 0 0 1 1 11472 +periodic 1000000 9012666 2 13 0 1639 +one-shot 0 0 1 1 0 11472 I (9294) example: Periodic timer called, time since boot: 9012692 us I (10294) example: Periodic timer called, time since boot: 10012692 us I (10314) example: Entering light sleep for 0.5s, time since boot: 10024351 us @@ -96,12 +96,12 @@ I (265) example: Starting timers, time since boot: 2479 us These two repeating lines are the output of `esp_timer_dump()` function. There is one line for each of the timers created. This function can be useful for debugging purposes. Note that such debugging information is available because the example sets `CONFIG_ESP_TIMER_PROFILING` option in sdkconfig. Without this option, less information will be available. See documentation of `esp_timer_dump()` in ESP-IDF programming guide for more details. ``` -timer period next time times times callback -name to fire started fired run time (us) ------------------------------------------------------------------------------------- +timer period next time times times times callback +name to fire started fired skipped run time (us) +------------------------------------------------------------------------------------------------- -periodic 500000 502455 1 0 0 -one-shot 0 5002469 1 0 0 +periodic 500000 502455 1 0 0 0 +one-shot 0 5002469 1 0 0 0 ``` ### 3. Periodic timer keeps running at 500ms period: @@ -111,14 +111,14 @@ I (765) example: Periodic timer called, time since boot: 502506 us I (1265) example: Periodic timer called, time since boot: 1002478 us I (1765) example: Periodic timer called, time since boot: 1502478 us I (2265) example: Periodic timer called, time since boot: 2002478 us -periodic 500000 2502455 1 4 511 -one-shot 0 5002469 1 0 0 +periodic 500000 2502455 1 4 0 511 +one-shot 0 5002469 1 0 0 0 I (2765) example: Periodic timer called, time since boot: 2502478 us I (3265) example: Periodic timer called, time since boot: 3002478 us I (3765) example: Periodic timer called, time since boot: 3502478 us I (4265) example: Periodic timer called, time since boot: 4002478 us -periodic 500000 4502455 1 8 971 -one-shot 0 5002469 1 0 0 +periodic 500000 4502455 1 8 0 971 +one-shot 0 5002469 1 0 0 0 I (4765) example: Periodic timer called, time since boot: 4502478 us I (5265) example: Periodic timer called, time since boot: 5002476 us ``` @@ -131,12 +131,12 @@ The one-shot timer runs and changes the period of the periodic timer. Now the pe I (5265) example: One-shot timer called, time since boot: 5002586 us I (5265) example: Restarted periodic timer with 1s period, time since boot: 5005475 us I (6265) example: Periodic timer called, time since boot: 6005492 us -periodic 1000000 7005469 2 11 1316 -one-shot 0 0 1 1 11474 +periodic 1000000 7005469 2 11 0 1316 +one-shot 0 0 1 1 0 11474 I (7265) example: Periodic timer called, time since boot: 7005492 us I (8265) example: Periodic timer called, time since boot: 8005492 us -periodic 1000000 9005469 2 13 1550 -one-shot 0 0 1 1 11474 +periodic 1000000 9005469 2 13 0 1550 +one-shot 0 0 1 1 0 11474 I (9265) example: Periodic timer called, time since boot: 9005492 us I (10265) example: Periodic timer called, time since boot: 10005492 us ``` diff --git a/examples/system/esp_timer/example_test.py b/examples/system/esp_timer/example_test.py index ddc9c85d51..4a8730e455 100644 --- a/examples/system/esp_timer/example_test.py +++ b/examples/system/esp_timer/example_test.py @@ -5,8 +5,8 @@ import ttfw_idf STARTING_TIMERS_REGEX = re.compile(r'Started timers, time since boot: (\d+) us') -# name, period, next_alarm, times_started, times_fired, cb_exec_time -TIMER_DUMP_LINE_REGEX = re.compile(r'([\w-]+)\s+(\d+)\s+(\d+)\s+(\d+)\s+(\d+)\s+(\d+)') +# name, period, next_alarm, times_started, times_fired, times_skipped, cb_exec_time +TIMER_DUMP_LINE_REGEX = re.compile(r'([\w-]+)\s+(\d+)\s+(\d+)\s+(\d+)\s+(\d+)\s+(\d+)\s+(\d+)') PERIODIC_TIMER_REGEX = re.compile(r'Periodic timer called, time since boot: (\d+) us')