Example: Fix `eventfd` example test and added a diagram to explain printed values

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)

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',
+    exp_list_5seconds = [
+        'eventfd_example: Select timeouted for 1 times',
+        'eventfd_example: Timer triggerred for 2 times',
+        'eventfd_example: Progress triggerred for 1 times',
+    ]
+
+    exp_list_10seconds = [
+        'eventfd_example: Select timeouted for 2 times',
         'eventfd_example: Timer triggerred for 4 times',
-        'eventfd_example: Progress triggerred for 3 times',
+        'eventfd_example: Progress triggerred for 2 times',
     ]
 
-    Utility.console_log('Expecting:{}{}'.format(os.linesep, os.linesep.join(exp_list)))
-    dut.expect_all(*exp_list, timeout=60)
+    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__':

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