Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Separate playlists for audio and video can take a long time to start fetching segments #4288

Closed
5 tasks done
Frenzie opened this issue Aug 24, 2021 · 1 comment · Fixed by #4600
Closed
5 tasks done

Separate playlists for audio and video can take a long time to start fetching segments #4288

Frenzie opened this issue Aug 24, 2021 · 1 comment · Fixed by #4600
Labels
Bug Needs Triage If there is a suspected stream issue, apply this label to triage if it is something we should fix.

Comments

@Frenzie
Copy link
Contributor

Frenzie commented Aug 24, 2021

What version of Hls.js are you using?

v1.0.10

What browser (including version) are you using?

Firefox 91.0.1, Chrome 92.0.4515.159

What OS (including version) are you using?

Kubuntu 21.04, Debian 10, Debian 11, Windows 10

Test stream

https://hls-js.netlify.app/demo/?src=https%3A%2F%2Fhlslive-origindev01-test.cdn03.rambla.be%2Fmain%2Fhls_multi%2Fmaster.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsInN0b3BPblN0YWxsIjpmYWxzZSwiZHVtcGZNUDQiOmZhbHNlLCJsZXZlbENhcHBpbmciOi0xLCJsaW1pdE1ldHJpY3MiOi0xfQ==

Configuration

{
  "debug": true,
  "enableWorker": true,
  "lowLatencyMode": true,
  "backBufferLength": 90
}

Additional player setup steps

No response

Checklist

Steps to reproduce

  1. You'll have to refresh it or click apply quite a number of times before the behavior is reproducible. I'd guess it happens between 1 in 10 and 1 in 20 times.
  2. The stream takes 10 or more seconds to start playing.

Expected behaviour

The stream starts playing within a few seconds.

What actually happened?

The stream takes 10 or more seconds to start playing.

Console output

[log] > loadSource:https://hlslive-origindev01-test.cdn03.rambla.be/main/hls_multi/master.m3u8 hls.ts:331:11
[log] > [stream-controller]: Trigger BUFFER_RESET stream-controller.ts:539:9
[log] > attachMedia hls.ts:302:11
[log] > [buffer-controller]: Media source opened buffer-controller.ts:742:11
[log] > [subtitle-stream-controller]: STOPPED->IDLE base-stream-controller.ts:1362:11
[log] > [level-controller]: manifest loaded, 4 level(s) found, first bitrate: 3369712 level-controller.ts:172:15
[log] > 2 bufferCodec event(s) expected buffer-controller.ts:136:11
[log] > startLoad(-1) hls.ts:353:11
[log] > [level-controller]: switching to level 3 from -1 level-controller.ts:251:9
[log] > [audio-track-controller]: Updating audio tracks, 1 track(s) found in "group_audio" group-id audio-track-controller.ts:134:11
[log] > [audio-track-controller]: Now switching to audio-track index 0 audio-track-controller.ts:185:9
[log] > [audio-stream-controller]: STOPPED->IDLE base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: IDLE->WAITING_TRACK base-stream-controller.ts:1362:11
[log] > [level-controller]: Attempt loading level index 3 with URL-id 0 https://hlslive-origindev01-test.cdn03.rambla.be/main/hls_multi/720p.m3u8 level-controller.ts:524:11
[log] > [stream-controller]: STOPPED->IDLE base-stream-controller.ts:1362:11
[log] > [audio-track-controller]: loading audio-track playlist for id: 0 audio-track-controller.ts:258:11
[log] > [audio-stream-controller]: WAITING_TRACK->STOPPED base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: STOPPED->WAITING_TRACK base-stream-controller.ts:1362:11
[log] > [subtitle-stream-controller]: IDLE->STOPPED base-stream-controller.ts:1362:11
[log] > [subtitle-stream-controller]: STOPPED->IDLE base-stream-controller.ts:1362:11
[log] > [audio-track-controller]: audioTrack 0 loaded [20210824110355-20210824110359] audio-track-controller.ts:87:9
[log] > [audio-track-controller]: reload live playlist 0 in 9945 ms base-playlist-controller.ts:211:11
[log] > [audio-stream-controller]: Track 0 loaded [20210824110355,20210824110359],duration:50 audio-stream-controller.ts:424:9
[log] > [level-controller]: reload live playlist 3 in 9891 ms base-playlist-controller.ts:211:11
[log] > [stream-controller]: Level 3 loaded [20210824110354,20210824110358], cc [0, 0] duration:50 stream-controller.ts:603:9
[log] > [stream-controller]: Live playlist sliding: 0.00 start-sn: na->20210824110354 prev-sn: na fragments: 5 base-stream-controller.ts:1106:11
[log] > [buffer-controller]: Updating Media Source duration to 50.000 buffer-controller.ts:635:13
[log] > [stream-controller]: Loading fragment 20210824110356 cc: 0 of [20210824110354-20210824110358] level: 3, target: 20.001 base-stream-controller.ts:569:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1362:11
[log] > demuxing in webworker transmuxer-interface.ts:67:13
[log] > [transmuxer-interface, main]: Starting new transmux session for sn: 20210824110356 p: -1 level: 3 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: false
        timeOffset: 20 transmuxer-interface.ts:183:13
