search

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.51k stars 7.26k forks source link

More stack size used by `sscanf("0.01", "%lg", ...);` when input value is between `-0.1 and `0.1` (IDFGH-13820) #14672

Open DCSBL opened 1 week ago

DCSBL commented 1 week ago

Answers checklist.

IDF version.

5.2.2

Espressif SoC revision.

ESP32-C3

Operating System used.

macOS

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

None

Development Kit.

Custom board

Power Supply used.

USB

What is the expected behavior?

I expect the stack usage to be constant with same input values and chips.

What is the actual behavior?

Okay this one is weird. We got a stack overflow by some data that contained 0.0078. We found out that the value 0.0078 was given to cJSON_CreateNumber(). This worked all the time.

This function uses the sscanf(value, %lg, ...) function, and it turns out that this function uses much more stack memory for values in the range of 0.01 to 0.1 (also 0.001, 0.00001 and the negative variant).

I have no idea if this is expected, or that this can be called a bug.

The reason why I open an issue here is that we do not have this issue on products with an ESP32-WROOM-32E, it only happens on ESP32-C3 modules.

Steps to reproduce.

Use the code example below, based on hello_world example

Code

```c /* * SPDX-FileCopyrightText: 2010-2022 Espressif Systems (Shanghai) CO LTD * * SPDX-License-Identifier: CC0-1.0 */ #include #include #include "sdkconfig.h" #include "freertos/FreeRTOS.h" #include "freertos/task.h" #include "freertos/semphr.h" #include "esp_chip_info.h" #include "esp_flash.h" #include "esp_system.h" SemaphoreHandle_t sem = NULL; static void task(void *args) { const char* value = (const char*)args; printf("Value: %s\n", value); int start_water_mark = uxTaskGetStackHighWaterMark(NULL); printf("Start HWM: %d bytes\n", start_water_mark); double test = 0.0; sscanf(value, "%lg", &test); int end_water_mark = uxTaskGetStackHighWaterMark(NULL); printf("Result: %f\n", test); // Make sure value gets used and not optimized out printf("End HWM: %d bytes (%d)\n", end_water_mark, start_water_mark - end_water_mark); printf("\n"); xSemaphoreGive(sem); vTaskDelete(NULL); } void app_main(void) { printf("Hello world!\n"); /* Print chip information */ esp_chip_info_t chip_info; uint32_t flash_size; esp_chip_info(&chip_info); printf("This is %s chip with %d CPU core(s), %s%s%s%s, ", CONFIG_IDF_TARGET, chip_info.cores, (chip_info.features & CHIP_FEATURE_WIFI_BGN) ? "WiFi/" : "", (chip_info.features & CHIP_FEATURE_BT) ? "BT" : "", (chip_info.features & CHIP_FEATURE_BLE) ? "BLE" : "", (chip_info.features & CHIP_FEATURE_IEEE802154) ? ", 802.15.4 (Zigbee/Thread)" : ""); unsigned major_rev = chip_info.revision / 100; unsigned minor_rev = chip_info.revision % 100; printf("silicon revision v%d.%d, ", major_rev, minor_rev); if(esp_flash_get_size(NULL, &flash_size) != ESP_OK) { printf("Get flash size failed"); return; } printf("%" PRIu32 "MB %s flash\n", flash_size / (uint32_t)(1024 * 1024), (chip_info.features & CHIP_FEATURE_EMB_FLASH) ? "embedded" : "external"); printf("Minimum free heap size: %" PRIu32 " bytes\n", esp_get_minimum_free_heap_size()); printf("Starting test:\n"); const char* values[] = { "1", "2", "3", "4", "1000000", "0.1", "0.2", "0.5", "0.9", "0.10", "0.20", "0.50", "0.90", "0.01", "0.02", "0.05", "0.09", "0.001", "0.002", "0.005", "0.009", "0.000000000000001" "0.00000000000000001" "-1", "-0.1", "-0.01", "hello world", "", "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ1234567890", "123456789012345678901234567890123456789012345678901234567890", NULL }; sem = xSemaphoreCreateBinary(); xSemaphoreGive(sem); for (int i = 0; values[i] != NULL; i++) { xTaskCreate(&task, "task", 4096, (void*)values[i], 10, NULL); xSemaphoreTake(sem, portMAX_DELAY); } } ```

Debug Logs.

ESP32C3

