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

maxMaxBufferLength is getting lower than the fragment duration #6428

Closed
5 tasks done
lianbenjamin opened this issue May 22, 2024 · 2 comments · Fixed by #6434
Closed
5 tasks done

maxMaxBufferLength is getting lower than the fragment duration #6428

lianbenjamin opened this issue May 22, 2024 · 2 comments · Fixed by #6434
Labels
Bug Confirmed non-independent-segments Stream Issue Suggested-Workaround
Milestone
1.5.9

Comments

@lianbenjamin
Copy link

What version of Hls.js are you using?

v1.5.8

What browser (including version) are you using?

Chrome 124.0.6367.209

What OS (including version) are you using?

macOS Sonoma 14.4.1

Test stream

https://hlsjs.video-dev.org/demo/?src=https%3A%2F%2Fcfvod.kaltura.com%2Ffhls%2Fp%2F5768482%2Fsp%2F576848200%2FserveFlavor%2FentryId%2F1_te7qb2q9%2Fv%2F11%2Fev%2F1%2FflavorId%2F1_mpdvaiwo%2Fname%2Fa.mp4%2Findex.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsInN0b3BPblN0YWxsIjpmYWxzZSwiZHVtcGZNUDQiOmZhbHNlLCJsZXZlbENhcHBpbmciOi0xLCJsaW1pdE1ldHJpY3MiOi0xfQ==

Configuration

{
  "enableWorker": false,
  "maxMaxBufferLength": 60
}

Additional player setup steps

No response

Checklist

Steps to reproduce

  1. Go to the provided test page
  2. Make sure the configuration includes "enableWorker": false and "maxMaxBufferLength": 60 (this one is not mandatory, though it will reproduce the issue faster)
  3. Make a seek a few times until the playback gets stuck
  4. Look at the console warnings- max buffer length is reduced each time by half, until it's smaller than the fragment duration - then it gets stuck.

Expected behaviour

  1. Playback should keep playing and not get stuck.
  2. Probably the maxMaxBufferLength shouldn't get smaller than the fragment duration

What actually happened?

The playback gets stuck because the maxMaxBufferLength is becoming smaller than the fragment duration.
Following a short investigation, it seems that there is a path where the maxMaxBufferLength can go lower than the duration of the fragment (or forward buffer whichever is bigger), where clearTrackerIfNeeded and reduceMaxBufferLength are called.
At this point of code - the code is checking maxMaxBufferLength against the threshold, where in my case the threshold is the fragment duration, and then cut maxMaxBufferLength by half; So, this is causing the value of maxMaxBufferLength to be smaller than the fragment duration.
My suggestion is to check for maxMaxBufferLength / 2 >= threshold before assigning it to maxMaxBufferLength.
NOTE- this is not reproducible when enableWorker configuration is set to true.

Console output

