search

muvox-io / euphonium

Tiny audio platform
GNU Affero General Public License v3.0
96 stars 15 forks source link

Bug - Stability problem on limited bandwidth #39

Open TooDissing opened 2 years ago

TooDissing commented 2 years ago

I am experiencing stability problems when using the platform (on µVox) on a Wifi setup with limited bandwidth. Especially error prone when the other family members start streaming video content.

The music simply stops playing and the device gets stuck. Resulting in a visit from the watchdog feature. Here's a small section of the logs below.

This problem seems to be related to euphonium/euphonium/cspot/cspot/src/ChunkedAudioStream.cpp:102. Could it be that it relates to the while(1) loop at in the ov_read() method?

Anyways. It works fine as long as we keep getting data.

And this is when using the Spotify playback.

E (230002) task_wdt: Print CPU 1 backtrace

Backtrace:0x4008E69D:0x3FFBF3D00x40084A15:0x3FFBF3F0 0x400976FB:0x3F8D28A0 0x40081845:0x3F8D28E0 0x400DE415:0x3F8D2900 0x4015383B:0x3F8D2920 0x4024362B:0x3F8D2990 0x40169462:0x3F8D29B0 0x40169B62:0x3F8D29D0 0x4016AD9A:0x3F8D2A30 0x40153399:0x3F8D2A60 0x4014FE62:0x3F8D2AE0 0x400DB22A:0x3F8D2B20
0x4008e69d: esp_crosscore_isr at /dev-tooling/esp/esp-idf/components/esp_system/crosscore_int.c:92

0x40084a15: _xt_lowint1 at /dev-tooling/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1111

0x400976fb: xQueueGenericSend at /dev-tooling/esp/esp-idf/components/freertos/queue.c:1043

0x40081845: pthread_mutex_unlock at /dev-tooling/esp/esp-idf/components/pthread/pthread.c:709

0x400de415: std::scoped_lock<std::mutex>::~scoped_lock() at /Volumes/Brugere/tue/.espressif/tools/xtensa-esp32-elf/esp-2021r2-8.4.0/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/8.4.0/xtensa-esp32-elf/esp32-psram/no-rtti/bits/gthr-default.h:791
 (inlined by) std::mutex::unlock() at /Volumes/Brugere/tue/.espressif/tools/xtensa-esp32-elf/esp-2021r2-8.4.0/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/8.4.0/bits/std_mutex.h:121
 (inlined by) std::scoped_lock<std::mutex>::~scoped_lock() at /Volumes/Brugere/tue/.espressif/tools/xtensa-esp32-elf/esp-2021r2-8.4.0/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/8.4.0/mutex:617

0x4015383b: ChunkedByteStream::read(unsigned char*, unsigned int) at /code/euphonium/euphonium/cspot/cspot/src/ChunkedByteStream.cpp:58

0x4024362b: vorbisReadCb(void*, unsigned int, unsigned int, ChunkedAudioStream*) at /code/euphonium/euphonium/cspot/cspot/src/ChunkedAudioStream.cpp:9

0x40169462: _get_data at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:73
 (inlined by) _get_next_page at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:125

0x40169b62: _fetch_and_process_packet at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:614

0x4016ad9a: ov_read at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:1581

0x40153399: ChunkedAudioStream::startPlaybackLoop(unsigned char*, unsigned int) at /code/euphonium/euphonium/cspot/cspot/src/ChunkedAudioStream.cpp:102

0x4014fe62: Player::runTask() at /code/euphonium/euphonium/cspot/cspot/src/Player.cpp:106

0x400db22a: bell::Task::taskEntryFuncPSRAM(void*) at /code/euphonium/euphonium/bell/include/Task.h:81

I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838923, (internal) 20097
I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838419, (internal) 20085
I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838419, (internal) 20085
I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838419, (internal) 20093
I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838419, (internal) 20085
E (235002) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (235002) task_wdt:  - IDLE (CPU 1)
E (235002) task_wdt: Tasks currently running:
E (235002) task_wdt: CPU 0: IDLE
E (235002) task_wdt: CPU 1: player
E (235002) task_wdt: Print CPU 0 (current core) backtrace

Backtrace:0x4019FC06:0x3FFBEBA00x40084A15:0x3FFBEBC0 0x402456DF:0x3FFBC770 0x400D3B2D:0x3FFBC790 0x40098114:0x3FFBC7B0
0x4019fc06: task_wdt_isr at /dev-tooling/esp/esp-idf/components/esp_system/task_wdt.c:183 (discriminator 3)

0x40084a15: _xt_lowint1 at /dev-tooling/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1111

0x402456df: cpu_ll_waiti at /dev-tooling/esp/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:183
 (inlined by) esp_pm_impl_waiti at /dev-tooling/esp/esp-idf/components/esp_pm/pm_impl.c:837

0x400d3b2d: esp_vApplicationIdleHook at /dev-tooling/esp/esp-idf/components/esp_system/freertos_hooks.c:63

0x40098114: prvIdleTask at /dev-tooling/esp/esp-idf/components/freertos/tasks.c:3974

E (235002) task_wdt: Print CPU 1 backtrace

Backtrace:0x4008E69D:0x3FFBF3D00x40084A15:0x3FFBF3F0 0x4000BFED:0x3F8D2850 0x4009A631:0x3F8D2860 0x40097CCC:0x3F8D2880 0x400817CE:0x3F8D28C0 0x400817E7:0x3F8D28E0 0x400D96F5:0x3F8D2900 0x40153726:0x3F8D2920 0x4024362B:0x3F8D2990 0x40169462:0x3F8D29B0 0x40169B62:0x3F8D29D0 0x4016AD9A:0x3F8D2A30 0x40153399:0x3F8D2A60 0x4014FE62:0x3F8D2AE0 0x400DB22A:0x3F8D2B20
0x4008e69d: esp_crosscore_isr at /dev-tooling/esp/esp-idf/components/esp_system/crosscore_int.c:92

0x40084a15: _xt_lowint1 at /dev-tooling/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1111

0x4009a631: vPortClearInterruptMaskFromISR at /dev-tooling/esp/esp-idf/components/freertos/port/xtensa/include/freertos/portmacro.h:571
 (inlined by) vPortExitCritical at /dev-tooling/esp/esp-idf/components/freertos/port/xtensa/port.c:319

0x40097ccc: xQueueSemaphoreTake at /dev-tooling/esp/esp-idf/components/freertos/queue.c:1612

0x400817ce: pthread_mutex_lock_internal at /dev-tooling/esp/esp-idf/components/pthread/pthread.c:620

0x400817e7: pthread_mutex_lock at /dev-tooling/esp/esp-idf/components/pthread/pthread.c:650

0x400d96f5: std::mutex::lock() at /Volumes/Brugere/tue/.espressif/tools/xtensa-esp32-elf/esp-2021r2-8.4.0/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/8.4.0/xtensa-esp32-elf/esp32-psram/no-rtti/bits/gthr-default.h:761
 (inlined by) std::mutex::lock() at /Volumes/Brugere/tue/.espressif/tools/xtensa-esp32-elf/esp-2021r2-8.4.0/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/8.4.0/bits/std_mutex.h:103

0x40153726: std::scoped_lock<std::mutex>::scoped_lock(std::mutex&) at /Volumes/Brugere/tue/.espressif/tools/xtensa-esp32-elf/esp-2021r2-8.4.0/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/8.4.0/mutex:610
 (inlined by) ChunkedByteStream::read(unsigned char*, unsigned int) at /code/euphonium/euphonium/cspot/cspot/src/ChunkedByteStream.cpp:58

0x4024362b: vorbisReadCb(void*, unsigned int, unsigned int, ChunkedAudioStream*) at /code/euphonium/euphonium/cspot/cspot/src/ChunkedAudioStream.cpp:9

0x40169462: _get_data at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:73
 (inlined by) _get_next_page at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:125

0x40169b62: _fetch_and_process_packet at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:614

0x4016ad9a: ov_read at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:1581

0x40153399: ChunkedAudioStream::startPlaybackLoop(unsigned char*, unsigned int) at /code/euphonium/euphonium/cspot/cspot/src/ChunkedAudioStream.cpp:102