[log] > [stream-controller]: Loaded fragment 20210824110356 of level 3 base-stream-controller.ts:345:15
[log] > 0965b4fc-e6ee-4c87-9c3f-abfad627a109:603:22
[log] > [mp4-remuxer]: ISGenerated flag reset 0965b4fc-e6ee-4c87-9c3f-abfad627a109:2699:58
[log] > [mp4-remuxer]: initPTS & initDTS reset 0965b4fc-e6ee-4c87-9c3f-abfad627a109:2688:58
[log] > [stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1362:11
[log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[/avc1.64001f] stream-controller.ts:1222:11
[log] > [transmuxer.ts]: Flushed fragment 20210824110356 of level 3 0965b4fc-e6ee-4c87-9c3f-abfad627a109:937:59
[log] > [audio-stream-controller]: InitPTS for cc: 0 found from main: 8264640 audio-stream-controller.ts:113:11
[log] > [stream-controller]: PARSING->PARSED base-stream-controller.ts:1362:11
[log] > [level-controller]: Attempt loading level index 3 at sn undefined part undefined with URL-id 0 https://hlslive-origindev01-test.cdn03.rambla.be/main/hls_multi/720p.m3u8 level-controller.ts:524:11
[log] > [audio-track-controller]: loading audio-track playlist for id: 0 audio-track-controller.ts:258:11
[log] > [audio-track-controller]: audioTrack 0 loaded [20210824110356-20210824110360] audio-track-controller.ts:87:9
[log] > [audio-track-controller]: live playlist 0 REFRESHED 20210824110360--1 base-playlist-controller.ts:120:13
[log] > [audio-track-controller]: reload live playlist 0 in 10000 ms base-playlist-controller.ts:211:11
[log] > [audio-stream-controller]: Track 0 loaded [20210824110356,20210824110360],duration:50 audio-stream-controller.ts:424:9
[log] > Adjusting PTS using programDateTime delta 20016ms, sliding:20.016 https://hlslive-origindev01-test.cdn03.rambla.be/main/hls_multi/eng_audio.m3u8 discontinuities.ts:168:11
[log] > [audio-stream-controller]: WAITING_TRACK->IDLE base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: Loading fragment 20210824110356 cc: 0 of [20210824110356-20210824110360] track: 0, target: 30.016 base-stream-controller.ts:569:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1362:11
[log] > [level-controller]: live playlist 3 REFRESHED 20210824110359--1 base-playlist-controller.ts:120:13
[log] > [level-controller]: reload live playlist 3 in 10000 ms base-playlist-controller.ts:211:11
[log] > [stream-controller]: Level 3 loaded [20210824110355,20210824110359], cc [0, 0] duration:50 stream-controller.ts:603:9
[log] > [buffer-controller]: Updating Media Source duration to 60.000 buffer-controller.ts:635:13
[log] > demuxing in webworker transmuxer-interface.ts:67:13
[log] > [transmuxer-interface, audio]: Starting new transmux session for sn: 20210824110356 p: -1 level: 0 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: false
        timeOffset: 30.016 transmuxer-interface.ts:183:13
[log] > [audio-stream-controller]: Loaded fragment 20210824110356 of level 0 base-stream-controller.ts:345:15
[log] > d0beab0d-2124-44f6-9150-5082a3feeb5e:603:22
[log] > [mp4-remuxer]: ISGenerated flag reset d0beab0d-2124-44f6-9150-5082a3feeb5e:2699:58
[log] > [mp4-remuxer]: initPTS & initDTS reset d0beab0d-2124-44f6-9150-5082a3feeb5e:2688:58
[log] > manifest codec:mp4a.40.2, ADTS type:2, samplingIndex:3 d0beab0d-2124-44f6-9150-5082a3feeb5e:7540:56
[log] > parsed codec:mp4a.40.2, rate:48000, channels:1 d0beab0d-2124-44f6-9150-5082a3feeb5e:7702:58
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1362:11
[log] > [transmuxer.ts]: Flushed fragment 20210824110356 of level 0 d0beab0d-2124-44f6-9150-5082a3feeb5e:937:59
[log] > [audio-stream-controller]: Switching audio track : flushing all audio audio-stream-controller.ts:809:11
[log] > [audio-stream-controller]: Init audio buffer, container:audio/mp4, codecs[parsed]=[mp4a.40.2] audio-stream-controller.ts:757:9
[log] > [buffer-controller]: creating sourceBuffer(video/mp4;codecs=avc1.64001f) buffer-controller.ts:704:15
[log] > [buffer-controller]: creating sourceBuffer(audio/mp4;codecs=mp4a.40.2) buffer-controller.ts:704:15
[log] > [stream-controller]: Alternate track found, use video.buffered to schedule main fragment loading stream-controller.ts:809:11
[log] > [buffer-controller]: Removing [0,60] from the audio SourceBuffer buffer-controller.ts:816:13
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1362:11
[log] > [stream-controller]: Buffered main sn: 20210824110356 of level 3 [20.000,30.000] base-stream-controller.ts:480:9
[log] > [stream-controller]: PARSED->IDLE base-stream-controller.ts:1362:11
[log] > [stream-controller]: Loading fragment 20210824110357 cc: 0 of [20210824110355-20210824110359] level: 3, target: 30.002 base-stream-controller.ts:569:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: Buffered audio sn: 20210824110356 of track 0 [18.187,28.171] base-stream-controller.ts:480:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: Loading fragment 20210824110357 cc: 0 of [20210824110356-20210824110360] track: 0, target: 40.016 base-stream-controller.ts:569:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1362:11
[log] > [stream-controller]: seek to target start position 20.000999999999998 from current time 0 stream-controller.ts:990:11
[log] > [stream-controller]: media seeking to 20.001, state: FRAG_LOADING base-stream-controller.ts:199:9
[log] > [audio-stream-controller]: media seeking to 20.001, state: FRAG_LOADING base-stream-controller.ts:199:9
[log] > [subtitle-stream-controller]: media seeking to 20.001, state: IDLE base-stream-controller.ts:199:9
[log] > [stream-controller]: Media seeked to 20.001 stream-controller.ts:530:11
[log] > [audio-stream-controller]: Loaded fragment 20210824110357 of level 0 base-stream-controller.ts:345:15
[log] > [transmuxer.ts]: Flushed fragment 20210824110357 of level 0 d0beab0d-2124-44f6-9150-5082a3feeb5e:937:59
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: Buffered audio sn: 20210824110357 of track 0 [18.187,38.176] base-stream-controller.ts:480:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: SN 20210824110357 just loaded, load next one: 20210824110358 base-stream-controller.ts:1027:17
[log] > [audio-stream-controller]: Loading fragment 20210824110358 cc: 0 of [20210824110356-20210824110360] track: 0, target: 50.016 base-stream-controller.ts:569:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: Loaded fragment 20210824110358 of level 0 base-stream-controller.ts:345:15
[log] > [transmuxer.ts]: Flushed fragment 20210824110358 of level 0 d0beab0d-2124-44f6-9150-5082a3feeb5e:937:59
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: Buffered audio sn: 20210824110358 of track 0 [18.187,48.181] base-stream-controller.ts:480:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: SN 20210824110358 just loaded, load next one: 20210824110359 base-stream-controller.ts:1027:17
[log] > [audio-stream-controller]: Loading fragment 20210824110359 cc: 0 of [20210824110356-20210824110360] track: 0, target: 60.016 base-stream-controller.ts:569:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: Loaded fragment 20210824110359 of level 0 base-stream-controller.ts:345:15
[log] > [transmuxer.ts]: Flushed fragment 20210824110359 of level 0 d0beab0d-2124-44f6-9150-5082a3feeb5e:937:59
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: Buffered audio sn: 20210824110359 of track 0 [18.187,58.187] base-stream-controller.ts:480:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1362:11
[log] > [stream-controller]: Loaded fragment 20210824110357 of level 3 base-stream-controller.ts:345:15
[log] > [stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1362:11
[log] > [transmuxer.ts]: Flushed fragment 20210824110357 of level 3 0965b4fc-e6ee-4c87-9c3f-abfad627a109:937:59
[log] > [stream-controller]: PARSING->PARSED base-stream-controller.ts:1362:11
[log] > [stream-controller]: Buffered main sn: 20210824110357 of level 3 [20.000,40.000] base-stream-controller.ts:480:9
[log] > [stream-controller]: PARSED->IDLE base-stream-controller.ts:1362:11
[log] > [stream-controller]: Loading fragment 20210824110358 cc: 0 of [20210824110355-20210824110359] level: 3, target: 40 base-stream-controller.ts:569:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1362:11
[log] > [stream-controller]: Loaded fragment 20210824110358 of level 3 base-stream-controller.ts:345:15
[log] > [stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1362:11
[log] > [transmuxer.ts]: Flushed fragment 20210824110358 of level 3 0965b4fc-e6ee-4c87-9c3f-abfad627a109:937:59
[log] > [stream-controller]: PARSING->PARSED base-stream-controller.ts:1362:11
[log] > [stream-controller]: Buffered main sn: 20210824110358 of level 3 [20.000,50.000] base-stream-controller.ts:480:9
[log] > [stream-controller]: PARSED->IDLE base-stream-controller.ts:1362:11
[log] > [stream-controller]: Loading fragment 20210824110359 cc: 0 of [20210824110355-20210824110359] level: 3, target: 50 base-stream-controller.ts:569:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1362:11
[log] > [stream-controller]: Loaded fragment 20210824110359 of level 3 base-stream-controller.ts:345:15
[log] > [transmuxer.ts]: Flushed fragment 20210824110359 of level 3 0965b4fc-e6ee-4c87-9c3f-abfad627a109:937:59
[log] > [stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1362:11
[log] > [stream-controller]: PARSING->PARSED base-stream-controller.ts:1362:11
[log] > [stream-controller]: Buffered main sn: 20210824110359 of level 3 [20.000,60.000] base-stream-controller.ts:480:9
[log] > [stream-controller]: PARSED->IDLE base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: SN 20210824110359 just loaded, load next one: 20210824110360 base-stream-controller.ts:1027:17
[log] > [audio-stream-controller]: Loading fragment 20210824110360 cc: 0 of [20210824110356-20210824110360] track: 0, target: 70.016 base-stream-controller.ts:569:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: Loaded fragment 20210824110360 of level 0 base-stream-controller.ts:345:15
[log] > [transmuxer.ts]: Flushed fragment 20210824110360 of level 0 d0beab0d-2124-44f6-9150-5082a3feeb5e:937:59
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1362:11
[log] > [audio-stream-controller]: Buffered audio sn: 20210824110360 of track 0 [18.187,68.171] base-stream-controller.ts:480:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1362:11

Chrome media internals output

No response
@Frenzie Frenzie added Bug Needs Triage If there is a suspected stream issue, apply this label to triage if it is something we should fix. labels Aug 24, 2021
@robwalch robwalch linked a pull request Nov 18, 2021 that will close this issue
Bugfix/live start bugs #4303
Merged
3 tasks
@robwalch robwalch removed a link to a pull request Dec 6, 2021
Bugfix/live start bugs #4303
Merged
3 tasks
@Frenzie
Copy link
Contributor Author

Frenzie commented Mar 10, 2022

This issue seems to have been introduced in one of these commits: v1.0.5...v1.0.6

Frenzie added a commit to Frenzie/hls.js that referenced this issue Mar 14, 2022
@Frenzie
Retry align audio playlist with main playlist if levelloaded came too…
ee4ff6a 
… early

Fixes video-dev#4288.
@Frenzie Frenzie mentioned this issue Mar 14, 2022
Merged
3 tasks
Frenzie added a commit to Frenzie/hls.js that referenced this issue Mar 24, 2022
@Frenzie
Retry align audio playlist with main playlist if levelloaded came too…
c7ca851 
… early

Fixes video-dev#4288.
Frenzie added a commit to Frenzie/hls.js that referenced this issue May 17, 2022
@Frenzie
Retry align audio playlist with main playlist if levelloaded came too…
b1a2d82 
… early

Fixes video-dev#4288.
Frenzie added a commit to Frenzie/hls.js that referenced this issue May 17, 2022
@Frenzie
Emit AUDIO_TRACK_LOADED event if LEVEL_LOADED came too early
60f363d 
Fixes video-dev#4288.
robwalch pushed a commit that referenced this issue May 20, 2022
@Frenzie
Retry aligning audio playlist with main playlist if levelloaded came …
07ec82c 
…too early (#4600)

* Retry align audio playlist with main playlist if levelloaded came too early

Fixes #4288.

* Revert "Retry align audio playlist with main playlist if levelloaded came too early"

This reverts commit b1a2d82.

* Emit AUDIO_TRACK_LOADED event if LEVEL_LOADED came too early

Fixes #4288.

* Mock mainDetails in test
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Bug Needs Triage If there is a suspected stream issue, apply this label to triage if it is something we should fix.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Retry aligning audio playlist with main playlist if levelloaded came too early Frenzie/hls.js
1 participant
@Frenzie