MP3 decoder crash

[felixcollins]

Hi,
I have a project playing mp3 files from sd card. The pipeline is fatfs_stream -> mp3_decoder -> i2s_writer. In between each play, I'm playing a wav file from flash memory: wav_decoder -> i2s_writer. I'm keeping the pipeline and elements allocated and just breaking up and relinking between each audio play.

The error seems to indicate memory exhaustion. I added some heap logging at the before the start and after the end of each pipeline run with this code:

Code: Select all

	
ESP_LOGW(TAG, "HEAP Available:%d, Largest:%d, Min:%d", xPortGetFreeHeapSize(), heap_caps_get_largest_free_block(MALLOC_CAP_8BIT), xPortGetMinimumEverFreeHeapSize());

Here is the output (with other log messages removed)...

Code: Select all

W (80412) MUSIC: HEAP Available:103844, Largest:71664, Min:8832
W (80412) MUSIC: HEAP Available:103848, Largest:71664, Min:8832
W (82012) MUSIC: HEAP Available:103848, Largest:71664, Min:8832
W (82012) MUSIC: HEAP Available:103856, Largest:71664, Min:8832
W (84022) MUSIC: HEAP Available:105656, Largest:71664, Min:8832
W (84022) MUSIC: HEAP Available:105660, Largest:71664, Min:8832
W (86452) MUSIC: HEAP Available:103856, Largest:69616, Min:8832
W (86452) MUSIC: HEAP Available:103856, Largest:69616, Min:8832
W (86452) MUSIC: HEAP Available:103856, Largest:69616, Min:8832
W (86452) MUSIC: HEAP Available:103856, Largest:69616, Min:8832
W (94862) MUSIC: HEAP Available:95252, Largest:69616, Min:8832
W (94862) MUSIC: HEAP Available:95248, Largest:69616, Min:8832
W (97492) MUSIC: HEAP Available:95248, Largest:69616, Min:8832
W (97492) MUSIC: HEAP Available:95248, Largest:69616, Min:8832
W (98902) MUSIC: HEAP Available:95248, Largest:69616, Min:8832
W (98902) MUSIC: HEAP Available:95248, Largest:69616, Min:8832
W (100102) MUSIC: HEAP Available:95248, Largest:69616, Min:8832
W (100102) MUSIC: HEAP Available:95220, Largest:69616, Min:8832
W (101682) MUSIC: HEAP Available:86612, Largest:61424, Min:8832
W (101682) MUSIC: HEAP Available:86620, Largest:61424, Min:8832
W (104872) MUSIC: HEAP Available:86620, Largest:61424, Min:8832
W (104882) MUSIC: HEAP Available:86628, Largest:61424, Min:8832
W (106872) MUSIC: HEAP Available:86628, Largest:61424, Min:8832
W (106882) MUSIC: HEAP Available:86628, Largest:61424, Min:8832
W (108872) MUSIC: HEAP Available:86628, Largest:61424, Min:8832
W (108872) MUSIC: HEAP Available:86640, Largest:61424, Min:8832
W (110792) MUSIC: HEAP Available:88440, Largest:61424, Min:8832
W (110802) MUSIC: HEAP Available:88440, Largest:61424, Min:8832
W (112402) MUSIC: HEAP Available:86640, Largest:61424, Min:8832
W (112412) MUSIC: HEAP Available:86640, Largest:61424, Min:8832
W (113992) MUSIC: HEAP Available:86640, Largest:61424, Min:8832
W (113992) MUSIC: HEAP Available:86640, Largest:61424, Min:8832
W (115552) MUSIC: HEAP Available:86640, Largest:61424, Min:8832
W (115552) MUSIC: HEAP Available:86640, Largest:61424, Min:8832
W (116742) MUSIC: HEAP Available:78048, Largest:53232, Min:8832
W (116742) MUSIC: HEAP Available:78048, Largest:53232, Min:8832
W (118342) MUSIC: HEAP Available:78048, Largest:53232, Min:8832
W (118342) MUSIC: HEAP Available:78020, Largest:53232, Min:8832
W (119692) MUSIC: HEAP Available:78020, Largest:53232, Min:8832
W (119692) MUSIC: HEAP Available:78028, Largest:53232, Min:8832
W (121042) MUSIC: HEAP Available:78028, Largest:53232, Min:8832
W (121042) MUSIC: HEAP Available:78032, Largest:53232, Min:8832
W (122312) MUSIC: HEAP Available:78032, Largest:53232, Min:8832
W (122322) MUSIC: HEAP Available:78032, Largest:53232, Min:8832
W (123712) MUSIC: HEAP Available:78032, Largest:53232, Min:8832
W (123712) MUSIC: HEAP Available:78048, Largest:53232, Min:8832

etc etc...

until the last logging before the crash

