1131884 - Video stalls for 30s before playback starts or resume from stall

Status: VERIFIED FIXED

(Core :: Audio/Video, defect)

Description

[Jean-Yves Avenard [:jya]]

Attachment: log.txt.zip

Was testing for possible regression and played that file:
http://216.18.212.226/PRODS/sony-nex-6/FULLRES/yvid_nex6_night_1080_30p.MP4

now here what I'm seeing is that video buffers briefly while it downloads. Then stalls and the waiting stuff appears. I can see in the slider that the video is being buffered, yet playback doesn't restart even with over half the video has been buffered.
After 30s playback restart and stall again shortly after.
At this time I can see that the entire video has been buffered, yet playback didn't restart.

Only after 30s will the video restart and play to its end.

On the console, before it restarts I can see:

448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 29.491s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 28.489s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 27.486s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 26.484s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 25.483s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 24.480s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 23.476s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 22.475s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 21.474s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 20.472s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 19.468s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 18.464s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 17.463s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 16.461s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 15.459s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 14.458s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 13.456s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 12.455s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 11.450s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 10.448s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 9.447s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 8.445s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 7.443s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 6.440s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 5.438s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 4.437s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 3.435s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 2.435s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 1.431s 
448569344[1342f0960]: Decoder=130c266d0 Buffering: wait 30s, timeout in 0.428s 
448569344[1342f0960]: Decoder=130c266d0 Changed state from BUFFERING to DECODING
448569344[1342f0960]: Decoder=130c266d0 Buffered for 30.573s
448569344[1342f0960]: Decoder=130c266d0 Change machine state from BUFFERING to DECODING
448569344[1342f0960]: Decoder=130c266d0 CheckIfDecodeComplete NOT completed
448569344[1342f0960]: Decoder=130c266d0 NeedToDecodeAudio() isDec=1 decToTar=0 minPrl=0 seek=0 enufAud=1

Once it has buffered for 30s it will restart.

It seems that once we enter that buffering state, even when we do have data we wait for the timeout.

complete log of playback is attached.

Comment 1

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

Is the spinner showing on the video?

Comment 2

[cajbir (:cajbir)]

The issues occurs due to the call to MediaDecoder::StartProgressUpdates() during the decoding of the metadata. This sets mPlaybackPosition to the current offset in the resource. In this particular file this is near the end of the file so mPlaybackPosition is close to EOF.

Future updates to mPlaybackPosition never happen as updates take the max of the offset and old mPlaybackPosition - which is already as high as it'll go.

This confuses our buffering calculation.

Changing StartProgressUpdates to not set mPlaybackPosition and changing the update to not use the max fixes the issue. This gets set anyway when the next frame is played so I'm not sure why we set it to the metadata position during metadata decoding.

Running tests to make sure nothing breaks.

Comment 3

[cajbir (:cajbir)]

Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=92a30cb2bbc4

Comment 5

[cajbir (:cajbir)]

Attachment: Fix CanPlayThrough calculation

Playback position used in calculating buffering time is set during metadata reading. This is at end of file for the video in the bug. As a result the buffering data is always wrong.
    
Changed to not setting position during metadata - it is set during frame playback anyway.
    
Also changes buffering timeout to 15s from 30s.

Comment 6

[Jean-Yves Avenard [:jya]]

Comment on attachment 8575743 [details] [diff] [review]
Fix CanPlayThrough calculation

