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

Status: ASSIGNED

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

Description

[Karl Tomlinson (:karlt)]

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}

Comment 1

[Karl Tomlinson (:karlt)]

Chrome rounds down the DefaultDuration.

Comment 2

[Karl Tomlinson (:karlt)]

https://treeherder.mozilla.org/jobs?repo=try&revision=edcafe85a20567aa666744bee523ecf134d735ff
Still getting some similar symptoms sometimes with those changes: https://share.firefox.dev/3ROLbRD

Comment 3

[Karl Tomlinson (:karlt)]

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.

Comment 4

[Karl Tomlinson (:karlt)]

Attachment: Bug 1904750 Fetch DefaultDuration in ReadMetadata() r?#media-playback-reviewers

Comment 5

[Karl Tomlinson (:karlt)]

Attachment: Bug 1904750 Round DefaultDuration down to nearest multiple of TimecodeScale r?#media-playback-reviewers

Depends on D215276

Comment 6

[Karl Tomlinson (:karlt)]

Attachment: Bug 1904750 Prefer DefaultDuration over previous inter-timestamp interval r?#media-playback-reviewers

Depends on D215277