From e91fd5ece9b72177133a1617cee32d34ce0bc3a4 Mon Sep 17 00:00:00 2001 From: Omar Chebib Date: Wed, 3 Nov 2021 19:31:33 +0800 Subject: [PATCH] Example: Fix `eventfd` example test and added a diagram to explain printed values --- examples/system/eventfd/README.md | 64 +- examples/system/eventfd/example_test.py | 21 +- .../system/eventfd/main/eventfd_example.c | 32 +- examples/system/eventfd/timeline.svg | 657 ++++++++++++++++++ 4 files changed, 727 insertions(+), 47 deletions(-) create mode 100644 examples/system/eventfd/timeline.svg diff --git a/examples/system/eventfd/README.md b/examples/system/eventfd/README.md index 2cbb444295..67fb1afdce 100644 --- a/examples/system/eventfd/README.md +++ b/examples/system/eventfd/README.md @@ -39,36 +39,36 @@ See the Getting Started Guide for full steps to configure and use ESP-IDF to bui The following log output should appear when the example runs (note that the bootloader log has been omitted). ``` -I (4310) eventfd_example: Time: 1.99s -I (4310) eventfd_example: Select timeout -I (4310) eventfd_example: ================================= -I (4310) eventfd_example: Select timeouted for 1 times -I (4320) eventfd_example: Timer triggerred for 0 times -I (4320) eventfd_example: Progress triggerred for 0 times -I (4330) eventfd_example: ================================= -I (4810) eventfd_example: Time: 2.50s -I (4810) eventfd_example: TimerEvent fd event triggered -I (5810) eventfd_example: Time: 3.49s -I (5810) eventfd_example: Progress fd event triggered -I (7310) eventfd_example: Time: 5.00s -I (7310) eventfd_example: TimerEvent fd event triggered -I (9310) eventfd_example: Time: 6.99s -I (9310) eventfd_example: Select timeout -I (9310) eventfd_example: Time: 6.99s -I (9310) eventfd_example: Progress fd event triggered -I (9810) eventfd_example: Time: 7.50s -I (9810) eventfd_example: TimerEvent fd event triggered -I (11810) eventfd_example: Time: 9.49s -I (11810) eventfd_example: Select timeout -I (12310) eventfd_example: Time: 10.00s -I (12310) eventfd_example: TimerEvent fd event triggered -I (12810) eventfd_example: Time: 10.49s -I (12810) eventfd_example: Progress fd event triggered -I (14810) eventfd_example: Time: 12.49s -I (14810) eventfd_example: Select timeout -I (14810) eventfd_example: ================================= -I (14810) eventfd_example: Select timeouted for 4 times -I (14820) eventfd_example: Timer triggerred for 4 times -I (14820) eventfd_example: Progress triggerred for 3 times -I (14830) eventfd_example: ================================= +I (4340) eventfd_example: Elapsed since test start: 2003 ms +I (4340) eventfd_example: Select timeout +I (4830) eventfd_example: Elapsed since test start: 2499 ms +I (4830) eventfd_example: TimerEvent fd event triggered +I (5830) eventfd_example: Elapsed since test start: 3493 ms +I (5830) eventfd_example: Progress fd event triggered +I (7330) eventfd_example: Elapsed since test start: 4999 ms +I (7330) eventfd_example: TimerEvent fd event triggered +I (7330) eventfd_example: ================================= +I (7340) eventfd_example: Select timeouted for 1 times +I (7340) eventfd_example: Timer triggerred for 2 times +I (7350) eventfd_example: Progress triggerred for 1 times +I (7360) eventfd_example: ================================= +I (9330) eventfd_example: Elapsed since test start: 6993 ms +I (9330) eventfd_example: Progress fd event triggered +I (9830) eventfd_example: Elapsed since test start: 7499 ms +I (9830) eventfd_example: TimerEvent fd event triggered +I (11840) eventfd_example: Elapsed since test start: 9503 ms +I (11840) eventfd_example: Select timeout +I (12330) eventfd_example: Elapsed since test start: 9999 ms +I (12330) eventfd_example: TimerEvent fd event triggered +I (12330) eventfd_example: ================================= +I (12340) eventfd_example: Select timeouted for 2 times +I (12340) eventfd_example: Timer triggerred for 4 times +I (12350) eventfd_example: Progress triggerred for 2 times +I (12360) eventfd_example: ================================= ``` + +## Diagram + +The following diagram shows, with a timeline, the order of the events: + +![Timeline](timeline.svg) diff --git a/examples/system/eventfd/example_test.py b/examples/system/eventfd/example_test.py index 8cce7fdad6..06774ecb10 100644 --- a/examples/system/eventfd/example_test.py +++ b/examples/system/eventfd/example_test.py @@ -15,14 +15,23 @@ def test_examples_eventfd(env, extra_data): dut.expect('cpu_start: Starting scheduler', timeout=30) - exp_list = [ - 'eventfd_example: Select timeouted for 4 times', - 'eventfd_example: Timer triggerred for 4 times', - 'eventfd_example: Progress triggerred for 3 times', + exp_list_5seconds = [ + 'eventfd_example: Select timeouted for 1 times', + 'eventfd_example: Timer triggerred for 2 times', + 'eventfd_example: Progress triggerred for 1 times', ] - Utility.console_log('Expecting:{}{}'.format(os.linesep, os.linesep.join(exp_list))) - dut.expect_all(*exp_list, timeout=60) + exp_list_10seconds = [ + 'eventfd_example: Select timeouted for 2 times', + 'eventfd_example: Timer triggerred for 4 times', + 'eventfd_example: Progress triggerred for 2 times', + ] + + Utility.console_log('Expecting:{}{}'.format(os.linesep, os.linesep.join(exp_list_5seconds))) + dut.expect_all(*exp_list_5seconds, timeout=60) + + Utility.console_log('Expecting:{}{}'.format(os.linesep, os.linesep.join(exp_list_10seconds))) + dut.expect_all(*exp_list_10seconds, timeout=60) if __name__ == '__main__': diff --git a/examples/system/eventfd/main/eventfd_example.c b/examples/system/eventfd/main/eventfd_example.c index 688231319f..58b4159074 100644 --- a/examples/system/eventfd/main/eventfd_example.c +++ b/examples/system/eventfd/main/eventfd_example.c @@ -28,11 +28,15 @@ #define PROGRESS_INTERVAL_MS 3500 #define TIMER_SIGNAL 1 #define PROGRESS_SIGNAL 2 +/* Print the signals value a bit before 5 seconds, else, `select` would run again + * and the following print may happen 2 seconds (timeout value) later. */ +#define PRINT_INTERVAL_MSEC 4990 static const char *TAG = "eventfd_example"; -int s_timer_fd; -int s_progress_fd; +static int s_timer_fd; +static int s_progress_fd; +static TaskHandle_t s_worker_handle; static bool eventfd_timer_isr_callback(void *arg) { @@ -78,6 +82,9 @@ static void eventfd_timer_init(int timer_idx, double timer_interval_sec) static void worker_task(void *arg) { + /* Wait for the collector to be ready. */ + ulTaskNotifyTake(true, portMAX_DELAY); + while (true) { vTaskDelay(pdMS_TO_TICKS(PROGRESS_INTERVAL_MS)); uint64_t signal = PROGRESS_SIGNAL; @@ -102,7 +109,12 @@ static void collector_task(void *arg) int timer_trigger_count = 0; int progress_trigger_count = 0; - for (size_t i = 0; ; i++) { + /* Notify the worker we are ready to catch the signals */ + assert( xTaskNotifyGive(s_worker_handle) == pdPASS ); + uint64_t start = esp_timer_get_time(); + uint64_t previous = start; + + while (1) { struct timeval timeout; uint64_t signal; @@ -117,9 +129,7 @@ static void collector_task(void *arg) int num_triggered = select(maxFd + 1, &readfds, NULL, NULL, &timeout); assert(num_triggered >= 0); - uint64_t task_counter_value; - timer_get_counter_value(TIMER_GROUP_0, TIMER_0, &task_counter_value); - ESP_LOGI(TAG, "Time: %.2fs", (double)task_counter_value / TIMER_SCALE); + ESP_LOGI(TAG, "Elapsed since test start: %lld ms", (esp_timer_get_time() - start) / 1000); if (FD_ISSET(s_progress_fd, &readfds)) { ssize_t ret = read(s_progress_fd, &signal, sizeof(signal)); @@ -140,13 +150,16 @@ static void collector_task(void *arg) ESP_LOGI(TAG, "Select timeout"); } - if (i % 10 == 0) { + /* Print information about received events every PRINT_INTERVAL_MSEC milliseconds. */ + const uint64_t current = esp_timer_get_time(); + const uint64_t elapsed = current - previous; + if (elapsed >= PRINT_INTERVAL_MSEC * 1000) { ESP_LOGI(TAG, "================================="); ESP_LOGI(TAG, "Select timeouted for %d times", select_timeout_count); ESP_LOGI(TAG, "Timer triggerred for %d times", timer_trigger_count); ESP_LOGI(TAG, "Progress triggerred for %d times", progress_trigger_count); ESP_LOGI(TAG, "================================="); - + previous = current; } } @@ -160,6 +173,7 @@ static void collector_task(void *arg) void app_main(void) { eventfd_timer_init(TIMER_0, TIMER_INTERVAL_SEC); - xTaskCreate(worker_task, "worker_task", 4 * 1024, NULL, 5, NULL); + /* Save the handle for this task as we will need to notify it */ + xTaskCreate(worker_task, "worker_task", 4 * 1024, NULL, 5, &s_worker_handle); xTaskCreate(collector_task, "collector_task", 4 * 1024, NULL, 5, NULL); } diff --git a/examples/system/eventfd/timeline.svg b/examples/system/eventfd/timeline.svg new file mode 100644 index 0000000000..8c2e7e660f --- /dev/null +++ b/examples/system/eventfd/timeline.svg @@ -0,0 +1,657 @@ + + + + + + + + image/svg+xml + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + 5s + + + + 5s + + + + + + + + + + + + + + + + + Select timeout + + + + Select timeout + + + + + + + + + Timer interrupt + + + + Timer interrupt + + + + + + + + + Progress event + + + + Progress event + + + + + + + + + + 10s + + + + 10s + + + + + + + + + + 15s + + + + 15s + + + + + + + + + + 20s + + + + 20s + + + + + + + + + + + Timeout not reached because it is rounded up to system tick + + + + Timeout not reached because it is rounded up to system tick + + + + + + + Viewer does not support full SVG 1.1 + + +