623637 - Can start playing too soon on live streams

Status: VERIFIED FIXED

(Core :: Audio/Video, defect)

Description

[Sander Plas]

User-Agent:       Mozilla/5.0 (X11; Linux i686; rv:2.0b9pre) Gecko/20110106 Firefox/4.0b9pre
Build Identifier: Mozilla/5.0 (X11; Linux i686; rv:2.0b9pre) Gecko/20110106 Firefox/4.0b9pre

I use an HTML 5 audio tag with 'autoplay' to play a radio stream that broadcasts in OGG Vorbis over Icecast (HTTP). 

In Opera 11 and Firefox 3.6, the stream starts playing almost instantly. On Firefox 4, it takes about 35 seconds before it starts playing. 

If i attach a javascript function that executes a play() to the 'onwaiting' event, it stutters a few times and plays correctly after about 10 seconds. That's better but still a lot longer than on the other browsers. 

Example: http://www.oele.net/audio.html
Same example with the javascript workaround: http://www.oele.net/audio_workaround.html

Reproducible: Always

Steps to Reproduce:
1. Open http://www.oele.net/audio.html in Opera, Firefox 3.6 and Firefox 4 and wait for audio. 

2. Try http://www.oele.net/audio_workaround.html in Opera, Firefox 3.6 and Firefox 4 and wait for audio. 
Actual Results:  
1. audio.html: Firefox 4 plays after 35 seconds. The other browsers play instantly

2. audio_workaround.html: Firefox 4 stutters for 10 seconds. The other browsers play instantly without stuttering. 

Expected Results:  
Firefox 4 should start playing as fast as the other browsers without stuttering and without the need for a javascript workaround. 

Tried this on Mac OS X too - same result.

Comment 1

[Chris Pearce [:cpearce (Not reading bugmail)]]

What's happening here is we're switching to readyState HAVE_ENOUGH_DATA after we consider the download rate to be "reliable", which for unknown length streams is after downloading for 3 seconds. We actually haven't downloaded enough to play by that time, so we switch to buffering mode.

This is related to bug 620715, except there the complaint is that we don't start playing soon enough on live streams, whereas in this bug we start playback too soon, and then switch to buffering mode immediately.

Comment 2

[Chris Pearce [:cpearce (Not reading bugmail)]]

Attachment: Patch

Part of the problem here is that we automatically start playback of live streams after they've been downloading for 3 seconds, but in this case we switching to buffering mode immediately because the decode position is within LIVE_BUFFER_MARGIN of the download position. LIVE_BUFFER_MARGIN is currently 100,000.

This patch reduces LIVE_BUFFER_MARGIN. This means we'll be less likely to go into buffering state after we start playback of a live stream. The value is still pretty arbitrary, just low enough that I'd expect live streams to start, and high enough to be larger than most Ogg pages/WebM elements.

Comment 3

[Timothy B. Terriberry (:derf)]

If you want to guarantee that it is larger than an Ogg page, they are restricted to slightly less than 64kB.

Comment 4

[Chris Pearce [:cpearce (Not reading bugmail)]]

Yeah, I tried 64kB, but it seems to be too large for this particular test case. Being too small doesn't seem to really matter, provided we catch the decode position within LIVE_BUFFER_MARGIN of the download position when we check this, which is once per frame. Normally when this test fails, the decode position *is* the download position, and we're blocked in a read. This is about as low as I dared make this threshold. I couldn't convince myself we could reliably detect when the decode catches the download if we're only checking once per frame if the threshold was much lower.

We could instead have the media stream read notify the decoder before it's about to block on a read, and put the decoder into buffering mode then instead, and remove LIVE_BUFFER_MARGIN altogether.

Comment 5

[Chris Pearce [:cpearce (Not reading bugmail)]]

Attachment: Patch: Restore playback statistics to enable more accurate media buffering duration calculation.

It turns out we're not actually recording playback statistics (I guess we never hooked it up in the new decoder) so the value returned by nsBuiltinDecoder::ComputePlaybackRate() will always be wrong. This means nsBuiltinDecoderStateMachine::StartBuffering() will estimate how long to buffer for using inaccurate data. This patch hooks up the playback statistics.

Comment 6

[Chris Pearce [:cpearce (Not reading bugmail)]]

