alex/esp-idf
alex/esp-idf
1
0
Fork 0
mirror of https://github.com/espressif/esp-idf.git synced 2024-10-05 20:47:46 -04:00
Code Issues Actions 2 Packages Projects Releases Wiki Activity

Merge branch 'bugfix/after_ligth_sleep_esp_timer_forms_one_event' into 'master'

Browse Source 
esp_timer: Add an option skip_unhandled_events

See merge request espressif/esp-idf!10969
This commit is contained in:
Angus Gratton 2020-12-11 06:04:58 +08:00
commit 7472d76db0
9 changed files with 221 additions and 67 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
components/esp_timer/include/esp_timer.h
View File

@ -41,6 +41,7 @@
#include <stdint.h>
#include <stdio.h>
#include <stdbool.h>
#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;
/**

100
components/esp_timer/src/esp_timer.c
View File

@ -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;

47
components/esp_timer/test/test_esp_timer.c
View File

@ -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));
}

52
components/esp_timer/test/test_esp_timer_light_sleep.c Normal file
View File

@ -0,0 +1,52 @@
#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <sys/time.h>
#include <sys/param.h>
#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)

7
components/esp_timer/test/test_ets_timer.c
View File

@ -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);
}

27
docs/en/api-reference/system/esp_timer.rst
View File

@ -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
----------------------

3
examples/cxx/experimental/experimental_cpp_component/esp_event_cxx.cpp
View File

@ -73,7 +73,8 @@ ESPEventRegTimed::ESPEventRegTimed(std::function<void(const ESPEvent &, void*)>
timer_cb_hook,
static_cast<void*>(this),
ESP_TIMER_TASK,
"event"
"event",
false // skip_unhandled_events
};
esp_err_t res = esp_timer_create(&oneshot_timer_args, &timer);

46
examples/system/esp_timer/README.md
View File

@ -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
```

4
examples/system/esp_timer/example_test.py
View File

@ -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')