"Transition jump" happening, when it should be gapless

[greatquux]

Tauon 7.9.0 is playing music files mounted over NFS. Occassionally (not all the time!), it will not precache the next track with enough time to play it gaplessly, and I will hear a gap of a couple seconds usually. I tried increasing device-buffer-ms but I don't think this is having the intended effect. precache-local-files is true. I think I may just need to have it precache 5-10 seconds before the end? Perhaps there is way to precache the queue or a playlist? (Obviously my whole music folder playlist would be above the cache-limit and so wouldn't make sense, but smaller playlists would.)

Log output from when there was a miss seems to know that it's close to the end but I still hear a gap.

2025-03-27 16:29:50 [ INFO ] [ t_phazor ] Open - requested start was 0 (0)
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] Extension: mp3
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] Got cached file
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] Digital Black -> Han-Tyumi, The Confused Cyborg
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] --- length: 166.652
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] --- position: 159.626
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] --- We are 7.025999999999982 from end
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] Open - requested start was 0 (0)
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] Extension: mp3
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] Got cached file
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] Digital Black -> Han-Tyumi, The Confused Cyborg
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] --- length: 166.652
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] --- position: 159.626
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] --- We are 7.025999999999982 from end
2025-03-27 16:29:50 [ INFO ] [ t_phazor ] Transition jump
2025-03-27 16:29:50 [ INFO ] [ t_main ] Submit Scrobble King Gizzard & The Lizard Wizard - Digital Black
2025-03-27 16:29:50 [ INFO ] [ t_main ] Submitting scrobble...
2025-03-27 16:29:50 [ INFO ] [ init ] track.scrobble
2025-03-27 16:29:50 [ INFO ] [ _client ] HTTP Request: POST https://ws.audioscrobbler.com/2.0/ "HTTP/1.1 200 OK"
2025-03-27 16:29:50 [ INFO ] [ init ] track.getInfo
2025-03-27 16:29:50 [ INFO ] [ _client ] HTTP Request: POST https://ws.audioscrobbler.com/2.0/?username=greatquux "HTTP/1.1 200 OK"
2025-03-27 16:29:50 [ INFO ] [ init ] track.getCorrection
2025-03-27 16:29:51 [ INFO ] [ _client ] HTTP Request: POST https://ws.audioscrobbler.com/2.0/ "HTTP/1.1 200 OK"
2025-03-27 16:29:51 [ INFO ] [ init ] artist.getCorrection
2025-03-27 16:29:51 [ INFO ] [ _client ] HTTP Request: POST https://ws.audioscrobbler.com/2.0/ "HTTP/1.1 200 OK"
2025-03-27 16:29:51 [ INFO ] [ t_phazor ] Precache next track
2025-03-27 16:29:51 [ INFO ] [ t_phazor ] Start transfer
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 107 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 7783 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 2409 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 423966 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 10052 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 2976 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 17961 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 18455 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 9525 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 9794 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 15651 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 13472 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 10028 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 23392 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] Caching file @ 12484 kbps
2025-03-27 16:29:52 [ INFO ] [ t_phazor ] got file
2025-03-27 16:29:56 [ INFO ] [ init ] track.updateNowPlaying
2025-03-27 16:29:56 [ INFO ] [ _client ] HTTP Request: POST https://ws.audioscrobbler.com/2.0/ "HTTP/1.1 200 OK"
2025-03-27 16:30:16 [ INFO ] [ init ] track.updateNowPlaying
2025-03-27 16:30:16 [ INFO ] [ _client ] HTTP Request: POST https://ws.audioscrobbler.com/2.0/ "HTTP/1.1 200 OK"

[Taiko2k]

Its already intended to cache the next track immediately. (So, ASAP rather than X from end)

Looking at the log... We are 7.025999999999982 from end isn't good. I think the issue is... when a track is clicked to play, when its not cached it downloads/buffers it, but during that buffer time its counting that time as playback time, so it ends up transitioning the song too early at the end. Under this theory it wouldn't happen if the current track is already cached.

Does that correlate with your experience?

[greatquux]

No.. but I also didn't have "persistent network cache" turned on, so I'm going to retry my testing tomorrow and see if this helps. Just watching the cache folder with that on, I do see it caching track n+1 within seconds of track n starting to play. Maybe it wasn't doing it at all with the persistent option turned off.

[greatquux]

Hmm.. it seems the problem is not the caching, it can happen on a cached track too. It's that for some reason it sometimes decides to do "Transition jump" instead of "Transition gapless" for no good reason I can discern, except perhaps NOT " 0 < remain < 5.5" ?

So most files play as normal and show something like

2025-03-28 09:42:47 [ INFO  ] [ t_phazor ] Got cached file
2025-03-28 09:42:47 [ INFO  ] [ t_phazor ] Alter Me II -> Altered Beast III
2025-03-28 09:42:47 [ INFO  ] [ t_phazor ]  --- length: 85.866
2025-03-28 09:42:47 [ INFO  ] [ t_phazor ]  --- position: 81.948
2025-03-28 09:42:47 [ INFO  ] [ t_phazor ]  --- We are 3.9180000000000064 from end
2025-03-28 09:42:47 [ INFO  ] [ t_phazor ] Transition gapless


