ESP_LOGx 消息中日志级别后面的数字表示什么？

Question

下面是在同一个内核上运行两个不同优先级任务的示例程序，其中任务函数记录了任务名称、coreId 和演示计数器。

#include <freertos/FreeRTOS.h>
#include <freertos/task.h>
#include <esp_log.h>

_Noreturn void taskFunction(void *taskParams);

_Noreturn void app_main(void) {
    const char *task1Name = "Running Task 1";
    const char *task2Name = "Running Task 2";
    xTaskCreatePinnedToCore(taskFunction, "Task1", 2048, (void *) task1Name, 1, NULL, 1);
    xTaskCreatePinnedToCore(taskFunction, "Task2", 2048, (void *) task2Name, 2, NULL, 1);
    for (;;);
}

void taskFunction(void *taskParams) {
    int counter = 0;
    const char *taskName = taskParams;
    for (;;) {
        ESP_LOGI(taskName, "on core %d counter %d\r\n", xPortGetCoreID(), ++counter);
        vTaskDelay(1000 / portTICK_RATE_MS);
    }
}

及其日志

I (305) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (0) Running Task 2: on core 1 counter 1

I (0) Running Task 1: on core 1 counter 1

0x40080fd4: call_start_cpu1 at D:/SDKs/ESPIDF/components/esp_system/port/cpu_start.c:141

I (1010) Running Task 2: on core 1 counter 2

I (1010) Running Task 1: on core 1 counter 2

I (2010) Running Task 2: on core 1 counter 3

I (2010) Running Task 1: on core 1 counter 3

I (3010) Running Task 2: on core 1 counter 4

I (3010) Running Task 1: on core 1 counter 4

I (4010) Running Task 2: on core 1 counter 5

I (4010) Running Task 1: on core 1 counter 5

E (10315) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (10315) task_wdt:  - IDLE (CPU 0)
E (10315) task_wdt: Tasks currently running:
E (10315) task_wdt: CPU 0: main
E (10315) task_wdt: CPU 1: IDLE
E (10315) task_wdt: Print CPU 0 (current core) backtrace
...
...
...

I (16375) Running Task 2: on core 1 counter 12

I (16385) Running Task 1: on core 1 counter 12

I (17375) Running Task 2: on core 1 counter 13

I (17385) Running Task 1: on core 1 counter 13

括号中日志级别后的数字 1010、2010、... 表示什么？

它们怎么可能在两个不同的任务开始时是相同的，而在看门狗定时器被触发后它们又可能不同呢？

Answer 1

这是当前时间，以毫秒为单位。

它们可能是相同的，因为您的任务几乎什么都不做； ESP32 可以在不到一毫秒的时间内在任务之间切换，因此它们运行在同一毫秒的计时内，即使不是在完全相同的时间。

您可以在 source code 中亲自查看：

#define ESP_LOGI( tag, format, ... ) ESP_LOG_LEVEL_LOCAL(ESP_LOG_INFO,    tag, format, ##__VA_ARGS__)

和ESP_LOG_LEVEL_LOCAL:

#define ESP_LOG_LEVEL_LOCAL(level, tag, format, ...) do {               \
        if ( LOG_LOCAL_LEVEL >= level ) ESP_LOG_LEVEL(level, tag, format, ##__VA_ARGS__); \
    } while(0)

和ESP_LOG_LEVEL:

#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_OPT__(,) __VA_ARGS__); } \
        else if (level==ESP_LOG_WARN )      { esp_log_write(ESP_LOG_WARN,       tag, LOG_FORMAT(W, format), esp_log_timestamp(), tag __VA_OPT__(,) __VA_ARGS__); } \
        else if (level==ESP_LOG_DEBUG )     { esp_log_write(ESP_LOG_DEBUG,      tag, LOG_FORMAT(D, format), esp_log_timestamp(), tag __VA_OPT__(,) __VA_ARGS__); } \
        else if (level==ESP_LOG_VERBOSE )   { esp_log_write(ESP_LOG_VERBOSE,    tag, LOG_FORMAT(V, format), esp_log_timestamp(), tag __VA_OPT__(,) __VA_ARGS__); } \
        else                                { esp_log_write(ESP_LOG_INFO,       tag, LOG_FORMAT(I, format), esp_log_timestamp(), tag __VA_OPT__(,) __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_OPT__(,) __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_OPT__(,) __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_OPT__(,) __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_OPT__(,) __VA_ARGS__); } \
        else                                { esp_log_write(ESP_LOG_INFO,       tag, LOG_SYSTEM_TIME_FORMAT(I, format), esp_log_system_timestamp(), tag __VA_OPT__(,) __VA_ARGS__); } \
    } while(0)
#endif //CONFIG_LOG_TIMESTAMP_SOURCE_xxx
#else // !(defined(__cplusplus) && (__cplusplus >  201703L))
#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__); } \
        else if (level==ESP_LOG_DEBUG )     { esp_log_write(ESP_LOG_DEBUG,      tag, LOG_FORMAT(D, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \
        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

最后一个是调用实际 C 日志记录函数的地方。如您所见，它传递了一个时间戳 - 系统可以配置为 select 时间戳的来源。

如果您想了解 printf() 黑客是如何工作的，您可以继续追踪到 C logging functions。

ESP_LOGx 消息中日志级别后面的数字表示什么？

What does the number after log level indicate in ESP_LOGx messages?

logging

esp32

esp-idf