Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

esp32c3: corrupted log output when light sleep is enabled (IDFGH-7809) #9343

Closed
2 tasks done
HiFiPhile opened this issue Jul 12, 2022 · 6 comments · May be fixed by #9673
Closed
2 tasks done

esp32c3: corrupted log output when light sleep is enabled (IDFGH-7809) #9343

HiFiPhile opened this issue Jul 12, 2022 · 6 comments · May be fixed by #9673
Assignees
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally

Comments

@HiFiPhile
Copy link
Contributor

Environment

  • Development Kit: [ESP32-C3-DevKitM-1]
  • Kit version (for WroverKit/PicoKit/DevKitC): [v1]
  • Module or chip used: [ESP32-C3-WROOM-02]
  • IDF version (run git describe --tags to find it):
    v5.0-dev-3202-ga2d5041492
  • Build System: [idf.py]
  • Compiler version (run xtensa-esp32-elf-gcc --version to find it):
    gcc version 8.4.0 (crosstool-NG esp-2021r2-patch3)
  • Operating System: [Windows]
  • (Windows only) environment type: [ESP Command Prompt]
  • Using an IDE?: [VSCode]
  • Power Supply: [USB]

Problem Description

When light sleep is enabled, uart log output become corrupted. First part of log is repeated multiples times.

Expected Behavior

With attached example:

I (298) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: 40, Light sleep: DISABLED
I (303) sleep: Disable automatic switching of GPIO sleep configuration
I (310) coexist: coexist rom version 9387209
I (315) cpu_start: Starting scheduler.
I (4586) main: In main task 1 dummy 1
I (4586) main: In main task 1 dummy 1
I (4606) main: In main task 1 dummy 1
I (4606) main: In main task 1 dummy 1
I (4626) main: In main task 1 dummy 1
I (4626) main: In main task 2 dummy 2
I (4646) main: In main task 3 dummy 3
I (4646) main: In main task 4 dummy 4
I (8646) main: In main task 1 dummy 1
I (8646) main: In main task 1 dummy 1
I (8666) main: In main task 1 dummy 1
I (8666) main: In main task 1 dummy 1
I (8686) main: In main task 1 dummy 1
I (8686) main: In main task 2 dummy 2
I (8706) main: In main task 3 dummy 3
I (8706) main: In main task 4 dummy 4

Actual Behavior

With attached example:

