diff --git a/components/wpa_supplicant/port/eloop.c b/components/wpa_supplicant/port/eloop.c index 300fcb8b77..92aaa02fb2 100644 --- a/components/wpa_supplicant/port/eloop.c +++ b/components/wpa_supplicant/port/eloop.c @@ -23,6 +23,10 @@ struct eloop_timeout { void *eloop_data; void *user_data; eloop_timeout_handler handler; +#ifdef ELOOP_DEBUG + char func_name[100]; + int line; +#endif }; struct eloop_data { @@ -56,12 +60,21 @@ int eloop_init(void) return 0; } +#ifdef ELOOP_DEBUG +int eloop_register_timeout_debug(unsigned int secs, unsigned int usecs, + eloop_timeout_handler handler, void *eloop_data, + void *user_data, const char *func, int line) +#else int eloop_register_timeout(unsigned int secs, unsigned int usecs, eloop_timeout_handler handler, void *eloop_data, void *user_data) +#endif { struct eloop_timeout *timeout, *tmp; os_time_t now_sec; +#ifdef ELOOP_DEBUG + int count = 0; +#endif timeout = os_zalloc(sizeof(*timeout)); if (timeout == NULL) @@ -84,6 +97,10 @@ int eloop_register_timeout(unsigned int secs, unsigned int usecs, timeout->eloop_data = eloop_data; timeout->user_data = user_data; timeout->handler = handler; +#ifdef ELOOP_DEBUG + os_strlcpy(timeout->func_name, func, 100); + timeout->line = line; +#endif /* Maintain timeouts in order of increasing time */ dl_list_for_each(tmp, &eloop.timeout, struct eloop_timeout, list) { @@ -93,12 +110,19 @@ int eloop_register_timeout(unsigned int secs, unsigned int usecs, ELOOP_UNLOCK(); goto run; } +#ifdef ELOOP_DEBUG + count++; +#endif } ELOOP_LOCK(); dl_list_add_tail(&eloop.timeout, &timeout->list); ELOOP_UNLOCK(); run: +#ifdef ELOOP_DEBUG + wpa_printf(MSG_DEBUG, "ELOOP: Added one timer from %s:%d to call %p, current order=%d", + timeout->func_name, line, timeout->handler, count); +#endif os_timer_disarm(&eloop.eloop_timer); os_timer_arm(&eloop.eloop_timer, 0, 0); @@ -126,8 +150,13 @@ static void eloop_remove_timeout(struct eloop_timeout *timeout) } +#ifdef ELOOP_DEBUG +int eloop_cancel_timeout_debug(eloop_timeout_handler handler, void *eloop_data, + void *user_data, const char *func, int line) +#else int eloop_cancel_timeout(eloop_timeout_handler handler, void *eloop_data, void *user_data) +#endif { struct eloop_timeout *timeout, *prev; int removed = 0; @@ -143,6 +172,10 @@ int eloop_cancel_timeout(eloop_timeout_handler handler, removed++; } } +#ifdef ELOOP_DEBUG + wpa_printf(MSG_DEBUG, "ELOOP: %s:%d called to remove timer handler=%p, removed count=%d", + func, line, handler, removed); +#endif return removed; } @@ -286,7 +319,16 @@ void eloop_run(void) void *user_data = timeout->user_data; eloop_timeout_handler handler = timeout->handler; +#ifdef ELOOP_DEBUG + char fn_name[100] = {0}; + int line = timeout->line; + os_strlcpy(fn_name, timeout->func_name, 100); +#endif eloop_remove_timeout(timeout); +#ifdef ELOOP_DEBUG + wpa_printf(MSG_DEBUG, "ELOOP: Running timer fn:%p scheduled by %s:%d ", + handler, fn_name, line); +#endif handler(eloop_data, user_data); } } diff --git a/components/wpa_supplicant/port/include/supplicant_opt.h b/components/wpa_supplicant/port/include/supplicant_opt.h index 74bd00d30d..2eb91956f6 100644 --- a/components/wpa_supplicant/port/include/supplicant_opt.h +++ b/components/wpa_supplicant/port/include/supplicant_opt.h @@ -11,6 +11,9 @@ #if CONFIG_WPA_DEBUG_PRINT #define DEBUG_PRINT +#if defined(CONFIG_LOG_DEFAULT_LEVEL_DEBUG) || defined(CONFIG_LOG_DEFAULT_LEVEL_VERBOSE) +#define ELOOP_DEBUG +#endif #endif #if CONFIG_WPA_SCAN_CACHE diff --git a/components/wpa_supplicant/port/os_xtensa.c b/components/wpa_supplicant/port/os_xtensa.c index bc5cbf72d8..7a2309e8b5 100644 --- a/components/wpa_supplicant/port/os_xtensa.c +++ b/components/wpa_supplicant/port/os_xtensa.c @@ -24,7 +24,6 @@ #include "os.h" #include -#include #include #include #include "esp_random.h" diff --git a/components/wpa_supplicant/src/utils/eloop.h b/components/wpa_supplicant/src/utils/eloop.h index 04ee6d1837..0bc8b5d6b3 100644 --- a/components/wpa_supplicant/src/utils/eloop.h +++ b/components/wpa_supplicant/src/utils/eloop.h @@ -176,9 +176,19 @@ void eloop_unregister_event(void *event, size_t event_size); * Register a timeout that will cause the handler function to be called after * given time. */ + +#ifdef ELOOP_DEBUG +int eloop_register_timeout_debug(unsigned int secs, unsigned int usecs, + eloop_timeout_handler handler, void *eloop_data, + void *user_data, const char *func, int line); + +#define eloop_register_timeout(secs, usecs, handler, eloop_data, user_data) \ + eloop_register_timeout_debug(secs, usecs, handler, eloop_data, user_data, __func__, __LINE__) +#else int eloop_register_timeout(unsigned int secs, unsigned int usecs, eloop_timeout_handler handler, void *eloop_data, void *user_data); +#endif /** * eloop_cancel_timeout - Cancel timeouts @@ -191,8 +201,15 @@ int eloop_register_timeout(unsigned int secs, unsigned int usecs, * eloop_register_timeout(). ELOOP_ALL_CTX can be used as a wildcard for * cancelling all timeouts regardless of eloop_data/user_data. */ +#ifdef ELOOP_DEBUG +int eloop_cancel_timeout_debug(eloop_timeout_handler handler, void *eloop_data, + void *user_data, const char *func, int line); +#define eloop_cancel_timeout(handler, eloop_data, user_data) \ + eloop_cancel_timeout_debug(handler, eloop_data, user_data, __func__, __LINE__) +#else int eloop_cancel_timeout(eloop_timeout_handler handler, void *eloop_data, void *user_data); +#endif /** * eloop_cancel_timeout_one - Cancel a single timeout diff --git a/components/wpa_supplicant/test/test_eloop.c b/components/wpa_supplicant/test/test_eloop.c index 7762e3399d..5b5fc722d9 100644 --- a/components/wpa_supplicant/test/test_eloop.c +++ b/components/wpa_supplicant/test/test_eloop.c @@ -16,6 +16,7 @@ #include "esp_log.h" #include "test_utils.h" #include "memory_checks.h" +#include uint32_t timeouts_usec[6] = { 10000, 1000, 10000, 5000, 15000, 1000 }; uint32_t timeouts_sec[6] = { 10, 1, 10, 5, 15, 1 }; @@ -23,6 +24,7 @@ int executed_order[6]; int t; struct os_reltime ts; + /* there is only single instance of esp_timer so no need of protection */ void callback(void *a, void *b) { @@ -32,15 +34,19 @@ void callback(void *a, void *b) os_get_reltime(&now); os_time_sub(&now, &ts, &age); - /* let's give 5 ms offset for this small block */ - if ((age.sec - timeouts_sec[*i]) || age.usec - timeouts_usec[*i] > 5000) { + int32_t ms_diff = (age.sec - timeouts_sec[*i]) * 1000 + + (age.usec - timeouts_usec[*i]) / 1000; + + /* let's give 50 ms offset for this small block */ + if (ms_diff > 50) { executed_order[t] = -1; } else { executed_order[t] = *i; } t++; - ESP_LOGI("Eloop Test", "timer ran after %lu sec and %lu usec of scheduled time", age.sec - timeouts_sec[*i], age.usec - timeouts_usec[*i]); + ESP_LOGI("Eloop Test", "timer[%d] ran after %d msec of scheduled time", + *i, ms_diff); }