Closed TheKeveloper closed 9 months ago
Hi @TheKeveloper,
What is the value of the "age" header on the initial Media Playlist response?
HLS.js implements the algorithm in Appendix C to acquire an up-to-date version of the Media Playlist:
https://datatracker.ietf.org/doc/html/draft-pantos-hls-rfc8216bis/#appendix-C
Please share the console logs from one of these sessions. The logs include information about how the delivery directives were determined.
A URL to the HLS asset would help as well.
Hey @robwalch thanks for the quick response!
We don't do any caching so we don't have an age header. Unfortunately I can't link to the HLS asset since the server is not public.
Based on my read of the algorithm that you linked, my rough guess is that something like the following is going on:
We use the time to complete the request as an estimate for how far in the future we should specify the delivery directives to be. If the page is resource/network constrained, the time estimate is longer so the delivery directives are farther in the future. If we get lucky and a request loads quickly, then we have delivery directives that don't load too far into the future, and subsequent loads work.
The above guess is just based on the fact that the bad loading behavior really only seems to happen on pages that have a lot of other things going on or if I have many other tabs open.
I have the following console logs from chrome for a case where the player just continuously buffered
hls.min.js:1 [log] >
hls.min.js:1 [log] > stopLoad
hls.min.js:1 [log] > loadSource:https://{base-path}/playlist.m3u8
hls.min.js:1 [log] > [stream-controller]: Trigger BUFFER_RESET
hls.min.js:1 [log] > attachMedia
hls.min.js:1 [log] > [buffer-controller]: Media source opened
hls.min.js:1 [log] > [subtitle-stream-controller]: STOPPED->IDLE
hls.min.js:1 [log] > [level-controller]: manifest loaded, 1 level(s) found, first bitrate: 4539463
hls.min.js:1 [log] > 1 bufferCodec event(s) expected
hls.min.js:1 [log] > startLoad(-1)
hls.min.js:1 [log] > [level-controller]: switching to level 0 from -1
hls.min.js:1 [log] > [level-controller]: Attempt loading level index 0 with URL-id 0 https://{base-path}/chunklist_vo_sfm4s.m3u8
hls.min.js:1 [log] > [stream-controller]: STOPPED->IDLE
hls.min.js:1 [log] > [subtitle-stream-controller]: IDLE->STOPPED
hls.min.js:1 [log] > [subtitle-stream-controller]: STOPPED->IDLE
hls.min.js:1 [log] > [level-controller]: CDN Tune-in age: 0s last advanced 754.72s goal: 9 skip sn 1 to part 7
hls.min.js:1 [log] > [level-controller]: Attempt loading level index 0 at sn 610 part 7 with URL-id 0 https://{base-path}/chunklist_vo_sfm4s.m3u8?_HLS_msn=610&_HLS_part=7&_HLS_skip=YES
hls.min.js:1 [log] > [stream-controller]: IDLE->WAITING_LEVEL
hls.min.js:1 [log] > [stream-controller]: Level 0 loaded [604,608], cc [0, 0] duration:34.033
hls.min.js:1 [log] > [stream-controller]: Live playlist sliding: 0.00 start-sn: na->604 prev-sn: na fragments: 5
hls.min.js:1 [log] > [buffer-controller]: Updating Media Source duration to 34.033
console.js:213 [warn] > [playlist-loader]: A network error occurred while loading level level: 0 id: 0 group-id: "null"
overrideMethod @ console.js:213
e.handleNetworkError @ hls.min.js:1
e.loaderror @ hls.min.js:1
handleError @ HlsWorkerLoader.js:56
onMessage @ HlsWorkerLoader.js:77
Show 5 more frames
Show less
console.js:213 [warn] > [level-controller]: retry playlist loading #1 in 2000 ms after "levelLoadError"
overrideMethod @ console.js:213
e.retryLoadingOrFail @ hls.min.js:1
d.recoverLevel @ hls.min.js:1
d.onError @ hls.min.js:1
u.emit @ hls.min.js:1
l.emit @ hls.min.js:1
l.trigger @ hls.min.js:1
e.handleNetworkError @ hls.min.js:1
e.loaderror @ hls.min.js:1
handleError @ HlsWorkerLoader.js:56
onMessage @ HlsWorkerLoader.js:77
Show 11 more frames
Show less
hls.min.js:1 [log] > [level-controller]: Attempt loading level index 0 with URL-id 0 https://{base-path}/chunklist_vo_sfm4s.m3u8
hls.min.js:1 [log] > [level-controller]: live playlist 0 REFRESHED 610-2
hls.min.js:1 [log] > [level-controller]: CDN Tune-in age: 0s last advanced 754.72s goal: 9 skip sn 1 to part 6
hls.min.js:1 [log] > [level-controller]: Attempt loading level index 0 at sn 611 part 6 with URL-id 0 https://{base-path}/chunklist_vo_sfm4s.m3u8?_HLS_msn=611&_HLS_part=6&_HLS_skip=YES
hls.min.js:1 [log] > [stream-controller]: Level 0 loaded [605,609], cc [0, 0] duration:33.032
hls.min.js:1 [log] > [buffer-controller]: Updating Media Source duration to 38.037
console.js:213 [warn] > [playlist-loader]: A network timeout occurred while loading level level: 0 id: 0 group-id: "null"
overrideMethod @ console.js:213
e.handleNetworkError @ hls.min.js:1
e.loadtimeout @ hls.min.js:1
handleTimeout @ HlsWorkerLoader.js:69
onMessage @ HlsWorkerLoader.js:80
Show 5 more frames
Show less
console.js:213 [warn] > [level-controller]: retry playlist loading #1 after "levelLoadTimeOut"
overrideMethod @ console.js:213
e.retryLoadingOrFail @ hls.min.js:1
d.recoverLevel @ hls.min.js:1
d.onError @ hls.min.js:1
u.emit @ hls.min.js:1
l.emit @ hls.min.js:1
l.trigger @ hls.min.js:1
e.handleNetworkError @ hls.min.js:1
e.loadtimeout @ hls.min.js:1
handleTimeout @ HlsWorkerLoader.js:69
onMessage @ HlsWorkerLoader.js:80
Show 11 more frames
Show less
hls.min.js:1 [log] > [level-controller]: Attempt loading level index 0 with URL-id 0 https://{base-path}/chunklist_vo_sfm4s.m3u8
hls.min.js:1 [log] > [level-controller]: live playlist 0 REFRESHED 610-7
hls.min.js:1 [log] > [level-controller]: CDN Tune-in age: 0s last advanced 754.72s goal: 9 skip sn 1 to part 11
hls.min.js:1 [log] > [level-controller]: Attempt loading level index 0 at sn 611 part 11 with URL-id 0 https://{base-path}/chunklist_vo_sfm4s.m3u8?_HLS_msn=611&_HLS_part=11&_HLS_skip=YES
hls.min.js:1 [log] > [stream-controller]: Level 0 loaded [605,609], cc [0, 0] duration:38.03699999999999
hls.min.js:1 [log] > [buffer-controller]: Updating Media Source duration to 43.042
console.js:213 [warn] > [playlist-loader]: A network error occurred while loading level level: 0 id: 0 group-id: "null"
overrideMethod @ console.js:213
e.handleNetworkError @ hls.min.js:1
e.loaderror @ hls.min.js:1
handleError @ HlsWorkerLoader.js:56
onMessage @ HlsWorkerLoader.js:77
Show 5 more frames
Show less
console.js:213 [warn] > [level-controller]: retry playlist loading #1 in 2000 ms after "levelLoadError"
overrideMethod @ console.js:213
e.retryLoadingOrFail @ hls.min.js:1
d.recoverLevel @ hls.min.js:1
d.onError @ hls.min.js:1
u.emit @ hls.min.js:1
l.emit @ hls.min.js:1
l.trigger @ hls.min.js:1
e.handleNetworkError @ hls.min.js:1
e.loaderror @ hls.min.js:1
handleError @ HlsWorkerLoader.js:56
onMessage @ HlsWorkerLoader.js:77
Show 11 more frames
Show less
hls.min.js:1 [log] > [level-controller]: Attempt loading level index 0 with URL-id 0 https://{base-path}/chunklist_vo_sfm4s.m3u8
hls.min.js:1 [log] > [level-controller]: live playlist 0 REFRESHED 611-2
hls.min.js:1 [log] > [level-controller]: CDN Tune-in age: 0s last advanced 754.72s goal: 9 skip sn 1 to part 6
hls.min.js:1 [log] > [level-controller]: Attempt loading level index 0 at sn 612 part 6 with URL-id 0 https://{base-path}/chunklist_vo_sfm4s.m3u8?_HLS_msn=612&_HLS_part=6&_HLS_skip=YES
hls.min.js:1 [log] > [stream-controller]: Level 0 loaded [606,610], cc [0, 0] duration:33.032
hls.min.js:1 [log] > [buffer-controller]: Updating Media Source duration to 48.047
The above guess is just based on the fact that the bad loading behavior really only seems to happen on pages that have a lot of other things going on or if I have many other tabs open.
CDN Tune-in age: 0s last advanced 754.72s goal: 9 skip sn 1 to part 6
If other things are going on, that's OK - up to a point. There's a tolerance for up to 1.5 times the target duration (9 seconds in your case) for the directives to try and catchup.
Here, the page/clock stalled (maybe you were debugging?) for 754 seconds after the first playlist response, and before estimating the goal. So really we're many minutes behind the live edge. Only advancing 9 seconds will not catch up. It tries, but the problem here is not that we're requesting segments too far ahead (greater than the Media Sequence Number of the last Media Segment plus two should return HTTP 400) but too far in the past. When the request fails for old media (ideally with HTTP 404 or 410) HLS.js should make another request without these directives.
From what I can tell this works as expected. If there is a valid reason why there is more than 1.5* the target duration between playlist response and next request that you think we should handle, please clarify - the page itself blocking for that long is a page issue (maybe one not performant enough to handle LL-HLS playback?). We might consider an enhancement that omits segment directives if the estimated age is great enough, or even fallback to standard HLS latency.
@TheKeveloper let me know if #6080 resolves this issue or better meets your expectations based on your testing. I'm only able to reproduce the issue when artificially pausing JS execution by debugging. Another scenario would be backrounding the page on a mobile device or putting the device to sleep and waking it after more than a couple of target durations. Hopefully you don't have anything else running on the page blocking for that long. This change should prevent some of those stale requests from being made after the execution resumes.
@robwalch I think the above delay is probably a red herring due to some debugging I was doing. Sorry about the confusion there!
Here's a more recent attempt where the video also fails to load
hls.mjs:412 [log] > Debug logs enabled for "Hls instance" in hls.js version 1.4.14
hls.mjs:25349 [log] > stopLoad
hls.mjs:25320 [log] > loadSource:https://{base-path}/playlist.m3u8
hls.mjs:15334 [log] > [stream-controller]: Trigger BUFFER_RESET
hls.mjs:25294 [log] > attachMedia
hls.mjs:18448 [log] > [buffer-controller]: Media source opened
hls.mjs:9577 [log] > [subtitle-stream-controller]: STOPPED->IDLE
hls.mjs:6142 [log] > [level-controller]: manifest loaded, 1 level(s) found, first bitrate: 4374459
hls.mjs:18547 [log] > 1 bufferCodec event(s) expected
hls.mjs:25339 [log] > startLoad(-1)
hls.mjs:6211 [log] > [level-controller]: Switching to level 0 from level -1
hls.mjs:6352 [log] > [level-controller]: Loading level index 0 with URI 1/1 https://{base-path}/chunklist_vo_sfm4s.m3u8
hls.mjs:9577 [log] > [stream-controller]: STOPPED->IDLE
hls.mjs:9577 [log] > [subtitle-stream-controller]: IDLE->STOPPED
hls.mjs:9577 [log] > [subtitle-stream-controller]: STOPPED->IDLE
hls.mjs:5849 [log] > [level-controller]: CDN Tune-in age: 0s last advanced 22.08s goal: 9 skip sn 1 to part 7
hls.mjs:6352 [log] > [level-controller]: Loading level index 0 at sn 993 part 7 with URI 1/1 https://{base-path}/chunklist_vo_sfm4s.m3u8?_HLS_msn=993&_HLS_part=7&_HLS_skip=YES
hls.mjs:9577 [log] > [stream-controller]: IDLE->WAITING_LEVEL
hls.mjs:15389 [log] > [stream-controller]: Level 0 loaded [987,991][part-992-3], cc [0, 0] duration:34.032999999999994
hls.mjs:9290 [log] > [stream-controller]: Live playlist sliding: 0.00 start-sn: na->987 prev-sn: na fragments: 5
hls.mjs:19015 [log] > [buffer-controller]: Updating Media Source duration to 34.033
console.js:213 [warn] > [playlist-loader]: A network error (status 0) occurred while loading level: 0 id: 0
overrideMethod @ console.js:213
handleNetworkError @ hls.mjs:3838
onError @ hls.mjs:3696
HlsWorkerLoader.handleError @ HlsWorkerLoader.js:56
HlsWorkerLoader.onMessage @ HlsWorkerLoader.js:77
Show 5 more frames
Show less
console.js:213 [warn] > [level-controller]: Retrying playlist loading 1/2 after "levelLoadError" in 1000ms
overrideMethod @ console.js:213
checkRetry @ hls.mjs:5932
onError @ hls.mjs:6272
emit @ hls.mjs:14148
emit @ hls.mjs:25244
trigger @ hls.mjs:25248
handleNetworkError @ hls.mjs:3881
onError @ hls.mjs:3696
HlsWorkerLoader.handleError @ HlsWorkerLoader.js:56
HlsWorkerLoader.onMessage @ HlsWorkerLoader.js:77
Show 10 more frames
Show less
hls.mjs:6352 [log] > [level-controller]: Loading level index 0 with URI 1/1 https://{base-path}/chunklist_vo_sfm4s.m3u8
hls.mjs:5803 [log] > [level-controller]: live playlist 0 REFRESHED 993-1
hls.mjs:5849 [log] > [level-controller]: CDN Tune-in age: 0s last advanced 22.08s goal: 9 skip sn 1 to part 5
hls.mjs:6352 [log] > [level-controller]: Loading level index 0 at sn 994 part 5 with URI 1/1 https://{base-path}/chunklist_vo_sfm4s.m3u8?_HLS_msn=994&_HLS_part=5&_HLS_skip=YES
hls.mjs:15389 [log] > [stream-controller]: Level 0 loaded [988,992][part-993-1], cc [0, 0] duration:32.03099999999999
hls.mjs:19015 [log] > [buffer-controller]: Updating Media Source duration to 37.036
console.js:213 [warn] > [playlist-loader]: A network error (status 0) occurred while loading level: 0 id: 0
overrideMethod @ console.js:213
handleNetworkError @ hls.mjs:3838
onError @ hls.mjs:3696
HlsWorkerLoader.handleError @ HlsWorkerLoader.js:56
HlsWorkerLoader.onMessage @ HlsWorkerLoader.js:77
Show 5 more frames
Show less
console.js:213 [warn] > [level-controller]: Retrying playlist loading 1/2 after "levelLoadError" in 1000ms
overrideMethod @ console.js:213
checkRetry @ hls.mjs:5932
onError @ hls.mjs:6272
emit @ hls.mjs:14148
emit @ hls.mjs:25244
trigger @ hls.mjs:25248
handleNetworkError @ hls.mjs:3881
onError @ hls.mjs:3696
HlsWorkerLoader.handleError @ HlsWorkerLoader.js:56
HlsWorkerLoader.onMessage @ HlsWorkerLoader.js:77
Show 10 more frames
Show less
hls.mjs:6352 [log] > [level-controller]: Loading level index 0 with URI 1/1 https://{base-path}/chunklist_vo_sfm4s.m3u8
hls.mjs:5803 [log] > [level-controller]: live playlist 0 REFRESHED 994-1
hls.mjs:5849 [log] > [level-controller]: CDN Tune-in age: 0s last advanced 22.08s goal: 9 skip sn 1 to part 5
hls.mjs:6352 [log] > [level-controller]: Loading level index 0 at sn 995 part 5 with URI 1/1 https://{base-path}/chunklist_vo_sfm4s.m3u8?_HLS_msn=995&_HLS_part=5&_HLS_skip=YES
hls.mjs:15389 [log] > [stream-controller]: Level 0 loaded [989,993][part-994-1], cc [0, 0] duration:32.032
hls.mjs:19015 [log] > [buffer-controller]: Updating Media Source duration to 42.041
console.js:213 [warn] > [playlist-loader]: A network timeout occurred while loading level: 0 id: 0
overrideMethod @ console.js:213
handleNetworkError @ hls.mjs:3838
onTimeout @ hls.mjs:3699
HlsWorkerLoader.handleTimeout @ HlsWorkerLoader.js:69
HlsWorkerLoader.onMessage @ HlsWorkerLoader.js:80
Show 5 more frames
Show less
console.js:213 [warn] > [level-controller]: Retrying playlist loading 1/2 after "levelLoadTimeOut" without delivery-directives
overrideMethod @ console.js:213
checkRetry @ hls.mjs:5926
onError @ hls.mjs:6272
emit @ hls.mjs:14148
emit @ hls.mjs:25244
trigger @ hls.mjs:25248
handleNetworkError @ hls.mjs:3881
onTimeout @ hls.mjs:3699
HlsWorkerLoader.handleTimeout @ HlsWorkerLoader.js:69
HlsWorkerLoader.onMessage @ HlsWorkerLoader.js:80
Show 10 more frames
Show less
hls.mjs:6352 [log] > [level-controller]: Loading level index 0 with URI 1/1 https://{base-path}/chunklist_vo_sfm4s.m3u8
hls.mjs:5803 [log] > [level-controller]: live playlist 0 REFRESHED 994-5
hls.mjs:5849 [log] > [level-controller]: CDN Tune-in age: 0s last advanced 22.08s goal: 9 skip sn 1 to part 9
hls.mjs:6352 [log] > [level-controller]: Loading level index 0 at sn 995 part 9 with URI 1/1 https://{base-path}/chunklist_vo_sfm4s.m3u8?_HLS_msn=995&_HLS_part=9&_HLS_skip=YES
hls.mjs:15389 [log] > [stream-controller]: Level 0 loaded [989,993][part-994-5], cc [0, 0] duration:36.035999999999994
I'll give the PR that you linked a shot, since it the target duration is 5s here, so we're falling 3 target durations behind.
Still a little unclear why that would be happening since the request to the server completes in about 50ms according to Chrome and it doesn't seem like anything on the browser is stalling that long?
...last advanced 22.08s goal: 9 skip sn 1 to part 5
Interesting that you're getting a consistent advancedDateTime
of 22.08
. I'm curious to know what the loader stats look like (is stats.loading.first
being manipulated?), and if there's something fishy going on with your clock (using performance.now()
and Date.now()
).
advancedDateTime
should be the date-time that the headers or first byte was received for the playlist. Since stats.loading.first
is expected to be a performance measurement, we subtract performance.now() - stats.loading.first
from Date.now()
to get this date-time value.
Ah, okay, I think it must be related to our custom HLS worker loader, since the loader stats do get modified there.
I tested it out without using a custom worker loader and things seem to work great. I think a lot of this code was written on a much older version of hls.js so I'm going to look into whether with more recent versions we're able to forgo using the custom worker loader.
I think this should be considered resolved, thank you so much for all of your help!
What do you want to do with Hls.js?
I'm filing this as a question since it's not clear to me whether this is intended behavior or not, but happy to re-file as a bug if that would make more sense.
I'm trying to play a Low-Latency HLS playlist, and it seems that hls.js is sending requests with delivery directives that request parts that are farther into the future than I would expect.
The following playlist is returned on initial load
The next request made by hls.js has the following delivery directives
The HLS server stalls and eventually returns an error. It's a bit surprising to me that the delivery directive specifies waiting for a part that is essentially a full segment into the future. Naively I would expect it the delivery directive to specify the first part of the next segment:
_HLS_msn=305&_HLS_part=0&_HLS_skip=YES
.This only happens on the initial segment load, right after a request to the media playlist. Once one of the requests with a delivery directive is successful, all subsequent requests succeed and the video plays smoothly. However, sometimes the player will never get a successful response and continue retrying requests with delivery directives that specify a segment and part that are too far into the future and the video will just buffer indefinitely.
It's not clear to me what determines whether the first request is successful. It seems vaguely like if Chrome is resource constrained (e.g. a lot of other tabs open), the player is more likely to get stuck on the initial load.
The HlsConfig I have is
The main question I have is: is there a way to customize the delivery directives such that we never try to load a part more than x seconds/parts into the future?
Another option would be retry with the same delivery directives, but even then it seems that I'm guaranteed to spend at least a full segment of time buffering when it would be preferable to load the video faster.
Unfortunately I don't control the behavior of the HLS server so I'm mainly looking for how I can change the HLS client behavior.
Any other help or debugging tips would also be greatly appreciated. Thank you!
What have you tried so far?
No response