W (138242) MUSIC: HEAP Available:78032, Largest:53232, Min:8832
W (138252) MUSIC: HEAP Available:78048, Largest:53232, Min:8832
I (138262) MP3_DECODER: MP3 opened
W (138262) MUSICLOG: Logged play 5,2022-09-14T01:19:02,1
W (138322) MUSIC: Got STATUS report from i2s_status 122s_status
W (138322) MUSIC: Other state reported by main i2s stream writer: 3
W (138362) MUSIC: message from fatfs reader 8
E (138392) MP3_DE_LIB: /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_framedecoder.cpp:700 (pvmp3_InitDecoder): Memory exhausted
W (138Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.

As you can see there is a memory leak somewhere but there is still plenty of ram when the crash occurs. Unfortunately the pvmp3_framedecoder.cpp is included only as a library so there is no opportunity for me to examine the code and see what might be going on (unless I decompile it).

Can someone from Espressif ADF team please take a look at this and see if you can shed some light on this error?

Thanks,
Felix

Code: Select all

E (138392) MP3_DE_LIB: /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_framedecoder.cpp:700 (pvmp3_InitDecoder): Memory exhausted
W (138Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x4000c350  PS      : 0x00060e30  A0      : 0x800e57c8  A1      : 0x3fff6ec0
A2      : 0x00000000  A3      : 0x3fff8138  A4      : 0x0000025d  A5      : 0x00000000
A6      : 0x694a3291  A7      : 0xb1b25769  A8      : 0xfe632660  A9      : 0x3fff6e80
A10     : 0x00000004  A11     : 0x00000001  A12     : 0x00b00000  A13     : 0x3fff6f60
A14     : 0x00000000  A15     : 0x00000001  SAR     : 0x00000008  EXCCAUSE: 0x0000001d
EXCVADDR: 0x00000000  LBEG    : 0x4000c349  LEND    : 0x4000c36b  LCOUNT  : 0x00000024


Backtrace:0x4000c34d:0x3fff6ec00x400e57c5:0x3fff6ed0 0x400e59d6:0x3fff6f00 0x400e2b0e:0x3fff6fa0 0x400e2cf5:0x3fff7040 0x400e0b2f:0x3fff7060
0x400e57c5: fillMainDataBuf at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_framedecoder.cpp:607

0x400e59d6: pvmp3_framedecoder at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_framedecoder.cpp:295

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

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

0x400e0b2f: audio_element_process_running at C:/SysGCC/esp32/esp-adf/v2.4/components/audio_pipeline/audio_element.c:336
 (inlined by) audio_element_task at C:/SysGCC/esp32/esp-adf/v2.4/components/audio_pipeline/audio_element.c:483

[felixcollins]

More of the core dump from monitor:

Code: Select all

Core dump started (further output muted)
Received  42 kB...
Core dump finished!
espcoredump.py v0.4-dev
===============================================================
==================== ESP32 CORE DUMP START ====================

Crashed task handle: 0x3ffda010, name: 'mp3', GDB name: 'process 1073586192'

================== CURRENT THREAD REGISTERS ===================
exccause       0x1d (StoreProhibitedCause)
excvaddr       0x0
epc1           0x400f5c30
epc2           0x0
epc3           0x0
epc4           0x0
epc5           0x0
epc6           0x0
eps2           0x0
eps3           0x0
eps4           0x0
eps5           0x0
eps6           0x0
pc             0x4000c350          0x4000c350
lbeg           0x4000c349          1073791817
lend           0x4000c36b          1073791851
lcount         0x24                36
sar            0x8                 8
ps             0x60e20             396832
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             0x800e57c8          -2146543672
a1             0x3fff6ec0          1073704640
a2             0x0                 0
a3             0x3fff8138          1073709368
a4             0x25d               605
a5             0x0                 0
a6             0x694a3291          1766470289
a7             0xb1b25769          -1313712279
a8             0xfe632660          -27056544
a9             0x3fff6e80          1073704576
a10            0x4                 4
a11            0x1                 1
a12            0xb00000            11534336
a13            0x3fff6f60          1073704800
a14            0x0                 0
a15            0x1                 1

==================== CURRENT THREAD STACK =====================
#0  0x4000c350 in ?? ()
#1  0x400e57c8 in fillMainDataBuf (pMem=0x3fff8974, temp=605) at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_framedecoder.cpp:607
#2  0x400e59d9 in pvmp3_framedecoder (pExt=0x3ffd9f90, pMem=0x3fff8974) at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_framedecoder.cpp:295
#3  0x400e2b11 in mp3_decoder_process (mp3_el=0x3ffc4e10) at /builds/adf/esp-adf-libs-source/esp_processing/esp-wrapper/mp3_decoder.c:446
#4  0x400e2cf8 in _mp3_decoder_process (self=0x3ffc4e10, in_buffer=0x0, in_len=0) at /builds/adf/esp-adf-libs-source/esp_processing/esp-wrapper/mp3_decoder.c:538
#5  0x400e0b32 in audio_element_process_running (el=0x3ffc4e10) at C:/SysGCC/esp32/esp-adf/v2.4/components/audio_pipeline/audio_element.c:336
#6  audio_element_task (pv=0x3ffc4e10) at C:/SysGCC/esp32/esp-adf/v2.4/components/audio_pipeline/audio_element.c:483

======================== THREADS INFO =========================
  Id   Target Id          Frame
* 1    process 1073586192 0x4000c350 in ?? ()
  2    process 1073609692 0x4008b442 in xQueueReceive (xQueue=0x3ffc843c, pvBuffer=0x3ffe2530, xTicksToWait=<optimized out>) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  3    process 1073492656 0x00000000 in ?? ()
  4    process 1073469260 0x4008da7c in prvProcessTimerOrBlockTask (xListWasEmpty=<optimized out>, xNextExpireTime=13747) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  5    process 1073467340 esp_pm_impl_waiti () at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/esp_pm/pm_impl.c:833
  6    process 1073465420 esp_pm_impl_waiti () at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/esp_pm/pm_impl.c:833
  7    process 1073583856 0x4008b5ac in xQueueSemaphoreTake (xQueue=0x3ffe3b34, xTicksToWait=<optimized out>) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  8    process 1073547560 0x4008b442 in xQueueReceive (xQueue=0x3ffcfa2c, pvBuffer=0x3ffd0880, xTicksToWait=<optimized out>) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  9    process 1073465056 0x4008cbe0 in vTaskDelay (xTicksToDelay=1000) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  10   process 1073551732 0x4008b442 in xQueueReceive (xQueue=0x3ffd0b90, pvBuffer=0x3ffd1890, xTicksToWait=<optimized out>) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  11   process 1073460380 0x4000bff0 in ?? ()
  12   process 1073609224 xEventGroupWaitBits (xEventGroup=0x3ffdd7f4, uxBitsToWaitFor=15, xClearOnExit=1, xWaitForAllBits=0, xTicksToWait=<optimized out>) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/freertos/event_groups.c:475
  13   process 1073600076 xEventGroupWaitBits (xEventGroup=0x3ffdb600, uxBitsToWaitFor=7, xClearOnExit=1, xWaitForAllBits=0, xTicksToWait=<optimized out>) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/freertos/event_groups.c:475
  14   process 1073562136 0x4008b442 in xQueueReceive (xQueue=0x3ffd20f4, pvBuffer=0x3ffd4170, xTicksToWait=<optimized out>) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  15   process 1073455900 0x4008b5ac in xQueueSemaphoreTake (xQueue=0x3ffb9aa0, xTicksToWait=<optimized out>) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  16   process 1073413748 0x4008b5ac in xQueueSemaphoreTake (xQueue=0x3ffaf5f8, xTicksToWait=<optimized out>) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  17   process 1073487832 0x4008b442 in xQueueReceive (xQueue=0x3ffc0f0c, pvBuffer=0x3ffc1f30, xTicksToWait=<optimized out>) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  18   process 1073499300 0x4008b442 in xQueueReceive (xQueue=0x3ffc35d0, pvBuffer=0x3ffc4b90, xTicksToWait=<optimized out>) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  19   process 1073482984 0x4008b442 in xQueueReceive (xQueue=0x3ffbec1c, pvBuffer=0x3ffc0c40, xTicksToWait=<optimized out>) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  20   process 1073505240 0x4008b442 in xQueueReceive (xQueue=0x3ffc5108, pvBuffer=0x3ffc6278, xTicksToWait=<optimized out>) at C:/SysGCC/esp32/esp-adf/v2.4/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39

==================== THREAD 1 (TCB: 0x3ffda010, name: 'mp3') =====================
#0  0x4000c350 in ?? ()
#1  0x400e57c8 in fillMainDataBuf (pMem=0x3fff8974, temp=605) at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_framedecoder.cpp:607
#2  0x400e59d9 in pvmp3_framedecoder (pExt=0x3ffd9f90, pMem=0x3fff8974) at /builds/adf/esp-adf-libs-source/esp_codec/esp-mp3/src/pvmp3_framedecoder.cpp:295
#3  0x400e2b11 in mp3_decoder_process (mp3_el=0x3ffc4e10) at /builds/adf/esp-adf-libs-source/esp_processing/esp-wrapper/mp3_decoder.c:446
#4  0x400e2cf8 in _mp3_decoder_process (self=0x3ffc4e10, in_buffer=0x0, in_len=0) at /builds/adf/esp-adf-libs-source/esp_processing/esp-wrapper/mp3_decoder.c:538
#5  0x400e0b32 in audio_element_process_running (el=0x3ffc4e10) at C:/SysGCC/esp32/esp-adf/v2.4/components/audio_pipeline/audio_element.c:336
#6  audio_element_task (pv=0x3ffc4e10) at C:/SysGCC/esp32/esp-adf/v2.4/components/audio_pipeline/audio_element.c:483

[felixcollins]

It looks like my leak is coming from the wifi/httpd. If I turn that code off the memory consumption is rock solid. I still think the mp3 decoder should fail to run rather than crash.