search

espressif / esp-adf

Espressif Audio Development Framework
Other
1.55k stars 685 forks source link

Crash in pvmp3_polyphase_filter_window_c (AUD-4619) #1003

Closed espradio closed 1 year ago

espradio commented 1 year ago

Found a very rare crash with IDF SDK 5.1. Very rare to reproduce.

mp3 info, sample_rates=44100, bits=16, ch=2
Guru Meditation Error: Core  0 panic'ed (LoadStoreError). Exception was unhandled.

Core  0 register dump:
PC      : 0x401ceac2  PS      : 0x00060430  A0      : 0x8013dbb7  A1      : 0x3ffcd730
0x401ceac2: pvmp3_polyphase_filter_window_c at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_polyphase_filter_window.cpp:200

A2      : 0x3f8ce8f0  A3      : 0x3fa826ec  A4      : 0x8013dbb8  A5      : 0x3f58b890
A6      : 0x00000d6b  A7      : 0x3ff795c8  A8      : 0x00000000  A9      : 0x3f41c658
A10     : 0x3f8ced90  A11     : 0x3f8ced50  A12     : 0x3f8ce990  A13     : 0x3f8ce950
A14     : 0x00000001  A15     : 0x00000040  SAR     : 0x0000001f  EXCCAUSE: 0x00000003
EXCVADDR: 0x3f58b890  LBEG    : 0x40143a44  LEND    : 0x40143a5c  LCOUNT  : 0x00000000
0x40143a44: pvmp3_equalizer at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_equalizer.cpp:341 (discriminator 3)

0x40143a5c: pvmp3_equalizer at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_equalizer.cpp:351

Backtrace: 0x401ceabf:0x3ffcd730 0x4013dbb4:0x3ffcd770 0x4013c14d:0x3ffcd7b0 0x4013814c:0x3ffcd850 0x40138355:0x3ffcd8f0 0x40132896:0x3ffcd910 0x40132a56:0x3ffcd940 0x40097a45:0x3ffcd970
0x401ceabf: pvmp3_polyphase_filter_window_c at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_polyphase_filter_window.cpp:125

0x4013dbb4: pvmp3_poly_phase_synthesis at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/esp_opt/xtensa_asm/xtensa_esp32/pvmp3_polyphase_filter_window_asm.h:109
 (inlined by) pvmp3_poly_phase_synthesis at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_poly_phase_synthesis.cpp:173

0x4013c14d: pvmp3_framedecoder at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_framedecoder.cpp:497 (discriminator 2)

0x4013814c: mp3_decoder_process at /builds/adf/esp-adf-libs-source/esp_processing/esp-wrapper/mp3_decoder.c:408

0x40138355: _mp3_decoder_process at /builds/adf/esp-adf-libs-source/esp_processing/esp-wrapper/mp3_decoder.c:496

0x40132896: audio_element_process_running at /export/iradio/esp-adf/components/audio_pipeline/audio_element.c:336

0x40132a56: audio_element_task at /export/iradio/esp-adf/components/audio_pipeline/audio_element.c:483

0x40097a45: vPortTaskWrapper at /export/iradio/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

esp-adf-libs's verion

commit 5d98bdac84ad9ffbbf87bb91c70486d7d11c912e (HEAD -> master, origin/master, origin/HEAD)
Merge: 91bdc15 e20512f
Author: Jason-mao <maojianxin@espressif.com>
Date:   Wed May 17 10:56:37 2023 +0800

    Merge branch 'bugfix/resample_multi_channel_audio_have_noise' into 'master'

    Fix a bug that resample multi channel audio have noise

    See merge request adf/esp-adf-libs!218
espradio commented 1 year ago

Hi Any update on this?

hakuna1995 commented 1 year ago

Hi, Can you give me more information (like your ADF commit id, IDF commit id, test code, sdkconfig) to help me recurrent this bug.

espradio commented 1 year ago

ADF commit id commit 5d98bdac84ad9ffbbf87bb91c70486d7d11c912e (HEAD -> master, origin/master, origin/HEAD) Merge: 91bdc15 e20512f Author: Jason-mao maojianxin@espressif.com Date: Wed May 17 10:56:37 2023 +0800

Merge branch 'bugfix/resample_multi_channel_audio_have_noise' into 'master'

Fix a bug that resample multi channel audio have noise

