Unnecessary snapping to live edge during startup on slower devices

[grabofus]

What version of Hls.js are you using?

1.5.12, 1.6.0-beta.2.0.canary.10930

What browser (including version) are you using?

Chrome 68.0.344.106

What OS (including version) are you using?

webOS 5

Test stream

No response

Configuration

{}

Additional player setup steps

No response

Checklist

• The issue observed is not already reported by searching on Github under https://github.com/video-dev/hls.js/issues
• The issue occurs in the stable client (latest release) on https://hlsjs.video-dev.org/demo and not just on my page
• The issue occurs in the latest client (main branch) on https://hlsjs-dev.video-dev.org/demo and not just on my page
• The stream has correct Access-Control-Allow-Origin headers (CORS)
• There are no network errors such as 404s in the browser console when trying to play the stream

Steps to reproduce

1. Load live stream with a start rendition that is above the network bandwidth of the device
2. Have the player refresh the playlist (increasing the seekable range start from 0 to something larger)
3. Wait for a segment to be downloaded & parsed

Expected behaviour

Device should load first segment and begin playback

What actually happened?

Device finishes downloading the first segment, but after the segment is parsed, but before it would be buffered, stream-controller's synchronizeToLiveEdge function can be called leading to an unnecessary seek. Since the segment has not yet been buffered, the media's currentTime is not yet adjusted, which makes synchronizeToLiveEdge think that the player has fallen out of the DVR window performing an additional seek to a new target start time. On slow network this process occasionally repeats leading to multiple segments being downloaded by the time playback can begin.

Console output