2025-03-28 09:45:00 [ INFO  ] [ t_phazor ] Open - requested start was 0 (0)
2025-03-28 09:45:00 [ INFO  ] [ t_phazor ] Extension: mp3
2025-03-28 09:45:00 [ INFO  ] [ t_phazor ] Got cached file
2025-03-28 09:45:00 [ INFO  ] [ t_phazor ] Altered Beast III -> Alter Me III
2025-03-28 09:45:00 [ INFO  ] [ t_phazor ]  --- length: 134.546
2025-03-28 09:45:00 [ INFO  ] [ t_phazor ]  --- position: 129.201
2025-03-28 09:45:00 [ INFO  ] [ t_phazor ]  --- We are 5.344999999999999 from end
2025-03-28 09:45:00 [ INFO  ] [ t_phazor ] Transition gapless

and the tracks are mentioned once.

But when I hear a gap, I see the track names mentioned twice and it is jumping:

2025-03-28 09:36:56 [ INFO  ] [ t_phazor ] Open - requested start was 0 (0)
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ] Extension: mp3
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ] Got cached file
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ] Alter Me I -> Altered Beast II
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ]  --- length: 45.546
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ]  --- position: 39.635
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ]  --- We are 5.911000000000001 from end
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ] Open - requested start was 0 (0)
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ] Extension: mp3
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ] Got cached file
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ] Alter Me I -> Altered Beast II
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ]  --- length: 45.546
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ]  --- position: 39.635
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ]  --- We are 5.911000000000001 from end
2025-03-28 09:36:56 [ INFO  ] [ t_phazor ] Transition jump


2025-03-28 09:46:25 [ INFO  ] [ t_phazor ] Extension: mp3
2025-03-28 09:46:25 [ INFO  ] [ t_phazor ] Got cached file
2025-03-28 09:46:25 [ INFO  ] [ t_phazor ] Alter Me III -> Altered Beast IV
2025-03-28 09:46:25 [ INFO  ] [ t_phazor ]  --- length: 86.426
2025-03-28 09:46:25 [ INFO  ] [ t_phazor ]  --- position: 79.199
2025-03-28 09:46:25 [ INFO  ] [ t_phazor ]  --- We are 7.227000000000004 from end
2025-03-28 09:46:25 [ INFO  ] [ t_phazor ] Open - requested start was 0 (0)
2025-03-28 09:46:25 [ INFO  ] [ t_phazor ] Extension: mp3
2025-03-28 09:46:25 [ INFO  ] [ t_phazor ] Got cached file
2025-03-28 09:46:25 [ INFO  ] [ t_phazor ] Alter Me III -> Altered Beast IV
2025-03-28 09:46:25 [ INFO  ] [ t_phazor ]  --- length: 86.426
2025-03-28 09:46:25 [ INFO  ] [ t_phazor ]  --- position: 79.292
2025-03-28 09:46:25 [ INFO  ] [ t_phazor ]  --- We are 7.134 from end
2025-03-28 09:46:25 [ INFO  ] [ t_phazor ] Transition jump

[greatquux]

I checked out 7.9.0 and modified line 1097

Tauon/src/tauon/t_modules/t_phazor.py

Line 1097 in ea43859

and 0 < remain < 5.5 \

to read
and 0 < remain < 25
and played a bunch of gapless tracks together without seeing "Transition jump" , and everything was gapless. Not sure if there is any rationale behind this heuristic being what it was?
EDIT: i didn't run through the code in my mind or anything (or ask an AI to do it lol) but i think the device-buffer-ms being set high (I set it to 8000ms) changes the heuristic of this number, as after changing the buffer i see much higher values of
"We are " remain " from end"
that would cause it to do a jump instead of gapless. So I think a value like 25 should definitely cover the max device-buffer-ms. Lemme know if you want me to make a pull request if you would accept that.

[Taiko2k]

device-buffer-ms isn't intended to be set that high, probably around 250 would be considered to be the upper range.

0 < remain < 25 is no good as in this case it will always wait that 25 seconds to transition. This issue is the clocks being out of sync, a small variation is expected, but yours is 3s+ which indicates a problem somewhere. Did you modify that device buffer setting before you had this issue?

Otherwise those extra seconds must come from somewhere, are you sure its not counting time at the beginning its not actually playing?

[greatquux]

When I make these modifications, it definitely isn't taking 25 seconds to transition. It's nice and gapless and pretty consistent. It is true that it's not counting the track time properly, but I'm not really bothered by that, it happens in Audacious too when I set a very high buffer size. I'm more bothered when my playback isn't gapless (I listen to a lot of live music).

I tried setting device-buffer-ms back to 250 and reversed the line back to 0<remain<5.5 but I still get occasional gaps. And even if I put my change 0<remain<25 back in place, I might still get into a "We are 0.0 from end" situation where there is not enough time to buffer the next track (and yeah, for some reason, it doesn't always buffer the next track ahead of time):

2025-04-02 14:37:03 [ INFO ] [ t_phazor ] Caching file @ 26219 kbps
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] Caching file @ 241514 kbps
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] got file
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] Got cached file
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] Cities -> Light
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] --- length: 1060.389
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] --- position: 1060.389
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] --- We are 0.0 from end
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] Open - requested start was 0 (0)
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] Extension: mp3
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] Got cached file
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] Cities -> Light
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] --- length: 1060.389
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] --- position: 1060.389
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] --- We are 0.0 from end
2025-04-02 14:37:03 [ INFO ] [ t_phazor ] Transition jump

My music library is on NFS, and it's usually a "good enough" connection, but it needs a few seconds to download the track, and it doesn't always seem to be caching the next track in time. And it just doesn't always have enough time with 250ms buffer. That is why I increased the device-buffer-ms. That led to a the 'remain' message triggering with more time left, which led to the change I made to that line. So yeah, not exactly sure what to do about it...