Merge branch 'feature/esp_log_master_option' into 'master'

log: Add master log option

Closes IDFGH-9721

See merge request espressif/esp-idf!23538

components/log/.build-test-rules.yml

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

components/log/Kconfig

@@ -84,6 +84,22 @@ menu "Log output"
         default 4 if LOG_MAXIMUM_LEVEL_DEBUG
         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
         bool "Use ANSI terminal colors in log output"
         default "y"

components/log/README.rst

@@ -4,11 +4,12 @@ Logging library
 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`.
 - 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**: 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:
 
@@ -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)``.
 
+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
 ^^^^^^^^^^^^^^^^^^^^^^^^
 

components/log/include/esp_log.h

@@ -41,6 +41,32 @@ typedef int (*vprintf_like_t)(const char *, va_list);
  */
 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
  *
@@ -425,13 +451,19 @@ void esp_log_writev(esp_log_level_t level, const char* tag, const char* format,
 #endif // !(defined(__cplusplus) && (__cplusplus >  201703L))
 
 /** 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``
  */
+#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 {               \
         if ( LOG_LOCAL_LEVEL >= level ) ESP_LOG_LEVEL(level, tag, format, ##__VA_ARGS__); \
     } while(0)
-
+#endif //CONFIG_LOG_MASTER_LEVEL
 
 /**
  * @brief Macro to output logs when the cache is disabled. Log at ``ESP_LOG_ERROR`` level.

components/log/log.c

@@ -62,6 +62,9 @@ typedef struct uncached_tag_entry_ {
     char tag[0];    // beginning of a zero-terminated string
 } 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;
 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];
@@ -91,6 +94,18 @@ vprintf_like_t esp_log_set_vprintf(vprintf_like_t 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)
 {
     esp_log_impl_lock();

components/log/test_apps/CMakeLists.txt

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

components/log/test_apps/README.md

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

components/log/test_apps/main/CMakeLists.txt

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

components/log/test_apps/main/test_app_main.c

@@ -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();
+}

components/log/test_apps/main/test_log.c

@@ -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");
+}

components/log/test_apps/pytest_esp_log.py

@@ -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()

components/log/test_apps/sdkconfig.defaults

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