0x4014fe62: Player::runTask() at /code/euphonium/euphonium/cspot/cspot/src/Player.cpp:106

0x400db22a: bell::Task::taskEntryFuncPSRAM(void*) at /code/euphonium/euphonium/bell/include/Task.h:81

I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838419, (internal) 20085
I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838419, (internal) 20093
I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838419, (internal) 20085
I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838403, (internal) 20085
I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838907, (internal) 20085
E (240002) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (240002) task_wdt:  - IDLE (CPU 1)
E (240002) task_wdt: Tasks currently running:
E (240002) task_wdt: CPU 0: IDLE
E (240002) task_wdt: CPU 1: player
E (240002) task_wdt: Print CPU 0 (current core) backtrace

Backtrace:0x4019FC06:0x3FFBEBA00x40084A15:0x3FFBEBC0 0x402456DF:0x3FFBC770 0x400D3B2D:0x3FFBC790 0x40098114:0x3FFBC7B0
0x4019fc06: task_wdt_isr at /dev-tooling/esp/esp-idf/components/esp_system/task_wdt.c:183 (discriminator 3)

0x40084a15: _xt_lowint1 at /dev-tooling/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1111

0x402456df: cpu_ll_waiti at /dev-tooling/esp/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:183
 (inlined by) esp_pm_impl_waiti at /dev-tooling/esp/esp-idf/components/esp_pm/pm_impl.c:837

0x400d3b2d: esp_vApplicationIdleHook at /dev-tooling/esp/esp-idf/components/esp_system/freertos_hooks.c:63

0x40098114: prvIdleTask at /dev-tooling/esp/esp-idf/components/freertos/tasks.c:3974

E (240002) task_wdt: Print CPU 1 backtrace

Backtrace:0x4008E69D:0x3FFBF3D00x40084A15:0x3FFBF3F0 0x401537AB:0x3F8D2920 0x4024362B:0x3F8D2990 0x40169462:0x3F8D29B0 0x40169B62:0x3F8D29D0 0x4016AD9A:0x3F8D2A30 0x40153399:0x3F8D2A60 0x4014FE62:0x3F8D2AE0 0x400DB22A:0x3F8D2B20
0x4008e69d: esp_crosscore_isr at /dev-tooling/esp/esp-idf/components/esp_system/crosscore_int.c:92

0x40084a15: _xt_lowint1 at /dev-tooling/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1111

0x401537ab: ChunkedByteStream::read(unsigned char*, unsigned int) at /Volumes/Brugere/tue/.espressif/tools/xtensa-esp32-elf/esp-2021r2-8.4.0/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/8.4.0/bits/shared_ptr_base.h:1167

0x4024362b: vorbisReadCb(void*, unsigned int, unsigned int, ChunkedAudioStream*) at /code/euphonium/euphonium/cspot/cspot/src/ChunkedAudioStream.cpp:9

0x40169462: _get_data at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:73
 (inlined by) _get_next_page at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:125

0x40169b62: _fetch_and_process_packet at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:614

--- unknown menu character Ctrl+C --
0x4016ad9a: ov_read at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:1581

0x40153399: ChunkedAudioStream::startPlaybackLoop(unsigned char*, unsigned int) at /code/euphonium/euphonium/cspot/cspot/src/ChunkedAudioStream.cpp:102

0x4014fe62: Player::runTask() at /code/euphonium/euphonium/cspot/cspot/src/Player.cpp:106

0x400db22a: bell::Task::taskEntryFuncPSRAM(void*) at /code/euphonium/euphonium/bell/include/Task.h:81

I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838907, (internal) 20085
I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838419, (internal) 20085
I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838419, (internal) 20097
I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838419, (internal) 20097
--- unknown menu character Ctrl+C --
I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838419, (internal) 20105
E (245002) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (245002) task_wdt:  - IDLE (CPU 1)
E (245002) task_wdt: Tasks currently running:
E (245002) task_wdt: CPU 0: IDLE
E (245002) task_wdt: CPU 1: player
E (245002) task_wdt: Print CPU 0 (current core) backtrace