[log] > Debug logs enabled for "Hls instance" in hls.js version 1.6.0-beta.2.0.canary.10930
hls.mjs:33874 [log] > stopLoad
hls.mjs:33816 [log] > loadSource:https://www.example.com/master.m3u8
hls.mjs:31848 [log] > [stream-controller]: Trigger BUFFER_RESET
hls.mjs:33769 [log] > attachMedia
hls.mjs:17891 [log] > [buffer-controller]: created media source: MediaSource
hls.mjs:20759 [log] > [content-steering]: Found 6/12 levels in Pathway "."
hls.mjs:31067 [log] > [level-controller]: manifest loaded, 6 level(s) found, first bitrate: 6324320
hls.mjs:17846 [log] > [buffer-controller]: 1 bufferCodec event(s) expected.
hls.mjs:19229 [log] > Setting autoLevelCapping to 5: 1080p@6324320 for media 3840x2160
hls.mjs:34191 [log] > set autoLevelCapping:5
hls.mjs:33859 [log] > startLoad(-1)
hls.mjs:1878 [log] > [abr]: picked start tier {"codecSet":"avc1,mp4a","videoRanges":["SDR"],"preferHDR":false,"minFramerate":0,"minBitrate":428640,"minIndex":0}
hls.mjs:1965 [info] > [abr]: switch candidate:5->5 adjustedbw(10000000)-bitrate=3675680 ttfb:0.1 avgDuration:0.0 maxFetchDuration:4.0 fetchDuration:0.1 firstSelection:true codecSet:avc1,mp4a videoRange:SDR hls.loadLevel:-1
hls.mjs:31141 [log] > [level-controller]: Switching to level 5 (1080p SDR avc1,mp4a @6324320) from level -1
hls.mjs:31300 [log] > [level-controller]: Loading level index 5 https://www.example.com/01.m3u8
hls.mjs:9459 [log] > [stream-controller]: STOPPED->IDLE
hls.mjs:9459 [log] > [subtitle-stream-controller]: STOPPED->IDLE
hls.mjs:17014 [log] > [level-controller]: live playlist 5 REFRESHED 6277297--1
hls.mjs:17098 [log] > [level-controller]: reload live playlist 6324320bps in 10784 ms
hls.mjs:31899 [log] > [stream-controller]: Level 5 loaded [6277292,6277297][part-6277297--1], cc [0, 0] duration:60
hls.mjs:9145 [log] > [stream-controller]: Live playlist sliding: 0.00 start-sn: na->6277292 fragments: 6
hls.mjs:24382 [log] > [interstitials]: setSchedulePosition 0, undefined
hls.mjs:24829 [log] > [interstitials]: buffered to boundary [primary: 0.00-Infinity]
hls.mjs:24554 [log] > [interstitials]: resuming [primary: 0.00-Infinity]
hls.mjs:33859 [log] > startLoad(27.066699951171877)
hls.mjs:17098 [log] > [level-controller]: reload live playlist 6324320bps in 10691 ms
hls.mjs:9459 [log] > [stream-controller]: IDLE->STOPPED
hls.mjs:9459 [log] > [stream-controller]: STOPPED->IDLE
hls.mjs:9459 [log] > [subtitle-stream-controller]: IDLE->STOPPED
hls.mjs:9459 [log] > [subtitle-stream-controller]: STOPPED->IDLE
hls.mjs:18729 [log] > [buffer-controller]: Updating MediaSource duration to 60.000
hls.mjs:17687 [log] > [buffer-controller]: Media source opened
hls.mjs:24382 [log] > [interstitials]: setSchedulePosition 0, undefined
hls.mjs:24829 [log] > [interstitials]: buffered to boundary [primary: 0.00-Infinity]
hls.mjs:24554 [log] > [interstitials]: resuming [primary: 0.00-Infinity]
hls.mjs:33859 [log] > startLoad(27.066699951171877)
hls.mjs:17098 [log] > [level-controller]: reload live playlist 6324320bps in 10568 ms
hls.mjs:9459 [log] > [stream-controller]: IDLE->STOPPED
hls.mjs:9459 [log] > [stream-controller]: STOPPED->IDLE
hls.mjs:9459 [log] > [subtitle-stream-controller]: IDLE->STOPPED
hls.mjs:9459 [log] > [subtitle-stream-controller]: STOPPED->IDLE
hls.mjs:18748 [log] > [buffer-controller]: checkPendingTracks (pending: 0 codec events expected: 1) {}
hls.mjs:8648 [log] > [stream-controller]: Loading main sn: 6277294 of level 5 (frag:[20.000-30.000]) cc: 0 [6277292-6277297], target: 27.067
hls.mjs:9459 [log] > [stream-controller]: IDLE->FRAG_LOADING
hls.mjs:31300 [log] > [level-controller]: Loading level index 5 age 10.8 https://www.example.com/01.m3u8
hls.mjs:17014 [log] > [level-controller]: live playlist 5 REFRESHED 6277298--1
hls.mjs:17098 [log] > [level-controller]: reload live playlist 6324320bps in 9183 ms
hls.mjs:31899 [log] > [stream-controller]: Level 5 loaded [6277293,6277298][part-6277298--1], cc [0, 0] duration:60
hls.mjs:18729 [log] > [buffer-controller]: Updating MediaSource duration to 70.000
hls.mjs:31300 [log] > [level-controller]: Loading level index 5 age 9.2 https://www.example.com/01.m3u8
hls.mjs:17014 [log] > [level-controller]: live playlist 5 REFRESHED 6277299--1
hls.mjs:17098 [log] > [level-controller]: reload live playlist 6324320bps in 9018 ms
hls.mjs:31899 [log] > [stream-controller]: Level 5 loaded [6277294,6277299][part-6277299--1], cc [0, 0] duration:60
hls.mjs:18729 [log] > [buffer-controller]: Updating MediaSource duration to 80.000
hls.mjs:15958 [log] > [transmuxer-interface]: Starting new transmux session for main sn: 6277294 level: 5 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: false
        timeOffset: 20
        initSegmentChange: true
hls.mjs:14357 [log] > [mp4-remuxer]: ISGenerated flag reset
hls.mjs:14348 [log] > [mp4-remuxer]: initPTS & initDTS reset
hls.mjs:14352 [log] > [mp4-remuxer]: reset next timestamp
hls.mjs:10071 [log] > manifest codec:mp4a.40.2, parsed codec:mp4a.40.2, channels:2, rate:48000 (ADTS object type:2 sampling index:3)
hls.mjs:9459 [log] > [stream-controller]: FRAG_LOADING->PARSING
hls.mjs:32500 [log] > [stream-controller]: Init audio buffer, container:audio/mp4, codecs[selected/level/parsed]=[mp4a.40.2/mp4a.40.2/mp4a.40.2]
hls.mjs:32523 [log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.640028/avc1.640028}]
hls.mjs:18105 [log] > [buffer-controller]: BUFFER_CODECS: "audio,video" (current SB count 0)
hls.mjs:18748 [log] > [buffer-controller]: checkPendingTracks (pending: 2 codec events expected: 1) {"audio":{"listeners":[],"codec":"mp4a.40.2","container":"audio/mp4","levelCodec":"mp4a.40.2","metadata":{"channelCount":2},"id":"main"},"video":{"listeners":[],"codec":"avc1.640028","container":"video/mp4","levelCodec":"avc1.640028","metadata":{"width":1920,"height":1080},"id":"main"}}
hls.mjs:18817 [log] > [buffer-controller]: creating sourceBuffer(audio/mp4;codecs=mp4a.40.2) {"listeners":[],"codec":"mp4a.40.2","container":"audio/mp4","levelCodec":"mp4a.40.2","metadata":{"channelCount":2},"id":"main"}
hls.mjs:18817 [log] > [buffer-controller]: creating sourceBuffer(video/mp4;codecs=avc1.640028) {"listeners":[],"codec":"avc1.640028","container":"video/mp4","levelCodec":"avc1.640028","metadata":{"width":1920,"height":1080},"id":"main"}
hls.mjs:18785 [log] > [buffer-controller]: SourceBuffers created. Running queue: 
video: (SourceBuffer) 
audio: (SourceBuffer) 
audiovideo: (none) }
hls.mjs:16144 [log] > [audio-stream-controller]: InitPTS for cc: 0 found from main: 37348010/90000
hls.mjs:8364 [log] > [stream-controller]: Loaded main sn: 6277294 of level 5
hls.mjs:15574 [log] > [transmuxer.ts]: Flushed main sn: 6277294 of level 5
hls.mjs:9459 [log] > [stream-controller]: PARSING->PARSED
hls.mjs:9417 [log] > [stream-controller]: Parsed main sn: 6277294 of level 5 (frag:[20.000-30.015])
hls.mjs:31300 [log] > [level-controller]: Loading level index 5 age 9.6 https://www.example.com/01.m3u8
hls.mjs:17014 [log] > [level-controller]: live playlist 5 REFRESHED 6277300--1
hls.mjs:17098 [log] > [level-controller]: reload live playlist 6324320bps in 8887 ms
hls.mjs:31899 [log] > [stream-controller]: Level 5 loaded [6277295,6277300][part-6277300--1], cc [0, 0] duration:60
hls.mjs:31965 [warn] > [stream-controller]: Playback: 0.000 is located too far from the end of live sliding playlist: 90, reset currentTime to : 57.034
hls.mjs:8060 [log] > [stream-controller]: media seeking to 57.034, state: PARSED
hls.mjs:8103 [log] > [stream-controller]: setting startPosition to 57.0341 because of seek before start
hls.mjs:8060 [log] > [audio-stream-controller]: media seeking to 57.034, state: STOPPED
hls.mjs:8103 [log] > [audio-stream-controller]: setting startPosition to 57.0341 because of seek before start
hls.mjs:8060 [log] > [subtitle-stream-controller]: media seeking to 57.034, state: IDLE
hls.mjs:8103 [log] > [subtitle-stream-controller]: setting startPosition to 57.0341 because of seek before start
hls.mjs:8522 [log] > [stream-controller]: Buffered main sn: 6277294 of level 5 (frag:[20.000-30.015] > buffer:[20.009-29.920])
hls.mjs:9459 [log] > [stream-controller]: PARSED->IDLE
hls.mjs:1965 [info] > [abr]: switch candidate:5->3 adjustedbw(1961807)-bitrate=129935 ttfb:0.1 avgDuration:10.0 maxFetchDuration:4.0 fetchDuration:9.9 firstSelection:false codecSet:avc1,mp4a videoRange:SDR hls.loadLevel:5
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:31642 [log] > [stream-controller]: Adapting to level 3 from level 5
hls.mjs:31141 [log] > [level-controller]: Switching to level 3 (540p SDR avc1,mp4a @1831872) from level 5
hls.mjs:31300 [log] > [level-controller]: Loading level index 3 https://www.example.com/03.m3u8
hls.mjs:9459 [log] > [stream-controller]: IDLE->WAITING_LEVEL
hls.mjs:18729 [log] > [buffer-controller]: Updating MediaSource duration to 90.000
hls.mjs:17014 [log] > [level-controller]: live playlist 3 REFRESHED 6277300--1
hls.mjs:17098 [log] > [level-controller]: reload live playlist 1831872bps in 9953 ms
hls.mjs:31899 [log] > [stream-controller]: Level 3 loaded [6277295,6277300][part-6277300--1], cc [0, 0] duration:60
hls.mjs:9145 [log] > [stream-controller]: Live playlist sliding: 30.00 start-sn: na->6277295 fragments: 6
hls.mjs:9459 [log] > [stream-controller]: WAITING_LEVEL->IDLE
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:8648 [log] > [stream-controller]: Loading main sn: 6277297 of level 3 (frag:[50.000-60.000]) cc: 0 [6277295-6277300], target: 57.034
hls.mjs:9459 [log] > [stream-controller]: IDLE->FRAG_LOADING
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:15958 [log] > [transmuxer-interface]: Starting new transmux session for main sn: 6277297 level: 3 id: 1
        discontinuity: false
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: false
        timeOffset: 50
        initSegmentChange: false
hls.mjs:14357 [log] > [mp4-remuxer]: ISGenerated flag reset
hls.mjs:14348 [log] > [mp4-remuxer]: initPTS & initDTS reset
hls.mjs:14352 [log] > [mp4-remuxer]: reset next timestamp
hls.mjs:10071 [log] > manifest codec:mp4a.40.2, parsed codec:mp4a.40.2, channels:2, rate:48000 (ADTS object type:2 sampling index:3)
hls.mjs:9459 [log] > [stream-controller]: FRAG_LOADING->PARSING
hls.mjs:32500 [log] > [stream-controller]: Init audio buffer, container:audio/mp4, codecs[selected/level/parsed]=[mp4a.40.2/mp4a.40.2/mp4a.40.2]
hls.mjs:32523 [log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.64001f/avc1.64001f}]
hls.mjs:18105 [log] > [buffer-controller]: BUFFER_CODECS: "audio,video" (current SB count 2)
hls.mjs:8364 [log] > [stream-controller]: Loaded main sn: 6277297 of level 3
hls.mjs:15574 [log] > [transmuxer.ts]: Flushed main sn: 6277297 of level 3
hls.mjs:9459 [log] > [stream-controller]: PARSING->PARSED
hls.mjs:9417 [log] > [stream-controller]: Parsed main sn: 6277297 of level 3 (frag:[50.000-60.009])
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:1801 [info] > [abr]: buffer is empty, optimal quality level 3
hls.mjs:8522 [log] > [stream-controller]: Buffered main sn: 6277297 of level 3 (frag:[50.000-60.009] > buffer:[20.009-29.920][50.004-59.920])
hls.mjs:9459 [log] > [stream-controller]: PARSED->IDLE
hls.mjs:8648 [log] > [stream-controller]: Loading main sn: 6277298 of level 3 (frag:[60.000-70.000]) cc: 0 [6277295-6277300], target: 60
hls.mjs:9459 [log] > [stream-controller]: IDLE->FRAG_LOADING
hls.mjs:31300 [log] > [level-controller]: Loading level index 3 age 10.0 https://www.example.com/03.m3u8
hls.mjs:17014 [log] > [level-controller]: live playlist 3 REFRESHED 6277301--1
hls.mjs:17098 [log] > [level-controller]: reload live playlist 1831872bps in 8717 ms
hls.mjs:31899 [log] > [stream-controller]: Level 3 loaded [6277296,6277301][part-6277301--1], cc [0, 0] duration:60.00924444444445
hls.mjs:18729 [log] > [buffer-controller]: Updating MediaSource duration to 100.009
hls.mjs:9459 [log] > [stream-controller]: FRAG_LOADING->PARSING
hls.mjs:8364 [log] > [stream-controller]: Loaded main sn: 6277298 of level 3
hls.mjs:15574 [log] > [transmuxer.ts]: Flushed main sn: 6277298 of level 3
hls.mjs:9459 [log] > [stream-controller]: PARSING->PARSED
hls.mjs:9417 [log] > [stream-controller]: Parsed main sn: 6277298 of level 3 (frag:[60.000-70.015])
hls.mjs:31445 [log] > [stream-controller]: Media seeked to 57.034
hls.mjs:8522 [log] > [stream-controller]: Buffered main sn: 6277298 of level 3 (frag:[60.000-70.015] > buffer:[20.009-29.920][50.004-69.920])
hls.mjs:9459 [log] > [stream-controller]: PARSED->IDLE
hls.mjs:8648 [log] > [stream-controller]: Loading main sn: 6277299 of level 3 (frag:[70.000-80.000]) cc: 0 [6277296-6277301], target: 70
hls.mjs:9459 [log] > [stream-controller]: IDLE->FRAG_LOADING
hls.mjs:31300 [log] > [level-controller]: Loading level index 3 age 8.7 https://www.example.com/03.m3u8
hls.mjs:17014 [log] > [level-controller]: live playlist 3 REFRESHED 6277302--1
hls.mjs:17098 [log] > [level-controller]: reload live playlist 1831872bps in 10070 ms
hls.mjs:31899 [log] > [stream-controller]: Level 3 loaded [6277297,6277302][part-6277302--1], cc [0, 0] duration:60.014577777777774
hls.mjs:18729 [log] > [buffer-controller]: Updating MediaSource duration to 110.015
hls.mjs:9459 [log] > [stream-controller]: FRAG_LOADING->PARSING
hls.mjs:8364 [log] > [stream-controller]: Loaded main sn: 6277299 of level 3
hls.mjs:15574 [log] > [transmuxer.ts]: Flushed main sn: 6277299 of level 3
hls.mjs:9459 [log] > [stream-controller]: PARSING->PARSED
hls.mjs:9417 [log] > [stream-controller]: Parsed main sn: 6277299 of level 3 (frag:[70.000-80.020])
hls.mjs:8522 [log] > [stream-controller]: Buffered main sn: 6277299 of level 3 (frag:[70.000-80.020] > buffer:[20.009-29.920][50.004-79.920])
hls.mjs:9459 [log] > [stream-controller]: PARSED->IDLE
hls.mjs:1965 [info] > [abr]: switch candidate:3->2 adjustedbw(1822376)-bitrate=808680 ttfb:0.1 avgDuration:10.0 maxFetchDuration:12.8 fetchDuration:6.5 firstSelection:false codecSet:avc1,mp4a videoRange:SDR hls.loadLevel:3
hls.mjs:31642 [log] > [stream-controller]: Adapting to level 2 from level 3
hls.mjs:31141 [log] > [level-controller]: Switching to level 2 (420p SDR avc1,mp4a @1013696) from level 3
hls.mjs:31300 [log] > [level-controller]: Loading level index 2 https://www.example.com/04.m3u8
hls.mjs:9459 [log] > [stream-controller]: IDLE->WAITING_LEVEL
hls.mjs:17014 [log] > [level-controller]: live playlist 2 REFRESHED 6277303--1
hls.mjs:17098 [log] > [level-controller]: reload live playlist 1013696bps in 9956 ms
hls.mjs:31899 [log] > [stream-controller]: Level 2 loaded [6277298,6277303][part-6277303--1], cc [0, 0] duration:60
hls.mjs:9145 [log] > [stream-controller]: Live playlist sliding: 60.00 start-sn: na->6277298 fragments: 6
hls.mjs:18729 [log] > [buffer-controller]: Updating MediaSource duration to 120.000
hls.mjs:9459 [log] > [stream-controller]: WAITING_LEVEL->IDLE
hls.mjs:9046 [log] > [stream-controller]: Live playlist, switching playlist, load frag with next SN: 6277300
hls.mjs:8952 [log] > [stream-controller]: Setting startPosition to 87.0475 to match initial live edge. mainStart: 87.0475 liveSyncPosition: 87.0835 frag.start: 80
hls.mjs:8648 [log] > [stream-controller]: Loading main sn: 6277300 of level 2 (frag:[80.000-90.000]) cc: 0 [6277298-6277303], target: 80

Chrome media internals output

[robwalch]

HLS.js is designed to start playback at specific distance from the end of the HLS playlist to maintain expected latency. The end of the playlist is updating and playback cannot start until media is buffered. When the media takes longer to buffer than playback can start, then the starting point will be moved forward to achieve target latency.

[robwalch]

If you'd like playback to start faster on slower connections, then start on a lower bitrate.

[grabofus]

The reason this felt like a bug because the target start time is still within the DVR window, it just happened to slide.

currentTime           target start position
v                        v
|------|------|------|---x--|------|------|------|

after first manifest refresh, once the initial segment is downloaded and readyState turns to 1, playback could begin at the intended position. In this scenario I think hls.js could still just begin with a slightly larger latency.

currentTime           target start position
v                        v
|xxxxxx|------|------|---x--|------|------|------|------|

but currently hls.js discards the already downloaded segment on slower devices and readjusts the start position as:

currentTime                  new target start position
v                               v
|xxxxxx|------|------|------|---x--|------|------|------|

I think this could be improved if we'd check the target start position, instead of the currentTime if the initial seek hasn't happened yet, due to the first segment not yet being buffered? This logic only seem to kick in once the first segment is downloaded as until then readyState is 0, so synchronizeToLiveEdge is never performing a seek.