search

music-assistant / hass-music-assistant

Turn your Home Assistant instance into a jukebox, hassle free streaming of your favorite media to Home Assistant media players.
Apache License 2.0
1.2k stars 44 forks source link

yt-dlp - Prefetch next tracks sooner to preclude long silence when skipping tracks #2536

Open TheWebMachine opened 4 days ago

TheWebMachine commented 4 days ago

What version of Music Assistant has the issue?

2.1.0b8

What version of the Home Assistant Integration have you got installed?

2024.6.2

Have you tried everything in the Troubleshooting FAQ and reviewed the Open and Closed Issues and Discussions to resolve this yourself?

The problem

With the new yt-dlp, the track prefetch is very slow (VM with ample resources and a gigabit internet connection). This, on it's own, is fine, but causes headache when skipping tracks.

Is it possible to: 1) Set next track prefetch to start immediately after the current track is fetched and starts playing - so it is ready in case we skip the currently playing track as soon as it starts

2) Provide an option that specifies how many tracks beyond the currently playing track we want prefetched - assuming this is consuming either disk or RAM for the prefetch, those of us with more generous builds can prefetch, say, up to 5 tracks in the upcoming queue, so if we skip more than one, playback of the next track is still quick

How to reproduce

Play YT music Await track to start Skip wait again for multiple seconds, sometimes 10+ before next track begins playback because it was not prefetched early enough

Music Providers

YTM

Player Providers

Google Cast

Full log output

No response

Additional information

No response

What version of Home Assistant Core are your running

2024.6.4

What type of installation are you running?

Home Assistant OS

On what type of hardware are you running?

Linux

MarvinSchenkel commented 4 days ago

Quick questions before I am gonna try reproducing this , since I noticed slowdown during development when running in a debug environment.

TheWebMachine commented 4 days ago
  • Do you have debug logging enabled? Either globally or in YT Music provider?

I experienced this with debug off across the board. I turned on debug to check for errors, which had no effect on the delay, which existed before I turned debug on.

  • You say you're running on a VM. Are you running MA on a VM or are you running it as an addon within MA? If the first, do you experience the same slowdown if you run MA in the addon?

My apologies. I always jumble the terms around. I am running HAOS within a virtualbox VM on a linux host and MA is running as add-on container within HAOS. Nothing special.

I had nearly zero delays with the previous yt library. It was only upon switching to the latest version with yt-dlp do I see the long delays on fetching tracks.

MarvinSchenkel commented 4 days ago

@tronikos Ouch, seems there are some delays with the new setup. Strange thing is that is working within 2-3 on my NUC + Proxmox + HAOS.

@TheWebMachine what hardware are you running your VM on? Also, when you enable debug logging, can you include a log after you are trying to play a track?

tronikos commented 4 days ago

In the VS code debugger I was seeing a delay of 30s. Running it directly on my dev machine I was seeing a delay of 2-5s. I just updated beta on my prod machine (i7 1.8 GHz, 4GB) that runs bare metal HAOS and I'm seeing a delay of 8-10s.

TheWebMachine commented 4 days ago

@TheWebMachine what hardware are you running your VM on? Also, when you enable debug logging, can you include a log after you are trying to play a track?

Oh, the VM is running on a beasty AMD R9 5900 host system and has the following assigned to it: 4 CPU cores, 8GiB RAM, direct bridged network adapter with static IP on the LAN

HA routinely pulls a CPU load of less than 10% with RAM usage around 20%. The MA add-on is pulling the following:

While fetching - about 20-40% CPU After fetching while playing a track - less than 1% CPU (RAM remains pretty constant)

This log begins from the time I click to skip to the next track and ends a few seconds after playback begins: MA-Debug-log-2.1.0b8.txt

Oh, and ignore the stream aborts at the end. Those were from previous track skips as I was preparing to capture a snip of the log. I forgot to redact them.

TheWebMachine commented 4 days ago

In the VS code debugger I was seeing a delay of 30s. Running it directly on my dev machine I was seeing a delay of 2-5s. I just updated beta on my prod machine (i7 1.8 GHz, 4GB) that runs bare metal HAOS and I'm seeing a delay of 8-10s.

8-10s is in line with what I'm experiencing most of the time. I don't think it's a resource bottleneck on the part of the hardware, though. Again, during normal playback, it isn't an issue, as prefetch is happening early enough. But, when trying to skip tracks, the delay is annoying. Especially since the current track continues to play after you click next...then 8-10s later the next track randomly starts playing.

If you click next a few times rapidly (like I did before I knew what was happening), then you experience a super long delay, as it prefetches before realizing you hit more than one skip, then just starts prefetching the next one, and the next, and the next, until it exhausts the skips...while keeping you in silence the whole time.

TheWebMachine commented 4 days ago