See merge request adf/esp-adf-libs!218

, IDF commit id,

commit fd5e03b22112d2762f3300c311df97a2d886e7c1 (origin/release/v4.4) Merge: c25d92074e 1c2e8f41f3 Author: Jiang Jiang Jian jack@espressif.com Date: Fri May 26 11:15:27 2023 +0800

Merge branch 'bugfix/fix_some_esp32c3_s3_ble_bugs_230422_4.4' into 'release/v4.4'

Fixed some ESP32C3/S3 BLE bugs 23-04-22(backport v4.4)

See merge request espressif/esp-idf!23354

It is WROVER module with external power supply and custom application.

hakuna1995 commented 1 year ago

Hi, I suspect it was caused by insufficient task stacks, or perhaps sdkconfig was not configured properly. Can you give sdkconfig to me and i can check it. It would be best if you could give test music to me.

espradio commented 1 year ago

Hi,

    mp3_decoder_cfg_t mp3_cfg = DEFAULT_MP3_DECODER_CONFIG();
    mp3_cfg.out_rb_size = 64 * 1024;
    mp3_cfg.task_prio = 5
    mp3_cfg.task_core = tskNO_AFFINITY;
    mp3_cfg.stack_in_ext = false;
    ctx->mp3_decoder = mp3_decoder_init(&mp3_cfg);
    if (ctx->mp3_decoder == NULL)
        goto err;

# System

CONFIG_MEMMAP_SMP=y
CONFIG_FREERTOS_UNICORE=n
CONFIG_FREERTOS_HZ=1000

CONFIG_ESP_INT_WDT=n
CONFIG_ESP_TASK_WDT=n

CONFIG_LWIP_ETHARP_TRUST_IP_MAC=n

CONFIG_LWIP_USE_ONLY_LWIP_SELECT=y

CONFIG_SPIRAM_ALLOW_BSS_SEG_EXTERNAL_MEMORY=y
CONFIG_SPIRAM_ALLOW_NOINIT_SEG_EXTERNAL_MEMORY=y

# RTOS
CONFIG_FREERTOS_VTASKLIST_INCLUDE_COREID=y
CONFIG_FREERTOS_GENERATE_RUN_TIME_STATS=y

# Release build (uncomment following)
CONFIG_BOOTLOADER_LOG_LEVEL_WARN=y
CONFIG_LOG_DEFAULT_LEVEL_WARN=y
CONFIG_LOG_COLORS=n

# Memory optimization
CONFIG_LWIP_IPV6=n
CONFIG_WIFI_LWIP_ALLOCATION_FROM_SPIRAM_FIRST=y
CONFIG_BT_ALLOCATION_FROM_SPIRAM_FIRST=y
CONFIG_MBEDTLS_EXTERNAL_MEM_ALLOC=y
CONFIG_SPIRAM_MALLOC_ALWAYSINTERNAL=0
CONFIG_SPIRAM_MALLOC_RESERVE_INTERNAL=65536

# BT
CONFIG_BT_ENABLED=y
CONFIG_BTDM_CTRL_MODE_BLE_ONLY=n
CONFIG_BTDM_CTRL_MODE_BR_EDR_ONLY=y
CONFIG_BTDM_CTRL_MODE_BTDM=n
CONFIG_BT_BLE_ENABLED=n
CONFIG_BT_BLUEDROID_ENABLED=y
CONFIG_BT_CLASSIC_ENABLED=y
CONFIG_BT_A2DP_ENABLE=y
CONFIG_BTDM_CTRL_PINNED_TO_CORE_1=y
CONFIG_BTDM_CTRL_PINNED_TO_CORE=1
CONFIG_BT_BLUEDROID_PINNED_TO_CORE_1=y
CONFIG_BT_BLUEDROID_PINNED_TO_CORE=1
CONFIG_BT_BTC_TASK_STACK_SIZE=3072
CONFIG_BT_BLUEDROID_MEM_DEBUG=n
CONFIG_A2DP_SINK_ENABLE=n
CONFIG_BT_STACK_NO_LOG=n
CONFIG_BT_BLE_DYNAMIC_ENV_MEMORY=n

# WIFI Rx perf improvement
CONFIG_ESP32_WIFI_STATIC_RX_BUFFER_NUM=16
CONFIG_ESP32_WIFI_DYNAMIC_RX_BUFFER_NUM=128
CONFIG_ESP32_WIFI_DYNAMIC_TX_BUFFER_NUM=128
CONFIG_ESP32_WIFI_STATIC_TX_BUFFER_NUM=16
CONFIG_ESP32_WIFI_AMPDU_TX_ENABLED=y
CONFIG_ESP32_WIFI_TX_BA_WIN=32
CONFIG_ESP32_WIFI_AMPDU_RX_ENABLED=y
CONFIG_ESP32_WIFI_RX_BA_WIN=32

# LWIP Rx perf improvement
CONFIG_LWIP_TCP_SND_BUF_DEFAULT=65534
CONFIG_LWIP_TCP_WND_DEFAULT=65534
CONFIG_LWIP_TCP_RECVMBOX_SIZE=64
CONFIG_LWIP_UDP_RECVMBOX_SIZE=64
CONFIG_LWIP_TCPIP_RECVMBOX_SIZE=64

# WIFI + BT
CONFIG_ESP32_WIFI_SW_COEXIST_ENABLE=y

# CPU
CONFIG_ESP32_DEFAULT_CPU_FREQ_240=y
CONFIG_ESP32_DEFAULT_CPU_FREQ_MHZ=240
CONFIG_ESP32_REV_MIN_3=y
CONFIG_ESP32_REV_MIN=3

# SPIRAM
CONFIG_ESP32_SPIRAM_SUPPORT=y
CONFIG_SPIRAM_BOOT_INIT=y

# Flash
CONFIG_ESPTOOLPY_FLASHMODE_QIO=y
CONFIG_ESPTOOLPY_BAUD_2MB=y
CONFIG_ESPTOOLPY_FLASHFREQ_80M=y
CONFIG_ESPTOOLPY_FLASHSIZE_4MB=y

# Partition
CONFIG_PARTITION_TABLE_CUSTOM=y
CONFIG_PARTITION_TABLE_CUSTOM_FILENAME="partitions.csv"
CONFIG_PARTITION_TABLE_FILENAME="partitions.csv"

# TLS
CONFIG_ESP_TLS_INSECURE=y
CONFIG_ESP_TLS_SKIP_SERVER_CERT_VERIFY=y
hakuna1995 commented 1 year ago

Hi, Make sure selected the CONFIG_SPIRAM_BOOT_INIT and CONFIG_SPIRAM_ALLOW_STACK_EXTERNAL_MEMORY by make menuconfig. And "mp3_cfg.task_stack" can set a bit larger.

espradio commented 1 year ago

Hi, There is enough memory in internal RAM (> 80KB) hence CONFIG_SPIRAM_ALLOW_STACK_EXTERNAL_MEMORY not selected. If task_stack running low then OS will be report that, May I know how it is connected panic? Are you able to figure out something from crashdump? Is it invalid access of memory?

hakuna1995 commented 1 year ago

I have encountered similar problems before. Sometimes if task_stack running low then OS will not report that, it will experience inexplicable crashes in codec LIB. So if encountered such problems, I usually check whether selected "CONFIG_SPIRAM_ALLOW_STACK_EXTERNAL_MEMORY", if already choose it, i will set the "task_stack" a bit larger. I guess it is invalid access of memory.

jason-mao commented 1 year ago

@espradio How can I reproduce your issue?

espradio commented 1 year ago

I could see this issue only with mp3 playback with IDF 5.1(not with 4.4) with custom application.

hakuna1995 commented 1 year ago

I could see this issue only with mp3 playback with IDF 5.1(not with 4.4) with custom application.

Can you give the commit id of IDF v5.1. The commit id about IDF you give before is v4.4 .

espradio commented 1 year ago

commit 4bc762621db30f253742bd3c439f80500fda0fb0 (origin/release/v5.1) Merge: 42592552b5 c5e580e522 Author: Jiang Jiang Jian jack@espressif.com Date: Sat Jun 3 08:43:09 2023 +0800

Merge branch 'bugfix/fix_bleqabr23_222_v5.1' into 'release/v5.1'

Revert "bluedroid: report disconnect event after BLE link closed" (backport 5.1)

See merge request espressif/esp-idf!24036
hakuna1995 commented 1 year ago

You can also check your internal memory to see if it is always sufficient.

espradio commented 1 year ago

Yes. Internal memory is available > 80KB