```plain ESP-ROM:esp32c3-api1-20210207 Build:Feb 7 2021 rst:0x1 (POWERON),boot:0xf (SPI_FAST_FLASH_BOOT) SPIWP:0xee mode:DIO, clock div:1 load:0x3fcd5820,len:0x1738 load:0x403cc710,len:0xb9c load:0x403ce710,len:0x2e40 entry 0x403cc71a I (30) boot: ESP-IDF v5.2.2 2nd stage bootloader I (30) boot: compile time Oct 4 2024 16:27:38 I (30) boot: chip revision: v0.4 I (33) boot.esp32c3: SPI Speed : 80MHz I (38) boot.esp32c3: SPI Mode : DIO I (43) boot.esp32c3: SPI Flash Size : 2MB I (47) boot: Enabling RNG early entropy source... I (53) boot: Partition Table: I (56) boot: ## Label Usage Type ST Offset Length I (64) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (71) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (79) boot: 2 factory factory app 00 00 00010000 00100000 I (86) boot: End of partition table I (90) esp_image: segment 0: paddr=00010020 vaddr=3c020020 size=09660h ( 38496) map I (105) esp_image: segment 1: paddr=00019688 vaddr=3fc8ae00 size=0121ch ( 4636) load I (108) esp_image: segment 2: paddr=0001a8ac vaddr=40380000 size=0576ch ( 22380) load I (120) esp_image: segment 3: paddr=00020020 vaddr=42000020 size=1e22ch (123436) map I (143) esp_image: segment 4: paddr=0003e254 vaddr=4038576c size=055c4h ( 21956) load I (151) boot: Loaded app from partition at offset 0x10000 I (151) boot: Disabling RNG early entropy source... I (163) cpu_start: Unicore app I (172) cpu_start: Pro cpu start user code I (172) cpu_start: cpu freq: 160000000 Hz I (173) cpu_start: Application information: I (175) cpu_start: Project name: hello_world I (181) cpu_start: App version: v5.3.1-dirty I (186) cpu_start: Compile time: Oct 4 2024 16:27:36 I (192) cpu_start: ELF file SHA256: 33998ba0e... I (198) cpu_start: ESP-IDF: v5.2.2 I (202) cpu_start: Min chip rev: v0.3 I (207) cpu_start: Max chip rev: v1.99 I (212) cpu_start: Chip rev: v0.4 I (217) heap_init: Initializing. RAM available for dynamic allocation: I (224) heap_init: At 3FC8CEE0 len 00033120 (204 KiB): RAM I (230) heap_init: At 3FCC0000 len 0001C710 (113 KiB): Retention RAM I (237) heap_init: At 3FCDC710 len 00002950 (10 KiB): Retention RAM I (244) heap_init: At 50000010 len 00001FD8 (7 KiB): RTCRAM I (251) spi_flash: detected chip: generic I (255) spi_flash: flash io: dio W (259) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header. I (272) sleep: Configure to isolate all GPIO pins in sleep state I (279) sleep: Enable automatic switching of GPIO sleep configuration I (286) main_task: Started on CPU0 I (286) main_task: Calling app_main() Hello world! This is esp32c3 chip with 1 CPU core(s), WiFi/BLE, silicon revision v0.4, 2MB external flash Minimum free heap size: 328280 bytes Starting test: Value: 1 Start HWM: 2508 bytes Result: 1.000000 End HWM: 2508 bytes (0) Value: 2 Start HWM: 2508 bytes Result: 2.000000 End HWM: 2508 bytes (0) Value: 3 Start HWM: 2508 bytes Result: 3.000000 End HWM: 2508 bytes (0) Value: 4 Start HWM: 2508 bytes Result: 4.000000 End HWM: 2508 bytes (0) Value: 1000000 Start HWM: 2508 bytes Result: 1000000.000000 End HWM: 2508 bytes (0) Value: 0.1 Start HWM: 2508 bytes Result: 0.100000 End HWM: 2508 bytes (0) Value: 0.2 Start HWM: 2508 bytes Result: 0.200000 End HWM: 2508 bytes (0) Value: 0.5 Start HWM: 2508 bytes Result: 0.500000 End HWM: 2508 bytes (0) Value: 0.9 Start HWM: 2508 bytes Result: 0.900000 End HWM: 2508 bytes (0) Value: 0.10 Start HWM: 2508 bytes Result: 0.100000 End HWM: 2508 bytes (0) Value: 0.20 Start HWM: 2508 bytes Result: 0.200000 End HWM: 2508 bytes (0) Value: 0.50 Start HWM: 2508 bytes Result: 0.500000 End HWM: 2508 bytes (0) Value: 0.90 Start HWM: 2508 bytes Result: 0.900000 End HWM: 2508 bytes (0) Value: 0.01 Start HWM: 2508 bytes Result: 0.010000 End HWM: 1640 bytes (868) Value: 0.02 Start HWM: 2508 bytes Result: 0.020000 End HWM: 1640 bytes (868) Value: 0.05 Start HWM: 2508 bytes Result: 0.050000 End HWM: 1640 bytes (868) Value: 0.09 Start HWM: 2508 bytes Result: 0.090000 End HWM: 1640 bytes (868) Value: 0.001 Start HWM: 2508 bytes Result: 0.001000 End HWM: 1640 bytes (868) Value: 0.002 Start HWM: 2508 bytes Result: 0.002000 End HWM: 1640 bytes (868) Value: 0.005 Start HWM: 2508 bytes Result: 0.005000 End HWM: 1640 bytes (868) Value: 0.009 Start HWM: 2508 bytes Result: 0.009000 End HWM: 1640 bytes (868) Value: 0.0000000000000010.00000000000000001-1 Start HWM: 2508 bytes Result: 0.000000 End HWM: 1640 bytes (868) Value: -0.1 Start HWM: 2508 bytes Result: -0.100000 End HWM: 2508 bytes (0) Value: -0.01 Start HWM: 2508 bytes Result: -0.010000 End HWM: 1640 bytes (868) Value: hello world Start HWM: 2508 bytes Result: 0.000000 End HWM: 2508 bytes (0) Value: Start HWM: 2512 bytes Result: 0.000000 End HWM: 2512 bytes (0) Value: abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ1234567890 Start HWM: 2500 bytes Result: 0.000000 End HWM: 2500 bytes (0) Value: 123456789012345678901234567890123456789012345678901234567890 Start HWM: 2504 bytes Result: 123456789012345670356319606483911229676122426202597038751744.000000 End HWM: 2504 bytes (0) I (516) main_task: Returned from app_main() ```

