1131487 - DASH sample stalls

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[Reinhard]

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_2) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/40.0.2214.111 Safari/537.36

Steps to reproduce:

Open the URL

http://www.dash-player.com/demo/streaming-server-and-encoder-support/?mpd=http%3A%2F%2Fbitcdn-global.bitmovin.com%2Fcontent%2Fsintel%2Fsintel.mpd

with Firefox 36.0


Actual results:

The streams starts playing, but video stalls after a few seconds (you might don't see it clearly, because there is a fade from black) - audio continues  playing. The buffer for video does not run try and no error message is generated.


Expected results:

The stream (audio and video) plays without stalls.

Comment 1

[Jean-Yves Avenard [:jya]]

that the start time is <= 0 isn't what is stalling the video. That's not the reason.

I only had a quick glance, but appendBuffer was called with video from 0 to 30s, and then it jumps to providing video to 600s+.. This is never going to play, as there's no data to play..

stalling video is the proper behaviour under those circumstances.

Now there may be an error on our side that would cause the cts to be improperly calculated... we'll see

Comment 2

[Reinhard]

Ok, I just added another stream with start time not equal to zero, but this time with a positive offset (as it might be helpful for testing) - 

http://www.dash-player.com/demo/streaming-server-and-encoder-support/?mpd=http%3A%2F%2Fgce-bitbucket.storage.googleapis.com%2FbitStorage%2F2_6f9d0adade5b9d4547d0ac6ae436ae9c%2F546_Sintel.2010.720p.mkv%2Fmpds%2FSintel.2010.720p.mkv.mpd

The behaviour is similar, although the video keeps playing for 10 seconds now. Are you getting the information which time span is added to the buffer from the about:media view? If so, how to read it?

Comment 3

[Jean-Yves Avenard [:jya]]

Hmm.. this time the behaviour is different. It seems to vary (this is the SegmentTemplate one, first one)

Internal Data:
	Dumping data for reader 143581c00:
		Dumping Audio Track Decoders: - mLastAudioTime: 31.231999
			Reader 1: 1369c2800 ranges=[(-0.021333, 73.386666)] active=true size=1196881
			Reader 0: 1369de800 ranges=[(-0.021333, 1.962666)] active=false size=33090
		Dumping Video Track Decoders - mLastVideoTime: 68.000000
			Reader 12: 12e00e000 ranges=[(68.000000, 70.000000)] active=true size=28442
			Reader 11: 12e008000 ranges=[(66.000000, 68.000000)] active=false size=52767
			Reader 10: 12e006000 ranges=[(64.000000, 66.000000)] active=false size=28593
			Reader 9: 12dc2d800 ranges=[(62.000000, 64.000000)] active=false size=69212
			Reader 8: 121424000 ranges=[(60.000000, 62.000000)] active=false size=58889
			Reader 7: 11d730800 ranges=[(58.000000, 60.000000)] active=false size=46096
			Reader 6: 12e019000 ranges=[(56.000000, 58.000000)] active=false size=61976
			Reader 5: 12a9d1800 ranges=[(54.000000, 56.000000)] active=false size=67301
			Reader 4: 12db77800 ranges=[(52.000000, 54.000000)] active=false size=80228
			Reader 3: 12e00b800 ranges=[(50.000000, 52.000000)] active=false size=79665
			Reader 2: 12dc45800 ranges=[(48.000000, 50.000000)] active=false size=955954
			Reader 1: 120ec4000 ranges=[(46.000000, 48.000000)] active=false size=976964
			Reader 0: 120c8e800 ranges=[(44.000000, 46.000000)] active=false size=544393

So here it shows that our current playback position is at 30s exactly.
but we have data to play only from 44s onward (up to 70s). The "active" reader is the one we last added data to.

I'm also puzzled on why we would have that many decoders. Are you using sourceBuffer.timestampOffset attribute or feeding the fragments out of order?
Did you call remove on the source buffer?

I have on my debug machine an eviction threshold pretty low (3MB) but this shouldn't explain what's happening here.

Comment 4

[Jean-Yves Avenard [:jya]]

oh, do you send the init segment before each media segment?

Comment 5

[Reinhard]

We are not using .timestampOffset. To add a segment to the buffer we are using .addSourceBuffer, with segments in order. At startup and at every representation switch we send an init segment, but not before every media segment. During the stream is playing we are not removing anything from the buffer manually.

The behaviour I experience is a little different, as I do not get a missing time span, although they are overlapping:

	mediasource:http://www.dash-player.com/76e85ab8-f0d4-0442-b575-d48812a666a0
	currentTime: 30.302041
		SourceBuffer 0
			start=0.083333 end=52.041666
			start=52.083333 end=74.083333
		SourceBuffer 1
			start=0 end=81.472
	Internal Data:
	Dumping data for reader 13ce3d000:
		Dumping Audio Track Decoders: - mLastAudioTime: 31.359999
			Reader 0: 11e73e800 ranges=[(0.000000, 81.472000)] active=true size=1294163
		Dumping Video Track Decoders - mLastVideoTime: 10.458333
			Reader 4: 13dcd3800 ranges=[(52.083333, 74.083333)] active=false size=9370391
			Reader 3: 1247d1000 ranges=[(41.666666, 52.041666)] active=false size=4673993
			Reader 2: 11d841000 ranges=[(20.875000, 41.708333)] active=false size=3843254
			Reader 1: 12bf15000 ranges=[(10.458333, 20.875000)] active=true size=605949
			Reader 0: 11e734000 ranges=[(0.083333, 10.500000)] active=false size=3171844

Comment 6

[Reinhard]

Correction: we are of course using .appendBuffer to add segments.

Comment 7

[Jean-Yves Avenard [:jya]]

(In reply to Reinhard from comment #5)
> We are not using .timestampOffset. To add a segment to the buffer we are
> using .addSourceBuffer, with segments in order. At startup and at every

??

you mean appendBuffer right?

We have a limitation of 16 (an arbitrary number) source buffers.

> representation switch we send an init segment, but not before every media
> segment. During the stream is playing we are not removing anything from the
> buffer manually.
> 
> The behaviour I experience is a little different, as I do not get a missing
> time span, although they are overlapping:

some are overlapping, some are discontinuous.. Over 0.04s gap between segments.

that video can't play, it's invalid at 52.04s.

We have a leeway for switching to the next frame, but you have big gap in your video here.

Now there could be a bug, it seems stuck at 10.458333s.

Did you try with Nightly?

> 			Reader 4: 13dcd3800 ranges=[(52.083333, 74.083333)] active=false
> size=9370391
> 			Reader 3: 1247d1000 ranges=[(41.666666, 52.041666)] active=false
> size=4673993
> 			Reader 2: 11d841000 ranges=[(20.875000, 41.708333)] active=false
> size=3843254
> 			Reader 1: 12bf15000 ranges=[(10.458333, 20.875000)] active=true
> size=605949
> 			Reader 0: 11e734000 ranges=[(0.083333, 10.500000)] active=false
> size=3171844

I haven't looked into the details to be honest, I'm finishing something else.

#media on the Mozilla IRC channel will be better to talk about this. my nick is jya

Comment 8

[Reinhard]

With Nighlty everything seems to work fine - no stalls. The stream is playing smooth, audio as well as video. Also the gap at 52.04s does not influence the behaviour. Is there a way to access some debug output like about:media also in the Nightly?

We can also talk via IRC channel.

Comment 9

[Jean-Yves Avenard [:jya]]

Attachment: Fix time calculations when segment doesn't start at 0

Fix timestamp calculations when start time aren't 0.

Comment 10

[Jean-Yves Avenard [:jya]]

(In reply to Reinhard from comment #8)
> With Nighlty everything seems to work fine - no stalls. The stream is
> playing smooth, audio as well as video. Also the gap at 52.04s does not
> influence the behaviour. Is there a way to access some debug output like
> about:media also in the Nightly?
> 
> We can also talk via IRC channel.

Good to know..

Nightly tomorrow will be broken :(

lucky you reported that video!

Sorry for not seeing the problem earlier, the reported timestamps were incorrect. 

about:media works in nightly, you need to install a plugin: https://github.com/gavinsharp/aboutmedia

Comment 11

[Jean-Yves Avenard [:jya]]

Attachment: Adjust negative start time near 0 to 0

Adjust negative start time near 0 to 0.

Comment 12

[Jean-Yves Avenard [:jya]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/d47b6f729996
https://hg.mozilla.org/integration/mozilla-inbound/rev/12295330cc7c

Comment 13

[Jean-Yves Avenard [:jya]]

That video still stall around 50s-ish due to discontinuity... We should handle such discontinuity and skip over it rather than treat it as not having enough data

Comment 14

[Jean-Yves Avenard [:jya]]

Hi.

Ok.. I've found out why this stall, and for once it's not us :)

This DASH player feeds data continuously, without ever stopping. This is not good to start with.

We have a 75MB buffer limit, at which time data will be evicted so memory usage stays within that memory constraint.

On this playback instance, playback stalled at 158s. Looking in the logs you can see that at some stage the segment [158,168] has been evicted. That data is never re-submitted.
It is up to the DASH player to check the buffered range and ensure that the player has enough data to play
 and reload if necessary. This happens during the Prepare Append algorithm and is synchronous. So as soon as you've called appendBuffer; you should check the sourcebuffer buffered range and see what has been evicted
(per spec: Implementations may use different methods for selecting removal ranges so web applications should not depend on a specific behavior. The web application can use the buffered attribute to observe whether portions of the buffered data have been evicted.)

Also, ideally you shouldn't feed data continuously like that, we're talking MB in RAM here. It fed the entire 15 minutes @ 1080p.

Youtube for example only buffered the entire video if the bitrate is low enough and ensure that it won't exceed the 75MB buffer.
Otherwise they only feed about 20s ahead of the current playback position.

Also when changing resolution, you could use sourcebuffer.remove to remove the old lower-res, so if the user were to seek backward they would get the new resolution content rather than get back to the old one.

Comment 15

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/d47b6f729996
https://hg.mozilla.org/mozilla-central/rev/12295330cc7c

Comment 16

[daniel.weinberger]

Hi,

Thanks for your effort!

I'm not sure this is really the reason for this issue, though.

Our player tries to maintain a constant buffer level, usually 40 seconds although this can be configured. I tried with 10 seconds buffer and it still has the same behavior - the video starts stalling at about 10 seconds of playback and returns at about 20 seconds and plays the rest of the video perfectly.

Also, if I manually select a single quality (even it's the highest) before starting playback, the video plays through without any problems. So maybe there is a problem when switching qualities? We do bitrate as well as resolution switching.

Until the stall occured (second 10), we have pushed about 10.3 MB (for both, audio and video combined) into the buffer, so we are far from the 75MB buffer limit at this point. Also the about:media says for me that everything should be there:

http://www.dash-player.com/release-test/?mpd=http%253A%252F%252Fgce-bitbucket.storage.googleapis.com%252FbitStorage%252F2_6f9d0adade5b9d4547d0ac6ae436ae9c%252F546_Sintel.2010.720p.mkv%252Fmpds%252FSintel.2010.720p.mkv.mpd
	mediasource:http://www.dash-player.com/2e393b07-b351-41b3-92bd-d976adec5cfa
	currentTime: 10.5
		SourceBuffer 0
			start=0.083333 end=52.083333
		SourceBuffer 1
			start=0 end=52.053333
	Internal Data:
	Dumping data for reader 10be1c30:
		Dumping Audio Track Decoders: - mLastAudioTime: 12,159999
			Reader 0: 2534d000 ranges=[(0,000000, 52,053333)] active=true size=827004
		Dumping Video Track Decoders - mLastVideoTime: 21,291667
			Reader 3: 254cb800 ranges=[] active=false size=794
			Reader 2: 21b23000 ranges=[(20,875000, 52,083333)] active=true size=5825200
			Reader 1: 1d447c00 ranges=[(10,458333, 20,875000)] active=false size=605949
			Reader 0: 2534b400 ranges=[(0,083333, 10,500000)] active=false size=3171844

I have noticed that the range of Reader 0 overlaps with the range of Reader 1 - and that's were (at least for me) the error occurs.

You are right, in continuous playback (i.e. without seeking) we do not re-submit data as it has never been necessary. We probably should observe the buffer better...
But wouldn't it be better to remove old, already played data instead of future data? ;) We probably will use sourcebuffer.remove to enhance our preferred behavior. At the moment, we do not delete any data as the MediaSource does usually a good job.

In the Firefox Nightly (38.01a 2014-02-10) the stream works like a charm!

Comment 17

[Jean-Yves Avenard [:jya]]

(In reply to daniel.weinberger from comment #16)
> Hi,
> 
> Thanks for your effort!
> 
> I'm not sure this is really the reason for this issue, though.

Your about:media shows a different condition than what I experienced. For me it my various attempts it stalled because data got evicted, not because there was overlap in segments. There may be a problem in switching, that's definitely possible. When selecting which sample to play, we select the last one added as we assume it will have the best quality.

> 
> Our player tries to maintain a constant buffer level, usually 40 seconds
> although this can be configured. I tried with 10 seconds buffer and it still
> has the same behavior - the video starts stalling at about 10 seconds of
> playback and returns at about 20 seconds and plays the rest of the video
> perfectly.

That's not what I'm experiencing.. I never see the rate of the appendBuffer calls slowing down, it just keep feeding new data.

> 
> Also, if I manually select a single quality (even it's the highest) before
> starting playback, the video plays through without any problems. So maybe
> there is a problem when switching qualities? We do bitrate as well as
> resolution switching.

There could be an issue when switching resolution if there's an overlap in timestamp.
That stream isn't per spec anyway as two segments for the same content do not always have the same time range.
But we should handle that better regardless.

> 
> Until the stall occured (second 10), we have pushed about 10.3 MB (for both,
> audio and video combined) into the buffer, so we are far from the 75MB
> buffer limit at this point. Also the about:media says for me that everything
> should be there:
> 
> http://www.dash-player.com/release-test/?mpd=http%253A%252F%252Fgce-
> bitbucket.storage.googleapis.
> com%252FbitStorage%252F2_6f9d0adade5b9d4547d0ac6ae436ae9c%252F546_Sintel.
> 2010.720p.mkv%252Fmpds%252FSintel.2010.720p.mkv.mpd
> 	mediasource:http://www.dash-player.com/2e393b07-b351-41b3-92bd-d976adec5cfa
> 	currentTime: 10.5
> 		SourceBuffer 0
> 			start=0.083333 end=52.083333
> 		SourceBuffer 1
> 			start=0 end=52.053333
> 	Internal Data:
> 	Dumping data for reader 10be1c30:
> 		Dumping Audio Track Decoders: - mLastAudioTime: 12,159999
> 			Reader 0: 2534d000 ranges=[(0,000000, 52,053333)] active=true size=827004
> 		Dumping Video Track Decoders - mLastVideoTime: 21,291667
> 			Reader 3: 254cb800 ranges=[] active=false size=794
> 			Reader 2: 21b23000 ranges=[(20,875000, 52,083333)] active=true
> size=5825200
> 			Reader 1: 1d447c00 ranges=[(10,458333, 20,875000)] active=false
> size=605949
> 			Reader 0: 2534b400 ranges=[(0,083333, 10,500000)] active=false
> size=3171844

That's interesting. I have an idea on what could be happening here. What's bizarre is that you're at 10.5s yet the current active reader doesn't have the time required.

> 
> I have noticed that the range of Reader 0 overlaps with the range of Reader
> 1 - and that's were (at least for me) the error occurs.
> 
> You are right, in continuous playback (i.e. without seeking) we do not
> re-submit data as it has never been necessary. We probably should observe
> the buffer better...
> But wouldn't it be better to remove old, already played data instead of
> future data? ;) We probably will use sourcebuffer.remove to enhance our

Oh, we do remove in priority past data. It's the first thing to go.

But in my case, I was at 150s play position, it had buffered over 600s already and had reached the 75MB limit. It had evicted everything prior 130s. The only thing left to be dropped was future data. And it always remove the oldest data first

Btw, you can change the buffer threshold if you want to stress your code, drop it to so,etching like 3MB.

> preferred behavior. At the moment, we do not delete any data as the
> MediaSource does usually a good job.
> 
> In the Firefox Nightly (38.01a 2014-02-10) the stream works like a charm!

Good to know, that will be all uplifted to 37.

Comment 18

[Jean-Yves Avenard [:jya]]

There's still a stall occurring, trying to get to the bottom of it

Comment 19

[Jean-Yves Avenard [:jya]]

Daniel, the setting you can play with to force evicting data quicker is:
media.mediasource.eviction_threshold , set it to 3145728 , it will cause to evict within 60s of buffered video.

Comment 20

[Jean-Yves Avenard [:jya]]

Actually no. I only get the stall once we reach a point where the data got evicted and the DASH player doesn't resubmit those data.

Issue is with the dash player. can open another bug if you see another problem.

thank you for reporting it!

Comment 21

[Jean-Yves Avenard [:jya]]

Actually, of course as I said that I did reproduce that stall (13')

Comment 22

[Jean-Yves Avenard [:jya]]

Attachment: Part3. Fix stall when switching decoders

Fix stall when changing decoders (usually happening when changing resolution). The buffered end time in those mp4 segments are made of a ratio that can't exactly be represented in IEEE 754 base 2 and are instead rounded, (like 287.45833300000004). When we attempt to skip to the next reader by adjusting the end time, 287.45833300000004 is rounded to 287.458333 (287458333us) which is always inferior to 287.45833300000004. So instead of switching to the next decoder, we select the same one, and we end up looping forever Seek -> Decode -> End of Stream Error -> Seek -> Decode. Add some logging.

Comment 23

[Jean-Yves Avenard [:jya]]

Attachment: Evict data we likely previously read and future data when possible

mCurrentDecoder is the decoder we're currently adding data to; not the decoder currently playing. It is always the last decoder in the list of decoders. As such, we were always evicting all data from all decoders but the currently playing one.
I split the loop in two as I felt it was clearer to understand.
We proceed in three steps, each step can be aborted if we've already evicted more data than required.
First step is to evict all past data from current playback position.
Step 2: Evict all data from decoders anterior to the currently playing one, assuming we've already played from those (and in practice unless you seek a lot, it's always true)
Step 3: We evict future data, starting from the furthest away, only keeping the currently playing reader and the next one we will be switching to once the current is done.

Comment 24

[Jean-Yves Avenard [:jya]]

Comment on attachment 8563901 [details] [diff] [review]
Evict data we likely previously read and future data when possible

Wrong bug number

Comment 25

[Matt Woodrow (:mattwoodrow)]

Comment on attachment 8563828 [details] [diff] [review]
Part3. Fix stall when switching decoders

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

::: dom/media/mediasource/MediaSourceReader.cpp
@@ +210,5 @@
>      aDecoder->GetBuffered(ranges);
>      if (ranges->Length() > 0) {
> +      // End time is a double so we convert to nearest greater by adding 1
> +      // to ensure we are always slightly past it.
> +      int64_t end = ranges->GetEndTime() * USECS_PER_S + 1;

Can't we just use ceil?

@@ +232,5 @@
>    // End of stream. Force switching past this stream to another reader by
>    // switching to the end of the buffered range.
>    MOZ_ASSERT(aReason == END_OF_STREAM);
>    if (mAudioSourceDecoder) {
> +    int64_t old = mLastAudioTime;

Might want to make this #ifdef PR_LOGGING to avoid unused variable warnings if it isn't defined.

Comment 26

[Jean-Yves Avenard [:jya]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/4c294d64d19f

Comment 27

[Jean-Yves Avenard [:jya]]

With bug 1132796, we don't evict as quickly future data. This allows this particular video to play all the way to the end.

Comment 28

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/4c294d64d19f

Comment 29

[Ralph Giles (:rillian)]

Comment on attachment 8563828 [details] [diff] [review]
Part3. Fix stall when switching decoders

Requesting 37 uplift for all 3 patches on this bug.

Approval Request Comment
[Feature/regressing bug #]: MSE
[User impact if declined]: Spec compliance, possible stalls playing MSE video. Less consistent testing and harder to port later changes.
[Describe test coverage new/current, TreeHerder]: Landed on m-c.
[Risks and why]: Changes are confined to MSE code, so regression risk is minimal.
[String/UUID change made/needed]: None.

Comment 30

[Ralph Giles (:rillian)]

Pushed to aurora with pre-approval from lmandel.

https://hg.mozilla.org/releases/mozilla-aurora/rev/387a228666a2
https://hg.mozilla.org/releases/mozilla-aurora/rev/21038ec77c02
https://hg.mozilla.org/releases/mozilla-aurora/rev/4088ee84874c

Comment 31

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

Comment on attachment 8563828 [details] [diff] [review]
Part3. Fix stall when switching decoders

As noted, pre-approval was granted for a collection of MSE changes. Adding approval to the bug.

Aurora+