1909543 - Assertion `MOZ_ASSERT(aTrackData.mBufferedRanges.IsEmpty())` while watching Ads on Netflix

Status: NEW

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

Description

[Alastor Wu [:alwu][PTO 11/1-11/9]]

Attachment: Log

This assertion was hit while watching Ads on Netflix.

D/MediaSource TrackBuffersManager[2d91e2edb00] ::RemoveFrames: Removing [(1141.555667, 1152.597292), (1152.597292, 1186.388667)] from bufferedRange [(1141.555667, 1186.388667)]

This removal range should be combined to one, not two separate ranges. This incorrect removal range causes wrong buffered range.

D/MediaSource TrackBuffersManager[2d91e2edb00] ::RemoveFrames: After removing frames, video/avc data sz=0, highestStartTimestamp= 0, bufferedRange=[(1152.597292, 1152.597292)], sanitizedBufferedRanges=[(1152.597292, 1152.597292)]

Comment 1

[Alastor Wu [:alwu][PTO 11/1-11/9]]

Attachment: Bug 1909543 - set fuzz on removed interval to keep the buffered range correct after removal.

Comment 2

[Karl Tomlinson (:karlt)]

Interesting!

CodedFrameRemoval: before video ranges=[({11415556670,10000000}, {11863886670,10000000})]

The base indicates that the numerator represents tenths of microseconds, but it looks to be rounded to microseconds here.

The difference in rounding between the 1152597291 from ToMicroseconds(), which rounds toward zero, and 1152.597292 from ToSeconds(), which rounds to nearest, implies that not all timestamps are rounded to microseconds.

TrackBuffersManager[2d91e2edb00] ::RemoveFrames: overriding start of frame [1152555667,1152597291] with [0,1186388667] dropping
TrackBuffersManager[2d91e2edb00] ::RemoveFrames: overriding start of frame [1152472333,1152514000] with [0,1186388667] dropping
TrackBuffersManager[2d91e2edb00] ::RemoveFrames: overriding start of frame [1152514000,1152555667] with [0,1186388667] dropping
TrackBuffersManager[2d91e2edb00] ::RemoveFrames: overriding start of frame [1152597291,1152638958] with [0,1186388667] dropping
TrackBuffersManager[2d91e2edb00] ::RemoveFrames: overriding start of frame [1152763958,1152805625] with [0,1186388667] dropping
TrackBuffersManager[2d91e2edb00] ::RemoveFrames: overriding start of frame [1152680625,1152722291] with [0,1186388667] dropping
TrackBuffersManager[2d91e2edb00] ::RemoveFrames: overriding start of frame [1152638958,1152680625] with [0,1186388667] dropping
TrackBuffersManager[2d91e2edb00] ::RemoveFrames: overriding start of frame [1152722291,1152763958] with [0,1186388667] dropping

The frame at 1152555667 has 41624 microsecond duration. The surrounding frames are either 41666 or 41667, as expected for 24 fps.

Perhaps the glitch might be due to the timestampOffset attribute, but that is rounded to microseconds, so the non-zero tenths of microseconds are not from that.

Comment 3

[Karl Tomlinson (:karlt)]

(In reply to Alastor Wu [:alwu] from comment #0)

This assertion was hit while watching Ads on Netflix.

D/MediaSource TrackBuffersManager[2d91e2edb00] ::RemoveFrames: Removing [(1141.555667, 1152.597292), (1152.597292, 1186.388667)] from bufferedRange [(1141.555667, 1186.388667)]

This removal range should be combined to one, not two separate ranges.

Perhaps. It would be interesting to know why it is not combined.
The first 1152.597292 comes from start time + duration arithmetic. This could be inaccurate if the denominators differ, perhaps due to duration truncation on frame insertion or elsewhere.

This incorrect removal range causes wrong buffered range.

D/MediaSource TrackBuffersManager[2d91e2edb00] ::RemoveFrames: After removing frames, video/avc data sz=0, highestStartTimestamp= 0, bufferedRange=[(1152.597292, 1152.597292)], sanitizedBufferedRanges=[(1152.597292, 1152.597292)]

Apparently either

1. we have bugs in our intervals arithmetic (e.g. bug 1909614),
2. the removal range does not accurately represent the frames removed,
3. mBufferedRanges did not accurately represent the frames before removal (e.g. bug 1909750),
4. or some combination of these.

Comment 4

[Tyson Smith [:tsmith]]

This issue has been detected by live site testing.

A Pernosco session is available here: https://pernos.co/debug/59FCY2uIYtfg3wAnMQPjPQ/index.html

Comment 5

[Karl Tomlinson (:karlt)]

Thank you, Tyson.

In that Pernosco session, mBufferedRanges gets out of sync with the frame presentation ranges for audio samples when the frame rate changes from 48000 to 22050.
The duration of a 48000-frames/s packet is truncated when a 22050-frames/s packet overlaps.
The end time of the truncated packet is derived from the start time of the first 22050-frame/s packet, but that start time is rounded to a multiple of 1/48000 s (using default RoundingPolicy of TruncatePolicy).
mHighestStartTimestamp is not updated to the start time of a packet at the new frame rate until after InsertFrames() and RemoveFrames() are called.
The end time of the (truncated) last 48000-frames/s packet is less than the start time of the first 22050-frame/s packet, but mBufferedRanges does not reflect that gap.
When the packets are removed, mBufferRanges retains its incorrect range over that gap, which is detected by the failed assertion.

Comment 6

[Karl Tomlinson (:karlt)]

I think we should not be rounding the start time of the new packet to a different denominator for buffered ranges calculations.
However, only removing the rounding to the denominator of mHighestStartTimestamp will still leave inaccuracies in the truncated duration calculated as a difference of TimeUnits with different denominators.
When that inaccuracy leaves a gap between truncated and new frames, that gap will need to be removed from mBufferedRanges, which is bug 1909750.

An alternative approach might be to replace packet durations with end times, so that the truncation can be exact. I haven't thought too much about that and whether or not it could introduce different inaccuracies. Perhaps the truncated end time could be used instead of duration only when truncation occurs, if necessary.