Audio from play_mp3 example lags behind same mp3 played on PC

[jeffdc1979]

When running the play_mp3 example on my LyraT, I am using a 5 minute long mp3 encoded as constant 128kbps bitrate and I am noticing the audio lagging behind the same mp3 being played on my PC.

I am running a time-sensitive program that needs the audio to match exactly to the time it was expected to play and I am unable to achieve that with the current state of the LyraT mp3 decoder ... I am unsure if this is hardware or software but I have tried just about everything I can think of to get this to work.

The audio seems to lag behind roughly 2 seconds over the course of the 5 minutes by the end of the mp3.... that is unacceptable to me

Please let me know how I can further debug this issue because it is time sensitive (no pun intended)

[ESP_Sprite]

Up to a certain point, this issue can't be solved, as the PC and the LyraT use independent time bases, both with a certain error in their time tracking... but 0.6% time difference seems suspect. Do you know if you're using the APLL? Can you post the output (especially debug lines from the I2S driver) here?

[jeffdc1979]

Here it is below .. the only thing that looked suspect to me was the bits being 16 instead of 32 (like my PC tells me they are)

ets Jun 8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x3f (SPI_FAST_FLASH_BOOT)
flash read err, 1000
ets_main.c 371
ets Jun 8 2016 00:22:57