hakuna1995 commented 1 year ago

Can you provide test music and complete log information from the moment of power on？I also want to know the complete chip model(eg. ESP32-WROVER-E).

espradio commented 1 year ago

@hakuna1995 It is not specific a music, it comes with a lot mp3 streams. One music stream is https://sp14.instainternet.com/8050/stream Also, it is coming only with v5.1 IDF branch(which is stable IDF branch)


(gdb) info reg
pc             0x401da2e3          0x401da2e3 <pvmp3_polyphase_filter_window_c(int32*, int16*, int32, int32 const*)+411>
lbeg           0x40143c18          1075067928
lend           0x40143c30          1075067952
lcount         0x0                 0
sar            0x1f                31
ps             0x60c20             396320
threadptr      <unavailable>
br             <unavailable>
scompare1      <unavailable>
acclo          <unavailable>
acchi          <unavailable>
m0             <unavailable>
m1             <unavailable>
m2             <unavailable>
m3             <unavailable>
expstate       <unavailable>
f64r_lo        <unavailable>
f64r_hi        <unavailable>
f64s           <unavailable>
fcr            <unavailable>
fsr            <unavailable>
a0             0x8013e116          -2146180842
a1             0x3ffd9cb0          1073585328
a2             0x3f961fa8          1066803112
a3             0x3f96e928          1066854696
a4             0xfffff269          -3479
a5             0x3f476550          1061643600
a6             0xfffffb9d          -1123
a7             0x3fe66d80          1072065920
a8             0x0                 0
a9             0x3f41dda8          1061281192
a10            0x3f96242c          1066804268
a11            0x3f962424          1066804260
a12            0x3f96202c          1066803244
a13            0x3f962024          1066803236
a14            0x1                 1
a15            0x40                64
(gdb) bt
#0  0x401da2e3 in pvmp3_polyphase_filter_window_c (synth_buffer=0x3f961fa8, outPcm=0x3f96e928, numChannels=2, pqmfSynthWin=0x3f41da28 <pqmfSynthWin>)
    at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_polyphase_filter_window.cpp:200
#1  0x4013e116 in pvmp3_polyphase_filter_window_pv (pqmfSynthWin=<optimized out>, version=44, numChannels=2, outPcm=0x3f96e928, synth_buffer=0x3f961fa8)
    at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/esp_opt/xtensa_asm/xtensa_esp32/pvmp3_polyphase_filter_window_asm.h:109
#2  pvmp3_poly_phase_synthesis (version=44, pChVars=0x3f961918, numChannels=2, equalizerType=<optimized out>, outPcm=<optimized out>) at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_poly_phase_synthesis.cpp:173
#3  0x4013c7c5 in pvmp3_framedecoder (pExt=0x3f95d2c4, pMem=0x3f9615f4) at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_framedecoder.cpp:497
#4  0x40138aeb in mp3_decoder_process (mp3_el=0x3f94968c) at /builds/adf/esp-adf-libs-source/esp_processing/esp-wrapper/mp3_decoder.c:408
#5  0x40138cd8 in _mp3_decoder_process (self=0x3f94968c, in_buffer=0x0, in_len=0) at /builds/adf/esp-adf-libs-source/esp_processing/esp-wrapper/mp3_decoder.c:496
#6  0x40133681 in audio_element_process_running (el=0x3f94968c) at /export/app/esp-adf/components/audio_pipeline/audio_element.c:336
#7  0x40133841 in audio_element_task (pv=0x3f94968c) at /export/app/esp-adf/components/audio_pipeline/audio_element.c:483
#8  0x40096cc8 in vPortTaskWrapper (pxCode=0x40133780 <audio_element_task>, pvParameters=0x3f94968c) at /export/app/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162
(gdb)
espradio commented 1 year ago

Bootup log here:

load:0x40080400,len:4
0x40080400: _init at ??:?

