From 69278b28bfc326e3a04c2c934dd59885c0906bfe Mon Sep 17 00:00:00 2001 From: Ivan Grokhotkov Date: Sun, 18 Sep 2016 20:24:31 +0800 Subject: [PATCH] components/log: fix bugs, add options to override log level for files, components, and bootloader --- components/bootloader/Kconfig.projbuild | 28 +++++ components/log/include/esp_log.h | 65 +++++------- components/log/log.c | 134 +++++++++++++++--------- 3 files changed, 138 insertions(+), 89 deletions(-) diff --git a/components/bootloader/Kconfig.projbuild b/components/bootloader/Kconfig.projbuild index 8d5f66721..394bcc1bd 100644 --- a/components/bootloader/Kconfig.projbuild +++ b/components/bootloader/Kconfig.projbuild @@ -1,3 +1,31 @@ menu "Bootloader config" +choice LOG_BOOTLOADER_LEVEL + bool "Bootloader log verbosity" + default LOG_BOOTLOADER_LEVEL_WARN + help + Specify how much output to see in bootloader logs. + +config LOG_BOOTLOADER_LEVEL_NONE + bool "No output" +config LOG_BOOTLOADER_LEVEL_ERROR + bool "Error" +config LOG_BOOTLOADER_LEVEL_WARN + bool "Warning" +config LOG_BOOTLOADER_LEVEL_INFO + bool "Info" +config LOG_BOOTLOADER_LEVEL_DEBUG + bool "Debug" +config LOG_BOOTLOADER_LEVEL_VERBOSE + bool "Verbose" +endchoice + +config LOG_BOOTLOADER_LEVEL + int + default 0 if LOG_BOOTLOADER_LEVEL_NONE + default 1 if LOG_BOOTLOADER_LEVEL_ERROR + default 2 if LOG_BOOTLOADER_LEVEL_WARN + default 3 if LOG_BOOTLOADER_LEVEL_INFO + default 4 if LOG_BOOTLOADER_LEVEL_DEBUG + default 5 if LOG_BOOTLOADER_LEVEL_VERBOSE endmenu diff --git a/components/log/include/esp_log.h b/components/log/include/esp_log.h index 32f6d0bb3..a12d324de 100644 --- a/components/log/include/esp_log.h +++ b/components/log/include/esp_log.h @@ -68,8 +68,17 @@ extern "C" { * from _EARLY version to normal version on the fly. Unfortunately, ets_vprintf in ROM * has been inlined by the compiler into ets_printf, so it is not accessible outside.) * + * To override default verbosity level at file or component scope, define LOG_LOCAL_LEVEL macro. + * At file scope, define it before including esp_log.h, e.g.: * - * To configure logging output per module, add calls to esp_log_set_level function: + * #define LOG_LOCAL_LEVEL ESP_LOG_VERBOSE + * #include "esp_log.h" + * + * At component scope, define it in component makefile: + * + * CFLAGS += -D LOG_LOCAL_LEVEL=ESP_LOG_DEBUG + * + * To configure logging output per module at runtime, add calls to esp_log_set_level function: * * esp_log_set_level("*", ESP_LOG_ERROR); // set all components to ERROR level * esp_log_set_level("wifi", ESP_LOG_WARN); // enable WARN logs from WiFi stack @@ -162,68 +171,50 @@ uint32_t esp_log_timestamp(); #define LOG_RESET_COLOR #endif //CONFIG_LOG_COLORS +#ifndef LOG_LOCAL_LEVEL +#ifndef BOOTLOADER_BUILD +#define LOG_LOCAL_LEVEL ((esp_log_level_t) CONFIG_LOG_DEFAULT_LEVEL) +#else +#define LOG_LOCAL_LEVEL ((esp_log_level_t) CONFIG_LOG_BOOTLOADER_LEVEL) +#endif +#endif + #define LOG_FORMAT(letter, format) LOG_COLOR_ ## letter #letter " (%d) %s: " format LOG_RESET_COLOR "\n" -#if (CONFIG_LOG_DEFAULT_LEVEL >= ESP_LOG_ERROR) -#define ESP_EARLY_LOGE( tag, format, ... ) ets_printf(LOG_FORMAT(E, format), esp_log_timestamp(), tag, ##__VA_ARGS__) +#define ESP_EARLY_LOGE( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_ERROR) { ets_printf(LOG_FORMAT(E, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } #ifndef BOOTLOADER_BUILD -#define ESP_LOGE( tag, format, ... ) esp_log_write(ESP_LOG_ERROR, tag, LOG_FORMAT(E, format), esp_log_timestamp(), tag, ##__VA_ARGS__) +#define ESP_LOGE( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_ERROR) { esp_log_write(ESP_LOG_ERROR, tag, LOG_FORMAT(E, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } #else #define ESP_LOGE( tag, format, ... ) ESP_EARLY_LOGE( tag, format, ##__VA_ARGS__) #endif // BOOTLOADER_BUILD -#else -#define ESP_LOGE( tag, format, ... ) -#define ESP_EARLY_LOGE( tag, format, ... ) -#endif -#if (CONFIG_LOG_DEFAULT_LEVEL >= ESP_LOG_WARN) -#define ESP_EARLY_LOGW( tag, format, ... ) ets_printf(LOG_FORMAT(W, format), esp_log_timestamp(), tag, ##__VA_ARGS__) +#define ESP_EARLY_LOGW( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_WARN) { ets_printf(LOG_FORMAT(W, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } #ifndef BOOTLOADER_BUILD -#define ESP_LOGW( tag, format, ... ) esp_log_write(ESP_LOG_WARN, tag, LOG_FORMAT(W, format), esp_log_timestamp(), tag, ##__VA_ARGS__) +#define ESP_LOGW( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_WARN) { esp_log_write(ESP_LOG_WARN, tag, LOG_FORMAT(W, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } #else #define ESP_LOGW( tag, format, ... ) ESP_EARLY_LOGW( tag, format, ##__VA_ARGS__) #endif // BOOTLOADER_BUILD -#else -#define ESP_LOGW( tag, format, ... ) -#define ESP_EARLY_LOGW( tag, format, ... ) -#endif -#if (CONFIG_LOG_DEFAULT_LEVEL >= ESP_LOG_INFO) -#define ESP_EARLY_LOGI( tag, format, ... ) ets_printf(LOG_FORMAT(I, format), esp_log_timestamp(), tag, ##__VA_ARGS__) +#define ESP_EARLY_LOGI( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_INFO) { ets_printf(LOG_FORMAT(I, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } #ifndef BOOTLOADER_BUILD -#define ESP_LOGI( tag, format, ... ) esp_log_write(ESP_LOG_INFO, tag, LOG_FORMAT(I, format), esp_log_timestamp(), tag, ##__VA_ARGS__) +#define ESP_LOGI( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_INFO) { esp_log_write(ESP_LOG_INFO, tag, LOG_FORMAT(I, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } #else #define ESP_LOGI( tag, format, ... ) ESP_EARLY_LOGI( tag, format, ##__VA_ARGS__) #endif //BOOTLOADER_BUILD -#else -#define ESP_LOGI( tag, format, ... ) -#define ESP_EARLY_LOGI( tag, format, ... ) -#endif - -#if (CONFIG_LOG_DEFAULT_LEVEL >= ESP_LOG_DEBUG) -#define ESP_EARLY_LOGD( tag, format, ... ) ets_printf(LOG_FORMAT(D, format), esp_log_timestamp(), tag, ##__VA_ARGS__) +#define ESP_EARLY_LOGD( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_DEBUG) { ets_printf(LOG_FORMAT(D, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } #ifndef BOOTLOADER_BUILD -#define ESP_LOGD( tag, format, ... ) esp_log_write(ESP_LOG_DEBUG, tag, LOG_FORMAT(D, format), esp_log_timestamp(), tag, ##__VA_ARGS__) +#define ESP_LOGD( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_DEBUG) { esp_log_write(ESP_LOG_DEBUG, tag, LOG_FORMAT(D, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } #else #define ESP_LOGD( tag, format, ... ) ESP_EARLY_LOGD(tag, format, ##__VA_ARGS__) #endif // BOOTLOADER_BUILD -#else -#define ESP_LOGD( tag, format, ... ) -#define ESP_EARLY_LOGD( tag, format, ... ) -#endif -#if (CONFIG_LOG_DEFAULT_LEVEL >= ESP_LOG_VERBOSE) -#define ESP_EARLY_LOGV( tag, format, ... ) ets_printf(LOG_FORMAT(V, format), esp_log_timestamp(), tag, ##__VA_ARGS__) +#define ESP_EARLY_LOGV( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_VERBOSE) { ets_printf(LOG_FORMAT(V, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } #ifndef BOOTLOADER_BUILD -#define ESP_LOGV( tag, format, ... ) esp_log_write(ESP_LOG_VERBOSE, tag, LOG_FORMAT(V, format), esp_log_timestamp(), tag, ##__VA_ARGS__) +#define ESP_LOGV( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_VERBOSE) { esp_log_write(ESP_LOG_VERBOSE, tag, LOG_FORMAT(V, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } #else #define ESP_LOGV( tag, format, ... ) ESP_EARLY_LOGV(tag, format, ##__VA_ARGS__) #endif // BOOTLOADER_BUILD -#else -#define ESP_LOGV( tag, format, ... ) -#define ESP_EARLY_LOGV( tag, format, ... ) -#endif #ifdef __cplusplus } diff --git a/components/log/log.c b/components/log/log.c index bd6df01b2..9063d264e 100644 --- a/components/log/log.c +++ b/components/log/log.c @@ -51,13 +51,21 @@ #include #include #include +#include #include "esp_log.h" #ifndef BOOTLOADER_BUILD -#define TAG_CACHE_SIZE 32 -#define MAX_MUTEX_WAIT_TICKS ((10 + portTICK_PERIOD_MS - 1) / portTICK_PERIOD_MS) +// Number of tags to be cached. Must be 2**n - 1, n >= 2. +#define TAG_CACHE_SIZE 31 + +// Maximum time to wait for the mutex in a logging statement. +#define MAX_MUTEX_WAIT_MS 10 +#define MAX_MUTEX_WAIT_TICKS ((MAX_MUTEX_WAIT_MS + portTICK_PERIOD_MS - 1) / portTICK_PERIOD_MS) + +// Uncomment this to enable consistency checks and cache statistics in this file. +// #define LOG_BUILTIN_CHECKS typedef struct { const char* tag; @@ -71,14 +79,18 @@ typedef struct uncached_tag_entry_{ char tag[0]; // beginning of a zero-terminated string } uncached_tag_entry_t; -static esp_log_level_t s_default_level = (esp_log_level_t) CONFIG_LOG_DEFAULT_LEVEL; -static uncached_tag_entry_t* s_head = NULL; -static uncached_tag_entry_t* s_tail = NULL; -static cached_tag_entry_t s_cache[TAG_CACHE_SIZE]; -static uint32_t s_cache_max_generation = 0; -static uint32_t s_cache_entry_count = 0; -static vprintf_like_t s_print_func = &vprintf; -static SemaphoreHandle_t s_mutex = NULL; +static esp_log_level_t s_log_default_level = (esp_log_level_t) CONFIG_LOG_DEFAULT_LEVEL; +static uncached_tag_entry_t* s_log_tags_head = NULL; +static uncached_tag_entry_t* s_log_tags_tail = NULL; +static cached_tag_entry_t s_log_cache[TAG_CACHE_SIZE]; +static uint32_t s_log_cache_max_generation = 0; +static uint32_t s_log_cache_entry_count = 0; +static vprintf_like_t s_log_print_func = &vprintf; +static SemaphoreHandle_t s_log_mutex = NULL; + +#ifdef LOG_BUILTIN_CHECKS +static uint32_t s_log_cache_misses = 0; +#endif static inline bool get_cached_log_level(const char* tag, esp_log_level_t* level); static inline bool get_uncached_log_level(const char* tag, esp_log_level_t* level); @@ -90,21 +102,21 @@ static inline void clear_log_level_list(); void esp_log_set_vprintf(vprintf_like_t func) { - s_print_func = func; + s_log_print_func = func; } void esp_log_level_set(const char* tag, esp_log_level_t level) { - if (!s_mutex) { - s_mutex = xSemaphoreCreateMutex(); + if (!s_log_mutex) { + s_log_mutex = xSemaphoreCreateMutex(); } - xSemaphoreTake(&s_mutex, portMAX_DELAY); + xSemaphoreTake(s_log_mutex, portMAX_DELAY); // for wildcard tag, remove all linked list items and clear the cache if (strcmp(tag, "*") == 0) { - s_default_level = level; + s_log_default_level = level; clear_log_level_list(); - xSemaphoreGive(&s_mutex); + xSemaphoreGive(s_log_mutex); return; } @@ -112,60 +124,68 @@ void esp_log_level_set(const char* tag, esp_log_level_t level) size_t entry_size = offsetof(uncached_tag_entry_t, tag) + strlen(tag) + 1; uncached_tag_entry_t* new_entry = (uncached_tag_entry_t*) malloc(entry_size); if (!new_entry) { - xSemaphoreGive(&s_mutex); + xSemaphoreGive(s_log_mutex); return; } new_entry->next = NULL; new_entry->level = (uint8_t) level; strcpy(new_entry->tag, tag); - if (s_tail) { - s_tail->next = new_entry; + if (s_log_tags_tail) { + s_log_tags_tail->next = new_entry; } - s_tail = new_entry; - if (!s_head) { - s_head = new_entry; + s_log_tags_tail = new_entry; + if (!s_log_tags_head) { + s_log_tags_head = new_entry; } - xSemaphoreGive(&s_mutex); + xSemaphoreGive(s_log_mutex); } void clear_log_level_list() { - for (uncached_tag_entry_t* it = s_head; it != NULL; ) { + for (uncached_tag_entry_t* it = s_log_tags_head; it != NULL; ) { uncached_tag_entry_t* next = it->next; free(it); it = next; } + s_log_tags_tail = NULL; + s_log_tags_head = NULL; + s_log_cache_entry_count = 0; + s_log_cache_max_generation = 0; +#ifdef LOG_BUILTIN_CHECKS + s_log_cache_misses = 0; +#endif - s_cache_entry_count = 0; - s_cache_max_generation = 0; } void IRAM_ATTR esp_log_write(esp_log_level_t level, const char* tag, const char* format, ...) { - if (!s_mutex) { - s_mutex = xSemaphoreCreateMutex(); + if (!s_log_mutex) { + s_log_mutex = xSemaphoreCreateMutex(); } - if (xSemaphoreTake(&s_mutex, MAX_MUTEX_WAIT_TICKS) == pdFALSE) { + if (xSemaphoreTake(s_log_mutex, MAX_MUTEX_WAIT_TICKS) == pdFALSE) { return; } esp_log_level_t level_for_tag; // Look for the tag in cache first, then in the linked list of all tags if (!get_cached_log_level(tag, &level_for_tag)) { if (!get_uncached_log_level(tag, &level_for_tag)) { - level_for_tag = s_default_level; + level_for_tag = s_log_default_level; } add_to_cache(tag, level_for_tag); +#ifdef LOG_BUILTIN_CHECKS + ++s_log_cache_misses; +#endif } - xSemaphoreGive(&s_mutex); + xSemaphoreGive(s_log_mutex); if (!should_output(level, level_for_tag)) { return; } va_list list; va_start(list, format); - (*s_print_func)(format, list); + (*s_log_print_func)(format, list); va_end(list); } @@ -173,43 +193,53 @@ static inline bool get_cached_log_level(const char* tag, esp_log_level_t* level) { // Look for `tag` in cache int i; - for (i = 0; i < s_cache_entry_count; ++i) { - if (s_cache[i].tag == tag) { + for (i = 0; i < s_log_cache_entry_count; ++i) { +#ifdef LOG_BUILTIN_CHECKS + assert(i == 0 || s_log_cache[(i - 1) / 2].generation < s_log_cache[i].generation); +#endif + if (s_log_cache[i].tag == tag) { break; } } - if (i == s_cache_entry_count) { // Not found in cache + if (i == s_log_cache_entry_count) { // Not found in cache return false; } // Return level from cache - *level = (esp_log_level_t) s_cache[i].level; - // Update item generation - s_cache[i].generation = s_cache_max_generation++; - // Restore heap ordering - heap_bubble_down(i); + *level = (esp_log_level_t) s_log_cache[i].level; + // If cache has been filled, start taking ordering into account + // (other options are: dynamically resize cache, add "dummy" entries + // to the cache; this option was chosen because code is much simpler, + // and the unfair behavior of cache will show it self at most once, when + // it has just been filled) + if (s_log_cache_entry_count == TAG_CACHE_SIZE) { + // Update item generation + s_log_cache[i].generation = s_log_cache_max_generation++; + // Restore heap ordering + heap_bubble_down(i); + } return true; } static inline void add_to_cache(const char* tag, esp_log_level_t level) { - uint32_t generation = s_cache_max_generation++; + uint32_t generation = s_log_cache_max_generation++; // First consider the case when cache is not filled yet. // In this case, just add new entry at the end. // This happens to satisfy binary min-heap ordering. - if (s_cache_entry_count < TAG_CACHE_SIZE) { - s_cache[s_cache_entry_count] = (cached_tag_entry_t) { + if (s_log_cache_entry_count < TAG_CACHE_SIZE) { + s_log_cache[s_log_cache_entry_count] = (cached_tag_entry_t) { .generation = generation, .level = level, .tag = tag }; - ++s_cache_entry_count; + ++s_log_cache_entry_count; return; } // Cache is full, so we replace the oldest entry (which is at index 0 // because this is a min-heap) with the new one, and do bubble-down // operation to restore min-heap ordering. - s_cache[0] = (cached_tag_entry_t) { + s_log_cache[0] = (cached_tag_entry_t) { .tag = tag, .level = level, .generation = generation @@ -221,7 +251,7 @@ static inline bool get_uncached_log_level(const char* tag, esp_log_level_t* leve { // Walk the linked list of all tags and see if given tag is present in the list. // This is slow because tags are compared as strings. - for (uncached_tag_entry_t* it = s_head; it != NULL; ++it) { + for (uncached_tag_entry_t* it = s_log_tags_head; it != NULL; it = it->next) { if (strcmp(tag, it->tag) == 0) { *level = it->level; return true; @@ -240,7 +270,7 @@ static void heap_bubble_down(int index) while (index < TAG_CACHE_SIZE / 2) { int left_index = index * 2 + 1; int right_index = left_index + 1; - int next = (s_cache[left_index].generation < s_cache[right_index].generation) ? left_index : right_index; + int next = (s_log_cache[left_index].generation < s_log_cache[right_index].generation) ? left_index : right_index; heap_swap(index, next); index = next; } @@ -248,13 +278,13 @@ static void heap_bubble_down(int index) static inline void heap_swap(int i, int j) { - cached_tag_entry_t tmp = s_cache[i]; - s_cache[i] = s_cache[j]; - s_cache[j] = tmp; + cached_tag_entry_t tmp = s_log_cache[i]; + s_log_cache[i] = s_log_cache[j]; + s_log_cache[j] = tmp; } #endif //BOOTLOADER_BUILD -inline uint32_t esp_log_early_timestamp() +inline IRAM_ATTR uint32_t esp_log_early_timestamp() { return xthal_get_ccount() / (CPU_CLK_FREQ_ROM / 1000); } @@ -275,7 +305,7 @@ uint32_t IRAM_ATTR esp_log_timestamp() #else -uint32_t esp_log_timestamp() +uint32_t IRAM_ATTR esp_log_timestamp() { return esp_log_early_timestamp(); }