From cf21312d8d07cd1700c7e12f4d7e41abe21396c5 Mon Sep 17 00:00:00 2001 From: Omar Chebib Date: Tue, 28 Sep 2021 19:12:29 +0800 Subject: [PATCH 1/2] VFS: `select` function's timeout is now POSIX compliant `select` function will now round up the timeout passed as a parameter (if any). It makes it POSIX compliant. * Closes https://github.com/espressif/esp-idf/issues/7514 --- components/vfs/include/esp_vfs.h | 21 +++++++-------------- components/vfs/vfs.c | 28 +++++++++++++--------------- 2 files changed, 20 insertions(+), 29 deletions(-) diff --git a/components/vfs/include/esp_vfs.h b/components/vfs/include/esp_vfs.h index 2bc8c77fd2..0498a3aa59 100644 --- a/components/vfs/include/esp_vfs.h +++ b/components/vfs/include/esp_vfs.h @@ -1,16 +1,8 @@ -// Copyright 2015-2020 Espressif Systems (Shanghai) PTE LTD -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. +/* + * SPDX-FileCopyrightText: 2015-2021 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ #ifndef __ESP_VFS_H__ #define __ESP_VFS_H__ @@ -410,7 +402,8 @@ int esp_vfs_utime(const char *path, const struct utimbuf *times); * @param timeout If not NULL, then points to timeval structure which * specifies the time period after which the functions should * time-out and return. If it is NULL, then the function will - * not time-out. + * not time-out. Note that the timeout period is rounded up to + * the system tick and incremented by one. * * @return The number of descriptors set in the descriptor sets, or -1 * when an error (specified by errno) have occurred. diff --git a/components/vfs/vfs.c b/components/vfs/vfs.c index 9fb4c592ee..4eb0642f0a 100644 --- a/components/vfs/vfs.c +++ b/components/vfs/vfs.c @@ -1,16 +1,8 @@ -// Copyright 2015-2019 Espressif Systems (Shanghai) PTE LTD -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. +/* + * SPDX-FileCopyrightText: 2015-2021 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ #include #include @@ -1028,8 +1020,14 @@ int esp_vfs_select(int nfds, fd_set *readfds, fd_set *writefds, fd_set *errorfds TickType_t ticks_to_wait = portMAX_DELAY; if (timeout) { - uint32_t timeout_ms = timeout->tv_sec * 1000 + timeout->tv_usec / 1000; - ticks_to_wait = timeout_ms / portTICK_PERIOD_MS; + uint32_t timeout_ms = (timeout->tv_sec * 1000) + (timeout->tv_usec / 1000); + /* Round up the number of ticks. + * Not only we need to round up the number of ticks, but we also need to add 1. + * Indeed, `select` function shall wait for AT LEAST timeout, but on FreeRTOS, + * if we specify a timeout of 1 tick to `xSemaphoreTake`, it will take AT MOST + * 1 tick before triggering a timeout. Thus, we need to pass 2 ticks as a timeout + * to `xSemaphoreTake`. */ + ticks_to_wait = ((timeout_ms + portTICK_PERIOD_MS - 1) / portTICK_PERIOD_MS) + 1; ESP_LOGD(TAG, "timeout is %dms", timeout_ms); } ESP_LOGD(TAG, "waiting without calling socket_select"); From e91fd5ece9b72177133a1617cee32d34ce0bc3a4 Mon Sep 17 00:00:00 2001 From: Omar Chebib Date: Wed, 3 Nov 2021 19:31:33 +0800 Subject: [PATCH 2/2] 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 + + +