log: Add master log option

Closes https://github.com/espressif/esp-idf/issues/11049
Closes https://github.com/espressif/esp-idf/pull/11057

Signed-off-by: KonstantinKondrashov <konstantin@espressif.com>

Result from an example in 11057:
When this option is not enabled:
1000 iterations took 10914 microseconds (10.9 microseconds per invocation)
1000 iterations took 10909 microseconds (10.9 microseconds per invocation)

When this option is enabled:
1000 iterations took 10960 microseconds (10.9 microseconds per invocation)
1000 iterations took 107 microseconds (0.1 microseconds per invocation)
This commit is contained in:
Jeff H 2023-03-26 14:22:05 -07:00 committed by KonstantinKondrashov
parent 87dd7bb51a
commit 628b633e50
12 changed files with 194 additions and 2 deletions

View File

@ -4,3 +4,8 @@ components/log/host_test/log_test:
enable: enable:
- if: IDF_TARGET == "linux" - if: IDF_TARGET == "linux"
reason: only test on linux reason: only test on linux
components/log/test_apps:
enable:
- if: IDF_TARGET == "esp32"
reason: only test on esp32

View File

@ -84,6 +84,22 @@ menu "Log output"
default 4 if LOG_MAXIMUM_LEVEL_DEBUG default 4 if LOG_MAXIMUM_LEVEL_DEBUG
default 5 if LOG_MAXIMUM_LEVEL_VERBOSE default 5 if LOG_MAXIMUM_LEVEL_VERBOSE
config LOG_MASTER_LEVEL
bool "Enable global master log level"
default "n"
help
Enables an additional global "master" log level check that occurs
before a log tag cache lookup. This is useful if you want to
compile in a lot of logs that are selectable at runtime, but avoid the
performance hit during periods where you don't want log output. Examples
include remote log forwarding, or disabling logs during a time-critical
or CPU-intensive section and re-enabling them later. Results in
larger program size depending on number of logs compiled in.
If enabled, defaults to LOG_DEFAULT_LEVEL and can be set using
esp_log_set_level_master().
This check takes precedence over ESP_LOG_LEVEL_LOCAL.
config LOG_COLORS config LOG_COLORS
bool "Use ANSI terminal colors in log output" bool "Use ANSI terminal colors in log output"
default "y" default "y"

View File

@ -4,11 +4,12 @@ Logging library
Overview Overview
-------- --------
The logging library provides two ways for setting log verbosity: The logging library provides three ways for setting log verbosity:
- **At compile time**: in menuconfig, set the verbosity level using the option :ref:`CONFIG_LOG_DEFAULT_LEVEL`. - **At compile time**: in menuconfig, set the verbosity level using the option :ref:`CONFIG_LOG_DEFAULT_LEVEL`.
- Optionally, also in menuconfig, set the maximum verbosity level using the option :ref:`CONFIG_LOG_MAXIMUM_LEVEL`. By default, this is the same as the default level, but it can be set higher in order to compile more optional logs into the firmware. - Optionally, also in menuconfig, set the maximum verbosity level using the option :ref:`CONFIG_LOG_MAXIMUM_LEVEL`. By default, this is the same as the default level, but it can be set higher in order to compile more optional logs into the firmware.
- **At runtime**: all logs for verbosity levels lower than :ref:`CONFIG_LOG_DEFAULT_LEVEL` are enabled by default. The function :cpp:func:`esp_log_level_set` can be used to set a logging level on a per-module basis. Modules are identified by their tags, which are human-readable ASCII zero-terminated strings. - **At runtime**: all logs for verbosity levels lower than :ref:`CONFIG_LOG_DEFAULT_LEVEL` are enabled by default. The function :cpp:func:`esp_log_level_set` can be used to set a logging level on a per-module basis. Modules are identified by their tags, which are human-readable ASCII zero-terminated strings.
- **At runtime**: if :ref:`CONFIG_LOG_MASTER_LEVEL` is enabled then a ``Master logging level`` can be set using :cpp:func:`esp_log_set_level_master`. This option adds an additional logging level check for all compiled logs. Note that this will increase application size. This feature is useful if you want to compile in a lot of logs that are selectable at runtime, but also want to avoid the performance hit from looking up the tags and their log level when you don't want log output.
There are the following verbosity levels: There are the following verbosity levels:
@ -81,6 +82,33 @@ To configure logging output per module at runtime, add calls to the function :cp
The "DRAM" and "EARLY" log macro variants documented above do not support per module setting of log verbosity. These macros will always log at the "default" verbosity level, which can only be changed at runtime by calling ``esp_log_level("*", level)``. The "DRAM" and "EARLY" log macro variants documented above do not support per module setting of log verbosity. These macros will always log at the "default" verbosity level, which can only be changed at runtime by calling ``esp_log_level("*", level)``.
Even when logs are disabled by using a tag name they will still require a processing time of around 10.9 microseconds per entry.
Master Logging Level
^^^^^^^^^^^^^^^^^^^^
To enable the Master logging level feature, the :ref:`CONFIG_LOG_MASTER_LEVEL` option must be enabled. It adds an additional level check for ``ESP_LOGx`` macros before calling :cpp:func:`esp_log_write`. This allows to set a higher :ref:`CONFIG_LOG_MAXIMUM_LEVEL`, but not inflict a performance hit during normal operation (only when directed). An application may set the master logging level (:cpp:func:`esp_log_set_level_master`) globally to enforce a maximum log level. ``ESP_LOGx`` macros above this level will be skipped immediately, rather than calling :cpp:func:`esp_log_write` and doing a tag lookup. It is recommended to only use this in an top-level application and not in shared components as this would override the global log level for any user using the component. By default, at startup, the Master logging level is :ref:`CONFIG_LOG_DEFAULT_LEVEL`.
Note that this feature increases application size because the additional check is added into all ``ESP_LOGx`` macros.
The snippet below shows how it works. Setting the Master logging level to ``ESP_LOG_NONE`` disables all logging globally. :cpp:func:`esp_log_level_set` does not currently affect logging. But after the Master logging level is released, the logs will be printed as set by :cpp:func:`esp_log_level_set`.
.. code-block:: c
// Master logging level is CONFIG_LOG_DEFAULT_LEVEL at start up and = ESP_LOG_INFO
ESP_LOGI("lib_name", "Message for print"); // prints a INFO message
esp_log_level_set("lib_name", ESP_LOG_WARN); // enables WARN logs from lib_name
esp_log_set_level_master(ESP_LOG_NONE); // disables all logs globally. esp_log_level_set has no effect at the moment.
ESP_LOGW("lib_name", "Message for print"); // no print, Master logging level blocks it
esp_log_level_set("lib_name", ESP_LOG_INFO); // enable INFO logs from lib_name
ESP_LOGI("lib_name", "Message for print"); // no print, Master logging level blocks it
esp_log_set_level_master(ESP_LOG_INFO); // enables all INFO logs globally.
ESP_LOGI("lib_name", "Message for print"); // prints a INFO message
Logging to Host via JTAG Logging to Host via JTAG
^^^^^^^^^^^^^^^^^^^^^^^^ ^^^^^^^^^^^^^^^^^^^^^^^^