ESP32

```plain I (13) boot: ESP-IDF v5.2.2 2nd stage bootloader I (13) boot: compile time Oct 4 2024 16:38:15 I (13) boot: Multicore bootloader I (16) boot: chip revision: v1.0 I (20) boot.esp32: SPI Speed : 40MHz I (25) boot.esp32: SPI Mode : DIO I (29) boot.esp32: SPI Flash Size : 2MB I (34) boot: Enabling RNG early entropy source... I (39) boot: Partition Table: I (43) boot: ## Label Usage Type ST Offset Length I (50) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (58) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (65) boot: 2 factory factory app 00 00 00010000 00100000 I (73) boot: End of partition table I (77) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=09ec4h ( 40644) map I (99) esp_image: segment 1: paddr=00019eec vaddr=3ffb0000 size=0220ch ( 8716) load I (103) esp_image: segment 2: paddr=0001c100 vaddr=40080000 size=03f18h ( 16152) load I (111) esp_image: segment 3: paddr=00020020 vaddr=400d0020 size=1c9c0h (117184) map I (154) esp_image: segment 4: paddr=0003c9e8 vaddr=40083f18 size=088ech ( 35052) load I (174) boot: Loaded app from partition at offset 0x10000 I (174) boot: Disabling RNG early entropy source... I (185) cpu_start: Multicore app I (194) cpu_start: Pro cpu start user code I (194) cpu_start: cpu freq: 160000000 Hz I (194) cpu_start: Application information: I (197) cpu_start: Project name: hello_world I (202) cpu_start: App version: v5.3.1-dirty I (208) cpu_start: Compile time: Oct 4 2024 16:37:54 I (214) cpu_start: ELF file SHA256: c8437bf82... I (219) cpu_start: ESP-IDF: v5.2.2 I (224) cpu_start: Min chip rev: v0.0 I (229) cpu_start: Max chip rev: v3.99 I (234) cpu_start: Chip rev: v1.0 I (239) heap_init: Initializing. RAM available for dynamic allocation: I (246) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM I (252) heap_init: At 3FFB2AD0 len 0002D530 (181 KiB): DRAM I (258) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (264) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (271) heap_init: At 4008C804 len 000137FC (77 KiB): IRAM I (278) spi_flash: detected chip: generic I (282) spi_flash: flash io: dio W (285) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header. I (299) main_task: Started on CPU0 I (309) main_task: Calling app_main() Hello world! This is esp32 chip with 2 CPU core(s), WiFi/BTBLE, silicon revision v1.0, 2MB external flash Minimum free heap size: 300876 bytes Starting test: Value: 1 Start HWM: 2436 bytes Result: 1.000000 End HWM: 2436 bytes (0) Value: 2 Start HWM: 2432 bytes Result: 2.000000 End HWM: 2432 bytes (0) Value: 3 Start HWM: 2444 bytes Result: 3.000000 End HWM: 2444 bytes (0) Value: 4 Start HWM: 2432 bytes Result: 4.000000 End HWM: 2432 bytes (0) Value: 1000000 Start HWM: 2444 bytes Result: 1000000.000000 End HWM: 2444 bytes (0) Value: 0.1 Start HWM: 2444 bytes Result: 0.100000 End HWM: 2444 bytes (0) Value: 0.2 Start HWM: 2440 bytes Result: 0.200000 End HWM: 2440 bytes (0) Value: 0.5 Start HWM: 2444 bytes Result: 0.500000 End HWM: 2444 bytes (0) Value: 0.9 Start HWM: 2444 bytes Result: 0.900000 End HWM: 2444 bytes (0) Value: 0.10 Start HWM: 2432 bytes Result: 0.100000 End HWM: 2432 bytes (0) Value: 0.20 Start HWM: 2436 bytes Result: 0.200000 End HWM: 2436 bytes (0) Value: 0.50 Start HWM: 2444 bytes Result: 0.500000 End HWM: 2444 bytes (0) Value: 0.90 Start HWM: 2444 bytes Result: 0.900000 End HWM: 2444 bytes (0) Value: 0.01 Start HWM: 2440 bytes Result: 0.010000 End HWM: 1784 bytes (656) Value: 0.02 Start HWM: 2444 bytes Result: 0.020000 End HWM: 1788 bytes (656) Value: 0.05 Start HWM: 2444 bytes Result: 0.050000 End HWM: 1788 bytes (656) Value: 0.09 Start HWM: 2440 bytes Result: 0.090000 End HWM: 1784 bytes (656) Value: 0.001 Start HWM: 2444 bytes Result: 0.001000 End HWM: 1788 bytes (656) Value: 0.002 Start HWM: 2444 bytes Result: 0.002000 End HWM: 1788 bytes (656) Value: 0.005 Start HWM: 2444 bytes Result: 0.005000 End HWM: 1788 bytes (656) Value: 0.009 Start HWM: 2440 bytes Result: 0.009000 End HWM: 1784 bytes (656) Value: 0.0000000000000010.00000000000000001-1 Start HWM: 2444 bytes Result: 0.000000 End HWM: 1788 bytes (656) Value: -0.1 Start HWM: 2444 bytes Result: -0.100000 End HWM: 2444 bytes (0) Value: -0.01 Start HWM: 2440 bytes Result: -0.010000 End HWM: 1784 bytes (656) Value: hello world Start HWM: 2432 bytes Result: 0.000000 End HWM: 2432 bytes (0) Value: Start HWM: 2436 bytes Result: 0.000000 End HWM: 2436 bytes (0) Value: abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ1234567890 Start HWM: 2440 bytes Result: 0.000000 End HWM: 2440 bytes (0) Value: 123456789012345678901234567890123456789012345678901234567890 Start HWM: 2444 bytes Result: 123456789012345670356319606483911229676122426202597038751744.000000 End HWM: 2316 bytes (128) I (529) main_task: Returned from app_main() ```

