From 66013ba67564b76ac9a563c8710d2cf13b16177c Mon Sep 17 00:00:00 2001 From: Konstantin Kondrashov Date: Thu, 2 May 2024 12:24:23 +0300 Subject: [PATCH] feat(log): Refactoring timestamp APIs (move only) --- components/log/CMakeLists.txt | 12 ++- components/log/include/esp_log.h | 40 +--------- components/log/include/esp_log_timestamp.h | 56 ++++++++++++++ components/log/linker.lf | 7 +- components/log/log_freertos.c | 72 +----------------- components/log/log_linux.c | 11 --- components/log/log_noos.c | 12 +-- components/log/src/linux/log_timestamp.c | 18 +++++ components/log/src/noos/log_timestamp.c | 17 +++++ components/log/src/os/log_timestamp.c | 85 ++++++++++++++++++++++ docs/doxygen/Doxyfile | 1 + docs/en/api-reference/system/log.rst | 1 + docs/zh_CN/api-reference/system/log.rst | 3 + 13 files changed, 197 insertions(+), 138 deletions(-) create mode 100644 components/log/include/esp_log_timestamp.h create mode 100644 components/log/src/linux/log_timestamp.c create mode 100644 components/log/src/noos/log_timestamp.c create mode 100644 components/log/src/os/log_timestamp.c diff --git a/components/log/CMakeLists.txt b/components/log/CMakeLists.txt index c65fc621d7..a3c987322b 100644 --- a/components/log/CMakeLists.txt +++ b/components/log/CMakeLists.txt @@ -1,6 +1,16 @@ idf_build_get_property(target IDF_TARGET) -set(srcs "") +if(BOOTLOADER_BUILD) + set(system_target "noos") +else() + if(${target} STREQUAL "linux") + set(system_target "linux") + else() + set(system_target "os") + endif() +endif() + +set(srcs "src/${system_target}/log_timestamp.c") set(priv_requires "") if(BOOTLOADER_BUILD) diff --git a/components/log/include/esp_log.h b/components/log/include/esp_log.h index 7d11348614..529d00a176 100644 --- a/components/log/include/esp_log.h +++ b/components/log/include/esp_log.h @@ -14,6 +14,7 @@ #include "esp_rom_sys.h" #include "esp_log_level.h" #include "esp_log_buffer.h" +#include "esp_log_timestamp.h" #ifdef __cplusplus extern "C" { @@ -37,45 +38,6 @@ typedef int (*vprintf_like_t)(const char *, va_list); */ vprintf_like_t esp_log_set_vprintf(vprintf_like_t func); -/** - * @brief Function which returns timestamp to be used in log output - * - * This function is used in expansion of ESP_LOGx macros. - * In the 2nd stage bootloader, and at early application startup stage - * this function uses CPU cycle counter as time source. Later when - * FreeRTOS scheduler start running, it switches to FreeRTOS tick count. - * - * For now, we ignore millisecond counter overflow. - * - * @return timestamp, in milliseconds - */ -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. Wi-Fi & 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 - * - * This function uses HW cycle counter and does not depend on OS, - * so it can be safely used after application crash. - * - * @return timestamp, in milliseconds - */ -uint32_t esp_log_early_timestamp(void); - /** * @brief Write message into the log * diff --git a/components/log/include/esp_log_timestamp.h b/components/log/include/esp_log_timestamp.h new file mode 100644 index 0000000000..dfefbcdbb3 --- /dev/null +++ b/components/log/include/esp_log_timestamp.h @@ -0,0 +1,56 @@ +/* + * SPDX-FileCopyrightText: 2015-2024 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#pragma once + +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/** + * @brief Function which returns timestamp to be used in log output + * + * This function is used in expansion of ESP_LOGx macros. + * In the 2nd stage bootloader, and at early application startup stage + * this function uses CPU cycle counter as time source. Later when + * FreeRTOS scheduler start running, it switches to FreeRTOS tick count. + * + * For now, we ignore millisecond counter overflow. + * + * @return timestamp, in milliseconds + */ +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. Wi-Fi & 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 + * + * This function uses HW cycle counter and does not depend on OS, + * so it can be safely used after application crash. + * + * @return timestamp, in milliseconds + */ +uint32_t esp_log_early_timestamp(void); + +#ifdef __cplusplus +} +#endif diff --git a/components/log/linker.lf b/components/log/linker.lf index 10627148ff..0a9e476b26 100644 --- a/components/log/linker.lf +++ b/components/log/linker.lf @@ -2,8 +2,5 @@ archive: liblog.a entries: log_write:esp_log_write (noflash) - log_freertos:esp_log_timestamp (noflash) - log_freertos:esp_log_early_timestamp (noflash) - log_freertos:esp_log_impl_lock (noflash) - log_freertos:esp_log_impl_lock_timeout (noflash) - log_freertos:esp_log_impl_unlock (noflash) + log_timestamp:esp_log_timestamp (noflash) + log_timestamp:esp_log_early_timestamp (noflash) diff --git a/components/log/log_freertos.c b/components/log/log_freertos.c index b45da16d26..8a8a5febdf 100644 --- a/components/log/log_freertos.c +++ b/components/log/log_freertos.c @@ -1,18 +1,13 @@ /* - * SPDX-FileCopyrightText: 2015-2021 Espressif Systems (Shanghai) CO LTD + * SPDX-FileCopyrightText: 2015-2024 Espressif Systems (Shanghai) CO LTD * * SPDX-License-Identifier: Apache-2.0 */ -#include -#include -#include #include "freertos/FreeRTOS.h" #include "freertos/task.h" #include "freertos/semphr.h" -#include "esp_cpu.h" // for esp_cpu_get_cycle_count() #include "esp_compiler.h" -#include "esp_log.h" #include "esp_private/log_lock.h" // Maximum time to wait for the mutex in a logging statement. @@ -54,68 +49,3 @@ void esp_log_impl_unlock(void) } xSemaphoreGive(s_log_mutex); } - -char *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 esp_log_timestamp(void) -{ - if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) { - return esp_log_early_timestamp(); - } - static uint32_t base = 0; - if (base == 0 && xPortGetCoreID() == 0) { - base = esp_log_early_timestamp(); - } - TickType_t tick_count = xPortInIsrContext() ? xTaskGetTickCountFromISR() : xTaskGetTickCount(); - return base + tick_count * (1000 / configTICK_RATE_HZ); -} - -/* FIXME: define an API for getting the timestamp in soc/hal IDF-2351 */ -uint32_t esp_log_early_timestamp(void) -{ -#if CONFIG_IDF_TARGET_ESP32 - /* ESP32 ROM stores separate clock rate values for each CPU, but we want the PRO CPU value always */ - extern uint32_t g_ticks_per_us_pro; - return esp_cpu_get_cycle_count() / (g_ticks_per_us_pro * 1000); -#else - return esp_cpu_get_cycle_count() / (esp_rom_get_cpu_ticks_per_us() * 1000); -#endif -} diff --git a/components/log/log_linux.c b/components/log/log_linux.c index c27b1e592e..18bbd1cc93 100644 --- a/components/log/log_linux.c +++ b/components/log/log_linux.c @@ -5,9 +5,7 @@ */ #include -#include #include -#include #include "esp_private/log_lock.h" static pthread_mutex_t mutex1 = PTHREAD_MUTEX_INITIALIZER; @@ -27,12 +25,3 @@ void esp_log_impl_unlock(void) { assert(pthread_mutex_unlock(&mutex1) == 0); } - -uint32_t esp_log_timestamp(void) -{ - struct timespec current_time; - int result = clock_gettime(CLOCK_MONOTONIC, ¤t_time); - assert(result == 0); - uint32_t milliseconds = current_time.tv_sec * 1000 + current_time.tv_nsec / 1000000; - return milliseconds; -} diff --git a/components/log/log_noos.c b/components/log/log_noos.c index ae8ff62841..0e7acce0ad 100644 --- a/components/log/log_noos.c +++ b/components/log/log_noos.c @@ -1,13 +1,11 @@ /* - * SPDX-FileCopyrightText: 2019-2021 Espressif Systems (Shanghai) CO LTD + * SPDX-FileCopyrightText: 2019-2024 Espressif Systems (Shanghai) CO LTD * * SPDX-License-Identifier: Apache-2.0 */ #include #include "esp_private/log_lock.h" -#include "esp_rom_sys.h" -#include "esp_cpu.h" static int s_lock = 0; @@ -28,11 +26,3 @@ void esp_log_impl_unlock(void) assert(s_lock == 1); s_lock = 0; } - -/* FIXME: define an API for getting the timestamp in soc/hal IDF-2351 */ -uint32_t esp_log_early_timestamp(void) -{ - return esp_cpu_get_cycle_count() / (esp_rom_get_cpu_ticks_per_us() * 1000); -} - -uint32_t esp_log_timestamp(void) __attribute__((alias("esp_log_early_timestamp"))); diff --git a/components/log/src/linux/log_timestamp.c b/components/log/src/linux/log_timestamp.c new file mode 100644 index 0000000000..58cff4149a --- /dev/null +++ b/components/log/src/linux/log_timestamp.c @@ -0,0 +1,18 @@ +/* + * SPDX-FileCopyrightText: 2010-2024 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include +#include +#include "esp_log_timestamp.h" + +uint32_t esp_log_timestamp(void) +{ + struct timespec current_time; + int result = clock_gettime(CLOCK_MONOTONIC, ¤t_time); + assert(result == 0); + uint32_t milliseconds = current_time.tv_sec * 1000 + current_time.tv_nsec / 1000000; + return milliseconds; +} diff --git a/components/log/src/noos/log_timestamp.c b/components/log/src/noos/log_timestamp.c new file mode 100644 index 0000000000..4f1f88e352 --- /dev/null +++ b/components/log/src/noos/log_timestamp.c @@ -0,0 +1,17 @@ +/* + * SPDX-FileCopyrightText: 2019-2024 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include "esp_rom_sys.h" +#include "esp_cpu.h" +#include "esp_log_timestamp.h" + +/* FIXME: define an API for getting the timestamp in soc/hal IDF-2351 */ +uint32_t esp_log_early_timestamp(void) +{ + return esp_cpu_get_cycle_count() / (esp_rom_get_cpu_ticks_per_us() * 1000); +} + +uint32_t esp_log_timestamp(void) __attribute__((alias("esp_log_early_timestamp"))); diff --git a/components/log/src/os/log_timestamp.c b/components/log/src/os/log_timestamp.c new file mode 100644 index 0000000000..3bc7a5e6c6 --- /dev/null +++ b/components/log/src/os/log_timestamp.c @@ -0,0 +1,85 @@ +/* + * SPDX-FileCopyrightText: 2015-2024 Espressif Systems (Shanghai) CO LTD + * + * 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; + } +} + +uint32_t esp_log_timestamp(void) +{ + if (unlikely(is_early_log())) { + return esp_log_early_timestamp(); + } + static uint32_t base = 0; + if (base == 0 && xPortGetCoreID() == 0) { + base = esp_log_early_timestamp(); + } + TickType_t tick_count = xPortInIsrContext() ? xTaskGetTickCountFromISR() : xTaskGetTickCount(); + return base + tick_count * (1000 / configTICK_RATE_HZ); +} + +/* FIXME: define an API for getting the timestamp in soc/hal IDF-2351 */ +uint32_t esp_log_early_timestamp(void) +{ +#if CONFIG_IDF_TARGET_ESP32 + /* ESP32 ROM stores separate clock rate values for each CPU, but we want the PRO CPU value always */ + extern uint32_t g_ticks_per_us_pro; + return esp_cpu_get_cycle_count() / (g_ticks_per_us_pro * 1000); +#else + return esp_cpu_get_cycle_count() / (esp_rom_get_cpu_ticks_per_us() * 1000); +#endif +} diff --git a/docs/doxygen/Doxyfile b/docs/doxygen/Doxyfile index 4f5211532a..9f0c2cd37a 100644 --- a/docs/doxygen/Doxyfile +++ b/docs/doxygen/Doxyfile @@ -271,6 +271,7 @@ INPUT = \ $(PROJECT_PATH)/components/log/include/esp_log.h \ $(PROJECT_PATH)/components/log/include/esp_log_level.h \ $(PROJECT_PATH)/components/log/include/esp_log_buffer.h \ + $(PROJECT_PATH)/components/log/include/esp_log_timestamp.h \ $(PROJECT_PATH)/components/lwip/include/apps/esp_sntp.h \ $(PROJECT_PATH)/components/lwip/include/apps/ping/ping_sock.h \ $(PROJECT_PATH)/components/mbedtls/esp_crt_bundle/include/esp_crt_bundle.h \ diff --git a/docs/en/api-reference/system/log.rst b/docs/en/api-reference/system/log.rst index 9fb63a67e6..d472ddfaa0 100644 --- a/docs/en/api-reference/system/log.rst +++ b/docs/en/api-reference/system/log.rst @@ -153,3 +153,4 @@ API Reference .. include-build-file:: inc/esp_log.inc .. include-build-file:: inc/esp_log_level.inc .. include-build-file:: inc/esp_log_buffer.inc +.. include-build-file:: inc/esp_log_timestamp.inc diff --git a/docs/zh_CN/api-reference/system/log.rst b/docs/zh_CN/api-reference/system/log.rst index b2e313763e..a3147b6d1d 100644 --- a/docs/zh_CN/api-reference/system/log.rst +++ b/docs/zh_CN/api-reference/system/log.rst @@ -135,3 +135,6 @@ API 参考 ------------- .. include-build-file:: inc/esp_log.inc +.. include-build-file:: inc/esp_log_level.inc +.. include-build-file:: inc/esp_log_buffer.inc +.. include-build-file:: inc/esp_log_timestamp.inc