Closed Bug 1904750 Opened 1 month ago Closed 24 days ago

YouTube video pauses due to evicted frames on insertion of previous frame with duration estimate too long

Categories

(Core :: Audio/Video: Playback, defect)

defect

Tracking

()

RESOLVED FIXED
129 Branch
Tracking Status
firefox-esr115 --- affected
firefox-esr128 --- affected
firefox128 --- wontfix
firefox129 --- fixed

People

(Reporter: karlt, Assigned: karlt)

References

(Blocks 1 open bug)

Details

Attachments

(3 files)

  1. Play https://www.youtube.com/watch?v=rIYBi97ZKF8 @ 1440 fps until half way through
  2. Pause.
  3. Start logging to profiler with media preset and MediaSource:5,MediaSourceSamples:5,MediaDemuxer:5.
  4. Seek to the beginning.
  5. Play.

Video pauses after about Sample end time: 8,675,000μs; audio continues.

Logging in the profile at https://share.firefox.dev/4cCNzTC

The profile is from a local build that had fixes for bug 1878510 (mVideoFrameEndTimeBeforeReset) and for bug 1903974, and some logging changes for bug 1904729. It did not have DefaultDuration for bug 1900191, but I don't think that would have helped here because the frame duration was calculated from the previous timestamp difference, which is preferred over default duration. Even if the duration is preferred, then rounding of timestamps may cause even the default duration to overlap the next timestamp.

An inaccurate frame duration (end 5573000) of an inserted sample causes the next sample (start 5572000) and all depended samples to be evicted, including the samples necessary for immediate continuing playback. This is similar to what was observed in bug 1878510 comment 79.

26.606
LogMessages — (MediaDemuxer) WebMDemuxer[7f5b2bf93600] ::GetNextPacket: video: tstamp=5539000, duration=-1
LogMessages — (MediaDemuxer) WebMDemuxer[7f5b2bf93600] ::DemuxPacket: EOS
LogMessages — (MediaDemuxer) WebMDemuxer[7f5b2bf93600] ::GetNextPacket: next_holder N mLastVideoFrameTime Y
LogMessages — (MediaDemuxer) WebMDemuxer[7f5b2bf93600] ::GetNextPacket: push sample tstamp: 5539000 next_tstamp: 5573000 length: 183538 kf: 1

26.607
LogMessages — (MediaSource) TrackBuffersManager[7f5b7ae06d00] ::InsertFrames: Processing 1 video/vp9 frames(start:5539000 end:5573000)
LogMessages — (MediaSource) TrackBuffersManager[7f5b7ae06d00] ::RemoveFrames: overridding start of frame [5539000,5572000] with [5539000,5573000] dropping
LogMessages — (MediaSource) TrackBuffersManager[7f5b7ae06d00] ::RemoveFrames: overridding start of frame [5572000,5606000] with [5539000,5573000] dropping
LogMessages — (MediaSource) TrackBuffersManager[7f5b7ae06d00] ::RemoveFrames: Removing frames from:10 for video/vp9 (frames:156) ([5.539000, 10.744000))
LogMessages — (MediaSource) TrackBuffersManager[7f5b7ae06d00] ::RemoveFrames: Next sample to be played got evicted
LogMessages — (MediaSource) TrackBuffersManager[7f5b7ae06d00] ::RemoveFrames: Removing [(5.539000, 5.972000), (5.973000, 6.439000), (6.440000, 10.744000)] from bufferedRange [(5.205000, 5.538000), (5.539000, 5.972000), (5.973000, 6.439000), (6.440000, 23.022000), (58.058000, 60.760000), (60.761000, 133.367000)]
LogMessages — (MediaSource) TrackBuffersManager[7f5b7ae06d00] ::RemoveFrames: After removing frames, video/vp9 data sz=2635, highestStartTimestamp= 133333000, bufferedRange=[(5.205000, 5.538000), (10.744000, 23.022000), (58.058000, 60.760000), (60.761000, 133.367000)], sanitizedBufferedRanges=[(5.205000, 5.538000), (10.744000, 23.022000), (58.058000, 133.367000)]
LogMessages — (MediaSource) TrackBuffersManager[7f5b7ae06d00] ::InsertFrames: Inserted video/vp9 frame:[(5.539000, 5.573000)], buffered-range:[(5.205000, 5.538000), (5.539000, 5.573000), (10.744000, 23.022000), (58.058000, 60.760000), (60.761000, 133.367000)], mHighestEndTimestamp={5573000,1000000}