View File

@ -41,6 +41,32 @@ typedef int (*vprintf_like_t)(const char *, va_list);
*/ */
extern esp_log_level_t esp_log_default_level; extern esp_log_level_t esp_log_default_level;
#if defined(CONFIG_LOG_MASTER_LEVEL) || __DOXYGEN__
/**
* @brief Master log level.
*
* Optional master log level to check against for ESP_LOGx macros before calling
* esp_log_write. Allows one to set a higher CONFIG_LOG_MAXIMUM_LEVEL but not
* impose a performance hit during normal operation (only when instructed). An
* application may set esp_log_set_level_master(level) to globally enforce a
* maximum log level. ESP_LOGx macros above this level will be skipped immediately,
* rather than calling esp_log_write and doing a cache hit.
*
* The tradeoff is increased application size.
*
* @param level Master log level
*/
void esp_log_set_level_master(esp_log_level_t level);
/**
* @brief Returns master log level.
* @return Master log level
*/
esp_log_level_t esp_log_get_level_master(void);
#endif //CONFIG_LOG_MASTER_LEVEL
/** /**
* @brief Set log level for given tag * @brief Set log level for given tag
* *
@ -425,13 +451,19 @@ void esp_log_writev(esp_log_level_t level, const char* tag, const char* format,
#endif // !(defined(__cplusplus) && (__cplusplus > 201703L)) #endif // !(defined(__cplusplus) && (__cplusplus > 201703L))
/** runtime macro to output logs at a specified level. Also check the level with ``LOG_LOCAL_LEVEL``. /** runtime macro to output logs at a specified level. Also check the level with ``LOG_LOCAL_LEVEL``.
* If ``CONFIG_LOG_MASTER_LEVEL`` set, also check first against ``esp_log_get_level_master()``.
* *
* @see ``printf``, ``ESP_LOG_LEVEL`` * @see ``printf``, ``ESP_LOG_LEVEL``
*/ */
#ifdef CONFIG_LOG_MASTER_LEVEL
#define ESP_LOG_LEVEL_LOCAL(level, tag, format, ...) do { \
if ( (esp_log_get_level_master() >= level) && (LOG_LOCAL_LEVEL >= level) ) ESP_LOG_LEVEL(level, tag, format, ##__VA_ARGS__); \
} while(0)
#else
#define ESP_LOG_LEVEL_LOCAL(level, tag, format, ...) do { \ #define ESP_LOG_LEVEL_LOCAL(level, tag, format, ...) do { \
if ( LOG_LOCAL_LEVEL >= level ) ESP_LOG_LEVEL(level, tag, format, ##__VA_ARGS__); \ if ( LOG_LOCAL_LEVEL >= level ) ESP_LOG_LEVEL(level, tag, format, ##__VA_ARGS__); \
} while(0) } while(0)
#endif //CONFIG_LOG_MASTER_LEVEL
/** /**
* @brief Macro to output logs when the cache is disabled. Log at ``ESP_LOG_ERROR`` level. * @brief Macro to output logs when the cache is disabled. Log at ``ESP_LOG_ERROR`` level.

View File

@ -62,6 +62,9 @@ typedef struct uncached_tag_entry_ {
char tag[0]; // beginning of a zero-terminated string char tag[0]; // beginning of a zero-terminated string
} uncached_tag_entry_t; } uncached_tag_entry_t;
#ifdef CONFIG_LOG_MASTER_LEVEL
esp_log_level_t g_master_log_level = CONFIG_LOG_DEFAULT_LEVEL;
#endif
esp_log_level_t esp_log_default_level = CONFIG_LOG_DEFAULT_LEVEL; esp_log_level_t esp_log_default_level = CONFIG_LOG_DEFAULT_LEVEL;
static SLIST_HEAD(log_tags_head, uncached_tag_entry_) s_log_tags = SLIST_HEAD_INITIALIZER(s_log_tags); static SLIST_HEAD(log_tags_head, uncached_tag_entry_) s_log_tags = SLIST_HEAD_INITIALIZER(s_log_tags);
static cached_tag_entry_t s_log_cache[TAG_CACHE_SIZE]; static cached_tag_entry_t s_log_cache[TAG_CACHE_SIZE];
@ -91,6 +94,18 @@ vprintf_like_t esp_log_set_vprintf(vprintf_like_t func)
return orig_func; return orig_func;
} }
#ifdef CONFIG_LOG_MASTER_LEVEL
esp_log_level_t esp_log_get_level_master(void)
{
return g_master_log_level;
}
void esp_log_set_level_master(esp_log_level_t level)
{
g_master_log_level = level;
}
#endif // CONFIG_LOG_MASTER_LEVEL
void esp_log_level_set(const char *tag, esp_log_level_t level) void esp_log_level_set(const char *tag, esp_log_level_t level)
{ {
esp_log_impl_lock(); esp_log_impl_lock();

View File

@ -0,0 +1,7 @@
#This is the project CMakeLists.txt file for the test subproject
cmake_minimum_required(VERSION 3.16)
set(COMPONENTS main)
include($ENV{IDF_PATH}/tools/cmake/project.cmake)
project(esp_log)

View File

@ -0,0 +1,3 @@
| Supported Targets | ESP32 |
| ----------------- | ----- |

View File

@ -0,0 +1,3 @@
idf_component_register(SRC_DIRS "."
PRIV_REQUIRES unity esp_timer
WHOLE_ARCHIVE)

View File

@ -0,0 +1,11 @@
/*
* SPDX-FileCopyrightText: 2023 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Unlicense OR CC0-1.0
*/
#include "unity.h"
void app_main(void)
{
unity_run_menu();
}

