Arduino as IDF-Component: Serial.begin() mess up stdout if PM and DFS (Dynamic Frequency Scaling) is enabled

[LIFsCode]

Board

ESP32 Dev Board

Device Description

plain ESP32 Dev Borad connected via USB/UART

Hardware Configuration

plain ESP32 Dev Borad connected via USB/UART

Version

v2.0.7

IDE Name

PlatformIO

Operating System

Windows 10

Flash frequency

40 MHz

PSRAM enabled

no

Upload speed

115200

Description

Running Arduino as IDF component with a IDF app_main

Once I call Serial.begin(115200); the output on the serial terminal will get messed up, once the device is entering light sleep mode.

Running this sdkconfig FreeRTOS config

#
# FreeRTOS
#
# CONFIG_FREERTOS_UNICORE is not set
CONFIG_FREERTOS_NO_AFFINITY=0x7FFFFFFF
CONFIG_FREERTOS_TICK_SUPPORT_CORETIMER=y
CONFIG_FREERTOS_CORETIMER_0=y
# CONFIG_FREERTOS_CORETIMER_1 is not set
CONFIG_FREERTOS_SYSTICK_USES_CCOUNT=y
CONFIG_FREERTOS_HZ=1000
CONFIG_FREERTOS_ASSERT_ON_UNTESTED_FUNCTION=y
# CONFIG_FREERTOS_CHECK_STACKOVERFLOW_NONE is not set
# CONFIG_FREERTOS_CHECK_STACKOVERFLOW_PTRVAL is not set
CONFIG_FREERTOS_CHECK_STACKOVERFLOW_CANARY=y
# CONFIG_FREERTOS_WATCHPOINT_END_OF_STACK is not set
CONFIG_FREERTOS_INTERRUPT_BACKTRACE=y
CONFIG_FREERTOS_THREAD_LOCAL_STORAGE_POINTERS=1
CONFIG_FREERTOS_ASSERT_FAIL_ABORT=y
# CONFIG_FREERTOS_ASSERT_FAIL_PRINT_CONTINUE is not set
# CONFIG_FREERTOS_ASSERT_DISABLE is not set
CONFIG_FREERTOS_IDLE_TASK_STACKSIZE=1536
CONFIG_FREERTOS_ISR_STACKSIZE=1536
# CONFIG_FREERTOS_LEGACY_HOOKS is not set
CONFIG_FREERTOS_MAX_TASK_NAME_LEN=16
CONFIG_FREERTOS_SUPPORT_STATIC_ALLOCATION=y
# CONFIG_FREERTOS_ENABLE_STATIC_TASK_CLEAN_UP is not set
CONFIG_FREERTOS_TIMER_TASK_PRIORITY=1
CONFIG_FREERTOS_TIMER_TASK_STACK_DEPTH=2048
CONFIG_FREERTOS_TIMER_QUEUE_LENGTH=10
CONFIG_FREERTOS_QUEUE_REGISTRY_SIZE=0
# CONFIG_FREERTOS_USE_TRACE_FACILITY is not set
# CONFIG_FREERTOS_GENERATE_RUN_TIME_STATS is not set
CONFIG_FREERTOS_USE_TICKLESS_IDLE=y
CONFIG_FREERTOS_IDLE_TIME_BEFORE_SLEEP=3
CONFIG_FREERTOS_TASK_FUNCTION_WRAPPER=y
CONFIG_FREERTOS_CHECK_MUTEX_GIVEN_BY_OWNER=y
# CONFIG_FREERTOS_CHECK_PORT_CRITICAL_COMPLIANCE is not set
# CONFIG_FREERTOS_PLACE_FUNCTIONS_INTO_FLASH is not set
CONFIG_FREERTOS_DEBUG_OCDAWARE=y
# CONFIG_FREERTOS_FPU_IN_ISR is not set
CONFIG_FREERTOS_ENABLE_TASK_SNAPSHOT=y
# CONFIG_FREERTOS_PLACE_SNAPSHOT_FUNS_INTO_FLASH is not set
# end of FreeRTOS

Sketch

#include <stdio.h>
#include <freertos/FreeRTOS.h>
#include <freertos/task.h>
#include <driver/gpio.h>
#include "sdkconfig.h"
#include <Arduino.h>
#include "esp_pm.h"

extern "C" void app_main()
{
    // initialize arduino library before we start the tasks
    initArduino();
    
    // BUG-TRIGGER
    //NOTE: if uncomment this, the serial output will get corrupted
    //Serial.begin(115200);
    // BUG TRIGER END


    ESP_LOGI( LOG_TAG, "Starting"); 
        for (int i=0; i< 2; i++) {
              ESP_LOGE( LOG_TAG, "Error:%d", 100 ); 
                ESP_LOGW( LOG_TAG, "Warning:%d", 200 );
                ESP_LOGI( LOG_TAG, "Info:%d", 300 ); 
                ESP_LOGD( LOG_TAG, "Debug:%d", 400 );
                // for (int i=0;i<10;i++) Serial.println(i);
                delay(5000);
                ESP_LOGE( LOG_TAG, "Error:%d", 100 ); 
                ESP_LOGW( LOG_TAG, "Warning:%d", 200 );
                ESP_LOGI( LOG_TAG, "Info:%d", 300 ); 
                // for (int i=0;i<10;i++) Serial.println(i);
        }
        delay(1000);

        ESP_LOGI( LOG_TAG, "Setting up power saving" ); 
        esp_pm_config_esp32_t cfg = {
        .max_freq_mhz = 80,
        .min_freq_mhz = 40,
        .light_sleep_enable = true
        };
        // Serial.flush();
        esp_pm_configure(&cfg);   

        ESP_LOGI( LOG_TAG, "do test in power save" ); 
        vTaskDelay(pdMS_TO_TICKS(1000));
        ESP_LOGI( LOG_TAG, "testing..." ); 
        for (int i=0; i< 2; i++) {
              ESP_LOGE( LOG_TAG, "Error:%d", 100 ); 
                ESP_LOGW( LOG_TAG, "Warning:%d", 200 );
                ESP_LOGI( LOG_TAG, "Info:%d", 300 ); 
                ESP_LOGD( LOG_TAG, "Debug:%d", 400 );
                // for (int i=0;i<10;i++) Serial.println(i);
                delay(5000);
                ESP_LOGE( LOG_TAG, "Error:%d", 100 ); 
                ESP_LOGW( LOG_TAG, "Warning:%d", 200 );
                ESP_LOGI( LOG_TAG, "Info:%d", 300 ); 
                // for (int i=0;i<10;i++) Serial.println(i);
        }


        while(1) {
            vTaskDelay(pdMS_TO_TICKS(5000));
        }
}