09:50:18.415 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:18.415 base-stream-controller.ts:1025 [warn] > [stream-controller]: Reduce max buffer length to 30s
09:50:18.489 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:18.490 base-stream-controller.ts:748 [log] > [stream-controller]: Loading fragment 159 cc: 0 of [1-345] level: 0, target: 1550
09:50:18.490 base-stream-controller.ts:1781 [log] > [stream-controller]: IDLE->FRAG_LOADING
09:50:18.510 base-stream-controller.ts:1781 [log] > [stream-controller]: FRAG_LOADING->PARSING
09:50:18.516 base-stream-controller.ts:389 [log] > [stream-controller]: Loaded fragment 159 of level 0
09:50:18.516 transmuxer.ts:267 [log] > [transmuxer.ts]: Flushed fragment 159 of level 0
09:50:18.521 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSING->PARSED
09:50:18.542 base-stream-controller.ts:560 [log] > [stream-controller]: Buffered main sn: 159 of level 0 (frag:[1550.000-1560.000] > buffer:[1549.160-1560.000])
09:50:18.542 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSED->IDLE
09:50:18.542 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:18.542 base-stream-controller.ts:1025 [warn] > [stream-controller]: Reduce max buffer length to 15s
09:50:18.590 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:18.590 base-stream-controller.ts:748 [log] > [stream-controller]: Loading fragment 160 cc: 0 of [1-345] level: 0, target: 1560
09:50:18.590 base-stream-controller.ts:1781 [log] > [stream-controller]: IDLE->FRAG_LOADING
09:50:18.610 base-stream-controller.ts:1781 [log] > [stream-controller]: FRAG_LOADING->PARSING
09:50:18.616 base-stream-controller.ts:389 [log] > [stream-controller]: Loaded fragment 160 of level 0
09:50:18.616 transmuxer.ts:267 [log] > [transmuxer.ts]: Flushed fragment 160 of level 0
09:50:18.620 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSING->PARSED
09:50:18.638 base-stream-controller.ts:560 [log] > [stream-controller]: Buffered main sn: 160 of level 0 (frag:[1560.000-1570.016] > buffer:[1549.160-1570.000])
09:50:18.638 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSED->IDLE
09:50:18.638 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:18.639 base-stream-controller.ts:748 [log] > [stream-controller]: Loading fragment 161 cc: 0 of [1-345] level: 0, target: 1570
09:50:18.639 base-stream-controller.ts:1781 [log] > [stream-controller]: IDLE->FRAG_LOADING
09:50:18.716  [log] > [stream-controller]: FRAG_LOADING->PARSING
09:50:18.723  [log] > [stream-controller]: Loaded fragment 161 of level 0
09:50:18.723  [log] > [transmuxer.ts]: Flushed fragment 161 of level 0
09:50:18.730  [log] > [stream-controller]: PARSING->PARSED
09:50:18.755  [log] > [stream-controller]: Buffered main sn: 161 of level 0 (frag:[1570.000-1580.000] > buffer:[1549.160-1580.000])
09:50:18.755  [log] > [stream-controller]: PARSED->IDLE
09:50:18.756  [log] > [stream-controller]: Loading fragment 162 cc: 0 of [1-345] level: 0, target: 1580
09:50:18.756  [log] > [stream-controller]: IDLE->FRAG_LOADING
09:50:19.581  [log] > [stream-controller]: FRAG_LOADING->PARSING
09:50:19.587  [log] > [stream-controller]: Loaded fragment 162 of level 0
09:50:19.588  [log] > [transmuxer.ts]: Flushed fragment 162 of level 0
09:50:19.594  [log] > [stream-controller]: PARSING->PARSED
09:50:19.622  [log] > [stream-controller]: Buffered main sn: 162 of level 0 (frag:[1580.000-1590.016] > buffer:[1549.160-1590.000])
09:50:19.622  [log] > [stream-controller]: PARSED->IDLE
09:50:19.622  [log] > [stream-controller]: Loading fragment 163 cc: 0 of [1-345] level: 0, target: 1590
09:50:19.622  [log] > [stream-controller]: IDLE->FRAG_LOADING
09:50:19.899  [log] > [stream-controller]: Media seeked to 1576.695
09:50:20.004  [log] > [stream-controller]: FRAG_LOADING->PARSING
09:50:20.010  [log] > [stream-controller]: Loaded fragment 163 of level 0
09:50:20.010  [log] > [transmuxer.ts]: Flushed fragment 163 of level 0
09:50:20.014  [log] > [stream-controller]: PARSING->PARSED
09:50:20.040  [log] > [stream-controller]: Buffered main sn: 163 of level 0 (frag:[1590.000-1600.000] > buffer:[1549.160-1600.000])
09:50:20.040  [log] > [stream-controller]: PARSED->IDLE
09:50:20.706  [log] > [stream-controller]: media seeking to 2130.302, state: IDLE
09:50:20.706  [log] > [audio-stream-controller]: media seeking to 2130.302, state: STOPPED
09:50:20.707  [log] > [subtitle-stream-controller]: media seeking to 2130.302, state: IDLE
09:50:20.707  [info] > [abr] buffer is empty, optimal quality level 0
09:50:20.707  [log] > [stream-controller]: Loading fragment 216 cc: 0 of [1-345] level: 0, target: 2130.302
09:50:20.707  [log] > [stream-controller]: IDLE->FRAG_LOADING
09:50:21.106  [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 216 p: -1 level: 0 id: 1
        discontinuity: false
        trackSwitch: false
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 2120
        initSegmentChange: false
09:50:21.106  [log] > [mp4-remuxer]: reset next timestamp
09:50:21.107 mp4-remuxer.ts:188 [warn] > [mp4-remuxer]: Dropped 195 out of 250 video samples due to a missing keyframe
09:50:21.108  [log] > [stream-controller]: FRAG_LOADING->PARSING
09:50:21.111  [log] > [buffer-controller] Removing [0,2120] from the audio SourceBuffer
09:50:21.114  [log] > [stream-controller]: Loaded fragment 216 of level 0
09:50:21.114  [log] > [transmuxer.ts]: Flushed fragment 216 of level 0
09:50:21.121  [log] > [stream-controller]: PARSING->PARSED
09:50:21.131  [log] > [buffer-controller] Removing [0,2120] from the video SourceBuffer
09:50:21.166  [log] > [stream-controller]: Buffered main sn: 216 of level 0 (frag:[2120.000-2130.016] > buffer:[2127.800-2130.000])
09:50:21.166  [log] > [stream-controller]: PARSED->IDLE
09:50:21.167  [info] > [abr] buffer is empty, optimal quality level 0
09:50:21.167  [log] > [stream-controller]: Loading fragment 217 cc: 0 of [1-345] level: 0, target: 2130.302
09:50:21.167  [log] > [stream-controller]: IDLE->FRAG_LOADING
09:50:21.761  [log] > [stream-controller]: FRAG_LOADING->PARSING
09:50:21.767  [log] > [stream-controller]: Loaded fragment 217 of level 0
09:50:21.767  [log] > [transmuxer.ts]: Flushed fragment 217 of level 0
09:50:21.771 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSING->PARSED
09:50:21.800 base-stream-controller.ts:560 [log] > [stream-controller]: Buffered main sn: 217 of level 0 (frag:[2130.000-2140.000] > buffer:[2127.800-2140.000])
09:50:21.800 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSED->IDLE
09:50:21.800 base-stream-controller.ts:748 [log] > [stream-controller]: Loading fragment 218 cc: 0 of [1-345] level: 0, target: 2140
09:50:21.801 base-stream-controller.ts:1781 [log] > [stream-controller]: IDLE->FRAG_LOADING
09:50:21.899 stream-controller.ts:556 [log] > [stream-controller]: Media seeked to 2130.302
09:50:22.121 base-stream-controller.ts:1781 [log] > [stream-controller]: FRAG_LOADING->PARSING
09:50:22.127 base-stream-controller.ts:389 [log] > [stream-controller]: Loaded fragment 218 of level 0
09:50:22.127 transmuxer.ts:267 [log] > [transmuxer.ts]: Flushed fragment 218 of level 0
09:50:22.133 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSING->PARSED
09:50:22.158 base-stream-controller.ts:560 [log] > [stream-controller]: Buffered main sn: 218 of level 0 (frag:[2140.000-2150.016] > buffer:[2127.800-2150.000])
09:50:22.158 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSED->IDLE
09:50:26.207 base-stream-controller.ts:241 [log] > [stream-controller]: media seeking to 644.823, state: IDLE
09:50:26.211 base-stream-controller.ts:241 [log] > [audio-stream-controller]: media seeking to 644.823, state: STOPPED
09:50:26.211 base-stream-controller.ts:241 [log] > [subtitle-stream-controller]: media seeking to 644.823, state: IDLE
09:50:26.211 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:26.211 base-stream-controller.ts:748 [log] > [stream-controller]: Loading fragment 67 cc: 0 of [1-345] level: 0, target: 644.823
09:50:26.212 base-stream-controller.ts:1781 [log] > [stream-controller]: IDLE->FRAG_LOADING
09:50:26.452 transmuxer-interface.ts:231 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 67 p: -1 level: 0 id: 1
        discontinuity: false
        trackSwitch: false
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 630
        initSegmentChange: false
09:50:26.452 mp4-remuxer.ts:92 [log] > [mp4-remuxer]: reset next timestamp
09:50:26.453 mp4-remuxer.ts:199 [warn] > [mp4-remuxer]: No keyframe found out of 250 video samples
09:50:26.454 base-stream-controller.ts:1781 [log] > [stream-controller]: FRAG_LOADING->PARSING
09:50:26.454 buffer-controller.ts:1097 [log] > [buffer-controller] Removing [0,630] from the audio SourceBuffer
09:50:26.454 buffer-controller.ts:1097 [log] > [buffer-controller] Removing [0,630] from the video SourceBuffer
09:50:26.454 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSING->IDLE
09:50:26.454 base-stream-controller.ts:389 [log] > [stream-controller]: Loaded fragment 67 of level 0
09:50:26.466 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:26.466 base-stream-controller.ts:748 [log] > [stream-controller]: Loading fragment 66 cc: 0 of [1-345] level: 0, target: 630
09:50:26.466 base-stream-controller.ts:1781 [log] > [stream-controller]: IDLE->FRAG_LOADING
09:50:26.930 transmuxer-interface.ts:231 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 66 p: -1 level: 0 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 620
        initSegmentChange: true
09:50:26.930 mp4-remuxer.ts:98 [log] > [mp4-remuxer]: ISGenerated flag reset
09:50:26.930 mp4-remuxer.ts:87 [log] > [mp4-remuxer]: initPTS & initDTS reset
09:50:26.931 mp4-remuxer.ts:92 [log] > [mp4-remuxer]: reset next timestamp
09:50:26.931 adts.ts:61 [log] > manifest codec:undefined, ADTS type:2, samplingIndex:5
09:50:26.931 adts.ts:247 [log] > parsed codec:mp4a.40.2, rate:32000, channels:1
09:50:26.933 mp4-remuxer.ts:199 [warn] > [mp4-remuxer]: No keyframe found out of 250 video samples
09:50:26.933 base-stream-controller.ts:1781 [log] > [stream-controller]: FRAG_LOADING->PARSING
09:50:26.933 stream-controller.ts:1297 [log] > [stream-controller]: Init audio buffer, container:audio/mp4, codecs[selected/level/parsed]=[//mp4a.40.2]
09:50:26.937 buffer-controller.ts:1097 [log] > [buffer-controller] Removing [0,620] from the video SourceBuffer
09:50:26.937 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSING->IDLE
09:50:26.937 base-stream-controller.ts:389 [log] > [stream-controller]: Loaded fragment 66 of level 0
09:50:26.938 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:26.938 base-stream-controller.ts:748 [log] > [stream-controller]: Loading fragment 65 cc: 0 of [1-345] level: 0, target: 620
09:50:26.938 base-stream-controller.ts:1781 [log] > [stream-controller]: IDLE->FRAG_LOADING
09:50:26.944 buffer-controller.ts:1097 [log] > [buffer-controller] Removing [0,620] from the audio SourceBuffer
09:50:27.405 transmuxer-interface.ts:231 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 65 p: -1 level: 0 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 610
        initSegmentChange: true
09:50:27.405 mp4-remuxer.ts:98 [log] > [mp4-remuxer]: ISGenerated flag reset
09:50:27.405 mp4-remuxer.ts:87 [log] > [mp4-remuxer]: initPTS & initDTS reset
09:50:27.405 mp4-remuxer.ts:92 [log] > [mp4-remuxer]: reset next timestamp
09:50:27.405 adts.ts:61 [log] > manifest codec:undefined, ADTS type:2, samplingIndex:5
09:50:27.406 adts.ts:247 [log] > parsed codec:mp4a.40.2, rate:32000, channels:1
09:50:27.407 mp4-remuxer.ts:188 [warn] > [mp4-remuxer]: Dropped 79 out of 250 video samples due to a missing keyframe
09:50:27.408 base-stream-controller.ts:1781 [log] > [stream-controller]: FRAG_LOADING->PARSING
09:50:27.408 stream-controller.ts:1297 [log] > [stream-controller]: Init audio buffer, container:audio/mp4, codecs[selected/level/parsed]=[//mp4a.40.2]
09:50:27.408 stream-controller.ts:1308 [log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[/avc1.640032]
09:50:27.420 base-stream-controller.ts:389 [log] > [stream-controller]: Loaded fragment 65 of level 0
09:50:27.421 transmuxer.ts:267 [log] > [transmuxer.ts]: Flushed fragment 65 of level 0
09:50:27.425 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSING->PARSED
09:50:27.436 buffer-controller.ts:1097 [log] > [buffer-controller] Removing [0,610] from the audio SourceBuffer
09:50:27.472 buffer-controller.ts:1097 [log] > [buffer-controller] Removing [0,610] from the video SourceBuffer
09:50:27.493 base-stream-controller.ts:560 [log] > [stream-controller]: Buffered main sn: 65 of level 0 (frag:[610.000-620.000] > buffer:[613.160-620.000][2127.800-2150.000])
09:50:27.493 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSED->IDLE
09:50:27.493 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:27.493 base-stream-controller.ts:1025 [warn] > [stream-controller]: Reduce max buffer length to 7.5s
09:50:27.500 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:27.500 base-stream-controller.ts:748 [log] > [stream-controller]: Loading fragment 66 cc: 0 of [1-345] level: 0, target: 620
09:50:27.500 base-stream-controller.ts:1781 [log] > [stream-controller]: IDLE->FRAG_LOADING
09:50:27.584 base-stream-controller.ts:1781 [log] > [stream-controller]: FRAG_LOADING->PARSING
09:50:27.590 base-stream-controller.ts:389 [log] > [stream-controller]: Loaded fragment 66 of level 0
09:50:27.590 transmuxer.ts:267 [log] > [transmuxer.ts]: Flushed fragment 66 of level 0
09:50:27.594 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSING->PARSED
09:50:27.616 base-stream-controller.ts:560 [log] > [stream-controller]: Buffered main sn: 66 of level 0 (frag:[620.000-630.016] > buffer:[613.160-630.000][2127.800-2150.000])
09:50:27.616 base-stream-controller.ts:1781 [log] > [stream-controller]: PARSED->IDLE
09:50:27.616 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:27.689 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:27.790 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:27.889 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:27.989 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:28.090 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0
09:50:28.189 abr-controller.ts:607 [info] > [abr] buffer is empty, optimal quality level 0

Chrome media internals output

No response
@lianbenjamin lianbenjamin added Bug Needs Triage If there is a suspected stream issue, apply this label to triage if it is something we should fix. labels May 22, 2024
@robwalch robwalch added non-independent-segments Stream Issue Confirmed and removed Needs Triage If there is a suspected stream issue, apply this label to triage if it is something we should fix. labels May 22, 2024
@robwalch
Copy link
Collaborator

robwalch commented May 22, 2024 •
edited
Loading

It looks like you have segments that are not independent:

[mp4-remuxer]: No keyframe found out of 250 video samples

Or ones which are but result in most of the fragment being dropped when seeked to:

[mp4-remuxer]: Dropped 179 out of 250 video samples due to a missing keyframe

We expect these to be handled with "backtracking" (finding the first fragment with a keyframe at or before the target buffer time to satisfy the playback). Backtracking is happening, but after appending the video segments with only some usable samples, the video SourceBuffer still shows no buffered media. This leaves the fragment tracker state of the fragment in "APPENDING" and since it was not buffered when it attempts to load it again, clearTrackerIfNeeded is run which calls reduceMaxBufferLength and removes the fragment from the tracker. This is meant to deal with SourceBuffer append errors like quota exceeded. Removing the fragment from the tracker is also required for backtracking to run. The problem occurs when the fragment is no longer removed because the buffer has been reduced beyond the minimum. It's not that it won't load more fragments, it's that it won't reload the problematic one.

hls.js/src/controller/base-stream-controller.ts

Lines 456 to 461 in 238f217

const minForwardBufferLength = Math.max(
frag.duration,
bufferedInfo ? bufferedInfo.len : this.config.maxBufferLength,
);
if (this.reduceMaxBufferLength(minForwardBufferLength)) {
fragmentTracker.removeFragment(frag);

@robwalch
Copy link
Collaborator

robwalch commented May 22, 2024 •
edited
Loading

As a workaround, you could set hls.config.maxMaxBufferLength back to 60 or any value large enough for it to be reduced again on regular intervals or on FRAG_LOADING.

@robwalch robwalch added this to the 1.5.9 milestone May 22, 2024
robwalch added a commit that referenced this issue May 22, 2024
@robwalch
Fix backtracking when an appended segment has no buffered timerange
78f8eef 
Fixes #6428
@robwalch robwalch mentioned this issue May 22, 2024
Merged
3 tasks
robwalch added a commit that referenced this issue May 23, 2024
@robwalch
Fix backtracking when an appended segment has no buffered timerange (#…
ee3abcd 
…6434)

Fixes #6428
robwalch added a commit that referenced this issue May 23, 2024
@robwalch
Fix backtracking when an appended segment has no buffered timerange (#…
76dd1dd 
…6434)

Fixes #6428

(cherry picked from commit ee3abcd)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Bug Confirmed non-independent-segments Stream Issue Suggested-Workaround
Projects
None yet
Milestone
1.5.9
Development

Successfully merging a pull request may close this issue.

Fix backtracking when an appended segment has no buffered timerange video-dev/hls.js
2 participants
@robwalch @lianbenjamin