Hang calling i2s_stream_set_clk during music play
Posted: Fri Nov 03, 2023 3:36 am
IDF :4.4.6
ADF :2.0.3
My pipeline is:
sdcard with mp3 file -> fatfs_stream_element_handle -> mp3_decoder_element_handle -> i2s_stream_writer_element
I have a task (thread 15 "music_task") that processes calls control messages from the app and events from the audio pipeline. When the mp3 element reports the sample rate etc. the music_task calls i2s_stream_set_clk() to set the output sample rate. Occasionally this call seems to hang when acquiring the sempahore protecting the i2s_stream element config.
I've set a task watchdog on the music_task so that I do not get a hang. When the watchdog fires it triggers a panic that does a core dump to flash. Shown below is the coredump decoded and output from gdb. I suspect that this is a deadlock situation. Can anyone shed any light on this? What would be a good work-around?
There is a httpd and mdns set up too but the hang seems to occur even if wifi is turned off (as is the case in the core dump below).
The thread priorities and core affinity for the tasks with no music playing (no audio element tasks). I can't figure out how to recover the task priority from the core dump. Doe anyone know the gdb command?
ADF :2.0.3
My pipeline is:
sdcard with mp3 file -> fatfs_stream_element_handle -> mp3_decoder_element_handle -> i2s_stream_writer_element
I have a task (thread 15 "music_task") that processes calls control messages from the app and events from the audio pipeline. When the mp3 element reports the sample rate etc. the music_task calls i2s_stream_set_clk() to set the output sample rate. Occasionally this call seems to hang when acquiring the sempahore protecting the i2s_stream element config.
I've set a task watchdog on the music_task so that I do not get a hang. When the watchdog fires it triggers a panic that does a core dump to flash. Shown below is the coredump decoded and output from gdb. I suspect that this is a deadlock situation. Can anyone shed any light on this? What would be a good work-around?
There is a httpd and mdns set up too but the hang seems to occur even if wifi is turned off (as is the case in the core dump below).
The thread priorities and core affinity for the tasks with no music playing (no audio element tasks). I can't figure out how to recover the task priority from the core dump. Doe anyone know the gdb command?
Code: Select all
Name Prity TaskNum CoreID
event_loop 10 8 0
Tmr Svc 5 7 0
IDLE 0 6 1
IDLE 0 5 0
music 24 9 1
tiT 18 11 0
ipc0 1 1 0
sys_evt 20 10 0
ipc1 24 2 1
dns_s 5 13 0
wifi 23 12 0
esp_timer 22 3 0Code: Select all
Thread 16 (process 1073480536):
#0 0x4008c4c6 in xQueueReceive (xQueue=0x3ffbef24, pvBuffer=0x3ffc0280, xTicksToWait=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/queue.c:1487
#1 0x40176580 in esp_event_loop_run (event_loop=0x3ffbeef8, ticks_to_run=4294967295) at C:/Users/felix/esp/esp-idf/components/esp_event/esp_event.c:566
#2 0x401766f3 in esp_event_loop_run_task (args=0x3ffbeef8) at C:/Users/felix/esp/esp-idf/components/esp_event/esp_event.c:115
Thread 15 (process 1073507392):
#0 0x4008c628 in xQueueSemaphoreTake (xQueue=0x3ffc78e0, xTicksToWait=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/queue.c:1687
#1 0x400f6070 in i2s_set_clk (i2s_num=I2S_NUM_0, rate=44100, bits_cfg=16, ch=I2S_CHANNEL_STEREO) at C:/Users/felix/esp/esp-idf/components/driver/i2s.c:1626
#2 0x400e4864 in _i2s_set_clk (ch=2, bits_cfg=16, rate=44100, i2s_num=<optimized out>) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_stream/i2s_stream.c:169
#3 i2s_stream_set_clk (i2s_stream=0x3ffc88ac, rate=44100, bits=16, ch=2) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_stream/i2s_stream.c:368
#4 0x400d82c9 in process_music_msgs (msg=0x3ffc6b80) at C:/Users/felix/source/beakbox/Firmware/beakbox3/main/music.c:463
#5 0x400d85e3 in music_task (ptr=<optimized out>) at C:/Users/felix/source/beakbox/Firmware/beakbox3/main/music.c:580
Thread 14 (process 1073604144):
#0 0x4008c628 in xQueueSemaphoreTake (xQueue=0x3ffdf684, xTicksToWait=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/queue.c:1687
#1 0x400eb020 in rb_write (rb=0x3ffdf56c, buf=0x3ffe29a6 <error: Cannot access memory at address 0x3ffe29a6>, buf_len=1118, ticks_to_wait=4294967295) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_pipeline/ringbuf.c:295
#2 0x400e9356 in audio_element_output (el=0x3ffc6ea8, buffer=0x3ffe1e04 <error: Cannot access memory at address 0x3ffe1e04>, write_size=4096) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_pipeline/audio_element.c:427
#3 0x400e4270 in _fatfs_process (self=0x3ffc6ea8, in_buffer=0x3ffe1e04 <error: Cannot access memory at address 0x3ffe1e04>, in_len=4096) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_stream/fatfs_stream.c:214
#4 0x400e97ca in audio_element_process_running (el=0x3ffc6ea8) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_pipeline/audio_element.c:336
#5 audio_element_task (pv=0x3ffc6ea8) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_pipeline/audio_element.c:483
Thread 13 (process 1073604520):
#0 0x4008c628 in xQueueSemaphoreTake (xQueue=0x3ffde46c, xTicksToWait=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/queue.c:1687
#1 0x400eb020 in rb_write (rb=0x3ffdf718, buf=0x3ffed2b4 <error: Cannot access memory at address 0x3ffed2b4>, buf_len=2560, ticks_to_wait=4294967295) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_pipeline/ringbuf.c:295
#2 0x400e9356 in audio_element_output (el=0x3ffc72dc, buffer=0x3ffecab4 <error: Cannot access memory at address 0x3ffecab4>, write_size=4608) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_pipeline/audio_element.c:427
#3 0x400eb9b9 in mp3_decoder_process (mp3_el=0x3ffc72dc) at /builds/adf/esp-adf-libs-source/esp_processing/esp-wrapper/mp3_decoder.c:457
#4 0x400eba18 in _mp3_decoder_process (self=0x3ffc72dc, in_buffer=0x0, in_len=0) at /builds/adf/esp-adf-libs-source/esp_processing/esp-wrapper/mp3_decoder.c:496
#5 0x400e97ca in audio_element_process_running (el=0x3ffc72dc) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_pipeline/audio_element.c:336
#6 audio_element_task (pv=0x3ffc72dc) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_pipeline/audio_element.c:483
Thread 12 (process 1073604896):
#0 0x4008c4c6 in xQueueReceive (xQueue=0x3ffc7868, pvBuffer=0x3ffc7804, xTicksToWait=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/queue.c:1487
#1 0x400f6620 in i2s_write (i2s_num=<optimized out>, src=<optimized out>, size=672, bytes_written=0x3ffe3ac0, ticks_to_wait=4294967295) at C:/Users/felix/esp/esp-idf/components/driver/i2s.c:2137
#2 0x400dd078 in _i2s_write (self=<optimized out>, buffer=0x3ffe56dc <error: Cannot access memory at address 0x3ffe56dc>, len=3600, ticks_to_wait=4294967295, context=<optimized out>) at C:/Users/felix/source/beakbox/Firmware/beakbox3/main/i2s_stream_workaround.c:169
#3 0x400e92f2 in audio_element_output (el=0x3ffc88ac, buffer=<optimized out>, write_size=3600) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_pipeline/audio_element.c:422
#4 0x400dd176 in _i2s_process (self=0x3ffc88ac, in_buffer=0x3ffe56dc <error: Cannot access memory at address 0x3ffe56dc>, in_len=3600) at C:/Users/felix/source/beakbox/Firmware/beakbox3/main/i2s_stream_workaround.c:193
#5 0x400e97ca in audio_element_process_running (el=0x3ffc88ac) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_pipeline/audio_element.c:336
#6 audio_element_task (pv=0x3ffc88ac) at C:/Users/felix/esp/esp-adf/esp-adf/components/audio_pipeline/audio_element.c:483
Thread 11 (process 1073466644):
--Type <RET> for more, q to quit, c to continue without paging--c
#0 0x4008c628 in xQueueSemaphoreTake (xQueue=0x3ffdc2a0, xTicksToWait=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/queue.c:1687
#1 0x4011948c in sys_arch_sem_wait (sem=0x3ffdc288, timeout=0) at C:/Users/felix/esp/esp-idf/components/lwip/port/esp32/freertos/sys_arch.c:184
#2 0x40107dc1 in lwip_select (maxfdp1=51, readset=0x3ffdbba0, writeset=0x0, exceptset=0x0, timeout=<optimized out>) at C:/Users/felix/esp/esp-idf/components/lwip/lwip/src/api/sockets.c:2153
#3 0x401199b0 in select (nfds=51, readfds=0x3ffdbba0, writefds=0x0, errorfds=0x0, timeout=0x0) at C:/Users/felix/esp/esp-idf/components/lwip/port/esp32/vfs_lwip.c:58
#4 0x4011ea1b in httpd_server (hd=<optimized out>) at C:/Users/felix/esp/esp-idf/components/esp_http_server/src/httpd_main.c:205
#5 httpd_thread (arg=0x3ffbbb38) at C:/Users/felix/esp/esp-idf/components/esp_http_server/src/httpd_main.c:250
Thread 10 (process 1073535072):
#0 0x4008c4c6 in xQueueReceive (xQueue=0x3ffcbf2c, pvBuffer=0x3ffcd7b0, xTicksToWait=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/queue.c:1487
#1 0x40105c24 in queue_recv_wrapper (queue=0x3ffcbf2c, item=0x3ffcd7b0, block_time_tick=4294967295) at C:/Users/felix/esp/esp-idf/components/esp_wifi/esp32/esp_adapter.c:441
#2 0x400951d8 in ppTask ()
Thread 9 (process 1073587248):
#0 0x4008c4c6 in xQueueReceive (xQueue=0x3ffda5f4, pvBuffer=0x3ffd9fa0, xTicksToWait=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/queue.c:1487
#1 0x40119584 in sys_arch_mbox_fetch (mbox=<optimized out>, msg=0x3ffd9fa0, timeout=0) at C:/Users/felix/esp/esp-idf/components/lwip/port/esp32/freertos/sys_arch.c:326
#2 0x4011a8b3 in netconn_recv_data (conn=0x3ffda5a8, new_buf=0x3ffd9ff0, apiflags=<optimized out>) at C:/Users/felix/esp/esp-idf/components/lwip/lwip/src/api/api_lib.c:628
#3 0x4011a959 in netconn_recv_udp_raw_netbuf_flags (conn=<optimized out>, new_buf=0x3ffd9ff0, apiflags=0 '\000') at C:/Users/felix/esp/esp-idf/components/lwip/lwip/src/api/api_lib.c:860
#4 0x401065f4 in lwip_recvfrom_udp_raw (sock=0x3ffb6608 <sockets>, flags=0, msg=0x3ffda030, datagram_len=0x3ffda054, dbg_s=<optimized out>) at C:/Users/felix/esp/esp-idf/components/lwip/lwip/src/api/sockets.c:1171
#5 0x401078a5 in lwip_recvfrom (s=<optimized out>, mem=0x3ffda2a0, len=127, flags=0, from=0x3ffda320, fromlen=<optimized out>) at C:/Users/felix/esp/esp-idf/components/lwip/lwip/src/api/sockets.c:1292
#6 0x400dd61f in recvfrom (fromlen=<unavailable>, from=<unavailable>, flags=0, len=127, mem=<unavailable>, s=<unavailable>) at C:/Users/felix/esp/esp-idf/components/lwip/lwip/src/include/lwip/sockets.h:648
#7 dns_server_task (pvParameters=<optimized out>) at C:/Users/felix/source/beakbox/Firmware/beakbox3/main/dns_server.c:215
Thread 8 (process 1073413500):
#0 0x40086fb8 in esp_crosscore_int_send_yield (core_id=1) at C:/Users/felix/esp/esp-idf/components/esp_system/crosscore_int.c:145
#1 0x4008c628 in xQueueSemaphoreTake (xQueue=0x3ffaf8f8, xTicksToWait=<optimized out>) at C:/Users/felix/esp/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
#2 0x40083f47 in ipc_task (arg=<optimized out>) at C:/Users/felix/esp/esp-idf/components/esp_ipc/src/esp_ipc.c:54
Thread 7 (process 1073521968):
#0 0x4008c4c6 in xQueueReceive (xQueue=0x3ffc993c, pvBuffer=0x3ffca450, xTicksToWait=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/queue.c:1487
#1 0x40176580 in esp_event_loop_run (event_loop=0x3ffc9800, ticks_to_run=4294967295) at C:/Users/felix/esp/esp-idf/components/esp_event/esp_event.c:566
#2 0x401766f3 in esp_event_loop_run_task (args=0x3ffc9800) at C:/Users/felix/esp/esp-idf/components/esp_event/esp_event.c:115
Thread 6 (process 1073411744):
#0 0x4008c628 in xQueueSemaphoreTake (xQueue=0x3ffaf21c, xTicksToWait=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/queue.c:1687
#1 0x40083f47 in ipc_task (arg=<optimized out>) at C:/Users/felix/esp/esp-idf/components/esp_ipc/src/esp_ipc.c:54
Thread 5 (process 1073460920):
#0 0x4000bff0 in ?? ()
#1 0x4008f409 in vPortClearInterruptMaskFromISR (prev_level=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/port/xtensa/include/freertos/portmacro.h:571
#2 vPortExitCritical (mux=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/port/xtensa/port.c:332
#3 0x4008e569 in ulTaskGenericNotifyTake (uxIndexToWait=<optimized out>, xClearCountOnExit=1, xTicksToWait=4294967295) at C:/Users/felix/esp/esp-idf/components/freertos/tasks.c:5401
#4 0x400d6cef in timer_task (arg=<optimized out>) at C:/Users/felix/esp/esp-idf/components/esp_timer/src/esp_timer.c:420
Thread 4 (process 1073525368):
#0 0x4008c4c6 in xQueueReceive (xQueue=0x3ffca974, pvBuffer=0x3ffcb1d0, xTicksToWait=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/queue.c:1487
#1 0x401195aa in sys_arch_mbox_fetch (mbox=<optimized out>, msg=0x3ffcb1d0, timeout=1000) at C:/Users/felix/esp/esp-idf/components/lwip/port/esp32/freertos/sys_arch.c:330
#2 0x4010819b in tcpip_timeouts_mbox_fetch (mbox=<optimized out>, msg=<optimized out>) at C:/Users/felix/esp/esp-idf/components/lwip/lwip/src/api/tcpip.c:110
#3 tcpip_thread (arg=<optimized out>) at C:/Users/felix/esp/esp-idf/components/lwip/lwip/src/api/tcpip.c:148
Thread 3 (process 1073472672):
#0 0x4008eff0 in prvProcessTimerOrBlockTask (xListWasEmpty=<optimized out>, xNextExpireTime=484013) at C:/Users/felix/esp/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
#1 prvTimerTask (pvParameters=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/timers.c:597
Thread 2 (process 1073469716):
#0 0x4000bff0 in ?? ()
#1 0x4008f409 in vPortClearInterruptMaskFromISR (prev_level=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/port/xtensa/include/freertos/portmacro.h:571
#2 vPortExitCritical (mux=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/port/xtensa/port.c:332
#3 0x401019d2 in esp_task_wdt_reset () at C:/Users/felix/esp/esp-idf/components/esp_system/task_wdt.c:330
#4 0x401019de in idle_hook_cb () at C:/Users/felix/esp/esp-idf/components/esp_system/task_wdt.c:80
#5 0x400d4a89 in esp_vApplicationIdleHook () at C:/Users/felix/esp/esp-idf/components/esp_system/freertos_hooks.c:51
#6 0x4008cb9b in prvIdleTask (pvParameters=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/tasks.c:3987
Thread 1 (process 1073468296):
#0 0x40081fb9 in panic_abort (details=0x3ffb0d60 "abort() was called at PC 0x401016e4 on core 0") at C:/Users/felix/esp/esp-idf/components/esp_system/panic.c:408
#1 0x4008b864 in esp_system_abort (details=0x3ffb0d60 "abort() was called at PC 0x401016e4 on core 0") at C:/Users/felix/esp/esp-idf/components/esp_system/esp_system.c:137
#2 0x4009392d in abort () at C:/Users/felix/esp/esp-idf/components/newlib/abort.c:46
#3 0x401016e7 in task_wdt_isr (arg=<optimized out>) at C:/Users/felix/esp/esp-idf/components/esp_system/task_wdt.c:176
#4 0x4008389c in _xt_lowint1 () at C:/Users/felix/esp/esp-idf/components/freertos/port/xtensa\xtensa_vectors.S:1114
#5 0x400fb5ce in cpu_ll_waiti () at C:/Users/felix/esp/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:183
#6 esp_pm_impl_waiti () at C:/Users/felix/esp/esp-idf/components/esp_pm/pm_impl.c:838
#7 0x400d4a9e in esp_vApplicationIdleHook () at C:/Users/felix/esp/esp-idf/components/esp_system/freertos_hooks.c:63
#8 0x4008cb9b in prvIdleTask (pvParameters=<optimized out>) at C:/Users/felix/esp/esp-idf/components/freertos/tasks.c:3987
(gdb)