Chrome rounds down the DefaultDuration.

Blocks: yt-playback
Summary: YouTube video pauses due to evicted frames and insertion of previous frame with duration estimate too long → YouTube video pauses due to evicted frames on insertion of previous frame with duration estimate too long

Analysis of the profile in comment 2 shows YouTube adding frames before currentTime, perhaps in response to Gecko's eviction of frames before currentTime, or perhaps in response to a failed AppendBuffer() due to eviction failing to evict enough ("buffer full").

17.094
LogMessages — (MediaSource) TrackBuffersManager[7f05a73e9f00] ::InsertFrames: Inserted video/vp9 frame:[(17.584000, 23.022000)], buffered-range:[(5.539000, 5.605000), (5.606000, 5.705000), (5.706000, 5.805000), (5.806000, 5.972000), (5.973000, 6.439000), (6.440000, 23.022000), (134.134000, 134.567000), (134.568000, 134.834000), (134.835000, 135.201000), (135.202000, 135.368000), (135.369000, 137.370000), (137.371000, 138.571000), (138.572000, 139.372000), (139.373000, 139.739000), (139.740000, 140.306000), (140.307000, 140.573000), (140.574000, 141.207000), (141.208000, 142.375000), (142.376000, 170.670000), (170.671000, 171.104000), (171.105000, 210.510000)], mHighestEndTimestamp={23022000,1000000}

17.166
LogMessages — (MediaSource) dom::SourceBuffer[7f05951afcc0] (video/webm; codecs="vp09.00.51.08.01.01.01.01.00")::AppendBuffer: AppendBuffer(ArrayBufferView)
LogMessages — (MediaSource) TrackBuffersManager[7f05a73e9f00] ::EvictData: Reached our size limit, schedule eviction of 86794 bytes (buffer full)
17.167
LogMessages — (MediaSource) TrackBuffersManager[7f05a73e9f00] ::CodedFrameRemoval: From 210.44s to inf
LogMessages — (MediaSource) dom::SourceBuffer[7f05951afcc0] (video/webm; codecs="vp09.00.51.08.01.01.01.01.00")::GetBuffered: intersection=[(5.539000, 23.022000), (134.134000, 210.510000)]
LogMessages — (MediaSource) dom::SourceBuffer[7f05951afcc0] (video/webm; codecs="vp09.00.51.08.01.01.01.01.00")::GetBuffered: currentValue=[(4.004000, 10.744000), (134.134000, 213.313000)]

17.324
LogMessages — (MediaSource) dom::SourceBuffer[7f05951afcc0] (video/webm; codecs="vp09.00.51.08.01.01.01.01.00")::AppendBuffer: AppendBuffer(ArrayBufferView)
LogMessages — (MediaSource) TrackBuffersManager[7f05a73e9f00] ::InsertFrames: Inserted video/vp9 frame:[(3.737000, 4.004000)], buffered-range:[(3.737000, 4.004000), (5.539000, 5.605000), (5.606000, 5.705000), (5.706000, 5.805000), (5.806000, 5.972000), (5.973000, 6.439000), (6.440000, 23.022000), (134.134000, 134.567000), (134.568000, 134.834000), (134.835000, 135.201000), (135.202000, 135.368000), (135.369000, 137.370000), (137.371000, 138.571000), (138.572000, 139.372000), (139.373000, 139.739000), (139.740000, 140.306000), (140.307000, 140.573000), (140.574000, 141.207000), (141.208000, 142.375000), (142.376000, 170.670000), (170.671000, 171.104000), (171.105000, 210.444000)], mHighestEndTimestamp={4004000,1000000}