Attachment: Patch 2/2: Initiate media buffering when decode hits end of downloaded data

We currently go into buffering mode when the decode is within X bytes of the download. This means if we have a low bitrate media with a slow connection, we can start buffering even though we could actually play smoothly (as happens in this bug's testcase). This patch makes us go into buffering just before the decode is going to block on a read. This mechanism is similar to how we used to go into buffering, except here we go into buffering *before* our read blocks, whereas we used to go into buffering *after* the decode's blocked read returned. This means we go into buffering when we're actually running out of data, not based on some arbitrary threshold.

Comment 7

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Comment on attachment 504337 [details] [diff] [review]
Patch: Restore playback statistics to enable more accurate media buffering duration calculation.

+          mBufferingStart = TimeStamp::Now();
+          PRPackedBool reliable;
+          double playbackRate = mDecoder->ComputePlaybackRate(&reliable);
+          mBufferingEndOffset = mDecoder->mDecoderPosition +
+            BUFFERING_RATE(playbackRate) * BUFFERING_WAIT;
+          LOG(PR_LOG_DEBUG, ("Starting to buffer playback=%.1lfKB/s%s download=%.1lfKB/s%s",
+              stats.mDownloadRate/1024, stats.mDownloadRateReliable ? "" : " (unreliable)",
+              stats.mPlaybackRate/1024, stats.mPlaybackRateReliable ? "" : " (unreliable)"));
+        }
+        NS_ASSERTION(mBufferingEndOffset != -1 && !mBufferingStart.IsNull(),
+                     "Must know buffering end conditions.");
+
         // We will remain in the buffering state if we've not decoded enough
         // data to begin playback, or if we've not downloaded a reasonable
         // amount of data inside our buffering time.
         TimeDuration elapsed = TimeStamp::Now() - mBufferingStart;

You can avoid making two calls to TimeStamp::Now() here.

Comment 8

[Chris Pearce [:cpearce (Not reading bugmail)]]

http://hg.mozilla.org/mozilla-central/rev/70f624db117f
http://hg.mozilla.org/mozilla-central/rev/5dfc48bca76d

Comment 9

[Chris Pearce [:cpearce (Not reading bugmail)]]

Assertion failure:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1295317005.1295318604.15058.gz

++DOMWINDOW == 164 (0x137cb9158) [serial = 10476] [outer = 0x1270e7120]
WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/slave/cen-osx64-dbg/build/layout/base/nsCSSFrameConstructor.cpp, line 3928
**nsSVGForeignObjectFrame::DoReflow()
**nsSVGForeignObjectFrame::DoReflow()
**nsSVGForeignObjectFrame::DoReflow()
**nsSVGForeignObjectFrame::DoReflow()
###!!! ASSERTION: We shouldn't be notified in this case!: '!stream->IsDataCachedToEndOfStream(mDecoder->mDecoderPosition)', file /builds/slave/cen-osx64-dbg/build/content/media/nsBuiltinDecoderStateMachine.cpp, line 911
nsBuiltinDecoderStateMachine::NotifyDataExhausted [content/media/nsBuiltinDecoderStateMachine.cpp:912]
nsBuiltinDecoder::NotifyDataExhausted [content/media/nsBuiltinDecoder.h:374]
nsMediaChannelStream::Read [content/media/nsMediaStream.cpp:583]
nsOggReader::ReadOggPage [content/media/ogg/nsOggReader.cpp:786]
nsOggReader::ReadMetadata [content/media/ogg/nsOggReader.cpp:193]
nsBuiltinDecoderStateMachine::LoadMetadata [content/media/nsBuiltinDecoderStateMachine.cpp:1475]
nsOggDecoderStateMachine::LoadMetadata [content/media/ogg/nsOggDecoderStateMachine.cpp:59]
nsBuiltinDecoderStateMachine::Run [content/media/nsBuiltinDecoderStateMachine.cpp:944]
nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:633]
NS_ProcessNextEvent_P [nsThreadUtils.cpp:250]
nsThread::ThreadFunc [xpcom/threads/nsThread.cpp:277]
_pt_root [nsprpub/pr/src/pthreads/ptthread.c:190]
libSystem.B.dylib + 0x39f8e
--DOCSHELL 0x1362e3dd0 == 4
**nsSVGForeignObjectFrame::DoReflow()
**nsSVGForeignObjectFrame::DoReflow()
**nsSVGForeignObjectFrame::DoReflow()
REFTEST TEST-START | http://localhost:4444/1295317282552/136/ogg-video/aspect-ratio-1-ref.html
++DOMWINDOW == 165 (0x137cbdd78) [serial = 10477] [outer = 0x1270e7120]
--DOCSHELL 0x12cdfb370 == 3
REFTEST TEST-PASS | file:///Users/cltbld/talos-slave/test/build/reftest/tests/layout/reftests/ogg-video/aspect-ratio-1a.xhtml | image comparison (==)
REFTEST INFO | Loading a blank page
++DOMWINDOW == 166 (0x138d96b78) [serial = 10478] [outer = 0x1270e7120]
NEXT ERROR REFTEST TEST-UNEXPECTED-FAIL | file:///Users/cltbld/talos-slave/test/build/reftest/tests/layout/reftests/ogg-video/aspect-ratio-1a.xhtml | assertion count 1 is more than expected 0 assertions
REFTEST TEST-START | http://localhost:4444/1295317282554/137/ogg-video/aspect-ratio-1b.xhtml
++DOMWINDOW == 167 (0x127adf588) [serial = 10479] [outer = 0x1270e7120]
WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/slave/cen-osx64-dbg/build/layout/base/nsCSSFrameConstructor.cpp, line 3928
**nsSVGForeignObjectFrame::DoReflow()
**nsSVGForeignObjectFrame::DoReflow()