Backtrace:0x4019FC06:0x3FFBEBA00x40084A15:0x3FFBEBC0 0x402456DF:0x3FFBC770 0x400D3B2D:0x3FFBC790 0x40098114:0x3FFBC7B0
0x4019fc06: task_wdt_isr at /dev-tooling/esp/esp-idf/components/esp_system/task_wdt.c:183 (discriminator 3)

0x40084a15: _xt_lowint1 at /dev-tooling/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1111

0x402456df: cpu_ll_waiti at /dev-tooling/esp/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:183
 (inlined by) esp_pm_impl_waiti at /dev-tooling/esp/esp-idf/components/esp_pm/pm_impl.c:837

0x400d3b2d: esp_vApplicationIdleHook at /dev-tooling/esp/esp-idf/components/esp_system/freertos_hooks.c:63

0x40098114: prvIdleTask at /dev-tooling/esp/esp-idf/components/freertos/tasks.c:3974

E (245002) task_wdt: Print CPU 1 backtrace

Backtrace:0x4008E69D:0x3FFBF3D00x40084A15:0x3FFBF3F0 0x401537AB:0x3F8D2920 0x4024362B:0x3F8D2990 0x40169462:0x3F8D29B0 0x40169B62:0x3F8D29D0 0x4016AD9A:0x3F8D2A30 0x40153399:0x3F8D2A60 0x4014FE62:0x3F8D2AE0 0x400DB22A:0x3F8D2B20
0x4008e69d: esp_crosscore_isr at /dev-tooling/esp/esp-idf/components/esp_system/crosscore_int.c:92

0x40084a15: _xt_lowint1 at /dev-tooling/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1111

0x401537ab: ChunkedByteStream::read(unsigned char*, unsigned int) at /Volumes/Brugere/tue/.espressif/tools/xtensa-esp32-elf/esp-2021r2-8.4.0/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/8.4.0/bits/shared_ptr_base.h:1167

0x4024362b: vorbisReadCb(void*, unsigned int, unsigned int, ChunkedAudioStream*) at /code/euphonium/euphonium/cspot/cspot/src/ChunkedAudioStream.cpp:9

0x40169462: _get_data at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:73
 (inlined by) _get_next_page at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:125

0x40169b62: _fetch_and_process_packet at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:614

0x4016ad9a: ov_read at /code/euphonium/euphonium/bell/tremor/vorbisfile.c:1581

0x40153399: ChunkedAudioStream::startPlaybackLoop(unsigned char*, unsigned int) at /code/euphonium/euphonium/cspot/cspot/src/ChunkedAudioStream.cpp:102

0x4014fe62: Player::runTask() at /code/euphonium/euphonium/cspot/cspot/src/Player.cpp:106

0x400db22a: bell::Task::taskEntryFuncPSRAM(void*) at /code/euphonium/euphonium/bell/include/Task.h:81

I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838419, (internal) 20105
I [core] Core.cpp:205: No data
D [core] Core.cpp:212: Free memory: (psram) 838419, (internal) 20105
ets Jul 29 2019 12:21:46

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 271414342, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:5612
ho 0 tail 12 room 4
load:0x40078000,len:14336
load:0x40080400,len:3680
0x40080400: _init at ??:?
TooDissing commented 2 years ago

Tried to turn down the quality to 160kbps, but that didn't really change anything. Only it took a little longer for the problem to occur.

TooDissing commented 2 years ago

Would it be possible to skip to the next chunk when packets are lost, or is there something else happening?

shark8594 commented 2 years ago

Try to disable or increase the watchdog timer using esp_task_wdt_init()

TooDissing commented 2 years ago

Try to disable or increase the watchdog timer using esp_task_wdt_init()

Thank you for the suggestion. When the watchdog timer triggers, they playback is already haltet. So this will only postpone the effect of the watchdog timer.

At this moment I believe that we are missing some packets that will never show up. Waiting for them is not the best option, as they will likely never appear.

feelfreelinux commented 2 years ago

Looking into the issue :)

shark8594 commented 2 years ago

I think supporting 24kbps would help with low speeds but it uses a different encoding (HE-AAC).

TooDissing commented 2 years ago

Just for reference. When using the same HW+SW setup on a higher bandwidth connection, this issue doesn't occur.