load:0x40080404,len:4284
entry 0x40080668
I (31) boot: ESP-IDF v5.1-1-g615170ec27 2nd stage bootloader
I (31) boot: compile time Jul  1 2023 22:19:40
I (32) boot: Multicore bootloader
I (36) boot: chip revision: v3.0
I (40) qio_mode: Enabling default flash chip QIO
I (46) boot.esp32: SPI Speed      : 80MHz
I (50) boot.esp32: SPI Mode       : QIO
I (55) boot.esp32: SPI Flash Size : 4MB
I (59) boot: Enabling RNG early entropy source...
I (65) boot: Partition Table:
I (68) boot: ## Label            Usage          Type ST Offset   Length
I (76) boot:  0 otadata          OTA data         01 00 00009000 00002000
I (83) boot:  1 nvs              WiFi data        01 02 0000b000 00005000
I (90) boot:  2 ota_0            OTA app          00 10 00010000 001c2000
I (98) boot:  3 ota_1            OTA app          00 11 001e0000 000fa000
I (105) boot:  4 tts              Unknown data     01 82 002da000 0006e000
I (113) boot:  5 playlist         WiFi data        01 02 00348000 00052000
I (121) boot:  6 coredump         Unknown data     01 03 0039a000 00010000
I (128) boot: End of partition table
I (132) boot: No factory image, trying OTA 0
I (137) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=50944h (330052) map
I (237) esp_image: segment 1: paddr=0006096c vaddr=3ffbdb60 size=06e28h ( 28200) load
I (245) esp_image: segment 2: paddr=0006779c vaddr=40080000 size=0887ch ( 34940) load
I (257) esp_image: segment 3: paddr=00070020 vaddr=400d0020 size=129640h (1218112) map
I (592) esp_image: segment 4: paddr=00199668 vaddr=4008887c size=13888h ( 80008) load
I (633) boot: Loaded app from partition at offset 0x10000
I (665) boot: Set actual ota_seq=1 in otadata[0]
I (665) boot: Disabling RNG early entropy source...
I (676) cpu_start: Multicore app
I (676) quad_psram: This chip is ESP32-D0WD
I (676) esp_psram: Found 8MB PSRAM device
I (678) esp_psram: Speed: 40MHz
I (682) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
W (690) esp_psram: Virtual address not enough for PSRAM, map as much as we can. 4MB is mapped
I (699) cpu_start: Pro cpu up.
I (702) cpu_start: Starting app cpu, entry point is 0x400815e0
0x400815e0: call_start_cpu1 at /export/app/esp-idf/components/esp_system/port/cpu_start.c:154

I (0) cpu_start: App cpu up.
I (1613) esp_psram: SPI SRAM memory test OK
I (1625) cpu_start: Pro cpu start user code
I (1625) cpu_start: cpu freq: 240000000 Hz
I (1625) cpu_start: Application information:
I (1628) cpu_start: Project name:     app
I (1633) cpu_start: App version:      43e3255-dirty
I (1638) cpu_start: Compile time:     Jul  1 2023 22:19:37
I (1645) cpu_start: ELF file SHA256:  f138bf99dc6776ec...
I (1651) cpu_start: ESP-IDF:          v5.1-1-g615170ec27
I (1657) cpu_start: Min chip rev:     v3.0
I (1661) cpu_start: Max chip rev:     v3.99
I (1666) cpu_start: Chip rev:         v3.0
I (1671) heap_init: Initializing. RAM available for dynamic allocation:
I (1679) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1685) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1691) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1697) heap_init: At 3FFC73F8 len 00018C08 (99 KiB): DRAM
I (1703) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1710) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1716) heap_init: At 4009C104 len 00003EFC (15 KiB): IRAM
I (1723) esp_psram: Adding pool of 4054K of PSRAM memory to heap allocator
I (1731) spi_flash: detected chip: gd
I (1734) spi_flash: flash io: qio
W (1738) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (1752) esp_core_dump_flash: Init core dump to flash
I (1767) esp_core_dump_flash: Found partition 'coredump' @ 39a000 65536 bytes
E (1768) esp_core_dump_flash: Incorrect size of core dump image: -2146697204
I (1773) coexist: coex firmware version: ebddf30
I (1779) app_start: Starting scheduler on CPU0
I (1783) app_start: Starting scheduler on CPU1
0;32mI (1783) main_task: Started on CPU0
I (1793) esp_psram: Reserving pool of 64K of internal memory for DMA/internal allocations
I (1801) main_task: Calling app_main()
jason-mao commented 1 year ago

@espradio Could you help to provide a minimum reproducible code? If there is some difficult. Please help to provide a reproducible program firmware based on Lyrat4.3 board.

jason-mao commented 1 year ago

This topic has become inactive so I'm going to close the issue. Please reopen this if you have any questions or need any further assistance.