This is why I propose proactively prefetching as many tracks ahead as we reasonably can (3-5 would be nice) while the current track is playing. Then, you'd have to hit next the 3-5x before you exhausted the prefetch cache and experienced a delay (at least beyond the first track you start playing, as that will always have a prefech silence before sound is heard).

What is our limiting factor in prefetching multiple tracks in succession? RAM? Storage?

MarvinSchenkel commented 4 days ago

Just to be super clear here, the delay is caused by resolving a stream url for a track, not playing back the actual audio from a given stream url. There's a lot of decryption and cipher magic happening in the background that involves downloading youtube source code to figure out decryption keys. This is CPU intensive and might explain why we are seeing higher delays on other systems. Once the url is resolved, the stream url itself starts instantly.

We could pre-fetch a couple of stream urls that are in the active queue, but this requires a change in the logic of handling the queue and only has a positive effect on YT Music, since it is not required for any other music providers. @marcelveldt any thoughts on this?

tronikos commented 4 days ago

In the meantime shall we add back the support for using the pytube library and default to it?

TheWebMachine commented 4 days ago

In the meantime shall we add back the support for using the pytube library and default to it?

I was having no issues with pytube (as far as I know). Perhaps add an advanced option in YTM provider to switch between libraries and/or default to pytube. This way we can quickly switch if pytube quits working in the future.

MarvinSchenkel commented 4 days ago

In the meantime shall we add back the support for using the pytube library and default to it?

Yeah sounds like a plan. Won't be later this week until I have time to add that back in.

MarvinSchenkel commented 4 days ago

@tronikos Do you think we can speed up yt dlp by providing some clever options? I came across quite some stuff we can try:

This file can be used to translate the cli flags/options to python options: https://github.com/yt-dlp/yt-dlp/blob/f3411af12e209bc5624e1ac31271b8aabe2d3c90/yt_dlp/options.py#L355

MarvinSchenkel commented 4 days ago

Okay I figured something out. I am now forcing the ios client to obtain stream urls and I get 2 secs in the debugger and somewhere between 1-2sec on a prd like environment

@TheWebMachine are you comfortable with installing the dev addon to give this a go on your setup? If you go to the addon configuration page you can use fix/ytdlp_delays as the branch name.

If you set the log level to DEBUG you will also see the exact timings in the log since I added a timer in the code.

TheWebMachine commented 3 days ago

Installed and waiting for it to build out and start...

I simply stopped the main add-on while testing dev; hopefully this doesn't cause any issues.

Will report back shortly...

Edit: Ah, it has to be setup from scratch. I'll report back tonight when I have time to set everything up in dev version.

MarvinSchenkel commented 3 days ago

Yep that should work fine. It's a separate addon / environment so you'll have to setup YT Music again.

Op di 25 jun 2024 om 19:43 schreef TheWebMachine @.***>

Installed and waiting for it to build out and start...

I simply stopped the main add-on while testing dev; hopefully this doesn't cause any issues.

Will report back shortly...

— Reply to this email directly, view it on GitHub https://github.com/music-assistant/hass-music-assistant/issues/2536#issuecomment-2189595497, or unsubscribe https://github.com/notifications/unsubscribe-auth/AEG2MJZCUUGL6BLCK5CR25LZJGT4FAVCNFSM6AAAAABJ2WPH3CVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCOBZGU4TKNBZG4 . You are receiving this because you were assigned.Message ID: @.***>

TheWebMachine commented 3 days ago

Yeah, immediately ran into issues:

First setup of YTM provider went fine, but loaded no playlists. Restarting dev add-on resulted in this error:

2024-06-25 12:47:58.813 ERROR (MainThread) [music_assistant] Error loading provider(instance) YouTube Music: Provider ytmusic did not load within 30 seconds

Attempted to rebuild add-on and started getting this error:

2024-06-25 12:50:57.668 ERROR (MainThread) [music_assistant] Error doing task: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/aiorun.py", line 219, in new_coro
    await coro
  File "/usr/local/lib/python3.12/site-packages/music_assistant/__main__.py", line 212, in start_mass
    await mass.start()
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/server.py", line 160, in start
    await self._load_providers()
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/server.py", line 510, in _load_providers
    await self.config.create_builtin_provider_config(prov_manifest.domain)
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/controllers/config.py", line 488, in create_builtin_provider_config
    for _ in await self.get_provider_configs(provider_domain=provider_domain):
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/controllers/config.py", line 171, in get_provider_configs
    and (provider_domain is None or prov_conf["domain"] == provider_domain)
                                    ~~~~~~~~~^^^^^^^^^^
KeyError: 'domain'

Blowing out the whole dev container and starting again...

TheWebMachine commented 3 days ago

Actually, just noticed I get the second error (KeyError: 'domain') on first install of Dev, even before changing branch. 🧐

