Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Bug - Stability problem on limited bandwidth #39

Open
TooDissing opened this issue May 26, 2022 · 7 comments
Open

Bug - Stability problem on limited bandwidth #39

TooDissing opened this issue May 26, 2022 · 7 comments

Comments

@TooDissing
Copy link
Contributor

TooDissing commented May 26, 2022 •
edited
Loading

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
Copy link
Contributor Author

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
Copy link
Contributor Author

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

@shark8594
Copy link

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

@TooDissing
Copy link
Contributor Author

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
Copy link
Member

Looking into the issue :)

@shark8594
Copy link

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

@TooDissing
Copy link
Contributor Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@feelfreelinux @TooDissing @shark8594