I imagine what happened after stream->IsDataCachedToEndOfStream(mDecoder->mDecoderPosition) was checked in nsMediaStream::Read(), the thread was interrupted before nsBuiltinDecoderStateMachine::NotifyDataExhausted had a chance to run, and while it was interrupted more data came in, so the result changed. We should just re-check IsDataCachedToEndOfStream in nsBuiltinDecoderStateMachine::NotifyDataExhausted, rather than asserting that.

Comment 10

[Chris Pearce [:cpearce (Not reading bugmail)]]

Attachment: Patch 3: Change assertion into check

The assertion that failed checks whether the rest of the stream is cached. nsMediaStream::Read() checks that itself, and when data is exhausted, it won't call through to nsBuiltinDecoderStateMachine::NotifyDataExhausted() if the stream is cached to the end of stream. We should just change the assertion to be part of the "should we go into buffering state" if condition.

Comment 11

[Chris Pearce [:cpearce (Not reading bugmail)]]

Landed assertion change:
http://hg.mozilla.org/mozilla-central/rev/3a41b17fb632

Comment 12

[u279076]

Verified using Minefield nightly from 2011-01-22.

Comment 13

[Sander Plas]

The problem is indeed fixed for the simple case of a static html audio tag with 'autoplay' enabled. 

The same kind of problem still seems to occur when an audio element is created through javascript and instead of using 'autoplay', play() is immediately called. Example: http://www.oele.net/audio_js_start.html

It seems that Opera 11 and Firefox 3.6 interpret a javascript 'play' call as "start playing as soon as enough data is buffered" whereas Firefox 4.0b10pre immediately starts playing. 

I'm not entirely sure what the "correct" behaviour is but Opera's and Firefox 3.6's behaviour seems more useful to me - i think it's rather pointless to ever allow a media element to start "playing" without having enough buffered data.

Comment 14

[u279076]

(In reply to comment #13)
> The problem is indeed fixed for the simple case of a static html audio tag with
> 'autoplay' enabled. 
> 
> The same kind of problem still seems to occur when an audio element is created
> through javascript and instead of using 'autoplay', play() is immediately
> called. Example: http://www.oele.net/audio_js_start.html
> 
> It seems that Opera 11 and Firefox 3.6 interpret a javascript 'play' call as
> "start playing as soon as enough data is buffered" whereas Firefox 4.0b10pre
> immediately starts playing. 
> 
> I'm not entirely sure what the "correct" behaviour is but Opera's and Firefox
> 3.6's behaviour seems more useful to me - i think it's rather pointless to ever
> allow a media element to start "playing" without having enough buffered data.

Please file this in a new bug, thanks.