From 23e9224be6ed5e62c26d7199df0d4708f244d4a3 Mon Sep 17 00:00:00 2001 From: "GOPTIONS\\pfrost" Date: Thu, 22 Aug 2019 17:44:09 +0100 Subject: [PATCH] log: Add menuconfig option to log system time rather than RTOS time Merges https://github.com/espressif/esp-idf/pull/3958 --- components/log/Kconfig | 25 +++++++++++++++++++ components/log/include/esp_log.h | 26 ++++++++++++++++++++ components/log/log.c | 42 ++++++++++++++++++++++++++++++++ 3 files changed, 93 insertions(+) diff --git a/components/log/Kconfig b/components/log/Kconfig index 9266ccfa3..1c624a216 100644 --- a/components/log/Kconfig +++ b/components/log/Kconfig @@ -44,5 +44,30 @@ menu "Log output" In order to view these, your terminal program must support ANSI color codes. + choice LOG_TIMESTAMP_SOURCE + prompt "Log Timestamps" + default LOG_TIMESTAMP_SOURCE_RTOS + help + Choose what sort of timestamp is displayed in the log output: + + - Milliseconds since boot is calulated from the RTOS tick count multiplied + by the tick period. This time will reset after a software reboot. + e.g. (90000) + + - System time is taken from POSIX time functions which use the ESP32's + RTC and FRC1 timers to maintain an accurate time. The system time is + initialized to 0 on startup, it can be set with an SNTP sync, or with + POSIX time functions. This time will not reset after a software reboot. + e.g. (00:01:30.000) + + - NOTE: Currently this will not get used in logging from binary blobs + (i.e WiFi & Bluetooth libraries), these will always print + milliseconds since boot. + + config LOG_TIMESTAMP_SOURCE_RTOS + bool "Milliseconds Since Boot" + config LOG_TIMESTAMP_SOURCE_SYSTEM + bool "System Time" + endchoice endmenu diff --git a/components/log/include/esp_log.h b/components/log/include/esp_log.h index 21ebbdf23..c00a3b63d 100644 --- a/components/log/include/esp_log.h +++ b/components/log/include/esp_log.h @@ -86,6 +86,21 @@ vprintf_like_t esp_log_set_vprintf(vprintf_like_t func); */ uint32_t esp_log_timestamp(void); +/** + * @brief Function which returns system timestamp to be used in log output + * + * This function is used in expansion of ESP_LOGx macros to print + * the system time as "HH:MM:SS.sss". The system time is initialized to + * 0 on startup, this can be set to the correct time with an SNTP sync, + * or manually with standard POSIX time functions. + * + * Currently this will not get used in logging from binary blobs + * (i.e WiFi & Bluetooth libraries), these will still print the RTOS tick time. + * + * @return timestamp, in "HH:MM:SS.sss" + */ +char* esp_log_system_timestamp(void); + /** * @brief Function which returns timestamp to be used in log output * @@ -242,6 +257,7 @@ void esp_log_write(esp_log_level_t level, const char* tag, const char* format, . #endif //CONFIG_LOG_COLORS #define LOG_FORMAT(letter, format) LOG_COLOR_ ## letter #letter " (%d) %s: " format LOG_RESET_COLOR "\n" +#define LOG_SYSTEM_TIME_FORMAT(letter, format) LOG_COLOR_ ## letter #letter " (%s) %s: " format LOG_RESET_COLOR "\n" /** @endcond */ @@ -295,6 +311,7 @@ void esp_log_write(esp_log_level_t level, const char* tag, const char* format, . * * @see ``printf`` */ +#if CONFIG_LOG_TIMESTAMP_SOURCE_RTOS #define ESP_LOG_LEVEL(level, tag, format, ...) do { \ if (level==ESP_LOG_ERROR ) { esp_log_write(ESP_LOG_ERROR, tag, LOG_FORMAT(E, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \ else if (level==ESP_LOG_WARN ) { esp_log_write(ESP_LOG_WARN, tag, LOG_FORMAT(W, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \ @@ -302,6 +319,15 @@ void esp_log_write(esp_log_level_t level, const char* tag, const char* format, . else if (level==ESP_LOG_VERBOSE ) { esp_log_write(ESP_LOG_VERBOSE, tag, LOG_FORMAT(V, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \ else { esp_log_write(ESP_LOG_INFO, tag, LOG_FORMAT(I, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \ } while(0) +#elif CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM +#define ESP_LOG_LEVEL(level, tag, format, ...) do { \ + if (level==ESP_LOG_ERROR ) { esp_log_write(ESP_LOG_ERROR, tag, LOG_SYSTEM_TIME_FORMAT(E, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \ + else if (level==ESP_LOG_WARN ) { esp_log_write(ESP_LOG_WARN, tag, LOG_SYSTEM_TIME_FORMAT(W, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \ + else if (level==ESP_LOG_DEBUG ) { esp_log_write(ESP_LOG_DEBUG, tag, LOG_SYSTEM_TIME_FORMAT(D, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \ + else if (level==ESP_LOG_VERBOSE ) { esp_log_write(ESP_LOG_VERBOSE, tag, LOG_SYSTEM_TIME_FORMAT(V, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \ + else { esp_log_write(ESP_LOG_INFO, tag, LOG_SYSTEM_TIME_FORMAT(I, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \ + } while(0) +#endif //CONFIG_LOG_TIMESTAMP_SOURCE_xxx /** runtime macro to output logs at a specified level. Also check the level with ``LOG_LOCAL_LEVEL``. * diff --git a/components/log/log.c b/components/log/log.c index fbbdf2406..6c71d1a07 100644 --- a/components/log/log.c +++ b/components/log/log.c @@ -53,6 +53,8 @@ #include #include #include +#include +#include #include "esp_log.h" @@ -332,6 +334,46 @@ uint32_t ATTR esp_log_early_timestamp(void) #ifndef BOOTLOADER_BUILD +char* IRAM_ATTR esp_log_system_timestamp(void) +{ + static char buffer[18] = {0}; + static _lock_t bufferLock = 0; + + if (xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED) { + uint32_t timestamp = esp_log_early_timestamp(); + for (uint8_t i = 0; i < sizeof(buffer); i++) { + if ((timestamp > 0) || (i == 0)) { + for (uint8_t j = sizeof(buffer) - 1; j > 0; j--) { + buffer[j] = buffer[j - 1]; + } + buffer[0] = (char) (timestamp % 10) + '0'; + timestamp /= 10; + } else { + buffer[i] = 0; + break; + } + } + return buffer; + } else { + struct timeval tv; + struct tm timeinfo; + + gettimeofday(&tv, NULL); + localtime_r(&tv.tv_sec, &timeinfo); + + _lock_acquire(&bufferLock); + snprintf(buffer, sizeof(buffer), + "%02d:%02d:%02d.%03ld", + timeinfo.tm_hour, + timeinfo.tm_min, + timeinfo.tm_sec, + tv.tv_usec / 1000); + _lock_release(&bufferLock); + + return buffer; + } +} + uint32_t IRAM_ATTR esp_log_timestamp(void) { if (xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED) {