Gecko is removing the recently added frames before currentTime:

17.333
LogMessages — (MediaSource) dom::SourceBuffer[7f05951afcc0] (video/webm; codecs="vp09.00.51.08.01.01.01.01.00")::AppendBuffer: AppendBuffer(ArrayBufferView)
LogMessages — (MediaSource) TrackBuffersManager[7f05a73e9f00] ::CodedFrameRemoval: From 3.74s to 5.54

YouTube continues to add subsequent frames before currentTime, until it overwrites a key frame required for the current playback position:

17.429
LogMessages — (MediaSource) dom::SourceBuffer[7f05951afcc0] (video/webm; codecs="vp09.00.51.08.01.01.01.01.00")::AppendBuffer: AppendBuffer(ArrayBufferView)
LogMessages — (MediaSourceSamples) WebMContainerParser[7f05bc2772b0] (video/webm; codecs="vp09.00.51.08.01.01.01.01.00")::ParseStartAndEndTimestamps: [5539000, 5572000] [fso=220, leo=183778, l=2 processedIdx=0 fs=0]
LogMessages — (MediaDemuxer) WebMDemuxer[7f0596469800] ::GetNextPacket: video: tstamp=5539000, duration=-1, mDuration=33000
LogMessages — (MediaDemuxer) WebMDemuxer[7f0596469800] ::DemuxPacket: EOS
LogMessages — (MediaDemuxer) WebMDemuxer[7f0596469800] ::GetNextPacket: next_holder N mLastVideoFrameTime Y
LogMessages — (MediaDemuxer) WebMDemuxer[7f0596469800] ::GetNextPacket: push sample tstamp: 5539000 next_tstamp: 5572000 length: 183538 kf: 1

17.430
LogMessages — (MediaSource) TrackBuffersManager[7f05a73e9f00] ::InsertFrames: Processing 1 video/vp9 frames(start:5539000 end:5572000)
LogMessages — (MediaSource) TrackBuffersManager[7f05a73e9f00] ::RemoveFrames: overriding start of frame [5539000,5572000] with [5539000,5572000] dropping
LogMessages — (MediaSource) TrackBuffersManager[7f05a73e9f00] ::RemoveFrames: Removing frames from:10 for video/vp9 (frames:156) ([5.539000, 10.744000))
LogMessages — (MediaSource) TrackBuffersManager[7f05a73e9f00] ::RemoveFrames: Next sample to be played got evicted

Here YouTube is overwriting what is required for current playback, rather than Gecko removing a key frame after the inserted frames. i.e. this bug is fixed by changes included in the build of this profile.
However, there is some other reason for YouTube adding frames that Gecko already has. Perhaps that is bug 1904937: evicting is failing as described in bug 1904937 comment 4. I don't see an additional SourceBuffer, but perhaps that was added before recording started for this profile.

I'll submit patches for this bug, but there is apparently another underlying trigger for getting into this situation, which we can investigate elsewhere, if not addressed by bug 1904937.

See Also: → 1904937
Assignee: nobody → karlt
Status: NEW → ASSIGNED
Pushed by ktomlinson@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/cb27ca2346e6
Fetch DefaultDuration in ReadMetadata() r=media-playback-reviewers,alwu
Pushed by ktomlinson@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/3688b37be063
Round DefaultDuration down to nearest multiple of TimecodeScale r=media-playback-reviewers,alwu
Pushed by ktomlinson@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/10308c3820c1
Prefer DefaultDuration over previous inter-timestamp interval r=media-playback-reviewers,alwu
Status: ASSIGNED → RESOLVED
Closed: 24 days ago
Resolution: --- → FIXED
Target Milestone: --- → 129 Branch
Flags: qe-verify+

Does this need a Release approval request?

Flags: needinfo?(karlt)

This didn't resolve the symptoms on the STR here and so I don't expect it to make a significant difference on YouTube on its own.
I therefore don't have sufficient justification for a release uplift.
The changes bring us closer to Chrome, but still not exactly the same.

Flags: needinfo?(karlt)
You need to log in before you can comment on or make changes to this bug.