1089937 - Video and sound stops at 50sec on certain youtube HTML5 video

Status: VERIFIED FIXED

(Core :: Audio/Video, defect)

Description

[Alice0775 White]

[Tracking Requested - why for this release]: Reproduced on Nightly36.0a1 but not Aurora35.0a2

When I test Bug 1089294, the problem occurs.

Reproducible: always

Steps To Reproduce:
1. Open https://www.youtube.com/watch?v=brpLKK5MeDw
2. Skip Ad if any
3. observe video/sound

Actual Results:
video and Audio stops at 50sec.
Buffering is continuing.

Expected Results:
video and Audio should not stop.

Comment 1

[Alice0775 White]

Regression window(m-c)
Good:
https://hg.mozilla.org/mozilla-central/rev/a5ee2769eb27
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:36.0) Gecko/20100101 Firefox/36.0 ID:20141024030200
Bad:
https://hg.mozilla.org/mozilla-central/rev/6e35802ae3e2
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:36.0) Gecko/20100101 Firefox/36.0 ID:20141024065410
Pushlog:
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=a5ee2769eb27&tochange=6e35802ae3e2


Regression window(m-i)
Good:
https://hg.mozilla.org/integration/mozilla-inbound/rev/95e70cc80f82
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:36.0) Gecko/20100101 Firefox/36.0 ID:20141023192010
Bad:
https://hg.mozilla.org/integration/mozilla-inbound/rev/918f4681e3f0
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:36.0) Gecko/20100101 Firefox/36.0 ID:20141023193309
Pushlog:
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=95e70cc80f82&tochange=918f4681e3f0
Regressed by:
	918f4681e3f0	Chris Double — Bug 1000686 - Enable Media Source Extensions on non-release builds - r=kentuckyfriedtakahe

Comment 2

[Eric Fowler]

I'm on Ubuntu 14.10 running:
Mozilla/5.0 (X11; Linux x86_64; rv:36.0) Gecko/20100101 Firefox/36.0 ID:20141027113017 CSet: da125623d9cb

I get the exact same issue using the video in the first comment, with most likely the same regression window. Can someone update the platform on this bug as it isn't a solely a Windows 7 bug.

Comment 3

[cajbir (:cajbir)]

I confirm that I see this on Ubuntu 14.10 as well.

Comment 4

[cajbir (:cajbir)]

This looks to be bug 1062055. We have the following audio buffers;

index=0 newReader=0x7f9f7dd43800 ranges=[(0.000000, 50.029000)] found=true active=true
index=1 newReader=0x7f9f73e0e800 ranges=[(50.019000, 180.161000)] found=false active=false

Buffer 0 is the active audio reader. We attempt to switch:

MediaSourceReader(7f9f7ecb9800)::SelectReader(50018902) newReader=7f9f73e0e800 target not in ranges=[(50.019000, 180.161000)]

But the time of 50018902 is less tha the range in the buffer we need to switch too switch starts at 50019000.

Comment 5

[cajbir (:cajbir)]

With the fix in attachment 8483922 [details] [diff] [review] in bug 1062055 applied this video plays through past the 50 second mark.

Comment 6

[cajbir (:cajbir)]