More Information.

We have fixed this issue by increasing the stack size and adding some extra validation steps.

Lapshin commented 2 days ago

I did not get this statement:

The reason why I open an issue here is that we do not have this issue on products with an ESP32-WROOM-32E, it only happens on ESP32-C3 modules.

What issue happens on esp32c3 but not for esp32?

Let me summarize the data you got:

Click to expand the table | Result | ESP32 | ESP32C3 | |-----------------:|--------------------:|----------------:| | 1.000000 | 2436 (0) | 2508 (0) | | 2.000000 | 2432 (0) | 2508 (0) | | 3.000000 | 2444 (0) | 2508 (0) | | 4.000000 | 2432 (0) | 2508 (0) | | 1000000.000000 | 2444 (0) | 2508 (0) | | 0.100000 | 2444 (0) | 2508 (0) | | 0.200000 | 2440 (0) | 2508 (0) | | 0.500000 | 2444 (0) | 2508 (0) | | 0.900000 | 2444 (0) | 2508 (0) | | 0.100000 | 2432 (0) | 2508 (0) | | 0.200000 | 2436 (0) | 2508 (0) | | 0.500000 | 2444 (0) | 2508 (0) | | 0.900000 | 2444 (0) | 2508 (0) | | 0.010000 | 1784 (656) | 1640 (868) | | 0.020000 | 1788 (656) | 1640 (868) | | 0.050000 | 1788 (656) | 1640 (868) | | 0.090000 | 1784 (656) | 1640 (868) | | 0.001000 | 1788 (656) | 1640 (868) | | 0.002000 | 1788 (656) | 1640 (868) | | 0.005000 | 1788 (656) | 1640 (868) | | 0.009000 | 1784 (656) | 1640 (868) | | -0.100000 | 2444 (0) | 2508 (0) | | -0.010000 | 1784 (656) | 1640 (868) |

As you can see, stack usage correlates across chips for the same values.

I expect the stack usage to be constant with same input values and chips.

Please don't forget that every call produces stack frame that consist of return address, saved registers, etc... The size of the stack frame cannot be the same for every architecture because each architecture has a different number of registers to save. So, for more nested calls you will see more difference in stack usage between architectures. (esp32 is xtensa; esp32c3 is riscv)

@DCSBL , in case my comment does not resolve your expectations or issue you have, could you please give more details that helps me to understand what's wrong?