rst:0x10 (RTCWDT_RTC_RESET),boot:0x3f (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:0x3fff0018,len:4
load:0x3fff001c,len:6140
load:0x40078000,len:8432
load:0x40080000,len:6540
entry 0x40080334
.[0;32mI (29) boot: ESP-IDF 3.30100.0 2nd stage bootloader.[0m
.[0;32mI (29) boot: compile time 23:53:42.[0m
.[0;32mI (31) boot: Enabling RNG early entropy source....[0m
.[0;32mI (34) qio_mode: Enabling QIO for flash chip GD.[0m
.[0;32mI (39) boot: SPI Speed : 40MHz.[0m
.[0;32mI (43) boot: SPI Mode : QIO.[0m
.[0;32mI (47) boot: SPI Flash Size : 4MB.[0m
.[0;32mI (51) boot: Partition Table:.[0m
.[0;32mI (55) boot: ## Label Usage Type ST Offset Length.[0m
.[0;32mI (62) boot: 0 nvs WiFi data 01 02 00009000 00006000.[0m
.[0;32mI (70) boot: 1 phy_init RF data 01 01 0000f000 00001000.[0m
.[0;32mI (77) boot: 2 factory factory app 00 00 00010000 00100000.[0m
.[0;32mI (85) boot: End of partition table.[0m
.[0;32mI (89) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x10008 ( 65544) map.[0m
.[0;32mI (117) esp_image: segment 1: paddr=0x00020030 vaddr=0x3ffc0000 size=0x020a8 ( 8360) load.[0m
.[0;32mI (120) esp_image: segment 2: paddr=0x000220e0 vaddr=0x3ffc20a8 size=0x00000 ( 0) load.[0m
.[0;32mI (124) esp_image: segment 3: paddr=0x000220e8 vaddr=0x40080000 size=0x00400 ( 1024) load.[0m
.[0;32mI (133) esp_image: segment 4: paddr=0x000224f0 vaddr=0x40080400 size=0x09e6c ( 40556) load.[0m
.[0;32mI (156) esp_image: segment 5: paddr=0x0002c364 vaddr=0x400c0000 size=0x00000 ( 0) load.[0m
.[0;32mI (156) esp_image: segment 6: paddr=0x0002c36c vaddr=0x50000000 size=0x00000 ( 0) load.[0m
.[0;32mI (163) esp_image: segment 7: paddr=0x0002c374 vaddr=0x00000000 size=0x03c9c ( 15516) .[0m
.[0;32mI (176) esp_image: segment 8: paddr=0x00030018 vaddr=0x400d0018 size=0x27a7c (162428) map.[0m
.[0;32mI (235) boot: Loaded app from partition at offset 0x10000.[0m
.[0;32mI (235) boot: Disabling RNG early entropy source....[0m
.[0;32mI (236) cpu_start: Pro cpu up..[0m
.[0;32mI (239) cpu_start: Starting app cpu, entry point is 0x400819bc.[0m
.[0;32mI (0) cpu_start: App cpu up..[0m
.[0;32mI (250) heap_init: Initializing. RAM available for dynamic allocation:.[0m
.[0;32mI (256) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM.[0m
.[0;32mI (263) heap_init: At 3FFC3220 len 0001CDE0 (115 KiB): DRAM.[0m
.[0;32mI (269) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM.[0m
.[0;32mI (275) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM.[0m
.[0;32mI (282) heap_init: At 4008A26C len 00015D94 (87 KiB): IRAM.[0m
.[0;32mI (288) cpu_start: Pro cpu start user code.[0m
.[0;32mI (81) cpu_start: Starting scheduler on PRO CPU..[0m
.[0;32mI (0) cpu_start: Starting scheduler on APP CPU..[0m
.[0;32mI (82) SDCARD_MP3_EXAMPLE: [ 1 ] Mount sdcard.[0m
.[0;32mI (182) SDCARD_MP3_EXAMPLE: [ 2 ] Start codec chip.[0m
.[0;31mE (182) gpio: gpio_install_isr_service(394): GPIO isr service already installed.[0m
.[0;32mI (202) SDCARD_MP3_EXAMPLE: [3.0] Create audio pipeline for playback.[0m
.[0;32mI (202) SDCARD_MP3_EXAMPLE: [3.1] Create fatfs stream to read data from sdcard.[0m
.[0;32mI (202) SDCARD_MP3_EXAMPLE: [3.2] Create i2s stream to write data to codec chip.[0m
.[0;32mI (212) SDCARD_MP3_EXAMPLE: [3.3] Create mp3 decoder to decode mp3 file.[0m
.[0;32mI (222) SDCARD_MP3_EXAMPLE: [3.4] Register all elements to audio pipeline.[0m
.[0;32mI (222) SDCARD_MP3_EXAMPLE: [3.5] Link it together [sdcard]-->fatfs_stream-->mp3_decoder-->i2s_stream-->[codec_chip].[0m
.[0;32mI (232) SDCARD_MP3_EXAMPLE: [3.6] Setup uri (file as fatfs_stream, mp3 as mp3 decoder, and default output is i2s).[0m
.[0;32mI (242) SDCARD_MP3_EXAMPLE: [ 4 ] Setup event listener.[0m
.[0;32mI (252) SDCARD_MP3_EXAMPLE: [4.1] Listening event from all elements of pipeline.[0m
.[0;32mI (262) SDCARD_MP3_EXAMPLE: [4.2] Listening event from peripherals.[0m
.[0;32mI (272) SDCARD_MP3_EXAMPLE: [ 5 ] Start audio_pipeline.[0m
.[0;32mI (272) SDCARD_MP3_EXAMPLE: [ 6 ] Listen for all pipeline events.[0m
.[0;32mI (302) SDCARD_MP3_EXAMPLE: [ * ] Receive music info from mp3 decoder, sample_rates=44100, bits=16, ch=2.[0m

[jeffdc1979]

Are the clock cycles not running fast enough that the audio codec is unable to keep the correct time for the mp3 exactly as it was exported? I am confused ... I thought the clock on the lyraT was more than fast enough to keep up with streaming the mp3 correctly

[ESP_Sprite]

It's hard to say, but unless you hear stutters in the music or have a point where you note the music de-syncs, I think CPU cycles is not your issue. You can check by recording the output of the ESP32 in e.g. Audacity, and looking at the wave stream to see if there's a particular point the stream de-syncs or if the change happens slowly over time. Given the ESP32 is pretty capable of decoding an MP3 plus doing a whole bunch of other things in parallel, I don't think this is the issue, however.

I just checked the ADK code, and the ADK uses the APLL, which should give you an output frequency stability that is pretty high, so I also don't think sync is the issue.... that leaves me out of ideas, sorry.

You said you already tried everything... did that include trying differently formatted MP3s, or even WAVs, bypassing the MP3 decoder alltogether? What was the result of that?

[jeffdc1979]

I did indeed try other encodings and WAV file and they all had the exact same problem. This leads be to believe it's something in the ADF code base. I haven't tried bypassing ADF yet. How can I do that? I can send the mp3 privately if that helps. I am using audacity to test everything vs ADF playback

[jeffdc1979]

I am going to try your suggestion of recording the output from the lyraT into audacity and examine the wavefront to see when it diverges. It definitely gets worse over time so it's a slow constant desynch

[ESP_Sprite]

Ah, that helps a lot: if the wav file has the same issue, the problem is not in the mp3 decoder; that is helpful because the mp3 decoder is quite complex, as you might imagine.

In case the difference between the PC and ESP32 indeed is gradual and the ESP32 doesn't just stop playing for a fraction of a second: do you have access to a frequency counter? If you generate a simple .wav containing e.g. an 1KHz sine wave and play it through both the ESP32 and through the PC, and connect the frequency counter to the audio output of the device that's playing it, what does it say?

[jeffdc1979]

I do not have a frequency counter or have access to one. Any other suggestions?

[jeffdc1979]

I have a recording of the output from the LyraT now and can send you both audio files to compare against in Audacity. You can easily see where the signal starts to diverge from the original mp3. By the end of the 5 minute mp3, the LyraT output is off by almost exactly 1 second when comparing wave peaks near the end of the file.

Tell me where to send the audio files and I will so someone can examine them. If I have a faulty LyraT, I would like to send it back to Espressif for a new one please ... I do not have a second one to test with though