I (320) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, I (320) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, AI (320) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: 10, Light sleep: ENABI (320) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: 10, Light sleep: ENABI (320) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: 10, Light sleep: ENABLI (320) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: 10, Light sleep: ENABLED
I (320) sleep: Enable automatic switching of GPIO sleep configuration
I (4340) main: In main task 1 dummy 1
I (4340) main: In main task 1 dummy 1
I (4360) main: In main task 1 dummy 1
I (4360) main: In main task 1 dummy 1
I (4380) main: In main task 1 dummy 1
I (4380) main: In main task 2 dummy 2
I I (I (4400) main: In main task 3 dummy 3
I (4400) main: In main task 4 dummy 4
I (8400) main: In main task 1 dummy 1
I (8400) main: In main task 1 dummy 1
I (8420) main: In main task 1 dummy 1
I (8420) main: In main task 1 dummy 1
I (8440) main: In main task 1 dummy 1
I (8440) main: In main task 2 dummy 2
II I (8460) main: In main task 3 dummy 3
I (8460) main: In main task 4 dummy 4

Steps to reproduce

Compile and run attached example.

Code to reproduce this issue

Log_corrupt.zip

Debug Logs

I (30) boot: ESP-IDF v5.0-dev-3202-ga2d5041492-dirty 2nd stage bootloader
I (30) boot: compile time 21:25:38
I (30) boot: chip revision: 3
I (34) boot.esp32c3: SPI Speed      : 80MHz
I (39) boot.esp32c3: SPI Mode       : DIO
I (43) boot.esp32c3: SPI Flash Size : 4MB
I (48) boot: Enabling RNG early entropy source...
I (54) boot: Partition Table:
I (57) boot: ## Label            Usage          Type ST Offset   Length
I (64) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (72) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (79) boot:  2 coredump         Unknown data     01 03 00010000 00010000
I (87) boot:  3 factory          factory app      00 00 00020000 00140000
I (94) boot:  4 ota_0            OTA app          00 10 00160000 00140000
I (102) boot:  5 ota_1            OTA app          00 11 002a0000 00140000
I (109) boot:  6 otadata          OTA data         01 00 003e0000 00002000
I (117) boot:  7 nvs_key          NVS keys         01 04 003e2000 00001000
I (124) boot: End of partition table
I (129) boot: Defaulting to factory image
I (133) esp_image: segment 0: paddr=00020020 vaddr=3c020020 size=04e60h ( 20064) map
I (145) esp_image: segment 1: paddr=00024e88 vaddr=3fc8a000 size=00c2ch (  3116) load
I (151) esp_image: segment 2: paddr=00025abc vaddr=40380000 size=09e64h ( 40548) load
I (167) esp_image: segment 3: paddr=0002f928 vaddr=50000010 size=00010h (    16) load
I (167) esp_image: segment 4: paddr=0002f940 vaddr=00000000 size=006d8h (  1752)
I (176) esp_image: segment 5: paddr=00030020 vaddr=42000020 size=11ef4h ( 73460) map
I (199) boot: Loaded app from partition at offset 0x20000
I (199) boot: Disabling RNG early entropy source...
I (211) cpu_start: Pro cpu up.
I (219) cpu_start: Pro cpu start user code
I (220) cpu_start: cpu freq: 80000000 Hz
I (220) cpu_start: Application information:
I (222) cpu_start: Project name:     linkify
I (227) cpu_start: App version:      0.1.0.15
I (232) cpu_start: Compile time:     Jul 12 2022 21:25:00
I (239) cpu_start: ELF file SHA256:  821786b3e1c20281...
ELF file not found. You need to build & flash the project before running 'monitor', and the binary on the device must match the one in the build directory exactly.
I (245) cpu_start: ESP-IDF:          v5.0-dev-3202-ga2d5041492-dirty
I (252) heap_init: Initializing. RAM available for dynamic allocation:
I (259) heap_init: At 3FC8BD60 len 000342A0 (208 KiB): DRAM
I (265) heap_init: At 3FCC0000 len 0001F060 (124 KiB): STACK/DRAM
I (272) heap_init: At 50000020 len 00001FE0 (7 KiB): RTCRAM
I (279) spi_flash: detected chip: generic
I (283) spi_flash: flash io: dio
I (298) sleep: Configure to isolate all GPIO pins in sleep state
I (298) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: 40, Light sleep: DISABLED
I (303) sleep: Disable automatic switching of GPIO sleep configuration
I (310) coexist: coexist rom version 9387209
I (315) cpu_start: Starting scheduler.
I (320) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, I (320) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, AI (320) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: 10, Light sleep: ENABI (320) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: 10, Light sleep: ENABI (320) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: 10, Light sleep: ENABLI (320) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: 10, Light sleep: ENABLED
I (320) sleep: Enable automatic switching of GPIO sleep configuration
I (4340) main: In main task 1 dummy 1
I (4340) main: In main task 1 dummy 1
I (4360) main: In main task 1 dummy 1
I (4360) main: In main task 1 dummy 1
I (4380) main: In main task 1 dummy 1
I (4380) main: In main task 2 dummy 2
I I (I (4400) main: In main task 3 dummy 3
I (4400) main: In main task 4 dummy 4
I (8400) main: In main task 1 dummy 1
I (8400) main: In main task 1 dummy 1
I (8420) main: In main task 1 dummy 1
I (8420) main: In main task 1 dummy 1
I (8440) main: In main task 1 dummy 1
I (8440) main: In main task 2 dummy 2
II I (8460) main: In main task 3 dummy 3
I (8460) main: In main task 4 dummy 4
I (12460) main: In main task 1 dummy 1
I (12460) main: In main task 1 dummy 1
I (12480) main: In main task 1 dummy 1
I (12480) main: In main task 1 dummy 1
I (12500) main: In main task 1 dummy 1
I (12500) main: In main task 2 dummy 2
I I (I (12520) main: In main task 3 dummy 3
I (12520) main: In main task 4 dummy 4
I (16520) main: In main task 1 dummy 1
I (16520) main: In main task 1 dummy 1
I (16540) main: In main task 1 dummy 1

Other items if possible

  • sdkconfig file (attach the sdkconfig file from your project folder)
  • elf file in the build folder (note this may contain all the code details and symbols of your project.)
    elf.zip
@espressif-bot espressif-bot added the Status: Opened Issue is new label Jul 12, 2022
@github-actions github-actions bot changed the title esp32c3: corrupted log output when light sleep is enabled esp32c3: corrupted log output when light sleep is enabled (IDFGH-7809) Jul 12, 2022
@igrr
Copy link
Member

igrr commented Jul 13, 2022

Hi @HiFiPhile, could you please check if #7341 (comment) helps in this case?

@HiFiPhile
Copy link
Contributor Author

I looked deeper this issue, it's a host side idf_monitor (or python upstream) issue, it's not #7341 (comment)

With my example, 4 groups of log are printed:

    while (1)
    {
            if(xTaskGetTickCount() - tLoop > pdMS_TO_TICKS(4000))
            {
                tLoop = xTaskGetTickCount();

                ESP_LOGI(TAG, "In main task 1 %s", "dummy 1");
                ESP_LOGI(TAG, "In main task 1 %s", "dummy 1");
                vTaskDelay(pdMS_TO_TICKS(20));
                ESP_LOGI(TAG, "In main task 1 %s", "dummy 1");
                ESP_LOGI(TAG, "In main task 1 %s", "dummy 1");
                vTaskDelay(pdMS_TO_TICKS(20));
                ESP_LOGI(TAG, "In main task 1 %s", "dummy 1");
                ESP_LOGI(TAG, "In main task 2 %s", "dummy 2");
                vTaskDelay(pdMS_TO_TICKS(20));
                ESP_LOGI(TAG, "In main task 3 %s", "dummy 3");
                ESP_LOGI(TAG, "In main task 4 %s", "dummy 4");

            }
            else
            {
                vTaskDelay(pdMS_TO_TICKS(250));
            }
    }

First 3 groups are separated by 10-20ms, last group is cutted by half with 250ms interval. In uart level there is no corruption.
image

So it means before entering light sleep there is no waiting for uart buffer flush.

I won't say this behavior is buggy, but it's better to add an option to flush uart log buffer before sleep.

What's interesting is the host side
I tried wireshark, tera term, hterm, all of them works perfectly !

It's only idf_monitor who repeat printing the same line if the message is cutted into multiples sections.

This comment is suspicious:

# Now we have the last part (incomplete line) in _last_line_part. By
# default we don't touch it and just wait for the arrival of the rest
# of the line. But after some time when we didn't received it we need
# to make a decision.

@dobairoland
Copy link
Collaborator

I have tried the attached project on Linux and it works perfectly well. It is possible that this is a Windows issue.

@esp-lis
Copy link
Collaborator

esp-lis commented Mar 8, 2025

@HiFiPhile In my local environment (Host: Windows 10 + PuTTY, Board: ESP32-C3 DevKitM-1 v1.0, esp-idf commit 94cfe394), I did not reproduce the issue. Below is my test code:

/*
 * SPDX-FileCopyrightText: 2010-2022 Espressif Systems (Shanghai) CO LTD
 *
 * SPDX-License-Identifier: CC0-1.0
 */

#include "freertos/FreeRTOS.h"
#include "freertos/event_groups.h"
#include "esp_log.h"
#include "esp_pm.h"

static const char *TAG = "Issue/9343";

static void idfgh_7809(void)
{
    int tLoop = 0;
    while (1)
    {
        if(xTaskGetTickCount() - tLoop > pdMS_TO_TICKS(4000))
        {
            tLoop = xTaskGetTickCount();

            ESP_LOGI(TAG, "In main task 1 %s", "dummy 1");
            ESP_LOGI(TAG, "In main task 1 %s", "dummy 1");
            vTaskDelay(pdMS_TO_TICKS(20));
            ESP_LOGI(TAG, "In main task 1 %s", "dummy 1");
            ESP_LOGI(TAG, "In main task 1 %s", "dummy 1");
            vTaskDelay(pdMS_TO_TICKS(20));
            ESP_LOGI(TAG, "In main task 1 %s", "dummy 1");
            ESP_LOGI(TAG, "In main task 2 %s", "dummy 2");
            vTaskDelay(pdMS_TO_TICKS(20));
            ESP_LOGI(TAG, "In main task 3 %s", "dummy 3");
            ESP_LOGI(TAG, "In main task 4 %s", "dummy 4");

        }
        else
        {
            vTaskDelay(pdMS_TO_TICKS(250));
        }
    }
}

void app_main(void)
{
#if CONFIG_PM_ENABLE
    // Configure dynamic frequency scaling:
    // maximum and minimum frequencies are set in sdkconfig,
    // automatic light sleep is enabled if tickless idle support is enabled.
    esp_pm_config_esp32c3_t pm_config = {
            .max_freq_mhz = CONFIG_EXAMPLE_MAX_CPU_FREQ_MHZ,
            .min_freq_mhz = CONFIG_EXAMPLE_MIN_CPU_FREQ_MHZ,
#if CONFIG_FREERTOS_USE_TICKLESS_IDLE
            .light_sleep_enable = true
#endif
    };
    ESP_ERROR_CHECK( esp_pm_configure(&pm_config) );
#endif // CONFIG_PM_ENABLE

    idfgh_7809();
}

@HiFiPhile
Copy link
Contributor Author

@esp-lis Thank you for looking at it. I haven't worked on the project recently, we can close the issue for now, if I met it again I'll come back.

@esp-lis
Copy link
Collaborator

esp-lis commented Mar 8, 2025

I won't say this behavior is buggy, but it's better to add an option to flush uart log buffer before sleep.

@HiFiPhile You can use fflush(stdout) and fsync(fileno(stdout)) at the application layer to force output of text logs.

If the UART module is not powered down during sleep (the implicit retention of UART Tx FIFO data during sleep ensures it is not lost), then there is no need to forcefully flush and clear the FIFO. This avoids missing sleep due to FIFO flushing.

At a UART baud rate of 115200, clearing a 128-byte Tx FIFO would take: (128 Byte x 8 bit/Byte) / 115200 bit/s x 1000 ms/s = 8.89  ms.

@espressif-bot espressif-bot added Status: Done Issue is done internally Resolution: Done Issue is done internally and removed Status: Opened Issue is new labels Mar 8, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants