From 4ad9ad80860059f9963fabf070b3ccbcb6501a8d Mon Sep 17 00:00:00 2001 From: Konstantin Kondrashov Date: Tue, 7 May 2024 17:01:10 +0300 Subject: [PATCH] feat(log): Adds new timestamp APIs and bootloader log Kconfigs --- components/bootloader/Kconfig.log | 34 +++++ components/bootloader/Kconfig.log.format | 28 ++++ components/bootloader/Kconfig.projbuild | 29 +--- components/log/CMakeLists.txt | 3 +- components/log/Kconfig.format | 20 ++- .../log/host_test/log_test/main/log_test.cpp | 70 +++++++--- .../host_test/log_test/pytest_log_linux.py | 1 + .../log_test/sdkconfig.ci.system_timestamp | 1 + .../log/include/esp_private/log_timestamp.h | 57 ++++++++ components/log/src/linux/log_timestamp.c | 4 +- components/log/src/log_timestamp_common.c | 129 ++++++++++++++++++ components/log/src/os/log_timestamp.c | 52 +------ 12 files changed, 326 insertions(+), 102 deletions(-) create mode 100644 components/bootloader/Kconfig.log create mode 100644 components/bootloader/Kconfig.log.format create mode 100644 components/log/host_test/log_test/sdkconfig.ci.system_timestamp create mode 100644 components/log/include/esp_private/log_timestamp.h create mode 100644 components/log/src/log_timestamp_common.c diff --git a/components/bootloader/Kconfig.log b/components/bootloader/Kconfig.log new file mode 100644 index 0000000000..151890753a --- /dev/null +++ b/components/bootloader/Kconfig.log @@ -0,0 +1,34 @@ +menu "Log" + + choice BOOTLOADER_LOG_LEVEL + bool "Bootloader log verbosity" + default BOOTLOADER_LOG_LEVEL_INFO + help + Specify how much output to see in bootloader logs. + + config BOOTLOADER_LOG_LEVEL_NONE + bool "No output" + config BOOTLOADER_LOG_LEVEL_ERROR + bool "Error" + config BOOTLOADER_LOG_LEVEL_WARN + bool "Warning" + config BOOTLOADER_LOG_LEVEL_INFO + bool "Info" + config BOOTLOADER_LOG_LEVEL_DEBUG + bool "Debug" + config BOOTLOADER_LOG_LEVEL_VERBOSE + bool "Verbose" + endchoice + + config BOOTLOADER_LOG_LEVEL + int + default 0 if BOOTLOADER_LOG_LEVEL_NONE + default 1 if BOOTLOADER_LOG_LEVEL_ERROR + default 2 if BOOTLOADER_LOG_LEVEL_WARN + default 3 if BOOTLOADER_LOG_LEVEL_INFO + default 4 if BOOTLOADER_LOG_LEVEL_DEBUG + default 5 if BOOTLOADER_LOG_LEVEL_VERBOSE + + orsource "Kconfig.log.format" + +endmenu diff --git a/components/bootloader/Kconfig.log.format b/components/bootloader/Kconfig.log.format new file mode 100644 index 0000000000..672001886d --- /dev/null +++ b/components/bootloader/Kconfig.log.format @@ -0,0 +1,28 @@ +menu "Format" + + choice BOOTLOADER_LOG_TIMESTAMP_SOURCE + prompt "Timestamp" + default BOOTLOADER_LOG_TIMESTAMP_SOURCE_CPU_TICKS + help + Choose what sort of timestamp is displayed in the log output: + + - "None" - The log will only contain the actual log messages themselves + without any time-related information. Avoiding timestamps can help conserve + processing power and memory. It might useful when you + perform log analysis or debugging, sometimes it's more straightforward + to work with logs that lack timestamps, especially if the time of occurrence + is not critical for understanding the issues. + "I log_test: info message" + + - "Milliseconds since boot" is calculated from the RTOS tick count multiplied + by the tick period. This time will reset after a software reboot. + "I (112500) log_test: info message" + + config BOOTLOADER_LOG_TIMESTAMP_SOURCE_NONE + bool "None" + depends on No # hide it now, turn it on final MR + config BOOTLOADER_LOG_TIMESTAMP_SOURCE_CPU_TICKS + bool "Milliseconds Since Boot" + endchoice # BOOTLOADER_LOG_TIMESTAMP_SOURCE + +endmenu diff --git a/components/bootloader/Kconfig.projbuild b/components/bootloader/Kconfig.projbuild index d1ea31925e..ba6f69f01b 100644 --- a/components/bootloader/Kconfig.projbuild +++ b/components/bootloader/Kconfig.projbuild @@ -38,34 +38,7 @@ menu "Bootloader config" endchoice - choice BOOTLOADER_LOG_LEVEL - bool "Bootloader log verbosity" - default BOOTLOADER_LOG_LEVEL_INFO - help - Specify how much output to see in bootloader logs. - - config BOOTLOADER_LOG_LEVEL_NONE - bool "No output" - config BOOTLOADER_LOG_LEVEL_ERROR - bool "Error" - config BOOTLOADER_LOG_LEVEL_WARN - bool "Warning" - config BOOTLOADER_LOG_LEVEL_INFO - bool "Info" - config BOOTLOADER_LOG_LEVEL_DEBUG - bool "Debug" - config BOOTLOADER_LOG_LEVEL_VERBOSE - bool "Verbose" - endchoice - - config BOOTLOADER_LOG_LEVEL - int - default 0 if BOOTLOADER_LOG_LEVEL_NONE - default 1 if BOOTLOADER_LOG_LEVEL_ERROR - default 2 if BOOTLOADER_LOG_LEVEL_WARN - default 3 if BOOTLOADER_LOG_LEVEL_INFO - default 4 if BOOTLOADER_LOG_LEVEL_DEBUG - default 5 if BOOTLOADER_LOG_LEVEL_VERBOSE + orsource "Kconfig.log" menu "Serial Flash Configurations" config BOOTLOADER_SPI_CUSTOM_WP_PIN diff --git a/components/log/CMakeLists.txt b/components/log/CMakeLists.txt index a3c987322b..a3cbd5d097 100644 --- a/components/log/CMakeLists.txt +++ b/components/log/CMakeLists.txt @@ -10,7 +10,8 @@ else() endif() endif() -set(srcs "src/${system_target}/log_timestamp.c") +set(srcs "src/${system_target}/log_timestamp.c" + "src/log_timestamp_common.c") set(priv_requires "") if(BOOTLOADER_BUILD) diff --git a/components/log/Kconfig.format b/components/log/Kconfig.format index 1ae55ba078..9e5b1bc6f7 100644 --- a/components/log/Kconfig.format +++ b/components/log/Kconfig.format @@ -13,24 +13,40 @@ menu "Format" help Choose what sort of timestamp is displayed in the log output: + - "None" - The log will only contain the actual log messages themselves + without any time-related information. Avoiding timestamps can help conserve + processing power and memory. It might useful when you + perform log analysis or debugging, sometimes it's more straightforward + to work with logs that lack timestamps, especially if the time of occurrence + is not critical for understanding the issues. + - "Milliseconds since boot" is calculated 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 chip's + - "System time (HH:MM:SS.sss)" is taken from POSIX time functions which use the chip's RTC and high resolution 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) + - "System time (YY-MM-DD HH:MM:SS.sss)" it is the same as the above, + but also prints the date as well. + - 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_NONE + bool "None" + depends on No # hide it now, turn it on final MR config LOG_TIMESTAMP_SOURCE_RTOS bool "Milliseconds Since Boot" config LOG_TIMESTAMP_SOURCE_SYSTEM - bool "System Time" + bool "System Time (HH:MM:SS.sss)" + config LOG_TIMESTAMP_SOURCE_SYSTEM_FULL + bool "System Time (YY-MM-DD HH:MM:SS.sss)" + depends on No # hide it now, turn it on final MR endchoice # LOG_TIMESTAMP_SOURCE endmenu diff --git a/components/log/host_test/log_test/main/log_test.cpp b/components/log/host_test/log_test/main/log_test.cpp index 0bd04363d7..040fbb97d3 100644 --- a/components/log/host_test/log_test/main/log_test.cpp +++ b/components/log/host_test/log_test/main/log_test.cpp @@ -11,11 +11,25 @@ #include #include "esp_log.h" #include "esp_private/log_util.h" +#include "esp_private/log_timestamp.h" +#include "sdkconfig.h" #include using namespace std; +#define EARLY_TIMESTAMP "[0-9]*" + +#if CONFIG_LOG_TIMESTAMP_SOURCE_RTOS +#define TIMESTAMP "[0-9]*" +#elif CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM +#define TIMESTAMP "[0-9]{2}:[0-9]{2}:[0-9]{2}\\.[0-9]{3}" +#elif CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM_FULL +#define TIMESTAMP "[0-9]{2}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}\\.[0-9]{3}" +#else +#define TIMESTAMP "" +#endif + static const char *TEST_TAG = "test"; class BasicLogFixture { @@ -135,7 +149,7 @@ PutcFixture *PutcFixture::instance = nullptr; TEST_CASE("verbose log level") { PrintFixture fix(ESP_LOG_VERBOSE); - const std::regex test_print("V \\([0-9]*\\) test: verbose", std::regex::ECMAScript); + const std::regex test_print("V \\(" TIMESTAMP "\\) test: verbose", std::regex::ECMAScript); ESP_LOGV(TEST_TAG, "verbose"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -144,7 +158,7 @@ TEST_CASE("verbose log level") TEST_CASE("debug log level") { PrintFixture fix(ESP_LOG_DEBUG); - const std::regex test_print("D \\([0-9]*\\) test: debug", std::regex::ECMAScript); + const std::regex test_print("D \\(" TIMESTAMP "\\) test: debug", std::regex::ECMAScript); ESP_LOGD(TEST_TAG, "debug"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -153,7 +167,7 @@ TEST_CASE("debug log level") TEST_CASE("info log level") { PrintFixture fix(ESP_LOG_INFO); - const std::regex test_print("I \\([0-9]*\\) test: info", std::regex::ECMAScript); + const std::regex test_print("I \\(" TIMESTAMP "\\) test: info", std::regex::ECMAScript); ESP_LOGI(TEST_TAG, "info"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -162,7 +176,7 @@ TEST_CASE("info log level") TEST_CASE("warn log level") { PrintFixture fix(ESP_LOG_WARN); - const std::regex test_print("W \\([0-9]*\\) test: warn", std::regex::ECMAScript); + const std::regex test_print("W \\(" TIMESTAMP "\\) test: warn", std::regex::ECMAScript); ESP_LOGW(TEST_TAG, "warn"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -171,7 +185,7 @@ TEST_CASE("warn log level") TEST_CASE("error log level") { PrintFixture fix(ESP_LOG_ERROR); - const std::regex test_print("E \\([0-9]*\\) test: error", std::regex::ECMAScript); + const std::regex test_print("E \\(" TIMESTAMP "\\) test: error", std::regex::ECMAScript); ESP_LOGE(TEST_TAG, "error"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -181,7 +195,7 @@ TEST_CASE("error log level") TEST_CASE("changing log level") { PrintFixture fix(ESP_LOG_INFO); - const std::regex test_print("I \\([0-9]*\\) test: must indeed be printed", std::regex::ECMAScript); + const std::regex test_print("I \\(" TIMESTAMP "\\) test: must indeed be printed", std::regex::ECMAScript); ESP_LOGI(TEST_TAG, "must indeed be printed"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -208,7 +222,7 @@ TEST_CASE("log buffer") 0x11, 0x12, 0x13, 0x14, 0x15, 0x16, 0x17, 0x18, }; ESP_LOG_BUFFER_HEX(TEST_TAG, buffer, sizeof(buffer)); - const std::regex buffer_regex("I \\([0-9]*\\) test: 01 02 03 04 05 06 07 08 11 12 13 14 15 16 17 18", std::regex::ECMAScript); + const std::regex buffer_regex("I \\(" TIMESTAMP "\\) test: 01 02 03 04 05 06 07 08 11 12 13 14 15 16 17 18", std::regex::ECMAScript); CHECK(regex_search(fix.get_print_buffer_string(), buffer_regex)); } @@ -219,7 +233,7 @@ TEST_CASE("log bytes > 127") 0xff, 0x80, }; ESP_LOG_BUFFER_HEX(TEST_TAG, buffer, sizeof(buffer)); - const std::regex buffer_regex("I \\([0-9]*\\) test: ff 80", std::regex::ECMAScript); + const std::regex buffer_regex("I \\(" TIMESTAMP "\\) test: ff 80", std::regex::ECMAScript); CHECK(regex_search(fix.get_print_buffer_string(), buffer_regex)); } @@ -227,11 +241,11 @@ TEST_CASE("log buffer char") { PrintFixture fix(ESP_LOG_INFO); const char g[] = "The way to get started is to quit talking and begin doing. - Walt Disney"; - const std::regex buffer_regex("I \\([0-9]*\\) test: The way to get s.*\n\ -.*I \\([0-9]*\\) test: tarted is to qui.*\n\ -.*I \\([0-9]*\\) test: t talking and be.*\n\ -.*I \\([0-9]*\\) test: gin doing. - Wal.*\n\ -.*I \\([0-9]*\\) test: t Disney", std::regex::ECMAScript); + const std::regex buffer_regex("I \\(" TIMESTAMP "\\) test: The way to get s.*\n\ +.*I \\(" TIMESTAMP "\\) test: tarted is to qui.*\n\ +.*I \\(" TIMESTAMP "\\) test: t talking and be.*\n\ +.*I \\(" TIMESTAMP "\\) test: gin doing. - Wal.*\n\ +.*I \\(" TIMESTAMP "\\) test: t Disney", std::regex::ECMAScript); ESP_LOG_BUFFER_CHAR(TEST_TAG, g, sizeof(g)); CHECK(regex_search(fix.get_print_buffer_string(), buffer_regex) == true); } @@ -244,7 +258,7 @@ TEST_CASE("log buffer dump") 0xff, 0xfe, 0xfd, 0xfc, 0xfb, 0xfa, 0xf9, 0xf8 }; ESP_LOG_BUFFER_HEXDUMP(TEST_TAG, buffer, sizeof(buffer), ESP_LOG_INFO); - const std::regex buffer_regex("I \\([0-9]*\\) test: 0x[0-9a-f]+\\s+" + const std::regex buffer_regex("I \\(" TIMESTAMP "\\) test: 0x[0-9a-f]+\\s+" "00 00 00 00 05 06 07 08 ff fe fd fc fb fa f9 f8 " "\\s+|[\\.]{16}|", std::regex::ECMAScript); CHECK(regex_search(fix.get_print_buffer_string(), buffer_regex)); @@ -262,7 +276,7 @@ TEST_CASE("rom printf") TEST_CASE("early verbose log level") { PutcFixture fix; - const std::regex test_print("V \\([0-9]*\\) test: verbose", std::regex::ECMAScript); + const std::regex test_print("V \\(" EARLY_TIMESTAMP "\\) test: verbose", std::regex::ECMAScript); ESP_EARLY_LOGV(TEST_TAG, "verbose"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -271,7 +285,7 @@ TEST_CASE("early verbose log level") TEST_CASE("early debug log level") { PutcFixture fix; - const std::regex test_print("D \\([0-9]*\\) test: debug", std::regex::ECMAScript); + const std::regex test_print("D \\(" EARLY_TIMESTAMP "\\) test: debug", std::regex::ECMAScript); ESP_EARLY_LOGD(TEST_TAG, "debug"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -280,7 +294,7 @@ TEST_CASE("early debug log level") TEST_CASE("early info log level") { PutcFixture fix; - const std::regex test_print("I \\([0-9]*\\) test: info", std::regex::ECMAScript); + const std::regex test_print("I \\(" EARLY_TIMESTAMP "\\) test: info", std::regex::ECMAScript); ESP_EARLY_LOGI(TEST_TAG, "info"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -289,7 +303,7 @@ TEST_CASE("early info log level") TEST_CASE("early warn log level") { PutcFixture fix; - const std::regex test_print("W \\([0-9]*\\) test: warn", std::regex::ECMAScript); + const std::regex test_print("W \\(" EARLY_TIMESTAMP "\\) test: warn", std::regex::ECMAScript); ESP_EARLY_LOGW(TEST_TAG, "warn"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -298,7 +312,7 @@ TEST_CASE("early warn log level") TEST_CASE("early error log level") { PutcFixture fix; - const std::regex test_print("E \\([0-9]*\\) test: error", std::regex::ECMAScript); + const std::regex test_print("E \\(" EARLY_TIMESTAMP "\\) test: error", std::regex::ECMAScript); ESP_EARLY_LOGE(TEST_TAG, "error"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -308,7 +322,7 @@ TEST_CASE("early error log level") TEST_CASE("changing early log level") { PutcFixture fix(ESP_LOG_INFO); - const std::regex test_print("I \\([0-9]*\\) test: must indeed be printed", std::regex::ECMAScript); + const std::regex test_print("I \\(" EARLY_TIMESTAMP "\\) test: must indeed be printed", std::regex::ECMAScript); ESP_EARLY_LOGI(TEST_TAG, "must indeed be printed"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -374,3 +388,19 @@ TEST_CASE("esp_log_util_cvt") CHECK(strcmp(buf, "073f") == 0); memset(buf, 0, sizeof(buf)); } + +TEST_CASE("esp_log_timestamp_str") +{ + char buffer[64]; + bool critical = true; + uint64_t timestamp_ms = esp_log_timestamp64(critical); + esp_log_timestamp_str(critical, timestamp_ms, buffer); + const std::regex test_print(EARLY_TIMESTAMP, std::regex::ECMAScript); + CHECK(regex_search(string(buffer), test_print) == true); + + critical = false; + timestamp_ms = esp_log_timestamp64(critical); + esp_log_timestamp_str(critical, timestamp_ms, buffer); + const std::regex test_print2(TIMESTAMP, std::regex::ECMAScript); + CHECK(regex_search(string(buffer), test_print2) == true); +} diff --git a/components/log/host_test/log_test/pytest_log_linux.py b/components/log/host_test/log_test/pytest_log_linux.py index 07078c4699..0425762aa4 100644 --- a/components/log/host_test/log_test/pytest_log_linux.py +++ b/components/log/host_test/log_test/pytest_log_linux.py @@ -8,6 +8,7 @@ from pytest_embedded import Dut @pytest.mark.host_test @pytest.mark.parametrize('config', [ 'default', + 'system_timestamp' 'tag_level_linked_list', 'tag_level_linked_list_and_array_cache', 'tag_level_none', diff --git a/components/log/host_test/log_test/sdkconfig.ci.system_timestamp b/components/log/host_test/log_test/sdkconfig.ci.system_timestamp new file mode 100644 index 0000000000..215a8e71dd --- /dev/null +++ b/components/log/host_test/log_test/sdkconfig.ci.system_timestamp @@ -0,0 +1 @@ +CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM=y diff --git a/components/log/include/esp_private/log_timestamp.h b/components/log/include/esp_private/log_timestamp.h new file mode 100644 index 0000000000..7312d332c6 --- /dev/null +++ b/components/log/include/esp_private/log_timestamp.h @@ -0,0 +1,57 @@ +/* + * SPDX-FileCopyrightText: 2024 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#pragma once + +#include +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/** + * @brief Get the timestamp in milliseconds for logging. + * + * This function retrieves the timestamp in milliseconds for logging purposes. + * + * @param[in] critical Flag indicating whether the timestamp is needed for a critical log. + * If this flag is true, it means the function is called in one of the following states: + * - early stage, when the Freertos scheduler is not running, + * - ISR, + * - CACHE is disabled. + * + * If the critical flag is set then uint32 timestamp is returned due to cpu ticks being used for this case. + * For some applications this uint32 timestamp may overflow after 4294967295/1000/86400 = 49 days of operation. + * + * @return The uint64 timestamp in milliseconds. + */ +uint64_t esp_log_timestamp64(bool critical); + +/** + * @brief Convert the uint64 timestamp to a string representation. + * + * This function converts the uint64 timestamp in milliseconds to a string representation. + * The string representation depends on Kconfig options: + * - Milliseconds since boot, + * - Date and time, + * - Time. + * + * @param[in] critical Flag indicating whether the timestamp is critical. If this flag is true, + * it means the function is called in one of the following states: + * - early stage, when the Freertos scheduler is not running, + * - ISR, + * - CACHE is disabled. + * @param[in] timestamp_ms The timestamp to convert, in milliseconds. + * @param[out] buffer Pointer to the buffer where the string representation will be stored. + * + * @return Pointer to the buffer containing the string representation of the timestamp. + */ +char* esp_log_timestamp_str(bool critical, uint64_t timestamp_ms, char* buffer); + +#ifdef __cplusplus +} +#endif diff --git a/components/log/src/linux/log_timestamp.c b/components/log/src/linux/log_timestamp.c index 58cff4149a..04fc51d433 100644 --- a/components/log/src/linux/log_timestamp.c +++ b/components/log/src/linux/log_timestamp.c @@ -8,7 +8,7 @@ #include #include "esp_log_timestamp.h" -uint32_t esp_log_timestamp(void) +uint32_t esp_log_early_timestamp(void) { struct timespec current_time; int result = clock_gettime(CLOCK_MONOTONIC, ¤t_time); @@ -16,3 +16,5 @@ uint32_t esp_log_timestamp(void) uint32_t milliseconds = current_time.tv_sec * 1000 + current_time.tv_nsec / 1000000; return milliseconds; } + +uint32_t esp_log_timestamp(void) __attribute__((alias("esp_log_early_timestamp"))); diff --git a/components/log/src/log_timestamp_common.c b/components/log/src/log_timestamp_common.c new file mode 100644 index 0000000000..ba9521908f --- /dev/null +++ b/components/log/src/log_timestamp_common.c @@ -0,0 +1,129 @@ +/* + * SPDX-FileCopyrightText: 2024 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include +#include +#include +#include "esp_log_timestamp.h" +#include "esp_private/log_util.h" +#include "esp_private/log_timestamp.h" +#include "sdkconfig.h" + +#if !BOOTLOADER_BUILD +#include +#include "freertos/FreeRTOS.h" +#include "freertos/task.h" + +char *esp_log_system_timestamp(void) +{ + static char buffer[18] = {0}; + static _lock_t bufferLock = 0; + +#if CONFIG_IDF_TARGET_LINUX + const bool early_log = false; +#else + const bool early_log = xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED; +#endif + if (early_log) { + 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; + } + } + } else { + struct timeval tv; + struct tm timeinfo; + + gettimeofday(&tv, NULL); + localtime_r(&tv.tv_sec, &timeinfo); + + _lock_acquire(&bufferLock); + unsigned msec = tv.tv_usec / 1000; + snprintf(buffer, sizeof(buffer), + "%02d:%02d:%02d.%03d", + timeinfo.tm_hour, + timeinfo.tm_min, + timeinfo.tm_sec, + msec); + _lock_release(&bufferLock); + } + return buffer; +} +#endif // !BOOTLOADER_BUILD + +uint64_t esp_log_timestamp64(bool critical) +{ + uint64_t timestamp_ms; +#if CONFIG_BOOTLOADER_LOG_TIMESTAMP_SOURCE_NONE || CONFIG_LOG_TIMESTAMP_SOURCE_NONE + (void) critical; + timestamp_ms = 0; +#elif CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM || CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM_FULL + if (critical) { + timestamp_ms = esp_log_early_timestamp(); + } else { +#if CONFIG_IDF_TARGET_LINUX + struct timespec tv; + int result = clock_gettime(CLOCK_MONOTONIC, &tv); + assert(result == 0); + timestamp_ms = tv.tv_sec * 1000 + tv.tv_nsec / 1000000; +#else + struct timeval tv; + gettimeofday(&tv, NULL); + timestamp_ms = tv.tv_sec * 1000 + tv.tv_usec / 1000; +#endif + } +#else + (void) critical; + timestamp_ms = esp_log_timestamp(); +#endif + return timestamp_ms; +} + +char* esp_log_timestamp_str(bool critical, uint64_t timestamp_ms, char* buffer) +{ + char* out_buffer = buffer; +#if CONFIG_BOOTLOADER_LOG_TIMESTAMP_SOURCE_NONE || CONFIG_LOG_TIMESTAMP_SOURCE_NONE + (void)critical; + *buffer = '\0'; +#elif CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM || CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM_FULL + if (critical) { + esp_log_util_cvt_dec(timestamp_ms, 0, buffer); + } else { + struct tm timeinfo; + time_t sec = timestamp_ms / 1000; + uint64_t msec = timestamp_ms % 1000; + localtime_r(&sec, &timeinfo); +#if CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM_FULL + // it takes 22 bytes to output it in the format: "YY-MM-DD HH:MM:SS.sss" + buffer += esp_log_util_cvt_dec(timeinfo.tm_year, 2, buffer); + *buffer++ = '-'; + buffer += esp_log_util_cvt_dec(timeinfo.tm_mon + 1, 2, buffer); + *buffer++ = '-'; + buffer += esp_log_util_cvt_dec(timeinfo.tm_mday, 2, buffer); + *buffer++ = ' '; +#endif // CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM_FULL + buffer += esp_log_util_cvt_dec(timeinfo.tm_hour, 2, buffer); + *buffer++ = ':'; + buffer += esp_log_util_cvt_dec(timeinfo.tm_min, 2, buffer); + *buffer++ = ':'; + buffer += esp_log_util_cvt_dec(timeinfo.tm_sec, 2, buffer); + *buffer++ = '.'; + esp_log_util_cvt_dec(msec, 3, buffer); // (ms) + } +#else + (void)critical; + esp_log_util_cvt_dec(timestamp_ms, 0, buffer); +#endif + return out_buffer; +} diff --git a/components/log/src/os/log_timestamp.c b/components/log/src/os/log_timestamp.c index 3bc7a5e6c6..484487e96d 100644 --- a/components/log/src/os/log_timestamp.c +++ b/components/log/src/os/log_timestamp.c @@ -4,64 +4,16 @@ * SPDX-License-Identifier: Apache-2.0 */ -#include -#include #include "freertos/FreeRTOS.h" #include "freertos/task.h" #include "esp_cpu.h" // for esp_cpu_get_cycle_count() #include "esp_compiler.h" -#include "esp_private/log_util.h" -#include "esp_private/log_lock.h" #include "esp_log_timestamp.h" - -static inline bool is_early_log(void) -{ - return xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED; -} - -char *esp_log_system_timestamp(void) -{ - static char buffer[18] = {0}; - static _lock_t bufferLock = 0; - - if (is_early_log()) { - 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; - } -} +#include "sdkconfig.h" uint32_t esp_log_timestamp(void) { - if (unlikely(is_early_log())) { + if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) { return esp_log_early_timestamp(); } static uint32_t base = 0;