loggingesp32esp-idf

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

Here is the sample program that runs two tasks on the same core with different priorities, where the task function logs the task name, coreId and a demo counter.

#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);
    }
}

and its log

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

What does the numbers 1010, 2010, ... indicate after log level in parenthesis?

And how can they be same at the start for two different tasks and later after watchdog timer gets triggered they could be different?

Solution

  • It's the current time in milliseconds.

    They can be the same because your tasks are doing almost nothing; the ESP32 can switch between tasks in well under a millisecond, so they run within the same millisecond of timing, even if not at the exact same time.

    You can see for yourself in the source code:

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

    and 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)

    and 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

    This last one is where the actual C logging function gets called. As you can see it's passed a timestamp - the system can be configured to select the source of the timestamp.

    You can continue tracing this into the C logging functions if you want to see how the printf() hackery works.