when I run nimble task, task wdt will often abort at nvs operate (IDFGH-8591)

luacerbb commented 2 years ago

Answers checklist.

[X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

4.1.3

Operating System used.

Windows

How did you build your project?

Command line with idf.py

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

CMD

Development Kit.

ESP32-DevKitC-V4_

Power Supply used.

External 5V

What is the expected behavior?

system can run normal,when i use nimble task and nvs operation

What is the actual behavior?

when I run nimble task, task wdt will often abort at nvs operate,I think nvs operaton abnormal caused by stopping nimble task

Steps to reproduce.

//when I stop nimble task, the other task will write nvs data to flash, 1、 start nimble task to recv wifi ssid and password 2、when use wifi ssid and password connected ap success ,I will save datas to flash by nvs operation. 3 、stop nimble task

Debug Logs.

GAP procedure initiated: terminate connection; conn_handle=0 hci_reason=19
ble_hs_hci_cmd_send: ogf=0x01 ocf=0x0006 len=3
0x06 0x04 0x03 0x00 0x00 0x13 
E (38350) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (38350) task_wdt:  - IDLE0 (CPU 0)
E (38350) task_wdt: Tasks currently running:
E (38350) task_wdt: CPU 0: main_task
E (38350) task_wdt: CPU 1: IDLE1
E (38350) task_wdt: Aborting.
abort() was called at PC 0x400d4d24 on core 0
0x400d4d24: task_wdt_isr at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/esp32/task_wdt.c:178 (discriminator 1)

ELF file SHA256: db2119b463bbbdc1

Backtrace: 0x4008f29c:0x3ffbe530 0x4008f685:0x3ffbe550 0x400d4d24:0x3ffbe570 0x400829b1:0x3ffbe590 0x4008a201:0x3ffdac90 0x4008b0d6:0x3ffdacb0 0x4008f1b5:0x3ffdacd0 0x4008af3d:0x3ffdacf0 0x4008b0c1:0x3ffdad20 0x4013b339:0x3ffdad40 0x4013a129:0x3ffdad60 0x4013a835:0x3ffdad80 0x40138f4f:0x3ffdade0 0x40139725:0x3ffdae30 0x40139c91:0x3ffdae90 0x401386b3:0x3ffdaeb0 0x4012ca0d:0x3ffdaef0 0x400de875:0x3ffdaf10 0x400e091b:0x3ffdaf70 0x400d85fc:0x3ffdb000 0x400d8dbb:0x3ffdb0e0 0x400db4b7:0x3ffdb2d0
0x4008f29c: invoke_abort at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/esp32/panic.c:159

0x4008f685: abort at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/esp32/panic.c:174

0x400d4d24: task_wdt_isr at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/esp32/task_wdt.c:178 (discriminator 1)

0x400829b1: _xt_lowint1 at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/freertos/xtensa_vectors.S:1153

0x4008a201: spi_flash_disable_interrupts_caches_and_other_cpu at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/spi_flash/cache_utils.c:143 (discriminator 1)

0x4008b0d6: spi1_start at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/spi_flash/spi_flash_os_func_app.c:61

0x4008f1b5: spiflash_start at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/spi_flash/esp_flash_api.c:78

0x4008af3d: esp_flash_read at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/spi_flash/esp_flash_api.c:547

0x4008b0c1: spi_flash_read at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/spi_flash/esp_flash_api.c:763

0x4013b339: nvs::nvs_flash_read(unsigned int, void*, unsigned int) at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/nvs_flash/src/nvs_ops.cpp:70

0x4013a129: nvs::Page::readEntry(unsigned int, nvs::Item&) const at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/nvs_flash/src/nvs_page.cpp:772

0x4013a835: nvs::Page::findItem(unsigned char, nvs::ItemType, char const*, unsigned int&, nvs::Item&, unsigned char, nvs::VerOffset) at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/nvs_flash/src/nvs_page.cpp:816
 (inlined by) nvs::Page::findItem(unsigned char, nvs::ItemType, char const*, unsigned int&, nvs::Item&, unsigned char, nvs::VerOffset) at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/nvs_flash/src/nvs_page.cpp:779

0x40138f4f: nvs::Storage::findItem(unsigned char, nvs::ItemType, char const*, nvs::Page*&, nvs::Item&, unsigned char, nvs::VerOffset) at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/nvs_flash/src/nvs_storage.cpp:140

0x40139725: nvs::Storage::eraseItem(unsigned char, nvs::ItemType, char const*) at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/nvs_flash/src/nvs_storage.cpp:582

0x40139c91: nvs::NVSHandleSimple::erase_item(char const*) at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/nvs_flash/src/nvs_storage.hpp:96
 (inlined by) ?? at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/nvs_flash/src/nvs_handle_simple.cpp:81
 (inlined by) nvs::NVSHandleSimple::erase_item(char const*) at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/nvs_flash/src/nvs_handle_simple.cpp:76

0x401386b3: nvs_erase_key at /mnt/hgfs/Project/gate_code/esp-idf-v4.1.3/components/nvs_flash/src/nvs_api.cpp:319

0x4012ca0d: HAL_Kv_Del at /mnt/hgfs/SUB_PROJECT/tmp_ver_switch/build/../components/ali_sdk/wrappers/freertos/HAL_KV.c:274

0x400de875: _deal_subdev_info_store at /mnt/hgfs/SUB_PROJECT/tmp_ver_switch/build/../main/bd_common.c:568
 (inlined by) bd_common_nvs_op at /mnt/hgfs/SUB_PROJECT/tmp_ver_switch/build/../main/bd_common.c:1134

0x400e091b: bd_comm_del_local_all_subdev_info at /mnt/hgfs/SUB_PROJECT/tmp_ver_switch/build/../main/bd_common.c:2939

0x400d85fc: _bd_app_dev_info_update at /mnt/hgfs/SUB_PROJECT/tmp_ver_switch/build/../main/main.c:418

0x400d8dbb: _bd_app_parse_property at /mnt/hgfs/SUB_PROJECT/tmp_ver_switch/build/../main/main.c:752

0x400db4b7: _app_main_task at /mnt/hgfs/SUB_PROJECT/tmp_ver_switch/build/../main/main.c:3338

More Information.

No response

chipweinberger commented 2 years ago

Is there a reason you are using v4.1.3?

v4.4.2 is much newer! and it's usually pretty minimal changes to upgrade.

luacerbb commented 2 years ago

Is there a reason you are using v4.1.3?

v4.4.2 is much newer! and it's usually pretty minimal changes to upgrade. Our product is developed based on 4.1. If we want to change it to version 4.4, it will take a lot of time to modify the adaptation interface and test. Please help me to see what causes this situation, thank you

chipweinberger commented 2 years ago

There was a similar issue I filed, that was fixed in v4.4.2

chipweinberger commented 2 years ago

https://github.com/espressif/esp-idf/issues/9155

luacerbb commented 2 years ago

I try to run nimble task in v4.4.2,it work well.but I find the v4.4.2 will consume more ram than v4.1.3. I just test hello world example. V4.4.2 Total sizes: Used static DRAM: 11312 bytes ( 169424 remain, 6.3% used) .data size: 9024 bytes .bss size: 2288 bytes Used static IRAM: 45790 bytes ( 85282 remain, 34.9% used) .text size: 44763 bytes .vectors size: 1027 bytes Used Flash size : 115423 bytes .text : 84459 bytes .rodata : 30708 bytes Total image size: 170237 bytes (.bin may be padded larger)

V4.1.3 Total sizes: DRAM .data size: 8248 bytes DRAM .bss size: 2056 bytes Used static DRAM: 10304 bytes ( 170432 available, 5.7% used) Used static IRAM: 40459 bytes ( 90613 available, 30.9% used) Flash code: 80043 bytes Flash rodata: 23304 bytes Total image size:~ 152054 bytes (.bin may be padded larger)

we can see v4.4.2 will consume more than 7k bytes. Can optimize ram usage in v4.4.2?

AxelLin commented 1 year ago

I try to run nimble task in v4.4.2,it work well.but I find the v4.4.2 will consume more ram than v4.1.3.

https://github.com/espressif/esp-idf/issues/7906 The memory issue should be fixed by v4.4.4.

luacerbb commented 1 year ago

There was a similar issue I filed, that was fixed in v4.4.2

but in v4.4.3,it abort again when I stop ble and operate flash. 14:11:24:18 [dbg] _bd_ble_stop(1328): ble stop E (108017) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time: E (108017) task_wdt: - IDLE (CPU 0) E (108017) task_wdt: Tasks currently running: E (108017) task_wdt: CPU 0: main_task E (108017) task_wdt: CPU 1: IDLE E (108017) task_wdt: Aborting.

abort() was called at PC 0x4013bac0 on core 0 0x4013bac0: task_wdt_isr at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/esp_system/task_wdt.c:176 (discriminator 3)

Backtrace: 0x40081c5a:0x3ffbe870 0x40091135:0x3ffbe890 0x400972ce:0x3ffbe8b0 0x4013bac0:0x3ffbe920 0x40082d75:0x3ffbe940 0x4008b5b3:0x3ffdce20 0x4008c5ad:0x3ffdce50 0x4008c5b7:0x3ffdce70 0x4008fd1d:0x3ffdce90 0x4008c189:0x3ffdceb0 0x4013856f:0x3ffdcef0 0x40139d32:0x3ffdcf20 0x401aeb65:0x3ffdcf40 0x4013a7ce:0x3ffdcf60 0x40138fa7:0x3ffdcfc0 0x40139729:0x3ffdd010 0x40139cc9:0x3ffdd070 0x4013897b:0x3ffdd090 0x4012b809:0x3ffdd0c0 0x400df2ca:0x3ffdd0e0 0x400e134f:0x3ffdd150 0x400d89fe:0x3ffdd1e0 0x400d94cf:0x3ffdd2d0 0x400dbc3c:0x3ffdd4f0 0x40081c5a: panic_abort at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/esp_system/panic.c:402

0x40091135: esp_system_abort at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/esp_system/esp_system.c:128

0x400972ce: abort at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/newlib/abort.c:46

0x4013bac0: task_wdt_isr at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/esp_system/task_wdt.c:176 (discriminator 3)

0x40082d75: _xt_lowint1 at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/freertos/port/xtensa/xtensa_vectors.S:1111

0x4008b5b3: spi_flash_disable_interrupts_caches_and_other_cpu at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/spi_flash/cache_utils.c:167 (discriminator 1)

0x4008c5ad: cache_disable at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/spi_flash/spi_flash_os_func_app.c:70

0x4008c5b7: spi1_start at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/spi_flash/spi_flash_os_func_app.c:99

0x4008fd1d: spiflash_start_default at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/spi_flash/esp_flash_api.c:128

0x4008c189: esp_flash_read at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/spi_flash/esp_flash_api.c:821

0x4013856f: esp_partition_read at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/spi_flash/partition.c:424

0x40139d32: nvs::NVSPartition::read(unsigned int, void, unsigned int) at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/nvs_flash/src/nvs_partition.cpp:45 (inlined by) nvs::NVSPartition::read(unsigned int, void, unsigned int) at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/nvs_flash/src/nvs_partition.cpp:39

0x401aeb65: nvs::Page::readEntry(unsigned int, nvs::Item&) const at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/nvs_flash/src/nvs_page.cpp:879

0x4013a7ce: nvs::Page::findItem(unsigned char, nvs::ItemType, char const, unsigned int&, nvs::Item&, unsigned char, nvs::VerOffset) at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/nvs_flash/src/nvs_page.cpp:929 (inlined by) nvs::Page::findItem(unsigned char, nvs::ItemType, char const, unsigned int&, nvs::Item&, unsigned char, nvs::VerOffset) at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/nvs_flash/src/nvs_page.cpp:886

0x40138fa7: nvs::Storage::findItem(unsigned char, nvs::ItemType, char const, nvs::Page&, nvs::Item&, unsigned char, nvs::VerOffset) at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/nvs_flash/src/nvs_storage.cpp:161

0x40139729: nvs::Storage::eraseItem(unsigned char, nvs::ItemType, char const*) at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/nvs_flash/src/nvs_storage.cpp:619

0x40139cc9: nvs::Storage::eraseItem(unsigned char, char const) at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/nvs_flash/src/nvs_storage.hpp:98 (inlined by) nvs::NVSHandleSimple::erase_item(char const) at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/nvs_flash/src/nvs_handle_simple.cpp:81 (inlined by) nvs::NVSHandleSimple::erase_item(char const*) at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/nvs_flash/src/nvs_handle_simple.cpp:76

0x4013897b: nvs_erase_key at /mnt/hgfs/SUB_PROJECT/esp-idf-v4.4.3/components/nvs_flash/src/nvs_api.cpp:322

0x4012b809: HAL_Kv_Del at /mnt/hgfs/HWG004WRF/build/../components/ali_sdk/wrappers/freertos/HAL_KV.c:274

0x400df2ca: _deal_subdev_info_store at /mnt/hgfs/HWG004WRF/build/../main/bd_common.c:573 (inlined by) bd_common_nvs_op at /mnt/hgfs/HWG004WRF/build/../main/bd_common.c:1144

0x400e134f: bd_comm_del_local_all_subdev_info at /mnt/hgfs/HWG004WRF/build/../main/bd_common.c:2955

0x400d89fe: _bd_app_dev_info_update at /mnt/hgfs/HWG004WRF/build/../main/main.c:425

0x400d94cf: _bd_app_parse_desired_reply at /mnt/hgfs/HWG004WRF/build/../main/main.c:1353

0x400dbc3c: _app_main_task at /mnt/hgfs/HWG004WRF/build/../main/main.c:3455

luacerbb commented 1 year ago

I try to run nimble task in v4.4.2,it work well.but I find the v4.4.2 will consume more ram than v4.1.3.

7906 The memory issue should be fixed by v4.4.4.

ok,I will try

espressif / esp-idf