From d8d3c50b3f96bfa598882a8f50df38e9496df454 Mon Sep 17 00:00:00 2001 From: Guillaume Souchere Date: Tue, 17 Dec 2024 11:46:58 +0100 Subject: [PATCH] fix(esp_event): Fix event loop profiling in handler_execute function handler_execute function is looking to match the handler only in the list of loop events but does not look in the base event handler list nor the id event handler list. So unless the event handler is registered to be triggered for all event bases and all event ids of an event loop, its profiling fields (invoked and time) are not updated when it is called. This commit updates the search for the matching handler to also look in base event list and ID event list. Closes https://github.com/espressif/esp-idf/issues/15041 --- components/esp_event/esp_event.c | 42 ++++++++++++++--- .../private_include/esp_event_internal.h | 2 +- .../test_apps/main/test_event_common.cpp | 46 +++++++++++++++++++ .../esp_event/test_apps/pytest_esp_event.py | 14 +++++- 4 files changed, 95 insertions(+), 9 deletions(-) diff --git a/components/esp_event/esp_event.c b/components/esp_event/esp_event.c index 0d9be71409..1e6fc99da6 100644 --- a/components/esp_event/esp_event.c +++ b/components/esp_event/esp_event.c @@ -22,7 +22,7 @@ /* ---------------------------- Definitions --------------------------------- */ #ifdef CONFIG_ESP_EVENT_LOOP_PROFILING -// LOOP @ rx: dr: +// LOOP @ rx: dr: #define LOOP_DUMP_FORMAT "LOOP @%p,%s rx:%" PRIu32 " dr:%" PRIu32 "\n" // handler @
ev: inv: time: #define HANDLER_DUMP_FORMAT " HANDLER @%p ev:%s,%s inv:%" PRIu32 " time:%lld us\n" @@ -146,14 +146,42 @@ static void handler_execute(esp_event_loop_instance_t* loop, esp_event_handler_n // This happens in "handler instance can unregister itself" test case. // To prevent memory corruption error it's necessary to check if pointer is still valid. esp_event_loop_node_t* loop_node; - esp_event_handler_node_t* handler_node; SLIST_FOREACH(loop_node, &(loop->loop_nodes), next) { + // try to find the handler amongst the list of handlers that are registered on the + // loop level (i.e., registered to be triggered for all events) + esp_event_handler_node_t* handler_node; SLIST_FOREACH(handler_node, &(loop_node->handlers), next) { if (handler_node == handler) { handler->invoked++; handler->time += diff; } } + + // try to find the handler amongst the list of handlers that are registered on the + // base level (i.e., registered to be triggered for all events of a specific event base) + esp_event_base_node_t* base_node; + SLIST_FOREACH(base_node, &(loop_node->base_nodes), next) { + esp_event_handler_node_t* base_handler_node; + SLIST_FOREACH(base_handler_node, &(base_node->handlers), next) { + if (base_handler_node == handler) { + handler->invoked++; + handler->time += diff; + } + } + + // try to find the handler amongst the list of handlers that are registered on the + // ID level (i.e., registered to be triggered for a specific event ID of a specific event base) + esp_event_id_node_t* id_node; + SLIST_FOREACH(id_node, &(base_node->id_nodes), next) { + esp_event_handler_node_t* id_handler_node; + SLIST_FOREACH(id_handler_node, &(id_node->handlers), next) { + if (id_handler_node == handler) { + handler->invoked++; + handler->time += diff; + } + } + } + } } xSemaphoreGive(loop->profiling_mutex); @@ -885,7 +913,7 @@ esp_err_t esp_event_post_to(esp_event_loop_handle_t event_loop, esp_event_base_t } #ifdef CONFIG_ESP_EVENT_LOOP_PROFILING - atomic_fetch_add(&loop->events_recieved, 1); + atomic_fetch_add(&loop->events_received, 1); #endif return ESP_OK; @@ -933,7 +961,7 @@ esp_err_t esp_event_isr_post_to(esp_event_loop_handle_t event_loop, esp_event_ba } #ifdef CONFIG_ESP_EVENT_LOOP_PROFILING - atomic_fetch_add(&loop->events_recieved, 1); + atomic_fetch_add(&loop->events_received, 1); #endif return ESP_OK; @@ -962,13 +990,13 @@ esp_err_t esp_event_dump(FILE* file) portENTER_CRITICAL(&s_event_loops_spinlock); SLIST_FOREACH(loop_it, &s_event_loops, next) { - uint32_t events_recieved, events_dropped; + uint32_t events_received, events_dropped; - events_recieved = atomic_load(&loop_it->events_recieved); + events_received = atomic_load(&loop_it->events_received); events_dropped = atomic_load(&loop_it->events_dropped); PRINT_DUMP_INFO(dst, sz, LOOP_DUMP_FORMAT, loop_it, loop_it->task != NULL ? loop_it->name : "none", - events_recieved, events_dropped); + events_received, events_dropped); int sz_bak = sz; diff --git a/components/esp_event/private_include/esp_event_internal.h b/components/esp_event/private_include/esp_event_internal.h index caa0f1614b..f6c6e870c1 100644 --- a/components/esp_event/private_include/esp_event_internal.h +++ b/components/esp_event/private_include/esp_event_internal.h @@ -76,7 +76,7 @@ typedef struct esp_event_loop_instance { esp_event_loop_nodes_t loop_nodes; /**< set of linked lists containing the registered handlers for the loop */ #ifdef CONFIG_ESP_EVENT_LOOP_PROFILING - atomic_uint_least32_t events_recieved; /**< number of events successfully posted to the loop */ + atomic_uint_least32_t events_received; /**< number of events successfully posted to the loop */ atomic_uint_least32_t events_dropped; /**< number of events dropped due to queue being full */ SemaphoreHandle_t profiling_mutex; /**< mutex used for profiliing */ SLIST_ENTRY(esp_event_loop_instance) next; /**< next event loop in the list */ diff --git a/components/esp_event/test_apps/main/test_event_common.cpp b/components/esp_event/test_apps/main/test_event_common.cpp index bbac3490f1..9666e5470b 100644 --- a/components/esp_event/test_apps/main/test_event_common.cpp +++ b/components/esp_event/test_apps/main/test_event_common.cpp @@ -1597,3 +1597,49 @@ TEST_CASE("default event loop: registering event handler instance without instan TEST_ESP_OK(esp_event_loop_delete_default()); } + +#if CONFIG_ESP_EVENT_LOOP_PROFILING +static void handler_all(void* arg, esp_event_base_t event_base, int32_t event_id, void* data) +{ + printf("Event received: base=%s, id=%" PRId32 ", data=%p\n", event_base, event_id, data); +} + +static void handler_base(void* arg, esp_event_base_t event_base, int32_t event_id, void* data) +{ + printf("Event received: base=%s, id=%" PRId32 ", data=%p\n", event_base, event_id, data); +} + +static void handler_id(void* arg, esp_event_base_t event_base, int32_t event_id, void* data) +{ + printf("Event received: base=%s, id=%" PRId32 ", data=%p\n", event_base, event_id, data); +} + +TEST_CASE("profiling reports valid values", "[event][default]") +{ + TEST_ESP_OK(esp_event_loop_create_default()); + + /* register handler for event base 1 and event id 1 */ + TEST_ESP_OK(esp_event_handler_register(s_test_base1, TEST_EVENT_BASE1_EV1, handler_id, NULL)); + + /* register handler for event base 1 and all event ids */ + TEST_ESP_OK(esp_event_handler_register(s_test_base1, ESP_EVENT_ANY_ID, handler_base, NULL)); + + /* register handler for all event bases and all event ids */ + TEST_ESP_OK(esp_event_handler_register(ESP_EVENT_ANY_BASE, ESP_EVENT_ANY_ID, handler_all, NULL)); + + /* post an event on event base 1, event id 1 */ + TEST_ESP_OK(esp_event_post(s_test_base1, TEST_EVENT_BASE1_EV1, NULL, 0, pdMS_TO_TICKS(1000))); + + /* post an event 1 from base 1 and check the dump. + * - 3 handlers invoked, exec time is not 0 */ + esp_event_dump(stdout); + + /* unregister handlers */ + TEST_ESP_OK(esp_event_handler_unregister(ESP_EVENT_ANY_BASE, ESP_EVENT_ANY_ID, handler_all)); + TEST_ESP_OK(esp_event_handler_unregister(s_test_base1, ESP_EVENT_ANY_ID, handler_base)); + TEST_ESP_OK(esp_event_handler_unregister(s_test_base1, TEST_EVENT_BASE1_EV1, handler_id)); + + /* delete loop */ + TEST_ESP_OK(esp_event_loop_delete_default()); +} +#endif // CONFIG_ESP_EVENT_LOOP_PROFILING diff --git a/components/esp_event/test_apps/pytest_esp_event.py b/components/esp_event/test_apps/pytest_esp_event.py index 9057e2ff9f..234382e176 100644 --- a/components/esp_event/test_apps/pytest_esp_event.py +++ b/components/esp_event/test_apps/pytest_esp_event.py @@ -1,4 +1,4 @@ -# SPDX-FileCopyrightText: 2022-2023 Espressif Systems (Shanghai) CO LTD +# SPDX-FileCopyrightText: 2022-2024 Espressif Systems (Shanghai) CO LTD # SPDX-License-Identifier: CC0-1.0 import pytest from pytest_embedded import Dut @@ -29,3 +29,15 @@ def test_esp_event_posix_simulator(dut: Dut) -> None: dut.expect_exact('Press ENTER to see the list of tests.') dut.write('*') dut.expect(r'\d{2} Tests 0 Failures 0 Ignored', timeout=120) + + +@pytest.mark.esp32 +@pytest.mark.generic +def test_esp_event_profiling(dut: Dut) -> None: + dut.expect_exact('Press ENTER to see the list of tests.') + dut.write('"profiling reports valid values"') + # look for all references of handlers invoked at least 1 time + # with an execution time superior to 0 us + matches = dut.expect(r'HANDLER .+ inv:[1-9][0-9]{0,} time:[1-9][0-9]{0,} us', timeout=2) + matches_arr = matches.group().split(b'\r\n') + assert (len(matches_arr) == 3)