Closed h3ndrik closed 7 months ago
pschatzmann
commented
7 months ago I think you are pulling your own leg by having the log level set to info. This is impacting the audio quality. Make sure that it is set the log level to warning or error
https://github.com/pschatzmann/arduino-snapclient/wiki/Testing-Output
I was just retesting this and could not reproduce your issues, so I am closing this...
h3ndrik
commented
7 months ago Yeah, I just set the loglevel to INFO to be able to provide logs. I've reverted that, set it to Error and it doesn't change anything. Issue remains the same.
Thanks for the link to the Testing-Output. Did you happen to write any more documentation on how to debug things and find out which buffers are filled to what level etc?
pschatzmann
commented
7 months ago Strange! Can it be that you have a bad wifi connection that is slowing things down ? Did you change any other settings on the server ? Did you try to repeat my testing steps ?
The current implementation is not using any buffering. The server sends the audio data which to the decoder which just forwards the result to the i2s output. So the only place where you could increase the buffer size is in the I2S configuration. In your log I can see that you are currently using 6 * 1024
You can also try to deactivate the PSRAM. If I remember right, I did not activate it in the Arduino Menu for my tests.
Of cause it would be pretty easy to subclass the SnapOutput class and extend it with a buffer, but I guess this would not really help if the sending from the server is too slow.
You could also try to play with the different Synchonization implemntations: e.g
ps. in your log, it shows that you are using WAV with 48000: This is definitely too much for a simple esp32 with it's slow wifi!
h3ndrik
commented
7 months ago Thank you. Somehow I missed that Wiki page about testing. I've done that in the meantime. I'm using 44100:16:2 now and I went back not using PCM, I've tested it all since I didn't know if it's the decoder performance or the network speed, and I'm still not sure. But the computer and my phone can play back the snapcast stream just fine.
I had hoped you'd provide me with something that newbies to the arduino-audio-lib frequently get wrong... Maybe I have to wrap my head around how all the internals tie together and add a few debug printf statements to get to the root.
I've restarted my wifi router, I've moved the ESP32 closer to the router and installed another Snapserver on my laptop and configured it like on the Wiki page. I've tried SnapTimeSyncFixed and PSRAM and no Psram, I've fiddled with many values but I can only make it worse.
I'm using an Lolin D32 Pro and a MAX98357A I2S amp, which is described in the arduino-audio-tools wiki.
I didn't understand that SnapClient::doLoop() was a blocking method. I've moved that into another task with a decent stack size, and I'm trying to use the main loop to get some debug information every few seconds... What I found out already:
The last two can't be right?! Doesn't that mean the i2s dma buffer is next to empty and underrunning? it is currently configured to be 6*512. But if it were empty all the time, it'd explain why changing the buffers doesn't do anything. What's the next step, see what the Decoder does? (I'll also set up yet another snapserver on a different Linux distro with a wired network.)
pschatzmann
commented
7 months ago Can you attach some recorded example how it sounds, so that I can get a better feeling. The i2s.available() and availableForWrite() just return a fixed value because the ESP has no API to provide this information and I am using a blocking read and blocking write so that this amount is always working.
h3ndrik
commented
7 months ago Ah, thx. Yeah I'm currently wrapping up things for today. I'll see if I can get some more info tomorrow. I also fiddled with the APLL (since I used to have issues with that on old revisions of the ESP32) and logging and currently everything is a mess ;-) I'll also try a different development board and provide the code and platformio.ini
pschatzmann
commented
7 months ago I committed some additional DRAFT code that implements a processor which uses FreeRTOS to buffer the encoded data.
If you can't resolve your issue by increasing the I2S buffer parameters, then this might be another option. To use this you also might need to update the AudioTools ...
Here is the corresponding example.
ps. The new procesor is only only 113 lines of code!
h3ndrik
commented
7 months ago Thank you. Sorry for this lengthy discussion. I've attached logs below... But I think I should take a step back and replicate your proven setup before wasting more of our time... I think I'm currently doing too many things at once. I'll clean up my development environment first.
May I have the details of the setup you use to compile this?
I got webradio streams from the audio-tools examples working, even the a2dp example. Increasing the I2S buffers helps there but 3 days ago when I tried increasing the buffers for the snapcast example, it didn't change anything.
I didn't have any success with the FreeRTOS code, yet:
ELF file SHA256: 97c69dc2502e6733
E (416) esp_core_dump_flash: Core dump flash config is corrupted! CRC=0x7bd5c66f instead of 0x0
Rebooting...
ets Jun 8 2016 00:22:57
rst:0xc (SW_CPU_RESET),boot:0x37 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:1344
load:0x40078000,len:13964
load:0x40080400,len:3600
entry 0x400805f0
assert failed: xStreamBufferGenericCreate stream_buffer.c:299 (xBufferSizeBytes > 0)
Backtrace: 0x40083b71:0x3ffe3a50 0x4008f09d:0x3ffe3a70 0x400951dd:0x3ffe3a90 0x4009268d:0x3ffe3bc0 0x400dd4c9:0x3ffe3be0 0x400dd76c:0x3ffe3c00 0x400febcb:0x3ffe3c20 0x40083285:0x3ffe3c50 0x40079316:0x3ffe3c90 |<-CORRUPTED
#0 0x40083b71:0x3ffe3a50 in panic_abort at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/esp_system/panic.c:408
#1 0x4008f09d:0x3ffe3a70 in esp_system_abort at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/esp_system/esp_system.c:137
#2 0x400951dd:0x3ffe3a90 in __assert_func at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/newlib/assert.c:85
#3 0x4009268d:0x3ffe3bc0 in xStreamBufferGenericCreate at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/freertos/stream_buffer.c:299 (discriminator 1)
#4 0x400dd4c9:0x3ffe3be0 in audio_tools::SynchronizedBufferRTOS<unsigned char>::SynchronizedBufferRTOS(unsigned int, unsigned int, unsigned int, unsigned int) at .pio/libdeps/lolin_d32_pro/- arduino-audio-tools/src/AudioTools/SynchronizedBuffers.h:348
(inlined by) SnapProcessorRTOS::SnapProcessorRTOS(int, int) at .pio/libdeps/lolin_d32_pro/- arduino-snapclient/src/api/SnapProcessorRTOS.h:23
(inlined by) __static_initialization_and_destruction_0 at src/main.cpp:20
#5 0x400dd76c:0x3ffe3c00 in _GLOBAL__sub_I__ZN17SnapProcessorRTOS4selfE at src/main.cpp:99
#6 0x400febcb:0x3ffe3c20 in do_global_ctors at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/esp_system/startup.c:201
(inlined by) start_cpu0_default at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/esp_system/startup.c:444
#7 0x40083285:0x3ffe3c50 in call_start_cpu0 at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/esp_system/port/cpu_start.c:679
#8 0x40079316:0x3ffe3c90 in ?? ??:0And in the normal example I had to add client.setServerIP() now. MDNS or setting CONFIG_SNAPCAST_SERVER_HOST seemed not to be enough anymore?!
[ 3655][I][SnapClient.h:98] begin(): [SnapClient] Connected to AP
[ 3656][I][SnapClient.h:222] setupMACAddress(): [SnapClient] mac: B4:E6:2D:A4:6D:E9
[ 6765][I][SnapClient.h:183] setupMDNS(): [SnapClient] SNAPCAST ip: 172.16.33.20, port: 1704
[ 7839][I][SnapTime.h:62] printLocalTime(): [SnapTime] SNTP: Time is 28-02-2024 18-22-18
[ 10842][I][WiFiClient.cpp:260] connect(): select returned due to timeout 3000 ms for fd 48
[ 10842][E][SnapProcessor.h:217] connectClient(): [SnapProcessor] ... socket connect failed errno=119
[ 17861][I][WiFiClient.cpp:260] connect(): select returned due to timeout 3000 ms for fd 48
[ 17861][E][SnapProcessor.h:217] connectClient(): [SnapProcessor] ... socket connect failed errno=119
[ 24880][I][WiFiClient.cpp:260] connect(): select returned due to timeout 3000 ms for fd 48
[ 24880][E][SnapProcessor.h:217] connectClient(): [SnapProcessor] ... socket connect failed errno=119And if I do [set setServerIP(...)], this also boot-loops now:
ELF file SHA256: da66da10cd850e9c
Rebooting...
ets Jun 8 2016 00:22:57
rst:0xc (SW_CPU_RESET),boot:0x37 (SPI_FAST_FLASH_BOOT)
configsip: 0, 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:1184
load:0x40078000,len:13232
load:0x40080400,len:3028
entry 0x400805e4
[ 471][I][esp32-hal-psram.c:96] psramInit(): PSRAM enabled
Connecting to WiFi .....
172.16.33.189
[I] AudioTypes.h : 104 - sample_rate: 48000
[I] AudioTypes.h : 105 - channels: 2
[I] AudioTypes.h : 106 - bits_per_sample: 16
[I] I2SConfigESP32.h : 90 - rx/tx mode: TX_MODE
[I] I2SConfigESP32.h : 91 - port_no: 0
[I] I2SConfigESP32.h : 92 - is_master: Master
[I] I2SConfigESP32.h : 93 - sample rate: 48000
[I] I2SConfigESP32.h : 94 - bits per sample: 16
[I] I2SConfigESP32.h : 95 - number of channels: 2
[I] I2SConfigESP32.h : 96 - signal_type: Digital
[I] I2SConfigESP32.h : 98 - i2s_format: I2S_STD_FORMAT
[I] I2SConfigESP32.h : 100 - auto_clear: true
[I] I2SConfigESP32.h : 102 - use_apll: true
[I] I2SConfigESP32.h : 107 - buffer_count:6
[I] I2SConfigESP32.h : 108 - buffer_size:512
[I] I2SConfigESP32.h : 113 - pin_bck: 14
[I] I2SConfigESP32.h : 115 - pin_ws: 15
[I] I2SConfigESP32.h : 117 - pin_data: 22
[ 3653][I][SnapClient.h:98] begin(): [SnapClient] Connected to AP
[ 3654][I][SnapClient.h:222] setupMACAddress(): [SnapClient] mac: B4:E6:2D:A4:6D:E9
[ 3662][I][SnapTime.h:62] printLocalTime(): [SnapTime] SNTP: Time is 28-02-2024 18-10-22
E (7644) wifi:CCMP replay detected: A1=b4:e6:2d:a4:6d:e9 A2=98:da:c4:bf:f3:96 PN=4, RSC=5 seq=26992
[ 6425][I][SnapProcessor.h:126] processLoopStep(): [SnapProcessor] ... connected
[ 6531][I][SnapProcessor.h:429] processMessageServerSettings(): [SnapProcessor] Message Buff.ms:1000
[ 6532][I][SnapProcessor.h:430] processMessageServerSettings(): [SnapProcessor] Latency: 0
[ 6538][I][SnapProcessor.h:431] processMessageServerSettings(): [SnapProcessor] Mute: false
[ 6547][I][SnapProcessor.h:432] processMessageServerSettings(): [SnapProcessor] Setting volume: 100
Guru Meditation Error: Core 1 panic'ed (LoadProhibited). Exception was unhandled.
Core 1 register dump:
PC : 0x400d7507 PS : 0x00060530 A0 : 0x800d9bc5 A1 : 0x3ffb3190
A2 : 0x3ffc3d38 A3 : 0x000001f4 A4 : 0x00000000 A5 : 0x3f4001ce
A6 : 0x00000000 A7 : 0x00010000 A8 : 0x800d74ff A9 : 0x3ffb3170
A10 : 0x0000199c A11 : 0x0000199c A12 : 0x3f4001ce A13 : 0x0000002e
A14 : 0x3f401932 A15 : 0x3f40157e SAR : 0x0000000a EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000004 LBEG : 0x40085bc1 LEND : 0x40085bc9 LCOUNT : 0x00000027
Backtrace: 0x400d7504:0x3ffb3190 0x400d9bc2:0x3ffb31e0 0x400d9d18:0x3ffb3200 0x400d9d2d:0x3ffb3250 0x400d69c7:0x3ffb3270 0x400ecc89:0x3ffb3290
#0 0x400d7504:0x3ffb3190 in SnapTimeSync::setMessageBufferDelay(int) at .pio/libdeps/lolin_d32_pro/- arduino-snapclient/src/api/SnapTimeSync.h:46 (discriminator 6)
(inlined by) SnapProcessor::processMessageServerSettings() at .pio/libdeps/lolin_d32_pro/- arduino-snapclient/src/api/SnapProcessor.h:435 (discriminator 6)
#1 0x400d9bc2:0x3ffb31e0 in SnapProcessor::processMessageLoop() at .pio/libdeps/lolin_d32_pro/- arduino-snapclient/src/api/SnapProcessor.h:190
#2 0x400d9d18:0x3ffb3200 in SnapProcessor::processLoopStep() at .pio/libdeps/lolin_d32_pro/- arduino-snapclient/src/api/SnapProcessor.h:141
#3 0x400d9d2d:0x3ffb3250 in SnapProcessor::doLoop() at .pio/libdeps/lolin_d32_pro/- arduino-snapclient/src/api/SnapProcessor.h:70
#4 0x400d69c7:0x3ffb3270 in SnapClient::doLoop() at .pio/libdeps/lolin_d32_pro/- arduino-snapclient/src/SnapClient.h:150
(inlined by) loop() at src/main.cpp:98
#5 0x400ecc89:0x3ffb3290 in loopTask(void*) at /home/hendrik/.platformio/packages/framework-arduinoespressif32/cores/esp32/main.cpp:50Unrelated to that, I found the following in the SnapServer log, regarding the sample rates, after I've changed to another Snapserver version on another (older Debian) computer... It overrides the sample rate I've configured:
Feb 28 18:15:43 host snapserver[20350]: Resampling input from 44100:16:2 to 48000:16:2 as required by Opus
Feb 28 18:15:43 host snapserver[20350]: Resampling from 44100:16:2 to 48000:16:2
Feb 28 18:15:43 host snapserver[20350]: Opus bitrate: 192000 bps, complexity: 10The error message: assert failed: xStreamBufferGenericCreate stream_buffer.c:299 (xBufferSizeBytes > 0) comes from a missing update of the AudioTools. I only recently added the functionality to support the creation of an empty buffer which is resized later.
I tested in Arduino with the ESP32 version 2.0.11 and 2.0.14. The Arduino IDE version does not matter.
The sample rate configuration is on the Server.
pschatzmann
commented
7 months ago You are right: the server IP logic was broken because I needed to change the data flow to support the new processor class. The correction has been committed
pschatzmann
commented
7 months ago ps. I noticed that I am getting crashes when the ESP32 is starting with a running snap sending audio. The sequence starting ESP32 and then starting the Server Audio seems to work reliably. I am not sure what might cause this...
h3ndrik
commented
7 months ago Wow, I've never had that many annoyances with PlatformIO. Thank you.
Additionally, it turns out PlatformIO doesn't choose a sane version of the Arduino framework per default. And my previous attempt at changing that somehow failed. I managed to set the version of the Arduino framework now and it sounds way better!
If I choose SnapTimeSyncFixed synch(CONFIG_PROCESSING_TIME_MS, 1.0); it plays almost fine but constantly makes some minor crackling noises. I think that's some resampling or dropping small chunks? It doesn't seem to apply the 1.0 correctly.
But when I use SnapTimeSyncDynamic synch(172, 10);, it'll intermittendly say the following and the sound becomes crystal clear:
[ 23496][I][SnapTimeSync.h:113] getFactor(): [SnapTimeSync] => adjusting playback speed by factor: 1.000000
[I] ResampleStream.h : 267 - setStepSize: 1.000000After that it'll sometimes choose different values and it starts to crackle again, but not as bad as it did before when it was super choppy. So I think I almost got it. My main issue seems to have been the Arduino framework version.
Two more things about the recent changes:
client.begin() a SnapTimeSync object. Maybe that's a regression?client.setServerIP() also doesn't seem right.pschatzmann
commented
7 months ago I also noticed some rare hickups and I think this might come when the i2s buffer is running empty, so increasing it might help. With the RTOS buffer version however there is no such issue any more...
h3ndrik
commented
7 months ago Does the PROCESSING_TIME_MS work with the SnapProcessorRTOS? The ESP is always a bit ahead and it doesn't seem to make a difference what I set there.
And I have one more question: How is the AudioConfigLocal.h in the arduino-audio-tools supposed to work? AudioConfig.h includes it, but I can practically not do anything as it goes on to then define everything anyways? I would have expected something like an ifdef and an else... And the opportunity to not define or undefine something.
pschatzmann
commented
7 months ago It should, but because I am also always confused how this is working, I reversed the logic today:
Before it was just the other way around.
If you use the SnapProcessorRTOS you can also play with the buffer size to adjust the delay
h3ndrik
commented
7 months ago I found another thing that seems related to my remaining crackling... Why is that a funny number and not 1.0f?
Additionally: SnapTimeSyncFixed seems to be constantly resampling with that... Is it correct that SnapTimeSync::isSync() can never be true with the SyncFixed? Since it never increases update_count, contrary to the other classes...
pschatzmann
commented
7 months ago You are right, it should be 1.0f. I guess I was playing around and forget to reset the value...
h3ndrik
commented
7 months ago Alright, by the way: the factor 1.0 from the SnapTimeSyncFixed constructor doesn't ever propagate to the resampler... This is another bug. I don't know why...
Edit: and snapProcessor.setVolumeFactor(0.1f) in my setup gets through, but then when the pipeline starts something messes with that and in the end the volume is 1.0 and not 0.1
pschatzmann
commented
7 months ago It is supposed to be res_cfg.step_size = p_snap_time_sync->getFactor();
h3ndrik
commented
7 months ago Thanks a lot for all the help! I'm closing this now. If someone else reads this: If you're using PlatformIO, make sure you're using a recent Arduino core. That was my very first issue. And use Opus. I've included the most important settings below, I'll try to contribute a more complete PlatformIO example once I get it working.
[env:lolin_d32_pro]
platform = https://github.com/platformio/platform-espressif32.git#develop
board = lolin_d32_pro
framework = arduino
platform_packages =
platformio/framework-arduinoespressif32 @ https://github.com/espressif/arduino-esp32.git#2.0.14
lib_deps =
arduino-snapclient=https://github.com/pschatzmann/arduino-snapclient
arduino-audio-tools=https://github.com/pschatzmann/arduino-audio-tools
arduino-libopus=https://github.com/pschatzmann/arduino-libopus
build_flags =
-D USE_AUDIO_LOGGING=true
-D LOG_LEVEL="AudioLogger::Warning"
-D LOG_STREAM="Serial"
-D LOG_LOCAL_LEVEL=ESP_LOG_WARNING
-D CORE_DEBUG_LEVEL=ARDUHAL_LOG_LEVEL_WARN
-D CONFIG_ARDUHAL_LOG_COLORSDid you finally use SnapProcessorRTOS or SnapProcessor ?
h3ndrik
commented
7 months ago I've switched to SnapProcessorRTOS not long after we talked about that. And I'm using Opus with its single supported bitrate of 48000. That seems to be the only working codec as of now. I've tested both a Snapserver in the local network and an unusual setup where it's running on a VPS on the internet. Both seem to work.
I followed the example code closely and set up an ESP32 with PSRAM and an external I2S DAC. Project is built in PlatformIO and I've made sure the CPU is set to 240MHz.
Sound output is very stuttery, from unusable to unbearable. What am I doing wrong?
My current try with PCM and an increased I2S buffer_size (same bad sound as with 512) gives that output: