mirror of
https://github.com/espressif/esp-idf.git
synced 2025-08-27 18:32:54 +00:00
feat(log): Use esp_log func in all LOG macros
This commit is contained in:
Konstantin Kondrashov
committed by
BOT
BOT
parent
a29589e266
commit
a5bc08fb55
@@ -48,7 +48,12 @@ TEST_CASE("test master logging level performance", "[log]")
|
||||
|
||||
#ifdef CONFIG_LOG_MASTER_LEVEL
|
||||
esp_log_set_level_master(ESP_LOG_NONE);
|
||||
TEST_ASSERT_INT_WITHIN(100, 150, calc_time_of_logging(ITERATIONS));
|
||||
#if ESP_LOG_VERSION == 1
|
||||
const int typical_value = 150;
|
||||
#else // ESP_LOG_VERSION == 2
|
||||
const int typical_value = 250;
|
||||
#endif // ESP_LOG_VERSION == 2
|
||||
TEST_ASSERT_INT_WITHIN(100, typical_value, calc_time_of_logging(ITERATIONS));
|
||||
#else
|
||||
esp_log_level_set("*", ESP_LOG_NONE);
|
||||
TEST_ASSERT_INT_WITHIN(DELTA_US, EXPECTED_US, calc_time_of_logging(ITERATIONS) / ITERATIONS);
|
||||
|
||||
@@ -55,8 +55,7 @@ void putc_to_buffer(char c)
|
||||
|
||||
static int print_to_buffer(const char *format, va_list args)
|
||||
{
|
||||
int ret = vsnprintf(s_print_buffer, BUFFER_SIZE, format, args);
|
||||
printf(s_print_buffer);
|
||||
int ret = vsnprintf(&s_print_buffer[s_counter], BUFFER_SIZE, format, args);
|
||||
s_counter += ret;
|
||||
assert(s_counter < BUFFER_SIZE);
|
||||
return ret;
|
||||
|
||||
360
components/log/test_apps/main/test_log_perf.c
Normal file
360
components/log/test_apps/main/test_log_perf.c
Normal file
@@ -0,0 +1,360 @@
|
||||
/*
|
||||
* SPDX-FileCopyrightText: 2023-2024 Espressif Systems (Shanghai) CO LTD
|
||||
*
|
||||
* SPDX-License-Identifier: Apache-2.0
|
||||
*/
|
||||
#include <stdio.h>
|
||||
#include <stdlib.h>
|
||||
#include <stdarg.h>
|
||||
#include <inttypes.h>
|
||||
#include "sys/param.h"
|
||||
#include "unity.h"
|
||||
#include "freertos/FreeRTOS.h"
|
||||
#include "freertos/task.h"
|
||||
#include "freertos/semphr.h"
|
||||
#include "esp_log.h"
|
||||
#include "esp_timer.h"
|
||||
#include "esp_rom_uart.h"
|
||||
#include "sdkconfig.h"
|
||||
|
||||
typedef struct {
|
||||
SemaphoreHandle_t done;
|
||||
int stack_usage;
|
||||
int (*func)(void);
|
||||
} perf_log_test_t;
|
||||
|
||||
static const char * TAG = "test";
|
||||
|
||||
const int max_loops = 5;
|
||||
|
||||
static void print_via_vprintf(const char *format, ...)
|
||||
{
|
||||
va_list args;
|
||||
va_start(args, format);
|
||||
vprintf(format, args);
|
||||
va_end(args);
|
||||
}
|
||||
|
||||
static void print_via_esp_rom_vprintf(const char *format, ...)
|
||||
{
|
||||
va_list args;
|
||||
va_start(args, format);
|
||||
esp_rom_vprintf(format, args);
|
||||
va_end(args);
|
||||
}
|
||||
|
||||
static int test_stack_usage_esp_rom_printf(void)
|
||||
{
|
||||
UBaseType_t start, end;
|
||||
start = uxTaskGetStackHighWaterMark(NULL);
|
||||
esp_rom_printf("test msg with value %d\n", 1);
|
||||
end = uxTaskGetStackHighWaterMark(NULL);
|
||||
return start - end;
|
||||
}
|
||||
|
||||
static int test_stack_usage_esp_rom_vprintf(void)
|
||||
{
|
||||
UBaseType_t start, end;
|
||||
start = uxTaskGetStackHighWaterMark(NULL);
|
||||
print_via_esp_rom_vprintf("test msg with value %d\n", 2);
|
||||
end = uxTaskGetStackHighWaterMark(NULL);
|
||||
return start - end;
|
||||
}
|
||||
|
||||
static int test_stack_usage_early_log(void)
|
||||
{
|
||||
UBaseType_t start, end;
|
||||
start = uxTaskGetStackHighWaterMark(NULL);
|
||||
ESP_EARLY_LOGI(TAG, "test msg with value %d", 3);
|
||||
end = uxTaskGetStackHighWaterMark(NULL);
|
||||
return start - end;
|
||||
}
|
||||
|
||||
static int test_stack_usage_dram_log(void)
|
||||
{
|
||||
UBaseType_t start, end;
|
||||
start = uxTaskGetStackHighWaterMark(NULL);
|
||||
ESP_DRAM_LOGI(TAG, "test msg with value %d", 4);
|
||||
end = uxTaskGetStackHighWaterMark(NULL);
|
||||
return start - end;
|
||||
}
|
||||
|
||||
static int test_stack_usage_printf(void)
|
||||
{
|
||||
UBaseType_t start, end;
|
||||
start = uxTaskGetStackHighWaterMark(NULL);
|
||||
printf("test msg with value %d\n", 5);
|
||||
end = uxTaskGetStackHighWaterMark(NULL);
|
||||
return start - end;
|
||||
}
|
||||
|
||||
static int test_stack_usage_vprintf(void)
|
||||
{
|
||||
UBaseType_t start, end;
|
||||
start = uxTaskGetStackHighWaterMark(NULL);
|
||||
print_via_vprintf("test msg with value %d\n", 6);
|
||||
end = uxTaskGetStackHighWaterMark(NULL);
|
||||
return start - end;
|
||||
}
|
||||
|
||||
static int test_stack_usage_esp_log(void)
|
||||
{
|
||||
UBaseType_t start, end;
|
||||
start = uxTaskGetStackHighWaterMark(NULL);
|
||||
ESP_LOGI(TAG, "test msg with value %d", 7);
|
||||
end = uxTaskGetStackHighWaterMark(NULL);
|
||||
return start - end;
|
||||
}
|
||||
|
||||
static void log_stack_usage_task(void* arg)
|
||||
{
|
||||
perf_log_test_t *a = (perf_log_test_t *) arg;
|
||||
|
||||
const uint32_t mask = esp_cpu_intr_get_enabled_mask();
|
||||
esp_cpu_intr_disable(0xFFFFFFFF);
|
||||
a->stack_usage = a->func();
|
||||
esp_cpu_intr_enable(mask);
|
||||
|
||||
TEST_ASSERT(xSemaphoreGive(a->done));
|
||||
vTaskDelete(NULL);
|
||||
}
|
||||
|
||||
TEST_CASE("Stack usage for log APIs", "[log]")
|
||||
{
|
||||
int priority = uxTaskPriorityGet(NULL) + 1;
|
||||
perf_log_test_t args = {
|
||||
.done = xSemaphoreCreateBinary(),
|
||||
.stack_usage = 0,
|
||||
.func = NULL,
|
||||
};
|
||||
|
||||
typedef struct {
|
||||
const char *name;
|
||||
int (*func)(void);
|
||||
int stack_usages;
|
||||
} log_test_case_t;
|
||||
|
||||
log_test_case_t test_cases[] = {
|
||||
{"esp_rom_printf", test_stack_usage_esp_rom_printf, 0},
|
||||
{"esp_rom_vprintf", test_stack_usage_esp_rom_vprintf, 0},
|
||||
{"early_log", test_stack_usage_early_log, 0},
|
||||
{"dram_log", test_stack_usage_dram_log, 0},
|
||||
{"printf", test_stack_usage_printf, 0},
|
||||
{"vprintf", test_stack_usage_vprintf, 0},
|
||||
{"esp_log", test_stack_usage_esp_log, 0},
|
||||
};
|
||||
|
||||
for (int i = 0; i < sizeof(test_cases) / sizeof(test_cases[0]); i++) {
|
||||
args.func = test_cases[i].func;
|
||||
TEST_ASSERT(xTaskCreatePinnedToCore(log_stack_usage_task, test_cases[i].name, 4095, &args, priority, NULL, 0));
|
||||
TEST_ASSERT(xSemaphoreTake(args.done, 100 / portTICK_PERIOD_MS));
|
||||
test_cases[i].stack_usages = args.stack_usage;
|
||||
}
|
||||
|
||||
printf("\nStack usage for %s chip:\n", CONFIG_IDF_TARGET);
|
||||
for (int i = 0; i < sizeof(test_cases) / sizeof(test_cases[0]); i++) {
|
||||
printf("%-20s %d bytes\n", test_cases[i].name, test_cases[i].stack_usages);
|
||||
}
|
||||
|
||||
vSemaphoreDelete(args.done);
|
||||
}
|
||||
|
||||
static void mock_putc(char c)
|
||||
{
|
||||
|
||||
}
|
||||
|
||||
static int mock_vprintf(const char *format, va_list args)
|
||||
{
|
||||
return 0;
|
||||
}
|
||||
|
||||
static int measuring_execution_time_esp_rom_printf(bool without_output)
|
||||
{
|
||||
int diff;
|
||||
int64_t start, end;
|
||||
diff = INT32_MAX;
|
||||
for (int i = 0; i < max_loops; i++) {
|
||||
start = esp_timer_get_time();
|
||||
if (without_output) {
|
||||
esp_rom_printf("\r");
|
||||
} else {
|
||||
esp_rom_printf("test msg %d\n", i);
|
||||
}
|
||||
end = esp_timer_get_time();
|
||||
diff = MIN(diff, end - start);
|
||||
}
|
||||
return diff;
|
||||
}
|
||||
|
||||
static int measuring_execution_time_esp_rom_vprintf(bool without_output)
|
||||
{
|
||||
int diff;
|
||||
int64_t start, end;
|
||||
diff = INT32_MAX;
|
||||
for (int i = 0; i < max_loops; i++) {
|
||||
start = esp_timer_get_time();
|
||||
if (without_output) {
|
||||
print_via_esp_rom_vprintf("\r");
|
||||
} else {
|
||||
print_via_esp_rom_vprintf("test msg %d\n", i);
|
||||
}
|
||||
end = esp_timer_get_time();
|
||||
diff = MIN(diff, end - start);
|
||||
}
|
||||
return diff;
|
||||
}
|
||||
|
||||
static int measuring_execution_time_early_log(bool without_output)
|
||||
{
|
||||
int diff;
|
||||
int64_t start, end;
|
||||
diff = INT32_MAX;
|
||||
if (without_output) {
|
||||
esp_rom_install_channel_putc(1, mock_putc);
|
||||
}
|
||||
for (int i = 0; i < max_loops; i++) {
|
||||
start = esp_timer_get_time();
|
||||
if (without_output) {
|
||||
ESP_EARLY_LOGI(TAG, "");
|
||||
} else {
|
||||
ESP_EARLY_LOGI(TAG, "test msg %d", i);
|
||||
}
|
||||
end = esp_timer_get_time();
|
||||
diff = MIN(diff, end - start);
|
||||
}
|
||||
if (without_output) {
|
||||
esp_rom_install_channel_putc(1, esp_rom_output_putc);
|
||||
}
|
||||
return diff;
|
||||
}
|
||||
|
||||
static int measuring_execution_time_dram_log(bool without_output)
|
||||
{
|
||||
int diff;
|
||||
int64_t start, end;
|
||||
diff = INT32_MAX;
|
||||
if (without_output) {
|
||||
esp_rom_install_channel_putc(1, mock_putc);
|
||||
}
|
||||
for (int i = 0; i < max_loops; i++) {
|
||||
start = esp_timer_get_time();
|
||||
if (without_output) {
|
||||
ESP_DRAM_LOGI(TAG, "");
|
||||
} else {
|
||||
ESP_DRAM_LOGI(TAG, "test msg %d", i);
|
||||
}
|
||||
end = esp_timer_get_time();
|
||||
diff = MIN(diff, end - start);
|
||||
}
|
||||
if (without_output) {
|
||||
esp_rom_install_channel_putc(1, esp_rom_output_putc);
|
||||
}
|
||||
return diff;
|
||||
}
|
||||
|
||||
static int measuring_execution_time_printf(bool without_output)
|
||||
{
|
||||
int diff;
|
||||
int64_t start, end;
|
||||
diff = INT32_MAX;
|
||||
for (int i = 0; i < max_loops; i++) {
|
||||
start = esp_timer_get_time();
|
||||
if (without_output) {
|
||||
printf("\r");
|
||||
} else {
|
||||
printf("test msg %d\n", i);
|
||||
}
|
||||
end = esp_timer_get_time();
|
||||
diff = MIN(diff, end - start);
|
||||
}
|
||||
return diff;
|
||||
}
|
||||
|
||||
static int measuring_execution_time_vprintf(bool without_output)
|
||||
{
|
||||
int diff;
|
||||
int64_t start, end;
|
||||
diff = INT32_MAX;
|
||||
for (int i = 0; i < max_loops; i++) {
|
||||
start = esp_timer_get_time();
|
||||
if (without_output) {
|
||||
print_via_vprintf("\r");
|
||||
} else {
|
||||
print_via_vprintf("test msg %d\n", i);
|
||||
}
|
||||
end = esp_timer_get_time();
|
||||
diff = MIN(diff, end - start);
|
||||
}
|
||||
return diff;
|
||||
}
|
||||
|
||||
static int measuring_execution_time_esp_log_macro(bool without_output)
|
||||
{
|
||||
int diff;
|
||||
int64_t start, end;
|
||||
diff = INT32_MAX;
|
||||
vprintf_like_t original_vprintf;
|
||||
if (without_output) {
|
||||
original_vprintf = esp_log_set_vprintf(mock_vprintf);
|
||||
}
|
||||
for (int i = 0; i < max_loops; i++) {
|
||||
start = esp_timer_get_time();
|
||||
if (without_output) {
|
||||
ESP_LOGI(TAG, "\r");
|
||||
} else {
|
||||
ESP_LOGI(TAG, "test msg %d", i);
|
||||
}
|
||||
end = esp_timer_get_time();
|
||||
diff = MIN(diff, end - start);
|
||||
}
|
||||
if (without_output) {
|
||||
esp_log_set_vprintf(original_vprintf);
|
||||
}
|
||||
return diff;
|
||||
}
|
||||
|
||||
TEST_CASE("Performance measurement for log APIs", "[log]")
|
||||
{
|
||||
#if ESP_LOG_VERSION == 2
|
||||
const int count_prints = 3;
|
||||
#else
|
||||
const int count_prints = 1;
|
||||
#endif
|
||||
|
||||
const uint32_t mask = esp_cpu_intr_get_enabled_mask();
|
||||
esp_cpu_intr_disable(0xFFFFFFFF);
|
||||
|
||||
int m_esp_rom_printf = measuring_execution_time_esp_rom_printf(true);
|
||||
int m_esp_rom_printf_output = measuring_execution_time_esp_rom_printf(false);
|
||||
|
||||
int m_esp_rom_vprintf = measuring_execution_time_esp_rom_vprintf(true);
|
||||
int m_esp_rom_vprintf_output = measuring_execution_time_esp_rom_vprintf(false);
|
||||
|
||||
int m_early_log = measuring_execution_time_early_log(true);
|
||||
int m_early_log_output = measuring_execution_time_early_log(false);
|
||||
|
||||
int m_dram_log_printf = measuring_execution_time_dram_log(true);
|
||||
int m_dram_log_printf_output = measuring_execution_time_dram_log(false);
|
||||
|
||||
int m_printf = measuring_execution_time_printf(true);
|
||||
int m_printf_output = measuring_execution_time_printf(false);
|
||||
|
||||
int m_vprintf = measuring_execution_time_vprintf(true);
|
||||
int m_vprintf_output = measuring_execution_time_vprintf(false);
|
||||
|
||||
int m_esp_log_macro = measuring_execution_time_esp_log_macro(true);
|
||||
int m_esp_log_macro_output = measuring_execution_time_esp_log_macro(false);
|
||||
|
||||
esp_cpu_intr_enable(mask);
|
||||
|
||||
esp_rom_printf("\nPerformance measurements for %s chip:\n", CONFIG_IDF_TARGET);
|
||||
esp_rom_printf("Function w/o output (us) | w/ output (us)\n");
|
||||
esp_rom_printf("esp_rom_printf %d %d\n", m_esp_rom_printf, m_esp_rom_printf_output);
|
||||
esp_rom_printf("esp_rom_vprintf %d %d\n", m_esp_rom_vprintf, m_esp_rom_vprintf_output);
|
||||
esp_rom_printf("ESP_EARLY_LOGI %d + %d %d\n", m_early_log, count_prints * m_esp_rom_printf, m_early_log_output);
|
||||
esp_rom_printf("ESP_DRAM_LOGI %d + %d %d\n", m_dram_log_printf, count_prints * m_esp_rom_vprintf, m_dram_log_printf_output);
|
||||
esp_rom_printf("printf %d %d\n", m_printf, m_printf_output);
|
||||
esp_rom_printf("vprintf %d %d\n", m_vprintf, m_vprintf_output);
|
||||
esp_rom_printf("ESP_LOGI %d + %d %d\n", m_esp_log_macro, count_prints * m_vprintf, m_esp_log_macro_output);
|
||||
}
|
||||
Reference in New Issue
Block a user