Review of attachment 8575743 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/media/MediaDecoder.cpp
@@ +1520,5 @@
>    MOZ_ASSERT(OnStateMachineThread() || OnDecodeThread());
>    GetReentrantMonitor().AssertCurrentThreadIn();
>    mIgnoreProgressData = false;
>    if (mResource) {
>      mResource->SetReadMode(MediaCacheStream::MODE_PLAYBACK);

StartProgressUpdates is called after a seek by the MDSM, shouldn't this value be set to a default value (maybe 0)?

@@ +1535,5 @@
>  
>  void MediaDecoder::UpdatePlaybackOffset(int64_t aOffset)
>  {
>    ReentrantMonitorAutoEnter mon(GetReentrantMonitor());
> +  mPlaybackPosition = aOffset;

Do you know why they used std::max before?

Comment 7

[cajbir (:cajbir)]

(In reply to Jean-Yves Avenard [:jya] from comment #6)
> StartProgressUpdates is called after a seek by the MDSM, shouldn't this
> value be set to a default value (maybe 0)?

It'll be set when the next frame is decoded in MDSM and UpdatePlaybackOffset is called so I left it as is.

> Do you know why they used std::max before?

Before we had buffered ranges and the like we used to just track the position and used that for tracking buffering. The theory being that if we seeked back and position was less, we still had the data buffered. I think it's a holdover from that.

Comment 8

[cajbir (:cajbir)]

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=05848c0df2f8

Comment 9

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/05848c0df2f8

Comment 10

[advcomp2019]

Is there a way to get this fixed in Firefox 36 and/or 37 or do I have to wait for it till 39? If this is the same bug that I am getting, it is just getting bad when I have to use VLC for the really long videos.

Comment 11

[cajbir (:cajbir)]

Comment on attachment 8575743 [details] [diff] [review]
Fix CanPlayThrough calculation

Approval Request Comment
[Feature/regressing bug #]:1131884
[User impact if declined]:Buffering of YouTube videos will be excessively long
[Describe test coverage new/current, TreeHerder]:None
[Risks and why]: Modifies the logic for when a video can 'play through completely' so may result in more buffering occurring but for shorter periods of time.
[String/UUID change made/needed]:None.

Comment 12

[Lawrence Mandel [:lmandel] (use needinfo)]

(In reply to cajbir (:cajbir) from comment #11)
> [Feature/regressing bug #]:1131884

I think this regressed with the switch from Flash to MSE. Is that correct?

> [User impact if declined]:Buffering of YouTube videos will be excessively
> long

I have experienced this firsthand. Glad to see a fix.

> [Describe test coverage new/current, TreeHerder]:None

Have you tested this on Nightly? Has QA had a chance to verify?

Comment 13

[Lawrence Mandel [:lmandel] (use needinfo)]

Comment on attachment 8575743 [details] [diff] [review]
Fix CanPlayThrough calculation

As this landed in 39, I think we need it in Aurora 38 as well.

Comment 14

[cajbir (:cajbir)]

(In reply to Lawrence Mandel [:lmandel] (use needinfo) from comment #12)
> (In reply to cajbir (:cajbir) from comment #11)
> > [Feature/regressing bug #]:1131884
> 
> I think this regressed with the switch from Flash to MSE. Is that correct?

It's not MSE related, but probably regressed as a result of refactorings that occurred during MSE development.

> 
> Have you tested this on Nightly? Has QA had a chance to verify?

Yes to the former. I don't think so to the latter.

Comment 15

[Lawrence Mandel [:lmandel] (use needinfo)]

Comment on attachment 8575743 [details] [diff] [review]
Fix CanPlayThrough calculation

As confirmed in comment 14 and on irc, this has been verified to fix the issue on Nightly. Let's get this into Beta 6. Beta+ Aurora+

Comment 16

[cajbir (:cajbir)]

Push to aurora: https://hg.mozilla.org/releases/mozilla-aurora/rev/4d2fec20b67f

Comment 17

[cajbir (:cajbir)]

Push to beta: https://hg.mozilla.org/releases/mozilla-beta/rev/bb7b546e6188

Comment 18

[Camelia Badau [:cbadau], Desktop QA]

Verified fixed on Windows 7 64bit and Mac OSX 10.9.5 using latest Nightly 39.0a1 (buildID: 20150330030203), latest Aurora 38.0a2 (buildID: 20150330004006) and Firefox 37 RC Build 2 (buildID: 	20150326190726).

Verified on Ubuntu 13.10 32bit using latest Nightly 39.0a1 (buildID: 20150330030203), latest Aurora 38.0a2 (buildID: 20150330004006) and Firefox 37 RC Build 2 (buildID: 20150326190726) and one mention should be done here: Start the video - after several seconds, I see in the slider that the entire video is buffered; the video started; after 15s the playback restarted, but stall again shortly after; after several seconds (<15s), the video stall again -> even if the slider show that the entire video is buffered, the video stall and restart again every several seconds - it is ok?

Comment 19

[cajbir (:cajbir)]

I'm not sure, I'd have to investigate. Can you raise a bug for it?

Comment 20

[Camelia Badau [:cbadau], Desktop QA]

(In reply to cajbir (:cajbir) from comment #19)
> I'm not sure, I'd have to investigate. Can you raise a bug for it?

I filled bug 1150413. 
Marking this as VERIFIED FIXED.