Debug Message

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:6660
load:0x40078000,len:14944
ho 0 tail 12 room 4
load:0x40080400,len:3816
entry 0x40080698
I (29) boot: ESP-IDF 4.4.4 2nd stage bootloader
I (29) boot: compile time 21:55:23
I (29) boot: chip revision: v3.0
I (32) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (39) boot.esp32: SPI Speed      : 40MHz
I (44) boot.esp32: SPI Mode       : DIO
I (48) boot.esp32: SPI Flash Size : 4MB
I (53) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (62) boot: ## Label            Usage          Type ST Offset   Length
I (69) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (77) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (84) boot:  2 factory          factory app      00 00 00010000 00100000
I (92) boot: End of partition table
I (96) boot_comm: chip revision: 3, min. application chip revision: 0
I (103) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=0b300h ( 45824) map
I (128) esp_image: segment 1: paddr=0001b328 vaddr=3ff80000 size=00004h (     4) load
I (128) esp_image: segment 2: paddr=0001b334 vaddr=3ffb0000 size=024c0h (  9408) load
I (138) esp_image: segment 3: paddr=0001d7fc vaddr=40080000 size=0281ch ( 10268) load
I (147) esp_image: segment 4: paddr=00020020 vaddr=400d0020 size=1d57ch (120188) map
I (194) esp_image: segment 5: paddr=0003d5a4 vaddr=4008281c size=0bee8h ( 48872) load
I (222) boot: Loaded app from partition at offset 0x10000
I (222) boot: Disabling RNG early entropy source...
I (233) cpu_start: Pro cpu up.
I (234) cpu_start: Starting app cpu, entry point is 0x40081e74
I (0) cpu_start: App cpu up.
I (248) cpu_start: Pro cpu start user code
I (248) cpu_start: cpu freq: 80000000
I (248) cpu_start: Application information:
I (252) cpu_start: Project name:     espidf-arduino-wifiscan
I (258) cpu_start: App version:      1
I (263) cpu_start: Compile time:     Apr 25 2023 21:52:02
I (269) cpu_start: ELF file SHA256:  496104206466ae6c...
I (275) cpu_start: ESP-IDF:          4.4.4
I (280) heap_init: Initializing. RAM available for dynamic allocation:
I (287) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (293) heap_init: At 3FFB2FB8 len 0002D048 (180 KiB): DRAM
I (299) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (306) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (312) heap_init: At 4008E704 len 000118FC (70 KiB): IRAM
I (320) spi_flash: detected chip: generic
I (323) spi_flash: flash io: dio
I (339) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (�]�I (403) Main: Starting
E (403) Main: Error:100
W (403) Main: Warning:200
I (403) Main: Info:300
E (5404) Main: Error:100
W (5404) Main: Warning:200
I (5404) Main: Info:300
E (5404) Main: Error:100
W (5405) Main: Warning:200
I (5409) Main: Info:300
E (10412) Main: Error:100
W (10412) Main: Warning:200
I (10412) Main: Info:300
I (11412) Main: Setting up power saving
I (11412) pm: Frequency switc�f���~����xf�~�~��ff�ff~b
A       }5a� 80, APB_MIN: 40, Light sleep: ENABLED
I (11415) Main: do test in power save
I (12422) Main: tes���~�������`���f����`��~����f(B�����Jj���� Error:100
W (12427) Main: Warning:200
I (12431) Main: Info:300
E (17435) Main: Error:100
W (17437) Main: Warning:200
I (17440) Main: I�x����x����f����`��~����f�B�����Jj���� Error:100
W (17446) Main: Warning:200
f�������x枘�x����f����x����f����`��~����f(��f���ff�����������>1�����f����`��~�x�~�x`��S��f�����f��������~�~����f����`��~x枆��x`��j

Other Steps to Reproduce

The rest of the code can be left unchanged. The behavior can be turned on and off with adding or removing this line:
Serial.begin(115200);

If Serial is kept running and the following code segment is removed, things work fine. So it seems do be definetly a problem with Serial in combination with light sleep mode.
esp_pm_configure(&cfg);

I have checked existing issues, online documentation and the Troubleshooting Guide

• I confirm I have checked existing issues, online documentation and Troubleshooting guide.

[SuGlider]

@LIFsCode

Could you test it by adding a code line to your sketch:

        // Serial.flush();
        esp_pm_configure(&cfg);   
        Serial.updateBaudRate(115200);    // <<<======= it may help to set all to a correct state
        ESP_LOGI( LOG_TAG, "do test in power save" ); 

[LIFsCode]

Hi,
I just tested it with this modification, but no change the behavior at all.

I also tried changing delay() statements to vTaskDelay(pdMS_TO_TICKS()) but with no change as well.

[SuGlider]

@LIFsCode - I have built and executed the suggested code and I got no issue.

I have set the sdkconfig.defaults to your sdkconfig FreeRTOS config and left the sdkconfig file empty.
Please make sure that the PROJECT/components/arduino folder has Arduino Core 2.0.7
You can enforce it by git checkout 2.0.7 in the arduino folder.

I used this code:

#include <stdio.h>
#include <freertos/FreeRTOS.h>
#include <freertos/task.h>
#include <driver/gpio.h>
#include "sdkconfig.h"
#include <Arduino.h>
#include "esp_pm.h"

const char* LOG_TAG = "issue8122";

extern "C" void app_main()
{
    // initialize arduino library before we start the tasks
    initArduino();
    
    // BUG-TRIGGER
    //NOTE: if uncomment this, the serial output will get corrupted
    Serial.begin(115200);
    // BUG TRIGER END


    ESP_LOGI( LOG_TAG, "Starting"); 
        for (int i=0; i< 2; i++) {
              ESP_LOGE( LOG_TAG, "Error:%d", 100 ); 
                ESP_LOGW( LOG_TAG, "Warning:%d", 200 );
                ESP_LOGI( LOG_TAG, "Info:%d", 300 ); 
                ESP_LOGD( LOG_TAG, "Debug:%d", 400 );
                // for (int i=0;i<10;i++) Serial.println(i);
                delay(5000);
                ESP_LOGE( LOG_TAG, "Error:%d", 100 ); 
                ESP_LOGW( LOG_TAG, "Warning:%d", 200 );
                ESP_LOGI( LOG_TAG, "Info:%d", 300 ); 
                // for (int i=0;i<10;i++) Serial.println(i);
        }
        Serial.println("\n-------\nbefore power saving\n------");
        delay(1000);

        ESP_LOGI( LOG_TAG, "Setting up power saving" ); 
        esp_pm_config_esp32_t cfg = {
        .max_freq_mhz = 80,
        .min_freq_mhz = 40,
        .light_sleep_enable = true
        };
        // Serial.flush();
        esp_pm_configure(&cfg);   

        Serial.println("\n-------\nafter power saving\n------");
        ESP_LOGI( LOG_TAG, "do test in power save" ); 
        vTaskDelay(pdMS_TO_TICKS(1000));
        ESP_LOGI( LOG_TAG, "testing..." ); 
        for (int i=0; i< 2; i++) {
              ESP_LOGE( LOG_TAG, "Error:%d", 100 ); 
                ESP_LOGW( LOG_TAG, "Warning:%d", 200 );
                ESP_LOGI( LOG_TAG, "Info:%d", 300 ); 
                ESP_LOGD( LOG_TAG, "Debug:%d", 400 );
                // for (int i=0;i<10;i++) Serial.println(i);
                delay(5000);
                ESP_LOGE( LOG_TAG, "Error:%d", 100 ); 
                ESP_LOGW( LOG_TAG, "Warning:%d", 200 );
                ESP_LOGI( LOG_TAG, "Info:%d", 300 ); 
                // for (int i=0;i<10;i++) Serial.println(i);
        }

        Serial.println("\n-------\nAt the end of execution!\n------");

        while(1) {
            vTaskDelay(pdMS_TO_TICKS(5000));
        }
}

Output:

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:6664
load:0x40078000,len:14944
load:0x40080400,len:3816
0x40080400: _init at ??:?

entry 0x40080698
I (26) boot: ESP-IDF v4.4.4 2nd stage bootloader
I (27) boot: compile time 20:33:53
I (27) boot: chip revision: v1.0
I (30) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (37) boot.esp32: SPI Speed      : 40MHz
I (41) boot.esp32: SPI Mode       : DIO
I (46) boot.esp32: SPI Flash Size : 2MB
I (50) boot: Enabling RNG early entropy source...
I (56) boot: Partition Table:
I (59) boot: ## Label            Usage          Type ST Offset   Length
I (67) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (74) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (82) boot:  2 factory          factory app      00 00 00010000 00100000
I (89) boot: End of partition table
I (93) boot_comm: chip revision: 1, min. application chip revision: 0
I (100) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=0a92ch ( 43308) map
I (125) esp_image: segment 1: paddr=0001a954 vaddr=3ffb0000 size=02460h (  9312) load
I (129) esp_image: segment 2: paddr=0001cdbc vaddr=40080000 size=0325ch ( 12892) load
I (136) esp_image: segment 3: paddr=00020020 vaddr=400d0020 size=1c7fch (116732) map
I (181) esp_image: segment 4: paddr=0003c824 vaddr=4008325c size=09f90h ( 40848) load
I (205) boot: Loaded app from partition at offset 0x10000
I (205) boot: Disabling RNG early entropy source...
I (216) cpu_start: Pro cpu up.
I (217) cpu_start: Starting app cpu, entry point is 0x40081230
0x40081230: call_start_cpu1 at C:/Users/rocor/Documents/esp-idf-v4.4.4/components/esp_system/port/cpu_start.c:148

I (0) cpu_start: App cpu up.
I (231) cpu_start: Pro cpu start user code
I (231) cpu_start: cpu freq: 160000000
I (231) cpu_start: Application information:
I (235) cpu_start: Project name:     arduino_test
I (240) cpu_start: App version:      1
I (245) cpu_start: Compile time:     Apr 26 2023 20:33:18
I (251) cpu_start: ELF file SHA256:  767d10db518dcf2d...
I (257) cpu_start: ESP-IDF:          v4.4.4
I (262) heap_init: Initializing. RAM available for dynamic allocation:
I (269) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (275) heap_init: At 3FFB2ED0 len 0002D130 (180 KiB): DRAM
I (281) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (288) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (294) heap_init: At 4008D1EC len 00012E14 (75 KiB): IRAM
I (302) spi_flash: detected chip: gd
I (305) spi_flash: flash io: dio
W (309) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (323) cpu_start: Starting scheduler on PRO CPU.
II (348) issue8122: Starting
E (349) issue8122: Error:100
W (349) issue8122: Warning:200
I (349) issue8122: Info:300
E (5352) issue8122: Error:100
W (5352) issue8122: Warning:200
I (5352) issue8122: Info:300
E (5352) issue8122: Error:100
W (5355) issue8122: Warning:200
I (5359) issue8122: Info:300
E (10362) issue8122: Error:100
W (10362) issue8122: Warning:200
I (10362) issue8122: Info:300
-------
before power saving
------
I (11372) issue8122: Setting up power saving
-------
after power saving
------
I (11372) issue8122: do test in power save
I (12373) issue8122: testing...
E (12373) issue8122: Error:100
W (12373) issue8122: Warning:200
I (12373) issue8122: Info:300
E (17377) issue8122: Error:100
W (17377) issue8122: Warning:200
I (17377) issue8122: Info:300
E (17377) issue8122: Error:100
W (17380) issue8122: Warning:200
I (17384) issue8122: Info:300
E (22388) issue8122: Error:100
W (22388) issue8122: Warning:200
I (22388) issue8122: Info:300
-------
At the end of execution!
------

[SuGlider]

@LIFsCode -

What exactly are you trying to achieve with this code?

        esp_pm_config_esp32_t cfg = {
        .max_freq_mhz = 80,
        .min_freq_mhz = 40,
        .light_sleep_enable = true
        };
        // Serial.flush();
        esp_pm_configure(&cfg);   

I didn't get the message
A }5a� 80, APB_MIN: 40, Light sleep: ENABLED

[SuGlider]

If the target is to lower the CPU Freq, you can use the Arduino call setCpuFrequencyMhz(40); to set it to 40Mhz.
When the CPUFreq is lower than 80MHz, ESP32 UART may send data in the wrong baud rate.
In order to fix it, we use to set the baud rate again, right after lowering the CPUFreq.
Serial.updateBaudRate(115200); // <<<======= it may help to set all to a correct state

I tested this code snipet:

        Serial.println("\n-------\nbefore power saving\n------");
        delay(1000);

        ESP_LOGI( LOG_TAG, "Setting up power saving" ); 
        esp_pm_config_esp32_t cfg = {
        .max_freq_mhz = 80,
        .min_freq_mhz = 40,
        .light_sleep_enable = true
        };

        // Serial.flush();
        esp_pm_configure(&cfg);   

        setCpuFrequencyMhz(40);
        Serial.updateBaudRate(115200);    // <<<======= it may help to set all to a correct state

        Serial.println("\n-------\nafter power saving\n------");
        ESP_LOGI( LOG_TAG, "do test in power save" ); 
        vTaskDelay(pdMS_TO_TICKS(1000));

Output:

-------
before power saving
------
;�ښ�j%�(11372) issue8122: Setting up power saving
-------
after power saving
------
I (11372) issue8122: do test in power save
I (12372) issue8122: testing...
E (12372) issue8122: Error:100
W (12372) issue8122: Warning:200
I (12373) issue8122: Info:300
E (17376) issue8122: Error:100
W (17376) issue8122: Warning:200
I (17376) issue8122: Info:300
E (17377) issue8122: Error:100
W (17380) issue8122: Warning:200
I (17384) issue8122: Info:300
E (22387) issue8122: Error:100
W (22387) issue8122: Warning:200
I (22387) issue8122: Info:300
-------
At the end of execution!
------

[LIFsCode]

The intention is to activate tickless idle, i.e. the freeRTOS is entering light sleep during Idle task if all tasks are blocked or waiting.

Did you turn on power management in sdkconfig?
The missing message you mentioned seems to indicate that the power management change is not in effect.

Sorry I just noticed I forgot to add my sdkconfig file. I can provide it to you. But I won't be at my place until monday.

[SuGlider]

I can provide it to you. But I won't be at my place until monday.

Please provide me the sdkconfig file in order to fully test it.
I'll resume this issue next week. Thanks.

[LIFsCode]

Maybe it's more related to DFS, with the wider range of CPU frequency: min=40, max=80
I didn't check that.

[SuGlider]

By default, Arduino Serial sets APB as clock source in Serial.begin().
When DFS is enabled, APB frequency changes at any time.
This will cause UART to fail. In order to fix it for you project, you need to change the Arduino Source Code.
PM and DFS are always disabled when Arduino is in use.

arduino-esp32/cores/esp32/esp32-hal-uart.c

Lines 202 to 210 in 8873adb

	#if SOC_UART_SUPPORT_XTAL_CLK
	// works independently of APB frequency
	uart_config.source_clk = UART_SCLK_XTAL; // ESP32C3, ESP32S3
	uart_config.baud_rate = baudrate;
	#else
	uart_config.source_clk = UART_SCLK_APB; // ESP32, ESP32S2
	uart_config.baud_rate = _get_effective_baudrate(baudrate);
	#endif
	ESP_ERROR_CHECK(uart_driver_install(uart_nr, rx_buffer_size, tx_buffer_size, 20, &(uart->uart_event_queue), 0));

Change Line 207 and 208 to:

    uart_config.source_clk = UART_SCLK_REF_TICK;  // ESP32, ESP32S2
    //uart_config.baud_rate = _get_effective_baudrate(baudrate);