View File

@ -0,0 +1,58 @@
/*
* SPDX-FileCopyrightText: 2023 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
#include <stdio.h>
#include <stdlib.h>
#include <inttypes.h>
#include "unity.h"
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "esp_log.h"
#include "esp_timer.h"
#include "sdkconfig.h"
static const char * TAG = "log_test";
static int calc_time_of_logging(int iterations)
{
int diff;
int64_t start, end;
int attempts = 2;
while (attempts--) {
start = esp_timer_get_time();
for (int i = 0; i < iterations; i++) {
ESP_LOGI(TAG, "some test data, %d, %d, %d", i, iterations - i, 12);
}
end = esp_timer_get_time();
}
diff = (int)(end - start);
printf("%d iterations took %d usec (%.02f usec per invocation)\n",
iterations, diff, (float)diff / iterations);
return diff;
}
TEST_CASE("test master logging level performance", "[log]")
{
const int ITERATIONS = 1000;
ESP_LOGI(TAG, "Start");
#ifdef CONFIG_LOG_MASTER_LEVEL
esp_log_set_level_master(ESP_LOG_NONE);
TEST_ASSERT_INT_WITHIN(100, 150, calc_time_of_logging(ITERATIONS));
#else
esp_log_level_set("*", ESP_LOG_NONE);
TEST_ASSERT_INT_WITHIN(5, 11, calc_time_of_logging(ITERATIONS) / ITERATIONS);
#endif
esp_log_level_set("*", ESP_LOG_NONE);
#ifdef CONFIG_LOG_MASTER_LEVEL
esp_log_set_level_master(ESP_LOG_DEBUG);
#endif
TEST_ASSERT_INT_WITHIN(5, 11, calc_time_of_logging(ITERATIONS) / ITERATIONS);
esp_log_level_set("*", ESP_LOG_INFO);
ESP_LOGI(TAG, "End");
}

View File

@ -0,0 +1,11 @@
# SPDX-FileCopyrightText: 2023 Espressif Systems (Shanghai) CO LTD
# SPDX-License-Identifier: Unlicense OR CC0-1.0
import pytest
from pytest_embedded import Dut
@pytest.mark.esp32
@pytest.mark.generic
def test_esp_log(dut: Dut) -> None:
dut.run_all_single_board_cases()

View File

@ -0,0 +1,3 @@
# General options for additional checks
CONFIG_ESP_TASK_WDT_INIT=n
CONFIG_LOG_MASTER_LEVEL=y