(In reply to cajbir (:cajbir) from comment #5)
> With the fix in attachment 8483922 [details] [diff] [review] in bug 1062055
> applied this video plays through past the 50 second mark.

And stops at the 27 minute mark:

MediaSourceReader(0x7eff3959c000)::SelectReader(1631628000) index=14 newReader=0x7eff29d18000 ranges=[(1621.634000, 1631.628000)] found=false active=true
MediaSourceReader(0x7eff3959c000)::SelectReader(1631628000) index=15 newReader=0x7eff2f73d800 ranges=[(1631.639000, 1791.815000)] found=false active=false

The target time (1631628000) is in between the two buffer time ranges so never switches. This is possibly related to bug 1065207 where the duration (and thus end time) of the final frame is inaccurate.

Comment 9

[Benjamin Smedberg]

bhearsum and I can reproduce this with https://www.youtube.com/watch?v=f26JPN7ZQ7Y&index=1&list=PLibWM9qo7h6l-VHTR2c-9qh8drcwoXXw7

Comment 10

[IU]

Here's a video that stalls at 1:39: https://www.youtube.com/watch?v=CIBIqaeiE2M

Comment 11

[Leman Bennett [Omega]]

I have also seen this issue: https://www.youtube.com/watch?v=CAjEkrS-HWs

Stops exactly :50 seconds.

Comment 12

[Olli Pettay [:smaug][[e-mail]]]

I can see this too.

Sounds like we should back out bug 1000686 for now.

Comment 13

[cajbir (:cajbir)]

Attachment: Add fuzz to time for switching readers on EOS

As discussed during standup, adds a fuzz factor for reader switching comparison of end of the buffer when reaching EOS.

Comment 14

[Matt Woodrow (:mattwoodrow)]

Comment on attachment 8516307 [details] [diff] [review]
Add fuzz to time for switching readers on EOS

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

::: dom/media/mediasource/MediaSourceReader.cpp
@@ +188,3 @@
>  
>    // See if we can find a different reader that can pick up where we left off.
> +  if (aType == MediaData::AUDIO_DATA && SwitchAudioReader(mLastAudioTime + EOS_FUZZ_US)) {

We compute 'time', but don't actually use it.

If we get the buffered ranges to be more accurate (bug 1065207), then we can just use 'time' here and get rid of EOS_FUZZ_US.

Comment 15

[cajbir (:cajbir)]

(In reply to Matt Woodrow (:mattwoodrow) from comment #14)
> Comment on attachment 8516307 [details] [diff] [review]
> We compute 'time', but don't actually use it.

'time' is a reference and is assigned to.

> If we get the buffered ranges to be more accurate (bug 1065207), then we can
> just use 'time' here and get rid of EOS_FUZZ_US.

Yes, we can remove it in that bug if we are able to. I suspect some fuzz will be need though due to difficulties in being able to calculate the actual frame durations.

Comment 16

[Matt Woodrow (:mattwoodrow)]

Sorry about the 'time' thing, missed that it was a reference.

Bit of a brain dump of my debugging a specific bug involving this:

The last frame of our reader has a duration of 14ms according to the WebM file (interval to the next frame), and a duration of 3ms according the vorbis audio data. The previous frame was 3ms (WebM duration), so that's what we use for the buffered range.

This leaves us with an 11ms gap between the end of this buffered range and the start of the next reader.

This patch updates mLastAudioTime, which has no effect since the audio end time and our buffered range end time are the same thing (entirely by luck though).

We then switch to the appropriate reader for 125ms beyond this point, which is enough to jump the 11ms gap and select the next reader.

RequestAudioData then calls SelectAudioReader again, but without the 125ms fuzz factor. This call will fail (since it's looking at the start of the 11ms empty space), but failure makes no changes so we remain on the newer reader. Once we decode more audio data we'll update mLastAudioTime (in OnAudioDecoded) to a time actually within the new reader and things will continue normally from there.



Also, note that in this case our buffered range is shorter than it probably should be, but it's equally possible for us to have buffered ranges that are too long (if the final frame is much shorter than the previous, rather than much longer). Given that, I don't think it'd be too bad to switch to using the fuzz in the buffered range calculation, since a small overestimate seems less likely to cause issues.

Comment 17

[Matt Woodrow (:mattwoodrow)]

(In reply to Matt Woodrow (:mattwoodrow) from comment #16)

> This patch updates mLastAudioTime, which has no effect since the audio end
> time and our buffered range end time are the same thing (entirely by luck
> though).

Note that in cases where these aren't the same thing, we've updated mLastAudioTime to be sufficiently large that any future calls to SwitchAudioReader won't ever select the reader that just got EOS.

Comment 18

[Karl Tomlinson (:karlt)]

Comment on attachment 8516307 [details] [diff] [review]
Add fuzz to time for switching readers on EOS

There are some things that are not yet clear to me here, and I'd like at least some minor changes.

>Bug 1089937 - MSE reader switches fails occasionally on source decoder EOS - r=karl

Can you update to comment to describe the code changes, please.
Reasons for the changes are helpful too, and can be included in checkin
comment, if helpful, or in this bug if easier.

>+// When a stream hits EOS it needs to decide what other stream to switch to. Due
>+// to inaccuracies is determining buffer end frames (Bug 1065207) and rounding
>+// issues we use a fuzz factor to determine the end time of this stream for
>+// switching to the new stream. This value is based on the end of frame
>+// default value used in Blink.
>+#define EOS_FUZZ_US 125000

I understand the need to use a fuzz as a tolerance, and this seems a
reasonable value based on a period to skip rather than stop and wait for
missing frames, if there are any.  Can you reference
kDefaultBufferDurationInMs from Blink, please, to make it a little easier for
people to find the corresponding Blink code?

It feels to me that the fuzz should be used as an acceptable tolerance, but
SelectReader() should prefer something closer to the expected, if available,
so as to avoid possibly skipping over available frames.  This can be a
separate bug if you like. 

I also suspect the fuzz should be applied in SelectReader() or other
SelectReader() callers will have similar problems.  It might be necessary now
however to find the closest available if applying the fuzz in SelectReader().
Is there a reason why this would only be necessary from OnNotDecoded()?

>+  // End of stream. Force switching past this stream to another reader by
>+  // switching to the end of the buffered range.

Please MOZ_ASSERT END_OF_STREAM and add a comment explaining why mLast*Time is
not at the end of the buffered range.  I guess comment 17 is the reason?

Should the maximum of time and end time be used?

Would this be unnecessary if the fuzz were applied in SelectReader()?

>+  nsRefPtr<MediaDecoderReader> reader = aType == MediaData::AUDIO_DATA ?
>+                                          mAudioReader : mVideoReader;
>+  int64_t& time = aType == MediaData::AUDIO_DATA ? mLastAudioTime : mLastVideoTime;
>+  if (reader) {
>+    nsRefPtr<dom::TimeRanges> ranges = new dom::TimeRanges();
>+    reader->GetBuffered(ranges, 0);
>+    if (ranges->Length() > 0) {
>+      time = ranges->GetEndTime() * USECS_PER_S;
>+    }
>+  }

A couple of us missed initially that time was a reference.
Would you mind making it a pointer to accentuate that, please?

GetEndTime() has been converted to double, so please round to nearest.
If it is always positive, then that can be done by just adding 0.5, and a
comment to indicate round to nearest.

>-  if (aType == MediaData::AUDIO_DATA && SwitchAudioReader(mLastAudioTime)) {
>+  if (aType == MediaData::AUDIO_DATA && SwitchAudioReader(mLastAudioTime + EOS_FUZZ_US)) {

Can mLast*Time have its initial value of -1 here?
What would happen in that situation?

Comment 19

[Karl Tomlinson (:karlt)]

(In reply to Karl Tomlinson (:karlt) from comment #18)
> Can you reference
> kDefaultBufferDurationInMs from Blink, please, to make it a little easier for
> people to find the corresponding Blink code?

Just the name I mean.  no need for url.

Comment 20

[cajbir (:cajbir)]

(In reply to Karl Tomlinson (:karlt) from comment #18)
> Comment on attachment 8516307 [details] [diff] [review]
> It feels to me that the fuzz should be used as an acceptable tolerance, but
> SelectReader() should prefer something closer to the expected, if available,
> so as to avoid possibly skipping over available frames. 

I can't parse this sentence. Closer to the expected what? And what does it mean for that what to be available?

> It might be necessary now
> however to find the closest available if applying the fuzz in SelectReader().

Same here. Closest available what? And definition of closest and available in that context?

Comment 21

[Karl Tomlinson (:karlt)]

(In reply to cajbir (:cajbir) from comment #20)
> (In reply to Karl Tomlinson (:karlt) from comment #18)
> > Comment on attachment 8516307 [details] [diff] [review]
> > It feels to me that the fuzz should be used as an acceptable tolerance, but
> > SelectReader() should prefer something closer to the expected, if available,
> > so as to avoid possibly skipping over available frames. 
> 
> I can't parse this sentence. Closer to the expected what? And what does it
> mean for that what to be available?

If we're know we're at the end of one buffered range, or we know what we have
just decoded, then we are kind of expecting a reader to cover a range starting
from what we have just decoded, or the end of the the current reader's range.
That point in the timescale is really our target point and what I mean by
"expected".

By "available" I mean in existence.

Because durations are inaccurate, there may not be a reader providing for that
target point.

When there is no reader available, then perhaps we could search over some tolerance interval for the reader with the range closest to the target.

> 
> > It might be necessary now
> > however to find the closest available if applying the fuzz in SelectReader().
> 
> Same here. Closest available what? And definition of closest and available
> in that context?

available and what are the same here.
Closest is the reader with the beginning nearest the target described above.

As you have probably gathered, I'm not familiar with this code, all the uses of SelectReader, when they are called, guarantees of order wrt updates in mLast*Time from the decoder, etc.  Perhaps someone else would be a better reviewer.

Comment 22

[Benjamin Kerensa [:bkerensa]]

Tracking this since multiple people reproducing

Comment 23

[Matt Woodrow (:mattwoodrow)]

(In reply to Karl Tomlinson (:karlt) from comment #18)
 
> GetEndTime() has been converted to double, so please round to nearest.
> If it is always positive, then that can be done by just adding 0.5, and a
> comment to indicate round to nearest.

This matters for the first video in the dashif player, where we truncate and end up wrong by 1us.

Comment 24

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

(In reply to Matt Woodrow (:mattwoodrow) from comment #23)
> This matters for the first video in the dashif player, where we truncate and
> end up wrong by 1us.

That video has its timescale converted to microseconds and these have been rounded down. This means that the sum of the sample durations does not add up to the intended duration. IIRC the 2 second fragments are 17us short.

Comment 25

[cajbir (:cajbir)]

(In reply to Karl Tomlinson (:karlt) from comment #18)
> Comment on attachment 8516307 [details] [diff] [review]
> It feels to me that the fuzz should be used as an acceptable tolerance, but
> SelectReader() should prefer something closer to the expected, if available,
> so as to avoid possibly skipping over available frames.  This can be a
> separate bug if you like.

I believe this would be bug 1065207. The main issue is that we test switching using mLastAudioTime which is the actual sample+duration time but SwitchReader compares using the buffered times - and this is computed using the estimate as described in bug 1065207.

This patch adjusts things by using the end time of the buffered ranges on EOS and using that in SwitchReader so we are comparing relevant times.

> I also suspect the fuzz should be applied in SelectReader() or other
> SelectReader() callers will have similar problems.  

If other callers are calling with the actual time like the EOS code does then they will have a similar issue. Unfortunately we can't find out what the buffered range equivalent of the mLastAudioTime is in these cases. For this reason the fix is not in SelectReader. 

The complete fix is to fix bug 1065207 and this bug is a workaround for that not being fixed. Given that we know the sample duration after decoding we could maybe feed this information back to the webm buffered parser somehow. Bug 1065207 is a difficult problem though so I think we should land the temporary fix for the current EOS issues while we debate how best to solve that.

> It might be necessary now
> however to find the closest available if applying the fuzz in SelectReader().

We will need to come up with a suitable algorithm for deciding which reader is best to switch through given +/-fuzz, and what is the most recent reader with data for the same time ranges.

> Is there a reason why this would only be necessary from OnNotDecoded()?

As described above, OnNotDecoded has the special case where we know the end time, and we know the buffered range end time, so can adjust for the call to SelectReader.

I've corrected for the other review comments and will upload shortly.

Comment 26

[cajbir (:cajbir)]

Try build: https://tbpl.mozilla.org/?tree=Try&rev=ca19e290c3ee

Comment 27

[cajbir (:cajbir)]

Attachment: Fix with review comments addressed

Address review comments.

Comment 28

[cajbir (:cajbir)]

Spun Bug 1096790 for doing SelectReader changes mentioned in comment 18.

Comment 29

[Karl Tomlinson (:karlt)]

(In reply to cajbir (:cajbir) from comment #25)
> (In reply to Karl Tomlinson (:karlt) from comment #18)
> > I also suspect the fuzz should be applied in SelectReader() or other
> > SelectReader() callers will have similar problems.  
> 
> If other callers are calling with the actual time like the EOS code does
> then they will have a similar issue. Unfortunately we can't find out what
> the buffered range equivalent of the mLastAudioTime is in these cases. For
> this reason the fix is not in SelectReader. 

Yes, advancing to buffered range end makes sense only on EOS.

Something like the fuzz part also seems necessary on seeking, but I'm not
clear yet whether that should be the same or different to the EOS case.  And in
the RequestAudioData case, it would be better not to jump over undecoded data,
so it seems there is not one algorithm to suit all callers.

Thanks for filing bug 1096790 on this.

Comment 30

[Karl Tomlinson (:karlt)]

Comment on attachment 8520381 [details] [diff] [review]
Fix with review comments addressed

(In reply to Karl Tomlinson (:karlt) from comment #18)
> Should the maximum of time and end time be used?

>+  int64_t* time = aType == MediaData::AUDIO_DATA ? &mLastAudioTime : &mLastVideoTime;

>+      *time = ranges->GetEndTime() * USECS_PER_S + 0.5;

The buffered range duration estimate may potentially be less than the actual
duration of the decoded data.  In that case, I don't think we want to make
mLastAudioTime go backwards.

>+  if (*time >= 0) {

I think leave this out for now.  I don't see anywhere else that -1 is handled
separately, and I don't know why it should be handled differently from 0 here.
If decoded data can be requested without a seek (to zero for example), then
mLastAudioTime should probably be initialized to 0.  If we need to seek first,
then the initial value of mLastAudioTime is just a distraction that will never
be used.

Comment 31

[Karl Tomlinson (:karlt)]

Attachment: Add a fuzz time to end times for MSE reader switching on EOS

I was asked to prepare this for landing.
Just minor changes in line with comment 30.

Comment 32

[Matt Woodrow (:mattwoodrow)]

Comment on attachment 8521025 [details] [diff] [review]
Add a fuzz time to end times for MSE reader switching on EOS

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

Look good. If cajbir strongly disagrees, he can do a followup tomorrow.

Comment 33

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

Thanks

Comment 34

[Karl Tomlinson (:karlt)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/d104c58ca967

Comment 35

[(Away)]

Bug 1091008 and bug 1089937 collided on inbound. Please review this bustage fix: https://hg.mozilla.org/integration/mozilla-inbound/rev/fda1b680307f

Comment 36

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/d104c58ca967

Comment 37

[Zac C (:zac)]

Youtube videos in today's nightly are running fantastically, thanks for patching this!

Comment 38

[akulle12]

(In reply to Zac C (:zac) from comment #37)
> Youtube videos in today's nightly are running fantastically, thanks for
> patching this!
The audio still stops if you rewind the video to the point where the audio would've stopped before.

Comment 39

[Zac C (:zac)]

(In reply to akulle12 from comment #38)
> (In reply to Zac C (:zac) from comment #37)
> > Youtube videos in today's nightly are running fantastically, thanks for
> > patching this!
> The audio still stops if you rewind the video to the point where the audio
> would've stopped before.

Let me try a few more videos, but are you on the latest Nightly?
36.0a1 (2014-11-13)
Built from https://hg.mozilla.org/mozilla-central/rev/ab137ddd3746

Comment 40

[Zac C (:zac)]

(In reply to akulle12 from comment #38)
> (In reply to Zac C (:zac) from comment #37)
> > Youtube videos in today's nightly are running fantastically, thanks for
> > patching this!
> The audio still stops if you rewind the video to the point where the audio
> would've stopped before.

btw yes I have also seen a similar problem to this on current Aurora and Vista, but in comment #37 I am only referring to linux64 and Nightly builds. 

We should probably check Aurora branch for this bug and uplift it.

Comment 41

[John Doe]

Much harder to reproduce, but i am still losing audio on some videos.
Using latest nightly (2014-11-13) on windows 8.1 x64.

Comment 42

[IU]

I can confirm that this bug is still present as stated in comment 38.

Here is an STR:

1. Play the video in comment 0, but...
2. When the video gets past the 1 minute mark, drag the progress bar back to about the 40 second mark and leave the video to continue playing

Result: At the 50 second mark, playback stalls.

Comment 43

[Alice0775 White]

(In reply to IU from comment #42)
> I can confirm that this bug is still present as stated in comment 38.
> 
> Here is an STR:
> 
> 1. Play the video in comment 0, but...
> 2. When the video gets past the 1 minute mark, drag the progress bar back to
> about the 40 second mark and leave the video to continue playing
> 
> Result: At the 50 second mark, playback stalls.

Could you please file a new bug?

Comment 44

[cajbir (:cajbir)]

(In reply to IU from comment #42)
> I can confirm that this bug is still present as stated in comment 38.

The fix here was for direct playback. We spawned bug 1096790 to deal with the remaining issues including seeking.

Comment 45

[IU]

(In reply to Alice0775 White from comment #43)
> Could you please file a new bug?

I guess, per comment 44, bug 1096790 covers it.

Comment 47

[Bogdan Maris, Desktop Test Engineering]

Reproduced the initial issue on a old Nightly build from 2014-10-27, verified that the issue is fixed on Windows 7 64bit, Mac OS X 10.9.5 and Ubuntu 14.04 32bit using Firefox 36 beta 4.