MarvinSchenkel commented 3 days ago

Yeah we are still tracing that weird "domain" error. A full reinstall of the addon sometimes fixes it 😁. Should be unrelated to YT Music though, so if you manage to get pass that you should be able to give it a go

Op di 25 jun 2024 om 19:53 schreef TheWebMachine @.***>

Yeah, immediately ran into issues:

First setup of YTM provider went fine, but loaded no playlists. Restarting dev add-on resulted in this error:

2024-06-25 12:47:58.813 ERROR (MainThread) [music_assistant] Error loading provider(instance) YouTube Music: Provider ytmusic did not load within 30 seconds

Attempted to rebuild add-on and started getting this error:

2024-06-25 12:50:57.668 ERROR (MainThread) [music_assistant] Error doing task: Task exception was never retrieved Traceback (most recent call last): File "/usr/local/lib/python3.12/site-packages/aiorun.py", line 219, in new_coro await coro File "/usr/local/lib/python3.12/site-packages/music_assistant/main.py", line 212, in start_mass await mass.start() File "/usr/local/lib/python3.12/site-packages/music_assistant/server/server.py", line 160, in start await self._load_providers() File "/usr/local/lib/python3.12/site-packages/music_assistant/server/server.py", line 510, in _load_providers await self.config.create_builtin_provider_config(prov_manifest.domain) File "/usr/local/lib/python3.12/site-packages/music_assistant/server/controllers/config.py", line 488, in create_builtin_providerconfig for in await self.get_provider_configs(provider_domain=provider_domain): ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/music_assistant/server/controllers/config.py", line 171, in get_provider_configs and (provider_domain is None or prov_conf["domain"] == provider_domain) ~~~~~^^^^^^^^^^ KeyError: 'domain'

Blowing out the whole dev container and starting again...

— Reply to this email directly, view it on GitHub https://github.com/music-assistant/hass-music-assistant/issues/2536#issuecomment-2189617621, or unsubscribe https://github.com/notifications/unsubscribe-auth/AEG2MJ7HJXQ25JS7TQZRHM3ZJGVDFAVCNFSM6AAAAABJ2WPH3CVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCOBZGYYTONRSGE . You are receiving this because you were assigned.Message ID: @.***>

TheWebMachine commented 3 days ago 
2024-06-25 13:01:15.022 WARNING (MainThread) [music_assistant] Exception in task Task-234 - target: <coroutine object MusicController._start_provider_sync.<locals>.run_sync at 0x7ff8885dfe20>: argument of type 'NoneType' is not iterable

No playlists or tracks sync from YTM at all. 🤷🏻‍♂️

TheWebMachine commented 3 days ago 
2024-06-25 13:01:15.035 WARNING (MainThread) [music_assistant.music] Sync task for YouTube Music completed with errors
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/controllers/music.py", line 700, in run_sync
    await provider.sync_library(media_types)
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/models/music_provider.py", line 413, in sync_library
    library_item = await controller.add_item_to_library(
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/controllers/media/base.py", line 128, in add_item_to_library
    library_id = await self._add_library_item(item)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/controllers/media/tracks.py", line 345, in _add_library_item
    await self._set_track_album(
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/controllers/media/tracks.py", line 427, in _set_track_album
    album = await self.mass.music.albums.get_provider_item(
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/controllers/media/base.py", line 558, in get_provider_item
    if item := await provider.get_item(self.media_type, item_id):
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/models/music_provider.py", line 278, in get_item
    return await self.get_album(prov_item_id)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/providers/ytmusic/__init__.py", line 298, in get_album
    return self._parse_album(album_obj=album_obj, album_id=prov_album_id)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/music_assistant/server/providers/ytmusic/__init__.py", line 625, in _parse_album
    album.metadata.description = unquote(album_obj["description"])
                                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/urllib/parse.py", line 684, in unquote
    if '%' not in string:
       ^^^^^^^^^^^^^^^^^
TypeError: argument of type 'NoneType' is not iterable
MarvinSchenkel commented 3 days ago

This fix is being worked on. The only relevant thing to test is the time it takes to start a track. Can you pick a random track to test? Or use the search to find something if nothing gets synced

TheWebMachine commented 3 days ago

Yeah, I can't do anything with the Dev version and YTM. Nothing syncs, search doesn't work. There's nothing here for me to play. Restarting the add-on, I see YTM provider has failed to load again and I'm seeing this in logs:

[youtube+oauth2] oauth2: Initializing OAuth2 Authorization Flow
[youtube+oauth2] To give yt-dlp access to your account, go to  https://www.google.com/device  and enter code  GFP-QKH-XWC
2024-06-25 13:18:33.847 ERROR (MainThread) [music_assistant] Error loading provider(instance) YouTube Music: Provider ytmusic did not load within 30 seconds

Screenshot_20240625_124844_Home Assistant

As an aside, been meaning to submit a request for this:

Can a re- authenticate button be added to YTM? If the token gets invalidated for any reason, you have to delete and setup the entire Provider again to obtain a new token, which means awaiting a new sync.

At any rate, restarting the Dev add-on loses the token and crashes the provider, but even from initial setup, I am unable to test YTM at all because nothing is accessible or visible from YTM, even in search. Tried setting up about 6 times in succession now and same results every time. Aside from the errors already shared here, I see nothing else in the debug log of interest.

MarvinSchenkel commented 3 days ago

Tokens should be revalidated automatically. Can you try completely removing the addon and reinstall it from the store and then fill in my branch to sync? I feel stuff is interfering with a possible previous dev instance, since you mentions that you got the domain error before you even put the branch name in? If that doesn't work I'll see if I can work out some stuff tomorrow so you can test properly

Op di 25 jun 2024 om 20:25 schreef TheWebMachine @.***>

Yeah, I can't do anything with the Dev version and YTM. Nothing syncs, search doesn't work. There's nothing here for me to play. Restarting the add-on, I see YTM provider has failed to load again and I'm seeing this in logs:

[youtube+oauth2] oauth2: Initializing OAuth2 Authorization Flow [youtube+oauth2] To give yt-dlp access to your account, go to https://www.google.com/device and enter code GFP-QKH-XWC 2024-06-25 13:18:33.847 ERROR (MainThread) [music_assistant] Error loading provider(instance) YouTube Music: Provider ytmusic did not load within 30 seconds

Screenshot_20240625_124844_Home.Assistant.jpg (view on web) https://github.com/music-assistant/hass-music-assistant/assets/1045052/a5800d72-231e-4525-9329-7faf0ee0be36

As an aside, been meaning to submit a request for this:

Can a re- authenticate button be added to YTM? If the token gets invalidated for any reason, you have to delete and setup the entire Provider again to obtain a new token, which means awaiting a new sync.

At any rate, restarting the Dev add-on loses the token and crashes the provider, but even from initial setup, I am unable to test YTM at all because nothing is accessible or visible from YTM, even in search. Tried setting up about 6 times in succession now and same results every time. Aside from the errors already shared here, I see nothing else in the debug log of interest.

— Reply to this email directly, view it on GitHub https://github.com/music-assistant/hass-music-assistant/issues/2536#issuecomment-2189681386, or unsubscribe https://github.com/notifications/unsubscribe-auth/AEG2MJ47NLYUPRMXDCF4SKDZJGYX7AVCNFSM6AAAAABJ2WPH3CVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCOBZGY4DCMZYGY . You are receiving this because you were assigned.Message ID: @.***>

TheWebMachine commented 3 days ago

since you mentions that you got the domain error before you even put the branch name in?

Disregard that comment: HA keeps add-on logs even after deleting and reinstalling, so I was seeing an old log message and thought it was from fresh install.

I fully removed the add-on, reinstalled it, set the branch, started it, and attempted YTM setup...7 times in total. Same results every time.

THEN...on the 8th attempt, MA somehow loaded a total of three random albums (not playlists) on the Home tab. Totally random and the first time it has happened. Anyway, I did start playback on one of them and the delay is now down to about 3-4s for me on first track play, about 2s on track skips.

So, this is much more acceptable and in line with the old library!

MarvinSchenkel commented 3 days ago

Awesome, love the perseverance. That's all I wanted to confirm. Really glad it's working because this means we can go ahead with ytdlp and will greatly improve the stability of the YT Music provider 💪. Will let you know when this hits beta.

Op di 25 jun 2024 om 20:45 schreef TheWebMachine @.***>

since you mentions that you got the domain error before you even put the branch name in?

Disregard that comment: HA keeps add-on logs even after deleting and reinstalling, so I was seeing an old log message and thought it was from fresh install.

I fully removed the add-on, reinstalled it, set the branch, started it, and attempted YTM setup...7 times in total. Same results every time.

THEN...on the 8th attempt, MA somehow loaded a total of three random albums (not playlists) on the Home tab. Totally random and the first time it has happened. Anyway, I did start playback on one of them and the delay is now down to about 3-4s for me on first track play, about 2s on track skips.

So, this is much more acceptable and in line with the old library!

— Reply to this email directly, view it on GitHub https://github.com/music-assistant/hass-music-assistant/issues/2536#issuecomment-2189722087, or unsubscribe https://github.com/notifications/unsubscribe-auth/AEG2MJ2XQOQZ4N2J6HGJNBLZJG3FLAVCNFSM6AAAAABJ2WPH3CVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCOBZG4ZDEMBYG4 . You are receiving this because you were assigned.Message ID: @.***>