Merge branch 'feature/raise_log_level' into 'master'

feature: Set maximum log level, add startup time example

Closes IDFGH-3599 and IDFGH-333

See merge request espressif/esp-idf!12714

components/app_trace/gcov/gcov_rtio.c

@@ -34,7 +34,6 @@
 
 #define ESP_GCOV_DOWN_BUF_SIZE  4200
 
-#define LOG_LOCAL_LEVEL CONFIG_LOG_DEFAULT_LEVEL
 #include "esp_log.h"
 const static char *TAG = "esp_gcov_rtio";
 

components/app_trace/host_file_io.c

@@ -27,7 +27,6 @@
 
 #if CONFIG_APPTRACE_ENABLE
 
-#define LOG_LOCAL_LEVEL CONFIG_LOG_DEFAULT_LEVEL
 #include "esp_log.h"
 const static char *TAG = "esp_host_file_io";
 

components/esp_system/dbg_stubs.c

@@ -32,7 +32,6 @@
     This entry is used by OpenOCD code to invoke other stub entries and allocate memory for them.
  */
 
-#define LOG_LOCAL_LEVEL CONFIG_LOG_DEFAULT_LEVEL
 #include "esp_log.h"
 const static char *TAG = "esp_dbg_stubs";
 

components/esp_system/stack_check.c

@@ -18,7 +18,6 @@
 
 #if CONFIG_COMPILER_STACK_CHECK
 
-#define LOG_LOCAL_LEVEL CONFIG_LOG_DEFAULT_LEVEL
 #include "esp_log.h"
 const static char *TAG = "stack_chk";
 

components/log/Kconfig

@@ -8,10 +8,11 @@ menu "Log output"
             You can set lower verbosity level at runtime using
             esp_log_level_set function.
 
-            Note that this setting limits which log statements
-            are compiled into the program. So setting this to, say,
+            By default, this setting limits which log statements
+            are compiled into the program. For example, selecting
             "Warning" would mean that changing log level to "Debug"
-            at runtime will not be possible.
+            at runtime will not be possible. To allow increasing log
+            level above the default at runtime, see the next option.
 
         config LOG_DEFAULT_LEVEL_NONE
             bool "No output"
@@ -36,6 +37,53 @@ menu "Log output"
         default 4 if LOG_DEFAULT_LEVEL_DEBUG
         default 5 if LOG_DEFAULT_LEVEL_VERBOSE
 
+    choice LOG_MAXIMUM_LEVEL
+        bool "Maximum log verbosity"
+        default LOG_MAXIMUM_EQUALS_DEFAULT
+        help
+            This config option sets the highest log verbosity that it's possible to select
+            at runtime by calling esp_log_level_set(). This level may be higher than
+            the default verbosity level which is set when the app starts up.
+
+            This can be used enable debugging output only at a critical point, for a particular
+            tag, or to minimize startup time but then enable more logs once the firmware has
+            loaded.
+
+            Note that increasing the maximum available log level will increase the firmware
+            binary size.
+
+            This option only applies to logging from the app, the bootloader log level is
+            fixed at compile time to the separate "Bootloader log verbosity" setting.
+
+        config LOG_MAXIMUM_EQUALS_DEFAULT
+            bool "Same as default"
+        config LOG_MAXIMUM_LEVEL_ERROR
+            bool "Error"
+            depends on LOG_DEFAULT_LEVEL < 1
+        config LOG_MAXIMUM_LEVEL_WARN
+            bool "Warning"
+            depends on LOG_DEFAULT_LEVEL < 2
+        config LOG_MAXIMUM_LEVEL_INFO
+            bool "Info"
+            depends on LOG_DEFAULT_LEVEL < 3
+        config LOG_MAXIMUM_LEVEL_DEBUG
+            bool "Debug"
+            depends on LOG_DEFAULT_LEVEL < 4
+        config LOG_MAXIMUM_LEVEL_VERBOSE
+            bool "Verbose"
+            depends on LOG_DEFAULT_LEVEL < 5
+    endchoice
+
+    config LOG_MAXIMUM_LEVEL
+        int
+        default LOG_DEFAULT_LEVEL if LOG_MAXIMUM_EQUALS_DEFAULT
+        default 0 if LOG_MAXIMUM_LEVEL_NONE
+        default 1 if LOG_MAXIMUM_LEVEL_ERROR
+        default 2 if LOG_MAXIMUM_LEVEL_WARN
+        default 3 if LOG_MAXIMUM_LEVEL_INFO
+        default 4 if LOG_MAXIMUM_LEVEL_DEBUG
+        default 5 if LOG_MAXIMUM_LEVEL_VERBOSE
+
     config LOG_COLORS
         bool "Use ANSI terminal colors in log output"
         default "y"

components/log/README.rst

@@ -6,8 +6,9 @@ Overview
 
 The logging library provides two ways for setting log verbosity:
 
-- **At compile time**: in menuconfig, set the verbosity level using the option :envvar:`CONFIG_LOG_DEFAULT_LEVEL`. All logging statements for verbosity levels higher than :envvar:`CONFIG_LOG_DEFAULT_LEVEL` will be removed by the preprocessor.
-- **At runtime**: all logs for verbosity levels lower than :envvar:`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 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 otional 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.
 
 There are the following verbosity levels:
 
@@ -19,7 +20,7 @@ There are the following verbosity levels:
 
 .. note::
 
-    The function :cpp:func:`esp_log_level_set` cannot set logging levels higher than specified by :envvar:`CONFIG_LOG_DEFAULT_LEVEL`. To increase log level for a specific file at compile time, use the macro `LOG_LOCAL_LEVEL` (see the details below).
+    The function :cpp:func:`esp_log_level_set` cannot set logging levels higher than specified by :ref:`CONFIG_LOG_MAXIMUM_LEVEL`. To increase log level for a specific file above this maximum at compile time, use the macro `LOG_LOCAL_LEVEL` (see the details below).
 
 
 How to use this library
@@ -45,7 +46,13 @@ Several macros are available for different verbosity levels:
 * ``ESP_LOGD`` - debug
 * ``ESP_LOGV`` - verbose (highest)
 
-Additionally, there are ``ESP_EARLY_LOGx`` versions for each of these macros, e.g., :c:macro:`ESP_EARLY_LOGE`. These versions have to be used explicitly in the early startup code only, before heap allocator and syscalls have been initialized. Normal ``ESP_LOGx`` macros can also be used while compiling the bootloader, but they will fall back to the same implementation as ``ESP_EARLY_LOGx`` macros.
+Additionally, there are ``ESP_EARLY_LOGx`` versions for each of these macros, e.g. :c:macro:`ESP_EARLY_LOGE`. These versions have to be used explicitly in the early startup code only, before heap allocator and syscalls have been initialized. Normal ``ESP_LOGx`` macros can also be used while compiling the bootloader, but they will fall back to the same implementation as ``ESP_EARLY_LOGx`` macros.
+
+There are also ``ESP_DRAM_LOGx`` versions for each of these macros, e.g. :c:macro:`ESP_DRAM_LOGE`. These versions are used in some places where logging may occur with interrupts disabled or with flash cache inaccessible. Use of this macros should be as sparing as possible, as logging in these types of code should be avoided for performance reasons.
+
+.. note::
+
+   Inside critical sections interrupts are disabled so it's only possible to use ``ESP_DRAM_LOGx`` (preferred) or ``ESP_EARLY_LOGx``. Even though it's possible to log in these situations, it's better if your program can be structured not to require it.
 
 To override default verbosity level at file or component scope, define the ``LOG_LOCAL_LEVEL`` macro.
 
@@ -58,9 +65,9 @@ At file scope, define it before including ``esp_log.h``, e.g.:
 
 At component scope, define it in the component makefile:
 
-.. code-block:: make
+.. code-block:: cmake
 
-   CFLAGS += -D LOG_LOCAL_LEVEL=ESP_LOG_DEBUG
+   target_compile_definitions(${COMPONENT_LIB} PUBLIC "-DLOG_LOCAL_LEVEL=ESP_LOG_VERBOSE")
 
 To configure logging output per module at runtime, add calls to the function :cpp:func:`esp_log_level_set` as follows:
 
@@ -70,6 +77,10 @@ To configure logging output per module at runtime, add calls to the function :cp
    esp_log_level_set("wifi", ESP_LOG_WARN);      // enable WARN logs from WiFi stack
    esp_log_level_set("dhcpc", ESP_LOG_INFO);     // enable INFO logs from DHCP client
 
+.. note::
+
+   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)``.
+
 Logging to Host via JTAG
 ^^^^^^^^^^^^^^^^^^^^^^^^
 

components/log/include/esp_log.h

@@ -40,13 +40,22 @@ typedef enum {
 
 typedef int (*vprintf_like_t)(const char *, va_list);
 
+/**
+ * @brief Default log level
+ *
+ * This is used by the definition of ESP_EARLY_LOGx macros. It is not
+ * recommended to set this directly, call esp_log_level_set("*", level)
+ * instead.
+ */
+extern esp_log_level_t esp_log_default_level;
+
 /**
  * @brief Set log level for given tag
  *
  * If logging for given component has already been enabled, changes previous setting.
  *
  * Note that this function can not raise log level above the level set using
- * CONFIG_LOG_DEFAULT_LEVEL setting in menuconfig.
+ * CONFIG_LOG_MAXIMUM_LEVEL setting in menuconfig.
  *
  * To raise log level above the default one for a given file, define
  * LOG_LOCAL_LEVEL to one of the ESP_LOG_* values, before including
@@ -137,7 +146,7 @@ void esp_log_writev(esp_log_level_t level, const char* tag, const char* format,
 
 #ifndef LOG_LOCAL_LEVEL
 #ifndef BOOTLOADER_BUILD
-#define LOG_LOCAL_LEVEL  CONFIG_LOG_DEFAULT_LEVEL
+#define LOG_LOCAL_LEVEL  CONFIG_LOG_MAXIMUM_LEVEL
 #else
 #define LOG_LOCAL_LEVEL  CONFIG_BOOTLOADER_LOG_LEVEL
 #endif
@@ -271,7 +280,7 @@ void esp_log_writev(esp_log_level_t level, const char* tag, const char* format,
 
 /** @endcond */
 
-/// macro to output logs in startup code, before heap allocator and syscalls have been initialized. log at ``ESP_LOG_ERROR`` level. @see ``printf``,``ESP_LOGE``
+/// macro to output logs in startup code, before heap allocator and syscalls have been initialized. log at ``ESP_LOG_ERROR`` level. @see ``printf``,``ESP_LOGE``,``ESP_DRAM_LOGE``
 #define ESP_EARLY_LOGE( tag, format, ... ) ESP_LOG_EARLY_IMPL(tag, format, ESP_LOG_ERROR,   E, ##__VA_ARGS__)
 /// macro to output logs in startup code at ``ESP_LOG_WARN`` level.  @see ``ESP_EARLY_LOGE``,``ESP_LOGE``, ``printf``
 #define ESP_EARLY_LOGW( tag, format, ... ) ESP_LOG_EARLY_IMPL(tag, format, ESP_LOG_WARN,    W, ##__VA_ARGS__)
@@ -282,8 +291,16 @@ void esp_log_writev(esp_log_level_t level, const char* tag, const char* format,
 /// macro to output logs in startup code at ``ESP_LOG_VERBOSE`` level.  @see ``ESP_EARLY_LOGE``,``ESP_LOGE``, ``printf``
 #define ESP_EARLY_LOGV( tag, format, ... ) ESP_LOG_EARLY_IMPL(tag, format, ESP_LOG_VERBOSE, V, ##__VA_ARGS__)
 
+#ifdef BOOTLOADER_BUILD
+#define _ESP_LOG_EARLY_ENABLED(log_level) (LOG_LOCAL_LEVEL >= (log_level))
+#else
+/* For early log, there is no log tag filtering. So we want to log only if both the LOG_LOCAL_LEVEL and the
+   currently configured min log level are higher than the log level */
+#define _ESP_LOG_EARLY_ENABLED(log_level) (LOG_LOCAL_LEVEL >= (log_level) && esp_log_default_level >= (log_level))
+#endif
+
 #define ESP_LOG_EARLY_IMPL(tag, format, log_level, log_tag_letter, ...) do {                             \
-        if (LOG_LOCAL_LEVEL >= log_level) {                                                              \
+        if (_ESP_LOG_EARLY_ENABLED(log_level)) {                                                         \
             esp_rom_printf(LOG_FORMAT(log_tag_letter, format), esp_log_timestamp(), tag, ##__VA_ARGS__); \
         }} while(0)
 
@@ -295,7 +312,9 @@ void esp_log_writev(esp_log_level_t level, const char* tag, const char* format,
 #define ESP_LOGV( tag, format, ... ) ESP_LOG_LEVEL_LOCAL(ESP_LOG_VERBOSE, tag, format, ##__VA_ARGS__)
 #else
 /**
- * macro to output logs at ESP_LOG_ERROR level.
+ * Macro to output logs at ESP_LOG_ERROR level.
+ *
+ * @note This macro cannot be used when interrupts are disabled or inside an ISR. @see ``ESP_DRAM_LOGE``.
  *
  * @param tag tag of the log, which can be used to change the log level by ``esp_log_level_set`` at runtime.
  *
@@ -351,7 +370,11 @@ void esp_log_writev(esp_log_level_t level, const char* tag, const char* format,
 /**
  * @brief Macro to output logs when the cache is disabled. log at ``ESP_LOG_ERROR`` level.
  *
- * Similar to `ESP_EARLY_LOGE`, the log level cannot be changed by `esp_log_level_set`.
+ * @note Unlike normal logging macros, it's possible to use this macro when interrupts are
+ * disabled or inside an ISR.
+ *
+ * Similar to @see ``ESP_EARLY_LOGE``, the log level cannot be changed per-tag, however
+ * esp_log_level_set("*", level) will set the default level which controls these log lines also.
  *
  * Usage: `ESP_DRAM_LOGE(DRAM_STR("my_tag"), "format", or `ESP_DRAM_LOGE(TAG, "format", ...)`,
  * where TAG is a char* that points to a str in the DRAM.
@@ -374,7 +397,7 @@ void esp_log_writev(esp_log_level_t level, const char* tag, const char* format,
 #define _ESP_LOG_DRAM_LOG_FORMAT(letter, format)  DRAM_STR(#letter " %s: " format "\n")
 
 #define ESP_DRAM_LOG_IMPL(tag, format, log_level, log_tag_letter, ...) do {                       \
-        if (LOG_LOCAL_LEVEL >= log_level) {                                                       \
+        if (_ESP_LOG_EARLY_ENABLED(log_level)) {                                                  \
             esp_rom_printf(_ESP_LOG_DRAM_LOG_FORMAT(log_tag_letter, format), tag, ##__VA_ARGS__); \
         }} while(0)
 /** @endcond */

components/log/log.c

@@ -61,7 +61,7 @@ typedef struct uncached_tag_entry_ {
     char tag[0];    // beginning of a zero-terminated string
 } uncached_tag_entry_t;
 
-static esp_log_level_t s_log_default_level = ESP_LOG_VERBOSE;
+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];
 static uint32_t s_log_cache_max_generation = 0;
@@ -96,7 +96,7 @@ void esp_log_level_set(const char *tag, esp_log_level_t level)
 
     // for wildcard tag, remove all linked list items and clear the cache
     if (strcmp(tag, "*") == 0) {
-        s_log_default_level = level;
+        esp_log_default_level = level;
         clear_log_level_list();
         esp_log_impl_unlock();
         return;
@@ -166,7 +166,7 @@ void esp_log_writev(esp_log_level_t level,
     // Look for the tag in cache first, then in the linked list of all tags
     if (!get_cached_log_level(tag, &level_for_tag)) {
         if (!get_uncached_log_level(tag, &level_for_tag)) {
-            level_for_tag = s_log_default_level;
+            level_for_tag = esp_log_default_level;
         }
         add_to_cache(tag, level_for_tag);
 #ifdef LOG_BUILTIN_CHECKS

components/log/log_freertos.c

@@ -11,11 +11,16 @@
 #include "freertos/task.h"
 #include "freertos/semphr.h"
 #include "hal/cpu_hal.h" // for cpu_hal_get_cycle_count()
+#include "esp_compiler.h"
 #include "esp_log.h"
 #include "esp_log_private.h"
 
 
 // Maximum time to wait for the mutex in a logging statement.
+//
+// We don't expect this to happen in most cases, as contention is low. The most likely case is if a
+// log function is called from an ISR (technically caller should use the ISR-friendly logging macros but
+// possible they use the normal one instead and disable the log type by tag).
 #define MAX_MUTEX_WAIT_MS 10
 #define MAX_MUTEX_WAIT_TICKS ((MAX_MUTEX_WAIT_MS + portTICK_PERIOD_MS - 1) / portTICK_PERIOD_MS)
 
@@ -23,22 +28,31 @@ static SemaphoreHandle_t s_log_mutex = NULL;
 
 void esp_log_impl_lock(void)
 {
-    if (!s_log_mutex) {
+    if (unlikely(!s_log_mutex)) {
         s_log_mutex = xSemaphoreCreateMutex();
     }
+    if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) {
+        return;
+    }
     xSemaphoreTake(s_log_mutex, portMAX_DELAY);
 }
 
 bool esp_log_impl_lock_timeout(void)
 {
-    if (!s_log_mutex) {
+    if (unlikely(!s_log_mutex)) {
         s_log_mutex = xSemaphoreCreateMutex();
     }
+    if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) {
+        return true;
+    }
     return xSemaphoreTake(s_log_mutex, MAX_MUTEX_WAIT_TICKS) == pdTRUE;
 }
 
 void esp_log_impl_unlock(void)
 {
+    if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) {
+        return;
+    }
     xSemaphoreGive(s_log_mutex);
 }
 
@@ -84,7 +98,7 @@ char *esp_log_system_timestamp(void)
 
 uint32_t esp_log_timestamp(void)
 {
-    if (xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED) {
+    if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) {
         return esp_log_early_timestamp();
     }
     static uint32_t base = 0;

components/pthread/pthread.c

@@ -31,7 +31,6 @@
 #include "pthread_internal.h"
 #include "esp_pthread.h"
 
-#define LOG_LOCAL_LEVEL CONFIG_LOG_DEFAULT_LEVEL
 #include "esp_log.h"
 const static char *TAG = "pthread";
 

components/pthread/pthread_cond_var.c

@@ -30,7 +30,6 @@
 #include <sys/queue.h>
 #include <sys/time.h>
 
-#define LOG_LOCAL_LEVEL CONFIG_LOG_DEFAULT_LEVEL
 #include "esp_log.h"
 const static char *TAG = "esp_pthread";
 

components/pthread/test/test_pthread_cxx.cpp

@@ -8,7 +8,6 @@
 
 #if __GTHREADS && __GTHREADS_CXX0X
 
-#define LOG_LOCAL_LEVEL CONFIG_LOG_DEFAULT_LEVEL
 #include "esp_log.h"
 const static char *TAG = "pthread_test";
 

examples/system/startup_time/CMakeLists.txt

@@ -0,0 +1,6 @@
+# The following lines of boilerplate have to be in your project's CMakeLists
+# in this exact order for cmake to work correctly
+cmake_minimum_required(VERSION 3.5)
+
+include($ENV{IDF_PATH}/tools/cmake/project.cmake)
+project(startup_time)

examples/system/startup_time/Makefile

@@ -0,0 +1,8 @@
+#
+# This is a project Makefile. It is assumed the directory this Makefile resides in is a
+# project subdirectory.
+#
+
+PROJECT_NAME := startup_time
+
+include $(IDF_PATH)/make/project.mk

examples/system/startup_time/README.md

@@ -0,0 +1,63 @@
+# Startup Time Example
+
+(See the README.md file in the upper level 'examples' directory for more information about examples.)
+
+This example demonstrates the configuration settings to obtain the minimum possible startup time for an ESP-IDF application (i.e. time from initial reset until the `app_main()` function is running).
+
+Note that some of the configuration settings in `sdkconfig.defaults` have trade-offs that may not be suitable for your project, see the "Applying To Your Own Project" section at the bottom for more details.
+
+## How to use example
+
+### Hardware Required
+
+This example should be able to run on any commonly available ESP32 development board.
+
+### Configure the project
+
+This step is optional, the default settings in `sdkconfig.defaults` are already set to minimize startup time.
+
+```
+idf.py menuconfig
+```
+
+### Build and Flash
+
+Build the project and flash it to the board, then run monitor tool to view serial output:
+
+```
+idf.py -p PORT flash monitor
+```
+
+(Replace PORT with the name of the serial port to use.)
+
+(To exit the serial monitor, type ``Ctrl-]``.)
+
+See the Getting Started Guide for full steps to configure and use ESP-IDF to build projects.
+
+## Example Output
+
+The example should have log output similar to the following:
+
+```
+W (34) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
+I (37) example: App started!
+```
+
+All early log output is disabled in order to save time (it's also possible to disable the ROM log output immediately after reset, see below.)
+
+Note that boot time reported in the log timestamp may vary depending on the chip target, chip revision, and eFuse configuration.
+
+## Applying To Your Own Project
+
+The file `sdkconfig.defaults` contains a range of setting which can be applied to any project in order for it to boot more rapidly.
+
+However, note that some of these settings may have tradeoffs - for example not all hardware may support all flash modes and speeds, some applications would prefer the reliability of checking the application on every boot rather than waiting for a crash and then checking the application, and some applications will use features such as Secure Boot which require additional overhead on boot.
+
+The `sdkconfig.defaults` file in this directory contains comments above each of the settings to optimize boot speed. To add the settings
+to your own project, either search for the setting name in `menuconfig` or exit `menuconfig` and then copy-paste the setting lines at the end of your project's `sdkconfig` file.
+
+## Additional Startup Speed
+
+Removing the default boot log output printed by the ROM can shave several milliseconds off the SoC boot time. The default configuration doesn't make this change, as it is done via eFuse the change is permanent.
+
+If you wish to make this change run `idf.py menuconfig`, navigate to "Boot ROM Behavior" and set the "Permanently change Boot ROM output" option.

examples/system/startup_time/example_test.py

@@ -0,0 +1,30 @@
+from __future__ import print_function
+
+import re
+
+import ttfw_idf
+
+
+@ttfw_idf.idf_example_test(env_tag='Example_GENERIC', target=['esp32', 'esp32s2', 'esp32c3'])
+def test_startup_time_example(env, extra_data):
+    app_name = 'startup_time'
+    dut = env.get_dut(app_name, 'examples/system/startup_time')
+    dut.start_app()
+
+    res = dut.expect(re.compile(r'\((\d+)\) [^:]+: App started!'))
+    time = int(res[0])
+
+    # Allow ci-dashboard to track startup times
+    print('------ startup time info ------\n'
+          '[app_name] {}\n'
+          '[startup_time] {}\n'
+          '[config] {}\n'
+          '[target] {}\n'
+          '------ startup time end ------'.format(app_name,
+                                                  time,
+                                                  dut.app.config_name,
+                                                  dut.TARGET))
+
+
+if __name__ == '__main__':
+    test_startup_time_example()

examples/system/startup_time/main/CMakeLists.txt

@@ -0,0 +1,2 @@
+idf_component_register(SRCS "hello_world_main.c"
+                    INCLUDE_DIRS "")

examples/system/startup_time/main/component.mk

@@ -0,0 +1,4 @@
+#
+# "main" pseudo-component makefile.
+#
+# (Uses default behaviour of compiling all source files in directory, adding 'include' to include path.)

examples/system/startup_time/main/hello_world_main.c

@@ -0,0 +1,23 @@
+/* Startup time example
+
+   This example code is in the Public Domain (or CC0 licensed, at your option.)
+
+   Unless required by applicable law or agreed to in writing, this
+   software is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR
+   CONDITIONS OF ANY KIND, either express or implied.
+*/
+#include <stdio.h>
+#include "esp_log.h"
+
+static const char *TAG = "example";
+
+/* The purpose of this app is to demonstrate fast startup time only, so feel free
+   to replace this app_main() with your own code or copy the sdkconfig.defaults contents
+   into a different project's sdkconfig file.
+*/
+void app_main(void)
+{
+    // Calling this function restores all Info-level logging at runtime (as "Log Maximum Verbosity" set to "Info")
+    esp_log_level_set("*", ESP_LOG_INFO);
+    ESP_LOGI(TAG, "App started!");
+}

examples/system/startup_time/sdkconfig.defaults

@@ -0,0 +1,19 @@
+# Set flash configuration as fast as possible (Quad I/O 80MHz)
+#
+# (Not all hardware may support this configuration.)
+CONFIG_ESPTOOLPY_FLASHMODE_QIO=y
+CONFIG_ESPTOOLPY_FLASHFREQ_80M=y
+
+# These two settings mean that no logs are printed
+# during startup, but it's possible to use esp_log_level_set("*", ESP_LOG_INFO)
+# at runtime to get Info-level logging back
+CONFIG_LOG_DEFAULT_LEVEL_WARN=y
+CONFIG_LOG_MAXIMUM_LEVEL_INFO=y
+CONFIG_BOOTLOADER_LOG_LEVEL_WARN=y
+
+# at risk of not detecting flash corruption, skip bootloader
+# verification of the app unless a soft reset or crash happened
+#
+# note: the larger the application, the bigger the time saved by
+# from this option
+CONFIG_BOOTLOADER_SKIP_VALIDATE_ON_POWER_ON=y

examples/system/startup_time/sdkconfig.defaults.esp32

@@ -0,0 +1,5 @@
+# Not calibrating RTC_SLOW_CLK saves a small amount of time during boot.
+#
+# Setting option to zero is only recommended if not using sleep modes, or
+# if you don't need accurate sleep times.
+CONFIG_ESP32_RTC_CLK_CAL_CYCLES=0

examples/system/startup_time/sdkconfig.defaults.esp32c3

@@ -0,0 +1,5 @@
+# Not calibrating RTC_SLOW_CLK saves a small amount of time during boot.
+#
+# Setting option to zero is only recommended if not using sleep modes, or
+# if you don't need accurate sleep times.
+CONFIG_ESP32C3_RTC_CLK_CAL_CYCLES=0

examples/system/startup_time/sdkconfig.defaults.esp32s2

@@ -0,0 +1,5 @@
+# Not calibrating RTC_SLOW_CLK saves a small amount of time during boot.
+#
+# Setting option to zero is only recommended if not using sleep modes, or
+# if you don't need accurate sleep times.
+CONFIG_ESP32S2_RTC_CLK_CAL_CYCLES=0

examples/system/startup_time/sdkconfig.defaults.esp32s3

@@ -0,0 +1,5 @@
+# Not calibrating RTC_SLOW_CLK saves a small amount of time during boot.
+#
+# Setting option to zero is only recommended if not using sleep modes, or
+# if you don't need accurate sleep times.
+CONFIG_ESP32S3_RTC_CLK_CAL_CYCLES=0

tools/ci/mypy_ignore_list.txt

@@ -141,6 +141,7 @@ examples/system/ota/otatool/otatool_example.py
 examples/system/ota/simple_ota_example/example_test.py
 examples/system/perfmon/example_test.py
 examples/system/select/example_test.py
+examples/system/startup_time/example_test.py
 examples/system/sysview_tracing/example_test.py
 examples/system/sysview_tracing_heap_log/example_test.py
 examples/system/task_watchdog/example_test.py