879717 - drawImage on MediaStream assigned to <video> stopped working again

Status: VERIFIED FIXED

(Core :: WebRTC: Audio/Video, defect, P1)

Description

[Rob Manson]

User Agent: Mozilla/5.0 (X11; Linux i686; rv:24.0) Gecko/20130529 Firefox/24.0 (Nightly/Aurora)
Build ID: 20130529031131

Steps to reproduce:

Loaded https://bug771833.bugzilla.mozilla.org/attachment.cgi?id=675234 (testcase v4 from attached to https://bugzilla.mozilla.org/show_bug.cgi?id=771833)


Actual results:

Error console reports:

NS_ERROR_NOT_AVAILABLE: Component is not available
context.drawImage(video, 0, 0);
attach...=675234 (line 20)


Expected results:

No error - should have been able to drawImage to the canvas context from the video element.

NOTE: This seemed to fail from v21.0 onwards on Ubuntu 12.04 LTS.  

Here's the latest UA I have tested:

Mozilla/5.0 (X11; Linux i686; rv:24.0) Gecko/20130529 Firefox/24.0

This was working fine in v20.n but stopped after upgrading to 21.  No other apps/libs were updated on this Ubuntu box and this gUM/drawImage flow definitely works on Chrome so there's no systemic issues.

If you need any other info please let me know.

BTW: I added a comment here but was then asked to raise this as a new ticket.
https://bugzilla.mozilla.org/show_bug.cgi?id=771833#c35

Comment 1

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

The problem here is that drawImage runs before there have been any calls to VideoFrameContainer::Invalidate. At least one call to VideoFrameContainer::Invalidate is needed to call mElement->UpdateMediaSize, to set the size of the video frame (and make sure there is a frame set in the ImageContainer!).

We should do something to ensure an image is set up and drawImage would succeed before we change the readyState to HAVE_CURRENT_DATA or greater.

Comment 2

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

What's tricky here is knowing whether to expect a video image to arrive or not. If we're expecting one, then we can simply not advance to HAVE_CURRENT_DATA until our ImageContainer has an image in it and we have an intrinsic size. But we can't wait for that if there is no video track.

Comment 3

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

Attachment: fix

Comment 4

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

Attachment: fix v2

We can't check mHasVideo in GetVideoFrameContainer since that's not set by the decoder until after the decoder has called GetVideoFrameContainer and stashed the value away. This means that <video> elements with resources that don't have a video track will create an unnecessary ImageContainer, but that's fine (and I think we already do that).

Comment 5

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

Comment on attachment 763430 [details] [diff] [review]
fix v2

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

::: content/html/content/src/HTMLMediaElement.cpp
@@ +2739,2 @@
>    ChangeDelayLoadStatus(false);
> +  UpdateReadyStateForData(NEXT_FRAME_UNAVAILABLE);

You definitely need a comment here explaining why we're *not* passing NEXT_FRAME_AVAILABLE here, since it seems counter-intuitive to pass UNAVAILABLE when the purpose of this function is to report availability of the first frame.

Comment 6

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/8866d9627149

Comment 7

[Ed Morley [:emorley]]

This and bug 883731 backed out for causing extremely frequent (but not 100%) assertions on Windows during test_playback_rate.html:
https://tbpl.mozilla.org/php/getParsedLog.php?id=24325130&full=1&branch=mozilla-inbound#error0
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&rev=04d60f86b935

https://hg.mozilla.org/integration/mozilla-inbound/rev/abe93cefa9cf
https://hg.mozilla.org/integration/mozilla-inbound/rev/5199b67ba029
https://hg.mozilla.org/integration/mozilla-inbound/rev/b22438ffe268
https://hg.mozilla.org/integration/mozilla-inbound/rev/bef10ede6c1e

Comment 8

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

Attachment: patch rebased

Comment 9

[Randell Jesup [:jesup] (needinfo me)]

Can we get the assertions addressed and get this patch in, or some variant of it?  Is there anything else blocking resolving the assertions; do we know why they happened?

Comment 10

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

We might just be able to reland this. I think bug 883731 was to blame, and I haven't had time to get back to that yet.

Comment 11

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/95ffea3d6908

Comment 12

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/95ffea3d6908

Comment 13

[Randell Jesup [:jesup] (needinfo me)]

backed out in bug 905002 for a mac-only regression (may be on others too dependent on timing)

Comment 15

[Daniele "Mte90" Scasciafratte]

This bug exist in the last version.

http://stackoverflow.com/questions/18580844/firefox-drawimagevideo-fails-with-ns-error-not-available-component-is-not-av

With code like this:

[code]
function drawVideo() {
  try {
    $vidCanvasCtx.drawImage($vid, 0, 0, $vidCanvas.width, $vidCanvas.height);
    ...
  } catch (e) {
    if (e.name == "NS_ERROR_NOT_AVAILABLE") {
      setTimeout(drawVideo, 0);
    } else {
      throw e;
    }
  }
}
[/code]
The problem is fixed.
For my test i have added a delay of 400ms that some time the webcam it's not showed correct.

Comment 16

[Maire Reavy [:mreavy]]

We should target fixing this for Fx 33.  I'm not sure that Rob/Roc has time to fix this, but I can try to find someone if he's swamped.

Comment 17

[:shell escalante]

Maire re-assigning so Roc is not getting this work.

Comment 18

[Maire Reavy [:mreavy]]

Paul -- After you're done with Bug 848954, I'd love for you to take a look at this.

Comment 19

[agamemnus]

This problem is not limited to video. The same thing happens to my jpegs... drawImage against them sometimes fails.

Comment 20

[agamemnus]

Sorry, that was drawImage using an image declared with new Image ().. creating a new image via createElement ('img') and then appending the image to the document does not mis-report onload, but just new Image () does...

Comment 21

[agamemnus]

Actually, taking that back. createElement ('img') doesn't help...

Comment 22

[Andreas Pehrson [:pehrsons]]

I reckon this bug is open to contributions considering the long silence in here. I hope no one objects if I take it.
I saw this had been backed out when working my way through HTMLMediaElement, so let's try to land it!

Comment 23

[Andreas Pehrson [:pehrsons]]

Attachment: Part 1. roc's patch rebased (carries r=cpearce)

I rebased roc's patch on top of m-c. Needed some trivial fixes.

Comment 24

[Andreas Pehrson [:pehrsons]]

I don't see quite the same symptoms as described in bug 905002 with this patch. Instead of occasional stream freezes I most of the time get no output at all, but occasionally it works. Bug 905002 was more than a year ago so something has probably changed. I'll try to work out the quirks below. For my own reference if nothing else.


See this code in HTMLMediaElement::UpdateReadyStateForData:

>  if (mReadyState < nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA && mHasVideo) {
>    VideoFrameContainer* container = GetVideoFrameContainer();
>    if (container && mMediaSize == nsIntSize(-1,-1)) {
>      // No frame has been set yet. Don't advance.
>      return;
>    }
>  }

where we'd now always get a container and mMediaSize would be (-1,-1) until a frame has been set in said container. The only way a frame could find its way to the container would be if mSrcStream was unblocked and played something. Conclusion: no incrementing mReadyState until mSrcStream is playing.


Now see this code:

>bool HTMLMediaElement::CanActivateAutoplay()
>{
>  // For stream inputs, we activate autoplay on HAVE_CURRENT_DATA because
>  // this element itself might be blocking the stream from making progress by
>  // being paused.
>  return !mPausedForInactiveDocumentOrChannel &&
>         mAutoplaying &&
>         mPaused &&
>         (mDownloadSuspendedByCache ||
>          (mDecoder && mReadyState >= nsIDOMHTMLMediaElement::HAVE_ENOUGH_DATA) ||
>          (mSrcStream && mReadyState >= nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA)) &&
>         HasAttr(kNameSpaceID_None, nsGkAtoms::autoplay) &&
>         mAutoplayEnabled &&
>         !IsEditable();
>}

If we are going to autoplay we won't unblock and play mSrcStream until this expression is true, aka when mReadyState has reached at least HAVE_CURRENT_DATA. But it won't, because that requires unblocking, see above.



The reason bug 905002 (my symptoms of it at least) does not occur on gupshup is because Play() is called before SetupSrcMediaStreamPlayback so both mPaused and mAutoplaying gets reset to false.

The reason it _sometimes_ works on apprtc is because the mSrcStream would those times let a video frame out after it has been blocked, plus after the VideoFrameContainer has been added as output to the stream. See http://dxr.mozilla.org/mozilla-central/source/content/html/content/src/HTMLMediaElement.cpp#2856 and #2866.

Comment 25

[Andreas Pehrson [:pehrsons]]

Attachment: Part 2. Don't block when autoplaying a stream

This patch makes autoplay proceed earlier than before. mSrcStream now gets properly unblocked and we don't end up in the deadlock described in comment 24.

Comment 26

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 8499801 [details] [diff] [review]
Part 1. roc's patch rebased (carries r=cpearce)

carry forward r=cpearce

Comment 27

[Randell Jesup [:jesup] (needinfo me)]

Normally you'd mark it checkin-needed in the keywords, and a sheriff would check it in, but I'm just going to land this after a local check-build

Comment 28

[Randell Jesup [:jesup] (needinfo me)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/c42b68e0db15
https://hg.mozilla.org/integration/mozilla-inbound/rev/6e2c7dd63fcf

Comment 29

[Jonathan Kew [:jfkthame]]

Unfortunately, this turned mochitest orange on all platforms:
  https://tbpl.mozilla.org/php/getParsedLog.php?id=49547006&tree=Mozilla-Inbound
  https://tbpl.mozilla.org/php/getParsedLog.php?id=49548544&tree=Mozilla-Inbound
  https://tbpl.mozilla.org/php/getParsedLog.php?id=49548473&tree=Mozilla-Inbound
etc.

So I backed it out:
　https://hg.mozilla.org/integration/mozilla-inbound/rev/4fe8ca5b1c15

Comment 30

[Andreas Pehrson [:pehrsons]]

Double checked here and couldn't reproduce. Rebasing on inbound now.

Comment 31

[Andreas Pehrson [:pehrsons]]

Seems to be a collision with bug 1022669 in HTMLMediaElement::GetVideoFrameContainer.

Comment 32

[Andreas Pehrson [:pehrsons]]

Attachment: Part 1. roc's patch rebased on inbound (carries r=cpearce)

This rebase solves the issues for me. I'll push to try before we land as well.

Comment 33

[Andreas Pehrson [:pehrsons]]

Attachment: Part 2. Don't block when autoplaying a stream (carries r=roc)

Rebased this one as well just to be sure.

Comment 34

[Andreas Pehrson [:pehrsons]]

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

Comment 35

[Randell Jesup [:jesup] (needinfo me)]

Orange on M1 with INFO TEST-UNEXPECTED-FAIL | /tests/content/html/content/test/test_video_wakelock.html | Video element locked the cpu - paused - got false, expected true

Comment 36

[Andreas Pehrson [:pehrsons]]

Attachment: Part 3. Update screen wake lock when metadata has loaded

We basically had a race condition between HTMLVideoElement::UpdateScreenWakeLock (depended on mHasVideo) and HTMLMediaElement::SetupSrcMediaStreamPlayback (would call MetadataLoaded to set mHasVideo if we had video tracks).

We couldn't set mHasVideo in GetVideoFrameContainer anymore - that gave the errors in comment 29.

If SetupSrcMediaStreamPlayback was called too late, the screen wake lock would have been updated based on mHasVideo == false, and would not get updated again.

Instead of this racy issue I am updating the screen wake lock after setting mHasVideo in MetadataLoaded, to make sure it is all up to date and happy.


Eugen, please make sure this solution works for bug 1022669.

Comment 37

[Andreas Pehrson [:pehrsons]]

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=7fd66b2d4ae7

Comment 38

[Andreas Pehrson [:pehrsons]]

Try looks good.

Comment 39

[Andreas Pehrson [:pehrsons]]

Attachment: Part 4. Add mochitest

Throwing in a test as well.

It checks for an exception when doing drawImage into a canvas for both a file and a stream on the 'play' event, as per http://stackoverflow.com/questions/18580844/firefox-drawimagevideo-fails-with-ns-error-not-available-component-is-not-av

Comment 40

[Andreas Pehrson [:pehrsons]]

Here's an up to date try: https://tbpl.mozilla.org/?tree=Try&rev=119555f1a3cf

Comment 41

[Eugen Sawin [:esawin]]

Comment on attachment 8500033 [details] [diff] [review]
Part 3. Update screen wake lock when metadata has loaded

No regressions on bug 1022669 with this, looks good.

Comment 42

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

Comment on attachment 8500325 [details] [diff] [review]
Part 4. Add mochitest

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

::: content/media/test/test_bug879717.html
@@ +26,5 @@
> +  } catch (e) {
> +    exception = e;
> +    exceptionName = e.name;
> +  }
> +  ok(exception === null, "drawImage shouldn't throw an exception on play of " + name + ", got " + exceptionName);

Make this exception === null || video.ended.

Comment 43

[Andreas Pehrson [:pehrsons]]

Attachment: Part 4. Add mochitest (carries r=roc)

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) (on vacation Sep 27 to Oct 12) from comment #42)
> Comment on attachment 8500325 [details] [diff] [review]
> Part 4. Add mochitest
> 
> Review of attachment 8500325 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: content/media/test/test_bug879717.html
> @@ +26,5 @@
> > +  } catch (e) {
> > +    exception = e;
> > +    exceptionName = e.name;
> > +  }
> > +  ok(exception === null, "drawImage shouldn't throw an exception on play of " + name + ", got " + exceptionName);
> 
> Make this exception === null || video.ended.

Done!

Comment 44

[Randell Jesup [:jesup] (needinfo me)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/29f4a39efc29
https://hg.mozilla.org/integration/mozilla-inbound/rev/78b01186ff85
https://hg.mozilla.org/integration/mozilla-inbound/rev/cd7d8b93923f
https://hg.mozilla.org/integration/mozilla-inbound/rev/353aee813484

Thanks Andreas!

Comment 45

[Ryan VanderMeulen [:RyanVM]]

Looks like the newly-added mochitest fails on OSX/Android/B2G. Backed out.
https://hg.mozilla.org/integration/mozilla-inbound/rev/b2d92cb44873

https://treeherder.mozilla.org/ui/logviewer.html#?job_id=2798067&repo=mozilla-inbound

Comment 46

[Andreas Pehrson [:pehrsons]]

It's some timing awesomeness. I just ran my test 100 times and got five errors.

Nice to have a test :)

Comment 47

[Andreas Pehrson [:pehrsons]]

Looks like the DOMMediaStream we get in SetupSrcMediaStreamPlayback doesn't have any tracks (also not audio) when this happens.

So mHasVideo becomes false and we advance past the HAVE_METADATA ready state before we have received a video frame.

Comment 48

[James Lal [:lightsofapollo]]

Attachment: Merge inbound to m-c. a=merge

--HG--
extra : rebase_source : 2a6319591731c2d46f12ac749f8e1f69d50762c5

--HG--
extra : rebase_source : c44d91125cf48e7f34fb92cd04670bac9247b0c2

--HG--
extra : rebase_source : f4e1d6c1067c2ae5c01f62dee3d4b28471c62e98

Backed out changeset 353aee813484 (bug 879717)
Backed out changeset cd7d8b93923f (bug 879717)
Backed out changeset 78b01186ff85 (bug 879717)
Backed out changeset 29f4a39efc29 (bug 879717)

CLOSED TREE





--HG--
extra : rebase_source : e8789fd34910ae510483034a769e77e70e644198

--HG--
extra : rebase_source : 3e73f02aa1c889f331c8326f17bb5e245204b780

--HG--
extra : rebase_source : 525e2d8455beff596c1ae13b4a8c4d062533a0df

--HG--
extra : rebase_source : 4a08b9b8bfcc026d05e6862dc08bad350033aa46



--HG--
extra : rebase_source : 5bff5b899c83796443c124dce0f5afbd16e611c2

--HG--
rename : gfx/angle/src/libGLESv2/constants.h => gfx/angle/src/libGLESv2/Constants.h
extra : rebase_source : 3147126bc9ccd9df61f4f27e91efe397a6538943

Comment 49

[Andreas Pehrson [:pehrsons]]

Attachment: Part 5. We don't have current data in TrackUnionStream with no tracks

The test failures happened when we processed input from a TrackUnionStream where the tracks had not been added yet. It would report that it had current data and throw the HTMLMediaElement in a bad state.

Haven't run through all media tests on my machine yet but the test I added in this bug I ran a few thousand times with success.

Previously both mHasAudio and mHasVideo would be false every time. We'd just be lucky that there was a video track around once the canvas tried to access it. Now we have tracks around each time we get into HAVE_CURRENT_DATA in HTMLMediaElement, so we should be safe from intermittent failures.

Comment 50

[Andreas Pehrson [:pehrsons]]

Running a few more tests this time.

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=2f206904859f

Comment 51

[Andreas Pehrson [:pehrsons]]

Comment on attachment 8501774 [details] [diff] [review]
Part 5. We don't have current data in TrackUnionStream with no tracks

So that broke some other tests. Let me revisit tomorrow.

Comment 52

[Randell Jesup [:jesup] (needinfo me)]

Adding jwwang since the fixes here may interest him and his work on cleaning up media tests

Comment 53

[Andreas Pehrson [:pehrsons]]

Attachment: Part 1. Reworked and squashed; handling stream tracks using DOMMediaStream event

I overhauled roc's old patch. Most notably we now use DOMMediaStream::OnTracksAvailableCallback to figure out when tracks are added to the stream. Because of asyncness between MediaStreamGraph and the main thread we would quite often get a media stream that didn't have any tracks when we set it up.

TrackUnionStream still reports that it has current data well before it has any tracks added. Not sure if we should fix it in TrackUnionStream because it'd most of the time report that it has current data before the wrapping DOMMediaStream has fully registered the tracks anyway (same asyncness as noted above). The media element will now in any case wait until a track is available before registering outputs and starting autoplay.

Comment 54

[Andreas Pehrson [:pehrsons]]

Attachment: Part 2. Add mochitest (carries r=roc)

Just changing the part number in the commit message.

Comment 55

[Andreas Pehrson [:pehrsons]]

All mochitests in content/html and content/media look good on my machine now. Let's see a couple more platforms: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=96199be7e492

Comment 56

[Andreas Pehrson [:pehrsons]]

Attachment: Part 1. Reworked and squashed; handling stream tracks using DOMMediaStream event

We were removing audio outputs that had not been added to mSrcStream. That caused assertions on debug builds.

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=5406160f6c7c

Comment 57

[Andreas Pehrson [:pehrsons]]

According to :aosmond, this breaks the gaia camera app. He's working on a fix and will attach it here. So no landing before that please :)

Comment 58

[Andrew Osmond [:aosmond] (he/him)]

Attachment: Part 3. Fix camera preview stream and wake locks from lock screen.

Comment 59

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

Comment on attachment 8503132 [details] [diff] [review]
Part 1. Reworked and squashed; handling stream tracks using DOMMediaStream event

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

Seems like a mochitest here would be good

Comment 60

[Randell Jesup [:jesup] (needinfo me)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/8f472a850073
https://hg.mozilla.org/integration/mozilla-inbound/rev/ecd54a3fbfdd
https://hg.mozilla.org/integration/mozilla-inbound/rev/f749e3f70ffc

Comment 61

[Randell Jesup [:jesup] (needinfo me)]

Broke some builds (likely works on some unified builds due to chance).

Bustage fix landed:
https://hg.mozilla.org/integration/mozilla-inbound/rev/ef6465b02d0d

Comment 62

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/8f472a850073
https://hg.mozilla.org/mozilla-central/rev/ecd54a3fbfdd
https://hg.mozilla.org/mozilla-central/rev/f749e3f70ffc
https://hg.mozilla.org/mozilla-central/rev/ef6465b02d0d

Comment 63

[Randell Jesup [:jesup] (needinfo me)]

backing out for b2g emulator and android 2.3 failures in test_streams_autoplay and test_streams_element_capture.

Adding "loop" to v1 in test_streams_autoplay got it past the timing race where the video could finish before the second video element was ready, but then it still fails in test_streams_element_capture.

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

Comment 64

[Randell Jesup [:jesup] (needinfo me)]

And backed out of aurora
https://hg.mozilla.org/releases/mozilla-aurora/rev/189ac924dfa6

Comment 65

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8503061 [details] [diff] [review]
Part 2. Add mochitest (carries r=roc)

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

::: content/media/test/test_bug879717.html
@@ +26,5 @@
> +  } catch (e) {
> +    exception = e;
> +    exceptionName = e.name;
> +  }
> +  ok(exception === null || video.ended,

I don't understand why checking video.ended here. Can't we capture image when the video is at the end?

@@ +40,5 @@
> +
> +  var v1Tested = false;
> +  var v2Tested = false;
> +
> +  v1.addEventListener('play', function() {

'play' is fired when play() is called, even before metadata is loaded. You might want to listen to 'loadeddata' which indicates readyState newly increased to HAVE_CURRENT_DATA or greater for the first time.

Comment 66

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8503132 [details] [diff] [review]
Part 1. Reworked and squashed; handling stream tracks using DOMMediaStream event

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

::: content/html/content/src/HTMLMediaElement.cpp
@@ +903,4 @@
>    }
>  }
>  
> +void HTMLMediaElement::NotifyMediaStreamTracksAvailable(DOMMediaStream* aStream)

Should we also handle the case where tracks are removed instead of being added?

@@ +921,5 @@
> +  mHasVideo = !videoTracks.IsEmpty();
> +
> +  if (!oldHasAudio && mHasAudio) {
> +    GetSrcMediaStream()->AddAudioOutput(this);
> +    GetSrcMediaStream()->SetAudioOutputVolume(this, float(mMuted ? 0.0 : mVolume));

Shouldn't volume be changed via HTMLMediaElement::SetVolumeInternal() which also handles audio channel and window volume?

@@ +932,5 @@
> +    // mHasVideo changed so make sure the screen wakelock is updated
> +    NotifyOwnerDocumentActivityChanged();
> +  }
> +
> +  CheckAutoplayDataReady();

I would like to associate track changes with readyState changes. Then you can call HTMLMediaElement::UpdateReadyStateForData() to update readyState and autoplay will be triggered if necessary during readyState transition.

@@ +2858,5 @@
> +  virtual void NotifyTracksAvailable(DOMMediaStream* aStream)
> +  {
> +    NS_ASSERTION(NS_IsMainThread(), "Should be on main thread.");
> +
> +    if (!mElement) {

How can |mElement| be null?

@@ +2889,5 @@
>    if (mPausedForInactiveDocumentOrChannel) {
>      GetSrcMediaStream()->ChangeExplicitBlockerCount(1);
>    }
> +
> +  mSrcStream->OnTracksAvailable(new MediaStreamTracksAvailableCallback(this, DOMMediaStream::HINT_CONTENTS_AUDIO));

Can we pass "HINT_CONTENTS_AUDIO | HINT_CONTENTS_VIDEO" and use one listener only?

@@ +2898,5 @@
> +  mediaInfo.mVideo.mHasVideo = mHasVideo;
> +  MetadataLoaded(&mediaInfo, nullptr);
> +
> +  DispatchAsyncEvent(NS_LITERAL_STRING("suspend"));
> +  mNetworkState = nsIDOMHTMLMediaElement::NETWORK_IDLE;

All changes to network state should be via HTMLMediaElement::ChangeNetworkState() which also fires "suspend" if necessary.

@@ +3164,5 @@
> +    return;
> +  }
> +
> +  if (!mHasAudio && !mHasVideo) {
> +    // No tracks available yet, don't advance from HAVE_METADATA

Should we switch back to HAVE_METADATA when all tracks are removed?

@@ +3188,4 @@
>      return;
>    }
>  
> +  if (mReadyState < nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA && mHasVideo) {

This check fails because we will advance anyway before video tracks are added.

@@ +3343,5 @@
>           mAutoplaying &&
>           mPaused &&
>           ((mDecoder && mReadyState >= nsIDOMHTMLMediaElement::HAVE_ENOUGH_DATA) ||
> +          (mSrcStream && mReadyState >= nsIDOMHTMLMediaElement::HAVE_METADATA)) &&
> +         (mHasAudio || mHasVideo) &&

We should remain checking |mSrcStream && mReadyState >= nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA| and ensure advancing to HAVE_CURRENT_DATA only when |mHasAudio| or |mHasVideo| is true. We should not introduce dependency on |mHasAudio| or |mHasVideo| to the logic of autoplay which depends on readyState which depends on |mHasAudio| and |mHasVideo|.

@@ +3488,4 @@
>  void HTMLMediaElement::UpdateMediaSize(nsIntSize size)
>  {
>    mMediaSize = size;
> +  UpdateReadyStateForData(mLastNextFrameStatus);

This should be done in MediaDecoder::Invalidate() and you can remove |mLastNextFrameStatus|.

Comment 67

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8503132 [details] [diff] [review]
Part 1. Reworked and squashed; handling stream tracks using DOMMediaStream event

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

::: content/html/content/src/HTMLMediaElement.cpp
@@ +3188,4 @@
>      return;
>    }
>  
> +  if (mReadyState < nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA && mHasVideo) {

Also this should move above the check of |mDownloadSuspendedByCache|. So the behavior is consistent for both file and stream cases.

@@ +3488,4 @@
>  void HTMLMediaElement::UpdateMediaSize(nsIntSize size)
>  {
>    mMediaSize = size;
> +  UpdateReadyStateForData(mLastNextFrameStatus);

Sorry, that don't handle the stream case. Stay where you are.

Comment 68

[Andreas Pehrson [:pehrsons]]

I'll use comments for bookkeeping; patch comes later.

(In reply to JW Wang [:jwwang] from comment #66)
> Comment on attachment 8503132 [details] [diff] [review]
> Part 1. Reworked and squashed; handling stream tracks using DOMMediaStream
> event
> 
> Review of attachment 8503132 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: content/html/content/src/HTMLMediaElement.cpp
> @@ +903,4 @@
> >    }
> >  }
> >  
> > +void HTMLMediaElement::NotifyMediaStreamTracksAvailable(DOMMediaStream* aStream)
> 
> Should we also handle the case where tracks are removed instead of being
> added?

Could you file a new bug for that? IMO let's not increase complexity here, it's been in and out enough.

> @@ +921,5 @@
> > +  mHasVideo = !videoTracks.IsEmpty();
> > +
> > +  if (!oldHasAudio && mHasAudio) {
> > +    GetSrcMediaStream()->AddAudioOutput(this);
> > +    GetSrcMediaStream()->SetAudioOutputVolume(this, float(mMuted ? 0.0 : mVolume));
> 
> Shouldn't volume be changed via HTMLMediaElement::SetVolumeInternal() which
> also handles audio channel and window volume?

Looks fine, done. However, I don't know if there was a reason for not using it before in SetupSrcMediaStreamPlayback().

> @@ +932,5 @@
> > +    // mHasVideo changed so make sure the screen wakelock is updated
> > +    NotifyOwnerDocumentActivityChanged();
> > +  }
> > +
> > +  CheckAutoplayDataReady();
> 
> I would like to associate track changes with readyState changes. Then you
> can call HTMLMediaElement::UpdateReadyStateForData() to update readyState
> and autoplay will be triggered if necessary during readyState transition.

Done.

> @@ +2858,5 @@
> > +  virtual void NotifyTracksAvailable(DOMMediaStream* aStream)
> > +  {
> > +    NS_ASSERTION(NS_IsMainThread(), "Should be on main thread.");
> > +
> > +    if (!mElement) {
> 
> How can |mElement| be null?

Done.

> @@ +2889,5 @@
> >    if (mPausedForInactiveDocumentOrChannel) {
> >      GetSrcMediaStream()->ChangeExplicitBlockerCount(1);
> >    }
> > +
> > +  mSrcStream->OnTracksAvailable(new MediaStreamTracksAvailableCallback(this, DOMMediaStream::HINT_CONTENTS_AUDIO));
> 
> Can we pass "HINT_CONTENTS_AUDIO | HINT_CONTENTS_VIDEO" and use one listener
> only?

No, then we'll get the callback when the first track is added, and we'll miss the other track. If we register another listener in that case, it will return directly with the existing track.

> @@ +2898,5 @@
> > +  mediaInfo.mVideo.mHasVideo = mHasVideo;
> > +  MetadataLoaded(&mediaInfo, nullptr);
> > +
> > +  DispatchAsyncEvent(NS_LITERAL_STRING("suspend"));
> > +  mNetworkState = nsIDOMHTMLMediaElement::NETWORK_IDLE;
> 
> All changes to network state should be via
> HTMLMediaElement::ChangeNetworkState() which also fires "suspend" if
> necessary.

I just kept them from roc's patch, but done, thanks.

> @@ +3164,5 @@
> > +    return;
> > +  }
> > +
> > +  if (!mHasAudio && !mHasVideo) {
> > +    // No tracks available yet, don't advance from HAVE_METADATA
> 
> Should we switch back to HAVE_METADATA when all tracks are removed?

Put in another way: If a video track ends, should we still show the last video frame we got, or remove it?
We also don't handle removed tracks yet.

> @@ +3188,4 @@
> >      return;
> >    }
> >  
> > +  if (mReadyState < nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA && mHasVideo) {
> 
> This check fails because we will advance anyway before video tracks are
> added.

That's why I added the "if (!mHasAudio && !mHasVideo)" check above this.
There's is still a gap if we first receive an audio track, then advance, then get the video track. But we can't predict the future, so what to do? Assume that <video> elements always have a video track? What does the spec say about that?

> @@ +3343,5 @@
> >           mAutoplaying &&
> >           mPaused &&
> >           ((mDecoder && mReadyState >= nsIDOMHTMLMediaElement::HAVE_ENOUGH_DATA) ||
> > +          (mSrcStream && mReadyState >= nsIDOMHTMLMediaElement::HAVE_METADATA)) &&
> > +         (mHasAudio || mHasVideo) &&
> 
> We should remain checking |mSrcStream && mReadyState >=
> nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA| and ensure advancing to
> HAVE_CURRENT_DATA only when |mHasAudio| or |mHasVideo| is true. We should
> not introduce dependency on |mHasAudio| or |mHasVideo| to the logic of
> autoplay which depends on readyState which depends on |mHasAudio| and
> |mHasVideo|.

We have to. For video, we have to start playback to get a video frame, but we can only set HAVE_CURRENT_DATA when we already have a video frame (deadlock!). Advancing to HAVE_CURRENT_DATA before we have a video frame was the previous behavior, so then we will run into the NS_ERROR_NOT_AVAILABLE as per the description.

Currently, TrackUnionStream reports HAVE_CURRENT_DATA before it has even gotten any tracks, so we can't act on that. Even if it reported HAVE_CURRENT_DATA only when it had some data, we could still have the issue where it has data for an audio track, and no video tracks. Then we'd still get NS_ERROR_NOT_AVAILABLE


(In reply to JW Wang [:jwwang] from comment #67)
> Comment on attachment 8503132 [details] [diff] [review]
> Part 1. Reworked and squashed; handling stream tracks using DOMMediaStream
> event
> 
> Review of attachment 8503132 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: content/html/content/src/HTMLMediaElement.cpp
> @@ +3188,4 @@
> >      return;
> >    }
> >  
> > +  if (mReadyState < nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA && mHasVideo) {
> 
> Also this should move above the check of |mDownloadSuspendedByCache|. So the
> behavior is consistent for both file and stream cases.

Done.

Comment 69

[Andreas Pehrson [:pehrsons]]

Here's a try push with a WIP patch where we register outputs right away instead of on new tracks: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=4ae12c82ec58

It seems to resolve the issues with the ready state on 'ended' of 320x240.ogv, in test_streams_element_capture.html.

Still some timeouts for test_streams_autoplay.html. We can fix those by adding a loop attribute to the video element in that test.

I'll fix that up for review tomorrow.


JW, that try also contains fixes to address your comments on the Part1 patch.
In addition I pushed another WIP patch to try, where we don't use media files shorter than 0.5 seconds for stream tests. It unexpectedly (and consistently) broke test_streams_element_capture_reset.html: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=348308fc093b

There's an old intermittent bug (901102) for the same symptom (one frame off - but there are other symptoms on that try as well), but it was never properly analyzed and things started to magically work again.

It reproduces nicely on my mac as well. I'd guess we're exposing a bug that was dormant with a really-short-video due to some race condition.

Comment 70

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #68)
> Put in another way: If a video track ends, should we still show the last
> video frame we got, or remove it?
The rule of thumb is we want a consistent behavior for both file and stream cases wherever possible.

> That's why I added the "if (!mHasAudio && !mHasVideo)" check above this.
> There's is still a gap if we first receive an audio track, then advance,
> then get the video track. But we can't predict the future, so what to do?
> Assume that <video> elements always have a video track? What does the spec
> say about that?
I don't know if there is a spec about that, but I will try to reason about it. After a video track is added, we should go back to HAVE_METADATA before the first frame is rendered which is similar to the seeking case.

> We have to. For video, we have to start playback to get a video frame, but
> we can only set HAVE_CURRENT_DATA when we already have a video frame
> (deadlock!).
Taking the file case for example, MediaDecoder::MetadataLoaded() will render the first frame as part of decoding metadata. Can we do the same thing to the stream case?

> Currently, TrackUnionStream reports HAVE_CURRENT_DATA before it has even
> gotten any tracks, so we can't act on that. Even if it reported
> HAVE_CURRENT_DATA only when it had some data, we could still have the issue
> where it has data for an audio track, and no video tracks. Then we'd still
> get NS_ERROR_NOT_AVAILABLE
I think it is up to the developer to check if there are video tracks and wait for HAVE_CURRENT_DATA before attempting to capture the image. Thought?

Comment 71

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #70)
> > That's why I added the "if (!mHasAudio && !mHasVideo)" check above this.
> > There's is still a gap if we first receive an audio track, then advance,
> > then get the video track. But we can't predict the future, so what to do?
> > Assume that <video> elements always have a video track? What does the spec
> > say about that?
> I don't know if there is a spec about that, but I will try to reason about
> it. After a video track is added, we should go back to HAVE_METADATA before
> the first frame is rendered which is similar to the seeking case.

Sure, makes sense. I think I'll refactor the track handling to use the MediaStreamListener for MediaStream instead of the callback I'm using now on DOMMediaStream. Then we'll be setup for handling removed tracks as well.

> > We have to. For video, we have to start playback to get a video frame, but
> > we can only set HAVE_CURRENT_DATA when we already have a video frame
> > (deadlock!).
> Taking the file case for example, MediaDecoder::MetadataLoaded() will render
> the first frame as part of decoding metadata. Can we do the same thing to
> the stream case?

There's no MetadataLoaded for streams, we're just simulating the event to get our state set up properly.
I think it's fine to go to HAVE_METADATA earlier and proceed only when we have a frame. HAVE_CURRENT_DATA is the state that means we have a frame anyway.

> > Currently, TrackUnionStream reports HAVE_CURRENT_DATA before it has even
> > gotten any tracks, so we can't act on that. Even if it reported
> > HAVE_CURRENT_DATA only when it had some data, we could still have the issue
> > where it has data for an audio track, and no video tracks. Then we'd still
> > get NS_ERROR_NOT_AVAILABLE
> I think it is up to the developer to check if there are video tracks and
> wait for HAVE_CURRENT_DATA before attempting to capture the image. Thought?

Sounds good.

Comment 72

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #65)
> Comment on attachment 8503061 [details] [diff] [review]
> Part 2. Add mochitest (carries r=roc)
> 
> Review of attachment 8503061 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: content/media/test/test_bug879717.html
> @@ +26,5 @@
> > +  } catch (e) {
> > +    exception = e;
> > +    exceptionName = e.name;
> > +  }
> > +  ok(exception === null || video.ended,
> 
> I don't understand why checking video.ended here. Can't we capture image
> when the video is at the end?

Per roc's review, maybe he can shed some light on this.

> @@ +40,5 @@
> > +
> > +  var v1Tested = false;
> > +  var v2Tested = false;
> > +
> > +  v1.addEventListener('play', function() {
> 
> 'play' is fired when play() is called, even before metadata is loaded. You
> might want to listen to 'loadeddata' which indicates readyState newly
> increased to HAVE_CURRENT_DATA or greater for the first time.

In this case we are autoplaying, so play will be called when we HAVE_METADATA and tracks. It is basically reproducing the steps from comment 15 (see the link and the jsfiddle). Perhaps we should try drawImage from setting the stream all the way until it has ended, to see that it works throughout the whole chain.

Comment 73

[Andreas Pehrson [:pehrsons]]

Attachment: Part 1. now registering outputs on stream setup.

JW, here is Part 1 with fixes for your first comments, plus we're now registering the outputs on stream setup instead of when tracks are added.

It's really what was tested here: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=4ae12c82ec58

Comment 74

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

Comment on attachment 8503061 [details] [diff] [review]
Part 2. Add mochitest (carries r=roc)

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

::: content/media/test/test_bug879717.html
@@ +26,5 @@
> +  } catch (e) {
> +    exception = e;
> +    exceptionName = e.name;
> +  }
> +  ok(exception === null || video.ended,

You're right, we should be able to get an image when the video has ended.

Comment 75

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8505364 [details] [diff] [review]
Part 1. now registering outputs on stream setup.

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

::: content/html/content/src/HTMLMediaElement.cpp
@@ +2992,4 @@
>    NS_ASSERTION(!mSuspendedAfterFirstFrame, "Should not have already suspended");
>  
>    ChangeDelayLoadStatus(false);
> +  UpdateReadyStateForData(NEXT_FRAME_UNAVAILABLE);

This is already done in HTMLMediaElement::StreamListener::DoNotifyHaveCurrentData().

@@ +3165,4 @@
>      return;
>    }
>  
> +  if (!mHasAudio && !mHasVideo) {

Shouldn't we go back to HAVE_METADATA when no tracks are available?

@@ +3174,5 @@
> +    }
> +    return;
> +  }
> +
> +  CheckAutoplayDataReady();

CheckAutoplayDataReady() is already called in ChangeReadyState(). Why do we need one here?

@@ +3183,5 @@
>    }
>  
> +  if (mReadyState < nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA && mHasVideo) {
> +    VideoFrameContainer* container = GetVideoFrameContainer();
> +    if (container && mMediaSize == nsIntSize(-1,-1)) {

We should only check |mMediaSize| here. We don't want to advance when |mMediaSize == nsIntSize(-1,-1)| no matter we have a video container or not.

Comment 76

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #75)
> Comment on attachment 8505364 [details] [diff] [review]
> Part 1. now registering outputs on stream setup.
> 
> Review of attachment 8505364 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: content/html/content/src/HTMLMediaElement.cpp
> @@ +2992,4 @@
> >    NS_ASSERTION(!mSuspendedAfterFirstFrame, "Should not have already suspended");
> >  
> >    ChangeDelayLoadStatus(false);
> > +  UpdateReadyStateForData(NEXT_FRAME_UNAVAILABLE);
> 
> This is already done in
> HTMLMediaElement::StreamListener::DoNotifyHaveCurrentData().

You are right, done.

> @@ +3165,4 @@
> >      return;
> >    }
> >  
> > +  if (!mHasAudio && !mHasVideo) {
> 
> Shouldn't we go back to HAVE_METADATA when no tracks are available?

As noted before we don't handle removed tracks here. File a new bug for that?

> @@ +3174,5 @@
> > +    }
> > +    return;
> > +  }
> > +
> > +  CheckAutoplayDataReady();
> 
> CheckAutoplayDataReady() is already called in ChangeReadyState(). Why do we
> need one here?

I'm not sure we do. I'll remove it and see how it goes.

> @@ +3183,5 @@
> >    }
> >  
> > +  if (mReadyState < nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA && mHasVideo) {
> > +    VideoFrameContainer* container = GetVideoFrameContainer();
> > +    if (container && mMediaSize == nsIntSize(-1,-1)) {
> 
> We should only check |mMediaSize| here. We don't want to advance when
> |mMediaSize == nsIntSize(-1,-1)| no matter we have a video container or not.

Good point!

Comment 77

[Andreas Pehrson [:pehrsons]]

Analysis for why test_streams_autoplay.html is failing:

Based on data from this try run (logging patch is here as well): https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=c92d61d1909d

---

From the log at http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/6d3bcc064fd0a745e903fe0275832727fef32744264e73fefb2798d116d98ec68f4f20cf3b211260a7c6c87e5e6ee164c286e4ce9f9dd0ea0f0706348f73cdd6

11:00:38.927 I/GeckoDump ⰲ겿{"action":"test_start","time":1413457238922,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/content/media/test/test_streams_autoplay.html"}ⰲ겿

11:00:40.527 I/Gecko ##### 3097732 Changing ready state to 1  <-HAVE_METADATA
* VideoFrameContainer has been set as output on stream
* StreamListener registered

11:00:40.837 I/Gecko ##### 3098050 Stream has current data
* TrackUnionStream has current data, but it doesn't have tracks yet
* Start of StreamListener::DoNotifyHaveCurrentData

11:00:40.847 I/Gecko ##### 3098050 Got next frame status 3    <-UNAVAILABLE
* FirstFrameLoaded called by StreamListener::DoNotifyHaveCurrentData

11:00:40.847 I/Gecko ##### 3098052 Got next frame status 1    <-UNAVAILABLE_BUFFERING
* MediaStream::AddListener dispatched to graph thread, reporting stream blocked

11:00:40.847 I/Gecko ##### 3098053 Stream has outgoing output <-DoNotifyOutput mainthread
* End of StreamListener::DoNotifyHaveCurrentData

11:00:40.917 I/Gecko ##### 3098120 Got next frame status 1    <-UNAVAILABLE_BUFFERING
* Tracks available

11:00:40.937 I/Gecko ##### 3098148 Stream has incoming output <-NotifyOutput graphthread
11:00:40.947 I/Gecko ##### 3098159 Stream has incoming output <-NotifyOutput graphthread
11:00:40.967 I/Gecko ##### 3098170 Stream has incoming output <-NotifyOutput graphthread
11:00:40.977 I/Gecko ##### 3098182 Stream has incoming output <-NotifyOutput graphthread
11:00:40.987 I/Gecko ##### 3098193 Stream has incoming output <-NotifyOutput graphthread
11:00:40.997 I/Gecko ##### 3098205 Stream has incoming output <-NotifyOutput graphthread
11:00:41.007 I/Gecko ##### 3098216 Stream has incoming output <-NotifyOutput graphthread
11:00:41.017 I/Gecko ##### 3098229 Stream has incoming output <-NotifyOutput graphthread
11:00:41.037 I/Gecko ##### 3098240 Stream has incoming output <-NotifyOutput graphthread
11:00:41.047 I/Gecko ##### 3098252 Stream has incoming output <-NotifyOutput graphthread
11:00:41.057 I/Gecko ##### 3098263 Stream has incoming output <-NotifyOutput graphthread
11:00:41.077 I/Gecko ##### 3098285 Stream has incoming output <-NotifyOutput graphthread
11:00:41.087 I/Gecko ##### 3098299 Stream has incoming output <-NotifyOutput graphthread
11:00:41.117 I/Gecko ##### 3098328 Stream has incoming output <-NotifyOutput graphthread
11:00:41.137 I/Gecko ##### 3098341 Stream has incoming output <-NotifyOutput graphthread
11:00:41.147 I/Gecko ##### 3098355 Stream has incoming output <-NotifyOutput graphthread
11:00:41.157 I/Gecko ##### 3098366 Stream has incoming output <-NotifyOutput graphthread
11:00:41.178 I/Gecko ##### 3098384 Stream has incoming output <-NotifyOutput graphthread
11:00:41.187 I/Gecko ##### 3098400 Stream has incoming output <-NotifyOutput graphthread
11:00:41.208 I/Gecko ##### 3098413 Stream has incoming output <-NotifyOutput graphthread
11:00:41.217 I/Gecko ##### 3098426 Stream has incoming output <-NotifyOutput graphthread
11:00:41.228 I/Gecko ##### 3098439 Stream has incoming output <-NotifyOutput graphthread
11:00:41.238 I/Gecko ##### 3098450 Stream has incoming output <-NotifyOutput graphthread
11:00:41.617 I/Gecko ##### 3098820 Got next frame status 0    <-AVAILABLE (stream unblocked)
11:00:41.617 I/Gecko ##### 3098821 Stream has outgoing output <-DoNotifyOutput mainthread
11:00:41.617 I/Gecko ##### 3098823 Got next frame status 1    <-UNAVAILABLE
11:00:41.617 I/Gecko ##### 3098823 Got next frame status 0    <-AVAILABLE
11:00:41.617 I/Gecko ##### 3098824 Got next frame status 1    <-UNAVAILABLE
11:00:41.617 I/Gecko ##### 3098825 Got next frame status 0    <-AVAILABLE
11:00:41.617 I/Gecko ##### 3098826 Got next frame status 1    <-UNAVAILABLE
11:00:41.617 I/Gecko ##### 3098826 Got next frame status 0    <-AVAILABLE
11:00:41.617 I/Gecko ##### 3098827 Got next frame status 1    <-UNAVAILABLE
11:00:41.617 I/Gecko ##### 3098827 Got next frame status 0    <-AVAILABLE
11:00:41.617 I/Gecko ##### 3098828 Got next frame status 1    <-UNAVAILABLE
11:00:41.627 I/Gecko ##### 3098833 Updated media size         <-First VideoFrameContainer::SetCurrentFrame
11:00:41.627 I/Gecko ##### 3098834 Got next frame status 1    <-UNAVAILABLE called by UpdateMediaSize
11:00:41.627 I/Gecko ##### 3098834 Changing ready state to 2  <-HAVE_CURRENT_DATA since we now have a frame
<-No more notifications :(
11:05:45.487 I/GeckoDump ⰲ겿{"action":"test_status","time":1413457545485,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/content/media/test/test_streams_autoplay.html","subtest":"Test timed out.","status":"FAIL","expected":"PASS"}ⰲ겿

---

To me it looks like we get the first frame out of the stream (into the VideoFrameContainer which updates our media size and advances the state machine).

With all the blocking/unblocking events coming on the same millisecond, it looks to me like the CPU was busy processing data and didn't have time to switch to the main thread to handle the events until it's played all of video1 and can flush all the events at once.

My patch clearly fixed a bug where we previously advanced to HAVE_CURRENT_DATA (and thus HAVE_ENOUGH_DATA); that seemed to have unrolled performance issues on the B2G emulator.

Gentlemen, any suggestions for fixes?

Comment 78

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8505364 [details] [diff] [review]
Part 1. now registering outputs on stream setup.

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

Tips: click [review] to add comments instead of replay. It is easier to associate comments with code snippets.

::: content/html/content/src/HTMLMediaElement.cpp
@@ +3165,4 @@
>      return;
>    }
>  
> +  if (!mHasAudio && !mHasVideo) {

Without considering track removal, it still doesn't make sense to get a video frame before any tracks are available.

Comment 79

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #77)
Since each change in the stream in the MSG thread will queue an event in the main thread, the ready state should go through all the changes intended by the changes in MSG thread even if CPU is busy and slow in context switch. The changes are propagated from MSG thread to the main thread in a slow fashion but not a lossy way, right?

Comment 80

[Andreas Pehrson [:pehrsons]]

Yes, you're right. However, the VideoFrameContainer::Invalidate calls are queued up in a different manner. I haven't yet figured out why they are called after all the MSG events, even though they were dispatched before some of them. Any ideas?

Comment 81

[Andreas Pehrson [:pehrsons]]

Further analysis: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=c4d9c74b99f6

@@@@@ = MSG thread
##### = main thread

---

00:13:11.387: ⰲ겿{"action":"test_start","time":1413504791387,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/content/media/test/test_streams_autoplay.html"}ⰲ겿
00:13:13.148: ##### Media element with stream is 0x4320dca0
00:13:13.148: ##### Changing ready state to HAVE_METADATA
00:13:13.158: ##### Autoplaying
00:13:13.167: ##### Dispatching AddVideoOutput
00:13:13.187: @@@@@ Dispatching DoNotifyBlocked
00:13:13.198: @@@@@ Calling AddVideoOutput
00:13:13.357: @@@@@ Dispatching DoNotifyHaveCurrentData
00:13:13.487: ##### Calling DoNotifyBlocked
00:13:13.487: ##### Calling DoNotifyHaveCurrentData
00:13:13.497: ##### Got next frame status UNAVAILABLE_BUFFERING
00:13:13.497: ##### Calling DoNotifyOutput
00:13:13.497: ##### Calling VideoFrameContainer::Invalidate for media element 0x4320db40 <- video1
00:13:13.577: ##### Got next frame status UNAVAILABLE_BUFFERING
00:13:13.587: @@@@@ Dispatching VideoFrameContainer::Invalidate
00:13:13.597: @@@@@ Dispatching DoNotifyUnblocked
00:13:13.597: @@@@@ Dispatching DoNotifyOutput
00:13:13.627: @@@@@ Dispatching VideoFrameContainer::Invalidate
00:13:13.657: @@@@@ Dispatching VideoFrameContainer::Invalidate
00:13:13.707: @@@@@ Dispatching VideoFrameContainer::Invalidate
00:13:13.727: @@@@@ Dispatching VideoFrameContainer::Invalidate
00:13:13.767: @@@@@ Dispatching DoNotifyBlocked
00:13:13.767: @@@@@ Dispatching VideoFrameContainer::Invalidate
00:13:13.787: @@@@@ Dispatching DoNotifyUnblocked
00:13:13.817: @@@@@ Dispatching DoNotifyBlocked
00:13:13.837: @@@@@ Dispatching DoNotifyUnblocked
00:13:13.837: @@@@@ Dispatching VideoFrameContainer::Invalidate
00:13:13.867: @@@@@ Dispatching DoNotifyBlocked
00:13:13.898: @@@@@ Dispatching VideoFrameContainer::Invalidate
00:13:13.908: @@@@@ Dispatching DoNotifyUnblocked
00:13:13.938: @@@@@ Dispatching DoNotifyBlocked
00:13:14.407: ##### Calling DoNotifyUnblocked
00:13:14.407: ##### Got next frame status AVAILABLE
00:13:14.407: ##### Calling DoNotifyOutput
00:13:14.407: ##### Calling DoNotifyBlocked
00:13:14.417: ##### Got next frame status UNAVAILABLE_BUFFERING
00:13:14.417: ##### Calling DoNotifyUnblocked
00:13:14.417: ##### Got next frame status AVAILABLE
00:13:14.427: ##### Calling DoNotifyBlocked
00:13:14.427: ##### Got next frame status UNAVAILABLE_BUFFERING
00:13:14.427: ##### Calling DoNotifyUnblocked
00:13:14.427: ##### Got next frame status AVAILABLE
00:13:14.427: ##### Calling DoNotifyBlocked
00:13:14.427: ##### Got next frame status UNAVAILABLE_BUFFERING
00:13:14.427: ##### Calling DoNotifyUnblocked
00:13:14.427: ##### Got next frame status AVAILABLE
00:13:14.427: ##### Calling DoNotifyBlocked
00:13:14.427: ##### Got next frame status UNAVAILABLE_BUFFERING
00:13:14.437: ##### Calling VideoFrameContainer::Invalidate for media element 0x4320dca0 <- video2
00:13:14.447: ##### Calling UpdateMediaSize with size 320x240
00:13:14.447: ##### Got next frame status UNAVAILABLE_BUFFERING
00:13:14.447: ##### Changing ready state to HAVE_CURRENT_DATA
00:13:14.447: ##### Calling VideoFrameContainer::Invalidate for media element 0x4320db40
00:13:14.457: ##### Calling VideoFrameContainer::Invalidate for media element 0x4320dca0
00:13:14.457: ##### Calling VideoFrameContainer::Invalidate for media element 0x4320dca0
00:13:14.457: ##### Calling VideoFrameContainer::Invalidate for media element 0x4320dca0
00:13:14.467: ##### Calling VideoFrameContainer::Invalidate for media element 0x4320dca0
00:13:14.467: ##### Calling VideoFrameContainer::Invalidate for media element 0x4320dca0
00:13:14.477: ##### Calling VideoFrameContainer::Invalidate for media element 0x4320dca0
00:13:14.477: ##### Calling VideoFrameContainer::Invalidate for media element 0x4320dca0
00:13:14.497: ##### Calling VideoFrameContainer::Invalidate for media element 0x4320db40
00:13:14.497: ##### Calling VideoFrameContainer::Invalidate for media element 0x4320db40
00:13:14.527: ##### Decoder playback ended                                                                                                                                                                                                                                                                             
00:18:14.257: ⰲ겿{"action":"test_status","time":1413505094243,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/content/media/test/test_streams_autoplay.html","subtest":"Test timed out.","status":"FAIL","expected":"PASS"}ⰲ겿

Comment 82

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #78)
> Comment on attachment 8505364 [details] [diff] [review]
> Part 1. now registering outputs on stream setup.
> 
> Review of attachment 8505364 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Tips: click [review] to add comments instead of replay. It is easier to
> associate comments with code snippets.
> 
> ::: content/html/content/src/HTMLMediaElement.cpp
> @@ +3165,4 @@
> >      return;
> >    }
> >  
> > +  if (!mHasAudio && !mHasVideo) {
> 
> Without considering track removal, it still doesn't make sense to get a
> video frame before any tracks are available.

That's the observation I have made on my machine. It's basically the opposite of what we're seeing on the B2G emulator (invalidate calls here skips ahead of other queued events), so probably related.

Comment 83

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #80)
> Yes, you're right. However, the VideoFrameContainer::Invalidate calls are
> queued up in a different manner. I haven't yet figured out why they are
> called after all the MSG events, even though they were dispatched before
> some of them. Any ideas?

That's the problem we are facing. Some events are dispatched to the main thread by NS_DispatchToMainThread, but others are by MediaStreamGraph::DispatchToMainThreadAfterStreamStateUpdate. Therefore, events get disordered after they arrive the main thread.

I wonder if we can just use NS_DispatchToMainThread in HTMLMediaElement::StreamListener::NotifyEvent() to solve the disorder. I can't see how stable state is relevant here.

Comment 84

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #83)
> (In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #80)
> > Yes, you're right. However, the VideoFrameContainer::Invalidate calls are
> > queued up in a different manner. I haven't yet figured out why they are
> > called after all the MSG events, even though they were dispatched before
> > some of them. Any ideas?
> 
> That's the problem we are facing. Some events are dispatched to the main
> thread by NS_DispatchToMainThread, but others are by
> MediaStreamGraph::DispatchToMainThreadAfterStreamStateUpdate. Therefore,
> events get disordered after they arrive the main thread.
> 
> I wonder if we can just use NS_DispatchToMainThread in
> HTMLMediaElement::StreamListener::NotifyEvent() to solve the disorder. I
> can't see how stable state is relevant here.

We only care about EVENT_FINISHED in HTMLMediaElement::StreamListener::NotifyEvent(). Do you mean to do it for all the StreamListener::Notify* methods?

Comment 85

[JW Wang [:jwwang] [:jw_wang]]

Yes, all of them. Since any of them will cause event disorder.

Comment 86

[Andreas Pehrson [:pehrsons]]

Attachment: Option 1: Invalidate stream video frames synchronously

I made three patches to the dispatching strategy. They all make test_streams_autoplay pass on the B2G ICS emulator, but behave a bit differently.

Any preference on which to take?

---

This is the first patch. Here we synchronously dispatch VideoFrameContainer::Invalidate to the main thread from MSG.

This gives us the least amount of state changes before the test passes, but does the sync dispatch also mean that we process all previously queued events on the main thread before MSG can continue?

Test: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=5cc127d786df

Output from http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/b9aa838b2b37f5c9f656ee3f48c5782e9d09dffad0eec0c41a87d390873dc6fd4bfe9930bbae505850c7871a823416b3d07adae452dee75f8f50079efda7e28f:
10:20:20.350 : ⰲ겿{"action":"test_start","time":1413541220354,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/content/media/test/test_streams_autoplay.html"}ⰲ겿
10:20:22.160 : ##### Media element with stream is 0x432ec5c0
10:20:22.160 : ##### Changing ready state to HAVE_METADATA 
10:20:22.170 : ##### Autoplaying
10:20:22.180 : ##### Dispatching AddVideoOutput
10:20:22.190 : @@@@@ Dispatching DoNotifyBlocked
10:20:22.200 : @@@@@ Calling AddVideoOutput
10:20:22.370 : @@@@@ Dispatching DoNotifyHaveCurrentData
10:20:22.500 : ##### Calling DoNotifyBlocked
10:20:22.500 : ##### Calling DoNotifyHaveCurrentData
10:20:22.500 : ##### Got next frame status UNAVAILABLE_BUFFERING
10:20:22.500 : ##### Calling DoNotifyOutput
10:20:22.500 : ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec300
10:20:22.580 : ##### Got next frame status UNAVAILABLE_BUFFERING
10:20:22.590 : @@@@@ Dispatching VideoFrameContainer::Invalidate
10:20:23.021 : ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec5c0 <- Synchronously dispatched
10:20:23.021 : ##### Calling UpdateMediaSize with size 320x240
10:20:23.030 : ##### Got next frame status UNAVAILABLE_BUFFERING
10:20:23.030 : ##### Changing ready state to HAVE_CURRENT_DATA
10:20:23.030 : @@@@@ Dispatching DoNotifyUnblocked
10:20:23.030 : @@@@@ Dispatching DoNotifyOutput
10:20:23.040 : @@@@@ Dispatching VideoFrameContainer::Invalidate
10:20:23.150 : ##### Calling DoNotifyUnblocked
10:20:23.150 : ##### Got next frame status AVAILABLE 
10:20:23.150 : ##### Changing ready state to HAVE_ENOUGH_DATA <- playing
10:20:23.150 : ##### Calling DoNotifyOutput
10:20:23.220 : ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec5c0
10:20:23.220 : @@@@@ Dispatching DoNotifyOutput
10:20:23.230 : @@@@@ Dispatching VideoFrameContainer::Invalidate
10:20:23.240 : ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec300
10:20:23.370 : ⰲ겿{"action":"test_status","time":1413541223344,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/content/media/test/test_streams_autoplay.html","subtest":"playback started","status":"PASS"}ⰲ겿

Comment 87

[Andreas Pehrson [:pehrsons]]

Attachment: Option 2: Invalidate stream video frames in the regular stream state event queue

Dispatching VideoFrameContainer::Invalidate in the same way as the HTMLMediaElement::StreamListener events.

Test: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=edb558ff0665

Output from http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/cc2cf1384a2f7b94fc052196d5bb6e810a0816379e9c41dadd3e6cf10416696ba6d0919a510102892078d3a5b12aeaf1301b201ab2890aecf238ea23e7c3bba6:
10:20:19.635: ⰲ겿{"action":"test_start","time":1413541219631,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/content/media/test/test_streams_autoplay.html"}ⰲ겿
10:20:21.474: ##### Media element with stream is 0x432ec880
10:20:21.474: ##### Changing ready state to HAVE_METADATA
10:20:21.484: ##### Autoplaying 
10:20:21.494: ##### Dispatching AddVideoOutput
10:20:21.504: @@@@@ Dispatching DoNotifyBlocked
10:20:21.524: @@@@@ Calling AddVideoOutput
10:20:21.694: @@@@@ Dispatching DoNotifyHaveCurrentData
10:20:21.804: ##### Calling DoNotifyBlocked
10:20:21.804: ##### Calling DoNotifyHaveCurrentData
10:20:21.804: ##### Got next frame status UNAVAILABLE_BUFFERING
10:20:21.804: ##### Calling DoNotifyOutput
10:20:21.804: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec720
10:20:21.894: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:20:21.904: @@@@@ Dispatching DoNotifyUnblocked 
10:20:21.904: @@@@@ Dispatching DoNotifyOutput
10:20:21.925: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:20:21.965: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:20:21.995: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:20:22.035: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:20:22.045: @@@@@ Dispatching DoNotifyBlocked
10:20:22.045: @@@@@ Dispatching DoNotifyUnblocked 
10:20:22.085: @@@@@ Dispatching DoNotifyBlocked
10:20:22.085: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:20:22.095: @@@@@ Dispatching DoNotifyUnblocked 
10:20:22.125: @@@@@ Dispatching DoNotifyBlocked
10:20:22.125: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:20:22.135: @@@@@ Dispatching DoNotifyUnblocked 
10:20:22.174: @@@@@ Dispatching DoNotifyBlocked
10:20:22.174: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:20:22.195: @@@@@ Dispatching DoNotifyUnblocked 
10:20:22.224: @@@@@ Dispatching DoNotifyBlocked
10:20:22.274: ##### Got next frame status UNAVAILABLE_BUFFERING
10:20:22.344: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec880
10:20:22.344: ##### Calling UpdateMediaSize with size 320x240 
10:20:22.344: ##### Got next frame status UNAVAILABLE_BUFFERING
10:20:22.344: ##### Changing ready state to HAVE_CURRENT_DATA 
10:20:22.344: ##### Calling DoNotifyUnblocked 
10:20:22.344: ##### Got next frame status AVAILABLE
10:20:22.344: ##### Changing ready state to HAVE_ENOUGH_DATA <- playing emitted for test PASS
10:20:22.344: ##### Calling DoNotifyOutput
10:20:22.354: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec880
10:20:22.354: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec880
10:20:22.354: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec880
10:20:22.354: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec880
10:20:22.354: ##### Calling DoNotifyBlocked
10:20:22.354: ##### Got next frame status UNAVAILABLE_BUFFERING
10:20:22.364: ##### Changing ready state to HAVE_CURRENT_DATA 
10:20:22.364: ##### Calling DoNotifyUnblocked 
10:20:22.364: ##### Got next frame status AVAILABLE
10:20:22.364: ##### Changing ready state to HAVE_ENOUGH_DATA
10:20:22.374: ##### Calling DoNotifyBlocked
10:20:22.374: ##### Got next frame status UNAVAILABLE_BUFFERING
10:20:22.374: ##### Changing ready state to HAVE_CURRENT_DATA 
10:20:22.374: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec880
10:20:22.374: ##### Calling DoNotifyUnblocked 
10:20:22.374: ##### Got next frame status AVAILABLE
10:20:22.374: ##### Changing ready state to HAVE_ENOUGH_DATA
10:20:22.374: ##### Calling DoNotifyBlocked
10:20:22.374: ##### Got next frame status UNAVAILABLE_BUFFERING
10:20:22.374: ##### Changing ready state to HAVE_CURRENT_DATA 
10:20:22.384: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec880
10:20:22.384: ##### Calling DoNotifyUnblocked 
10:20:22.384: ##### Got next frame status AVAILABLE
10:20:22.384: ##### Changing ready state to HAVE_ENOUGH_DATA
10:20:22.384: ##### Calling DoNotifyBlocked
10:20:22.384: ##### Got next frame status UNAVAILABLE_BUFFERING
10:20:22.384: ##### Changing ready state to HAVE_CURRENT_DATA 
10:20:22.394: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec880
10:20:22.394: ##### Calling DoNotifyUnblocked 
10:20:22.394: ##### Got next frame status AVAILABLE
10:20:22.394: ##### Changing ready state to HAVE_ENOUGH_DATA
10:20:22.394: ##### Calling DoNotifyBlocked
10:20:22.394: ##### Got next frame status UNAVAILABLE_BUFFERING
10:20:22.394: ##### Changing ready state to HAVE_CURRENT_DATA 
10:20:22.694: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ec720                                                                                                                                                                                                                                      
10:20:22.764: ⰲ겿{"action":"test_status","time":1413541222755,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/content/media/test/test_streams_autoplay.html","subtest":"playback started","status":"PASS"}ⰲ겿

Comment 88

[Andreas Pehrson [:pehrsons]]

Attachment: Option 3: Dispatch HTMLMediaElement stream events directly to main thread

Dispatch HTMLMediaElement::StreamListener events directly to main thread. Per JW's suggestion.

Test: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=0a292f824970

Output from http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/a48fffcbb1aa709689dc07b33e863e4dc6030b98ec09e90868c1f3941fc9262029a31592d065633e85d4f269d73cf08b54b801b72d6162f9d870d5f845c46e1d:
10:19:22.525: ⰲ겿{"action":"test_start","time":1413541162525,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/content/media/test/test_streams_autoplay.html"}ⰲ겿
10:19:24.065: ##### Media element with stream is 0x432ed640
10:19:24.065: ##### Changing ready state to HAVE_METADATA
10:19:24.075: ##### Autoplaying 
10:19:24.085: ##### Dispatching AddVideoOutput
10:19:24.095: @@@@@ Dispatching DoNotifyBlocked
10:19:24.105: @@@@@ Calling AddVideoOutput
10:19:24.296: @@@@@ Dispatching DoNotifyHaveCurrentData
10:19:24.336: ##### Calling DoNotifyBlocked
10:19:24.445: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ed380
10:19:24.505: ##### Got next frame status UNINITIALIZED
10:19:24.505: ##### Calling DoNotifyHaveCurrentData
10:19:24.505: ##### Got next frame status UNAVAILABLE_BUFFERING
10:19:24.505: ##### Calling DoNotifyOutput
10:19:24.525: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:19:24.535: @@@@@ Dispatching DoNotifyUnblocked 
10:19:24.535: @@@@@ Dispatching DoNotifyOutput
10:19:24.556: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:19:24.595: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:19:24.625: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:19:24.666: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:19:24.706: @@@@@ Dispatching DoNotifyBlocked
10:19:24.706: @@@@@ Dispatching DoNotifyUnblocked 
10:19:24.706: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:19:24.765: @@@@@ Dispatching DoNotifyBlocked
10:19:24.805: @@@@@ Dispatching DoNotifyUnblocked 
10:19:24.805: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:19:24.815: @@@@@ Dispatching VideoFrameContainer::Invalidate
10:19:24.845: @@@@@ Dispatching DoNotifyBlocked
10:19:25.306: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ed640
10:19:25.306: ##### Calling UpdateMediaSize with size 320x240 
10:19:25.306: ##### Got next frame status UNAVAILABLE_BUFFERING
10:19:25.306: ##### Changing ready state to HAVE_CURRENT_DATA 
10:19:25.316: ##### Calling DoNotifyUnblocked 
10:19:25.316: ##### Got next frame status AVAILABLE
10:19:25.316: ##### Changing ready state to HAVE_ENOUGH_DATA <- playing emitted for test PASS
10:19:25.316: ##### Calling DoNotifyOutput
10:19:25.316: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ed640
10:19:25.316: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ed380
10:19:25.326: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ed640
10:19:25.326: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ed640
10:19:25.326: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ed640
10:19:25.326: ##### Calling DoNotifyBlocked
10:19:25.326: ##### Got next frame status UNAVAILABLE_BUFFERING
10:19:25.326: ##### Changing ready state to HAVE_CURRENT_DATA 
10:19:25.336: ##### Calling DoNotifyUnblocked 
10:19:25.336: ##### Got next frame status AVAILABLE
10:19:25.336: ##### Changing ready state to HAVE_ENOUGH_DATA
10:19:25.336: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ed640
10:19:25.336: ##### Calling DoNotifyBlocked
10:19:25.336: ##### Got next frame status UNAVAILABLE_BUFFERING
10:19:25.336: ##### Changing ready state to HAVE_CURRENT_DATA 
10:19:25.346: ##### Calling DoNotifyUnblocked 
10:19:25.346: ##### Got next frame status AVAILABLE
10:19:25.346: ##### Changing ready state to HAVE_ENOUGH_DATA
10:19:25.346: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ed640
10:19:25.346: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ed640
10:19:25.346: ##### Calling DoNotifyBlocked
10:19:25.346: ##### Got next frame status UNAVAILABLE_BUFFERING
10:19:25.346: ##### Changing ready state to HAVE_CURRENT_DATA 
10:19:25.415: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ed380
10:19:25.415: ##### Calling VideoFrameContainer::Invalidate for media element 0x432ed380
10:19:25.449: ##### Decoder playback ended                                                                                                                                                                                                                                                                                    
10:19:25.515: ⰲ겿{"action":"test_status","time":1413541165517,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/content/media/test/test_streams_autoplay.html","subtest":"playback started","status":"PASS"}ⰲ겿

Comment 89

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 8506853 [details] [diff] [review]
Option 1: Invalidate stream video frames synchronously

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

No way can we block MSG on MainThread (which may stall us for 100's of ms)

Comment 90

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

Comment on attachment 8506856 [details] [diff] [review]
Option 2: Invalidate stream video frames in the regular stream state event queue

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

This looks good.

-U8 diffs please

Comment 91

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

Comment on attachment 8506858 [details] [diff] [review]
Option 3: Dispatch HTMLMediaElement stream events directly to main thread

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

This looks a bit scary

Comment 92

[Andreas Pehrson [:pehrsons]]

Attachment: Part 1. Invalidate stream video frames in the regular stream state event queue (carries r=roc)

Comment 93

[Andreas Pehrson [:pehrsons]]

Attachment: Part 1. Invalidate stream video frames in the regular stream state event queue (carries r=roc)

Ok, now with -U8.

Comment 94

[Andreas Pehrson [:pehrsons]]

Attachment: Part 1. Invalidate stream video frames in the regular stream state event queue

This also changes the track logic in DOMMediaStream to dispatch the tracks available callback after stream state update.

It is not strictly necessary for this patch, but if ready state will ever depend on tracks availability it will cause problems with events arriving out of order, like we saw with the invalidate calls.

Comment 95

[Andreas Pehrson [:pehrsons]]

Attachment: Part 2. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container

Slightly simplified now after the disordered events were fixed. Should also address JW's review feedback.

Comment 96

[Andreas Pehrson [:pehrsons]]

Attachment: Part 3. Don't report HaveCurrentData when there are no input streams to TrackUnionStream

Without this, TrackUnionStream reports HAVE_CURRENT_DATA before it has any tracks, hence also before it has any data on any of those tracks.

That puts us in HAVE_CURRENT_DATA before a video frame is available, so that 2dContext.drawImage() throws an exception like in the description.

Comment 97

[Andreas Pehrson [:pehrsons]]

Attachment: Part 4. Add mochitest

Now testing drawImage() on more events than before. It even helped me find an issue during all the debugging and reworking of patches that I was doing earlier, that the old test didn't catch.

Comment 98

[Andreas Pehrson [:pehrsons]]

Attachment: Part 5. Fix camera preview stream and wake locks from lock screen (carries r=roc)

Simple rebase and commit message fix.

Comment 99

[Andreas Pehrson [:pehrsons]]

Everything looks good with this set. I hope we can land this once and for all soon.

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=15f6370594c7

Comment 100

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

Comment on attachment 8507924 [details] [diff] [review]
Part 2. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container

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

::: content/html/content/src/HTMLMediaElement.cpp
@@ +2877,5 @@
> +
> +  MediaInfo mediaInfo;
> +  mediaInfo.mAudio.mHasAudio = mHasAudio;
> +  mediaInfo.mVideo.mHasVideo = mHasVideo;
> +  MetadataLoaded(&mediaInfo, nullptr);

Should we delay firing MetadataLoaded until we've received tracks?

Comment 101

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8507942 [details] [diff] [review]
Part 4. Add mochitest

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

::: content/media/test/test_bug879717.html
@@ +9,5 @@
> +<body>
> +<video id="v1" autoplay></video>
> +<video id="v2" autoplay></video>
> +<canvas id="c1"></canvas>
> +<canvas id="c2"></canvas>

Can't we have one canvas only and reuse it?

@@ +14,5 @@
> +<pre id="test">
> +<script class="testbody" type="text/javascript">
> +SimpleTest.waitForExplicitFinish();
> +
> +var media = getPlayableVideo(gSmallTests);

I have experience where some test passed with one file but failed with another. I would prefer to employ MediaTestManager to loop through all files of gSmallTests to increase the test coverage.

Comment 102

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8507924 [details] [diff] [review]
Part 2. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container

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

LGTM.

Comment 103

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8507942 [details] [diff] [review]
Part 4. Add mochitest

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

::: content/media/test/test_bug879717.html
@@ +42,5 @@
> +
> +  checkDrawImage("beforeplay", v1, c1, media.name);
> +  checkDrawImage("beforeplay", v2, c2, "Stream of " + media.name);
> +  v1.onloadedmetadata = checkDrawImageFunction("loadedmetadata", v1, c1, media.name);
> +  v2.onloadedmetadata = checkDrawImageFunction("loadedmetadata", v2, c2, "Stream of " + media.name);

'loadedmetadata' doesn't guarantee readyState >= HAVE_CURRENT_DATA. You should listener to 'loadeddata'.

Comment 104

[Andreas Pehrson [:pehrsons]]

Comment on attachment 8507942 [details] [diff] [review]
Part 4. Add mochitest

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

::: content/media/test/test_bug879717.html
@@ +9,5 @@
> +<body>
> +<video id="v1" autoplay></video>
> +<video id="v2" autoplay></video>
> +<canvas id="c1"></canvas>
> +<canvas id="c2"></canvas>

Sure.

@@ +14,5 @@
> +<pre id="test">
> +<script class="testbody" type="text/javascript">
> +SimpleTest.waitForExplicitFinish();
> +
> +var media = getPlayableVideo(gSmallTests);

Will do.

@@ +48,5 @@
> +  v2.onplay = checkDrawImageFunction("play", v2, c2, "Stream of " + media.name);
> +  v1.onplaying = checkDrawImageFunction("playing", v1, c1, media.name);
> +  v2.onplaying = checkDrawImageFunction("playing", v2, c2, "Stream of " + media.name);
> +  v1.onloadeddata = checkDrawImageFunction("loadeddata", v1, c1, media.name);
> +  v2.onloadeddata = checkDrawImageFunction("loadeddata", v2, c2, "Stream of " + media.name);

'loadeddata' is here.

Comment 105

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8507942 [details] [diff] [review]
Part 4. Add mochitest

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

::: content/media/test/test_bug879717.html
@@ +48,5 @@
> +  v2.onplay = checkDrawImageFunction("play", v2, c2, "Stream of " + media.name);
> +  v1.onplaying = checkDrawImageFunction("playing", v1, c1, media.name);
> +  v2.onplaying = checkDrawImageFunction("playing", v2, c2, "Stream of " + media.name);
> +  v1.onloadeddata = checkDrawImageFunction("loadeddata", v1, c1, media.name);
> +  v2.onloadeddata = checkDrawImageFunction("loadeddata", v2, c2, "Stream of " + media.name);

Weird. How do the tests in loadedmetadata pass when readyState is only HAVE_METADATA?

@@ +72,5 @@
> +    }
> +  };
> +
> +  v1.src = media.name;
> +  v2.mozSrcObject = v1.mozCaptureStreamUntilEnded();

I think we can add a 3rd video element to test the file case to ensure the changes apply to both stream and file case.

Comment 106

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #105)
> Comment on attachment 8507942 [details] [diff] [review]
> Part 4. Add mochitest
> 
> Review of attachment 8507942 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: content/media/test/test_bug879717.html
> @@ +48,5 @@
> > +  v2.onplay = checkDrawImageFunction("play", v2, c2, "Stream of " + media.name);
> > +  v1.onplaying = checkDrawImageFunction("playing", v1, c1, media.name);
> > +  v2.onplaying = checkDrawImageFunction("playing", v2, c2, "Stream of " + media.name);
> > +  v1.onloadeddata = checkDrawImageFunction("loadeddata", v1, c1, media.name);
> > +  v2.onloadeddata = checkDrawImageFunction("loadeddata", v2, c2, "Stream of " + media.name);
> 
> Weird. How do the tests in loadedmetadata pass when readyState is only
> HAVE_METADATA?

HAVE_NOTHING and HAVE_METADATA are interpreted as "Ah, the video element is still loading its content. That's fine.".
See exception here http://dxr.mozilla.org/mozilla-central/source/dom/canvas/CanvasRenderingContext2D.cpp#3922
and ready state logic here http://dxr.mozilla.org/mozilla-central/source/layout/base/nsLayoutUtils.cpp#5938

> @@ +72,5 @@
> > +    }
> > +  };
> > +
> > +  v1.src = media.name;
> > +  v2.mozSrcObject = v1.mozCaptureStreamUntilEnded();
> 
> I think we can add a 3rd video element to test the file case to ensure the
> changes apply to both stream and file case.

v1 is testing the file case and v2 the stream case.

Comment 107

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #106)
> HAVE_NOTHING and HAVE_METADATA are interpreted as "Ah, the video element is
> still loading its content. That's fine.".
> See exception here
> http://dxr.mozilla.org/mozilla-central/source/dom/canvas/
> CanvasRenderingContext2D.cpp#3922
> and ready state logic here
> http://dxr.mozilla.org/mozilla-central/source/layout/base/nsLayoutUtils.
> cpp#5938
I see.

> v1 is testing the file case and v2 the stream case.
Not quite the same. v1 is a "captured" media element while v2 is a normal media element fed by a media stream. I want a v3 which is a normal media element fed by a file to complete the test coverage.

Comment 108

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #107)
> (In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #106)
> > v1 is testing the file case and v2 the stream case.
> Not quite the same. v1 is a "captured" media element while v2 is a normal
> media element fed by a media stream. I want a v3 which is a normal media
> element fed by a file to complete the test coverage.

Oh, all right. Fixing.

Comment 109

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #101)
> Comment on attachment 8507942 [details] [diff] [review]
> Part 4. Add mochitest
> 
> Review of attachment 8507942 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: content/media/test/test_bug879717.html
> @@ +14,5 @@
> > +<pre id="test">
> > +<script class="testbody" type="text/javascript">
> > +SimpleTest.waitForExplicitFinish();
> > +
> > +var media = getPlayableVideo(gSmallTests);
> 
> I have experience where some test passed with one file but failed with
> another. I would prefer to employ MediaTestManager to loop through all files
> of gSmallTests to increase the test coverage.

Good point. It unveiled a problem when an audio track gets added first and we go to HAVE_CURRENT_DATA before the video track is added.

This has gotten a bit messy from before I realized the out-of-order events, but now that they are fixed I'll change to handle the tracks and metadata in StreamListener::DoNotifyHaveCurrentData. Then we should be guaranteed to have gotten all the tracks.

Comment 110

[Andreas Pehrson [:pehrsons]]

Attachment: Part 4. Add mochitest

Testing on 3 video elements; file, captured file and stream.
Testing all videos in gSmallTests.

Plus various simplifications in code.

Comment 111

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

Comment on attachment 8509074 [details] [diff] [review]
Part 4. Add mochitest

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

::: content/media/test/test_bug879717.html
@@ +31,5 @@
> +    " of " + videoElement.testName + ", got " + exceptionName);
> +};
> +
> +var checkDrawImageFunction = function() {
> +  return function(videoEvent) { checkDrawImage(videoEvent.type, videoEvent.target); };

Why are we returning new instances of the same function? Seems to me we could just use a single function for all the handlers.

Comment 112

[Andreas Pehrson [:pehrsons]]

Comment on attachment 8509074 [details] [diff] [review]
Part 4. Add mochitest

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

::: content/media/test/test_bug879717.html
@@ +59,5 @@
> +  v3.testName = "v3 (Stream of " + media.name + ")";
> +
> +  checkDrawImage("beforeplay", v1);
> +  checkDrawImage("beforeplay", v2);
> +  checkDrawImage("beforeplay", v3);

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #111)
> Why are we returning new instances of the same function? Seems to me we
> could just use a single function for all the handlers.

To allow for these manual calls where we fake an event.

Comment 113

[Andreas Pehrson [:pehrsons]]

Attachment: Part 2. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #100)
> Comment on attachment 8507924 [details] [diff] [review]
> Part 2. Delay entering HAVE_CURRENT_DATA state until a video frame has been
> stored in the image container
> 
> Review of attachment 8507924 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: content/html/content/src/HTMLMediaElement.cpp
> @@ +2877,5 @@
> > +
> > +  MediaInfo mediaInfo;
> > +  mediaInfo.mAudio.mHasAudio = mHasAudio;
> > +  mediaInfo.mVideo.mHasVideo = mHasVideo;
> > +  MetadataLoaded(&mediaInfo, nullptr);
> 
> Should we delay firing MetadataLoaded until we've received tracks?

That has the bi-effect of changing when we get to HAVE_METADATA since a captured media element has to be played for tracks to be added to its output stream:
http://dxr.mozilla.org/mozilla-central/source/content/media/MediaDecoderStateMachine.cpp#392

So it would change us emitting |loadedmetadata| from when the stream is set up to when the underlying stream source gets played. That breaks at least test_streams_srcObject.html: http://dxr.mozilla.org/mozilla-central/source/content/media/test/test_streams_srcObject.html#10

I added |autoplay| to its audio element but there was still something breaking it when calling |MetadataLoaded()| from |StreamListener::DoNotifyHaveCurrentData()|:
https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=a9bd048fcd44
Also note the graphics crash on windows (M-1) in test_bug879717...

---

This patch instead updates mHasAudio, mHasVideo and the ready state when the stream has current data, to fix the issue per comment 109.

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

Comment 114

[Andreas Pehrson [:pehrsons]]

Attachment: Part 4. Add mochitest

Removed the wrapping function and created fake event objects instead.

Comment 115

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8509074 [details] [diff] [review]
Part 4. Add mochitest

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

::: content/media/test/test_bug879717.html
@@ +8,5 @@
> +</head>
> +<body>
> +<pre id="test">
> +<script class="testbody" type="text/javascript">
> +SimpleTest.waitForExplicitFinish();

MediaTestManager will handle this.

@@ +39,5 @@
> +  manager.started(token);
> +
> +  // File playback
> +  var v1 = document.createElement("video");
> +  v1.setAttribute("autoplay", true);

say v1.autoplay = true.

@@ +59,5 @@
> +  v3.testName = "v3 (Stream of " + media.name + ")";
> +
> +  checkDrawImage("beforeplay", v1);
> +  checkDrawImage("beforeplay", v2);
> +  checkDrawImage("beforeplay", v3);

Then you can just have:
var checkDrawImageFunction = function(ev) {
  checkDrawImage(ev.type, ev.target);
}
v.onplay = checkDrawImageFunction;

@@ +73,5 @@
> +  v1.onplaying = checkDrawImageFunction();
> +  v2.onplaying = checkDrawImageFunction();
> +  v3.onplaying = checkDrawImageFunction();
> +
> +  v1.onloadeddata = ev => {

This coding style is different from those below. Can we have a consistent one?

@@ +95,5 @@
> +    ok(v1.gotLoadeddata, v1.testName + " should have gotten the 'loadeddata' event callback");
> +    ok(v2.gotLoadeddata, v2.testName + " should have gotten the 'loadeddata' event callback");
> +    ok(v3.gotLoadeddata, v3.testName + " should have gotten the 'loadeddata' event callback");
> +
> +    document.body.removeChild(v1);

Call removeNodeAndSource(v1) to release decoder resources right away.

@@ +126,5 @@
> +  v2.src = media.name;
> +  v3.mozSrcObject = v2.mozCaptureStreamUntilEnded();
> +}
> +
> +manager.runTests(gSmallTests.filter(t => t.type.match(/^video/)), startTest);

You can add a new function such as getPlayableVideos (as we have getPlayableVideo) to manifest.js which checks not only the major mime type but also if the video can be played by calling v.canPlayType().

Comment 116

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

Comment on attachment 8509106 [details] [diff] [review]
Part 4. Add mochitest

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

what jwwang said :-)

Comment 117

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #109)
> Good point. It unveiled a problem when an audio track gets added first and
> we go to HAVE_CURRENT_DATA before the video track is added.
Dealing with video first in MediaDecoderStateMachine::SendStreamData() should fix this problem.
 
> This has gotten a bit messy from before I realized the out-of-order events,
> but now that they are fixed I'll change to handle the tracks and metadata in
> StreamListener::DoNotifyHaveCurrentData. Then we should be guaranteed to
> have gotten all the tracks.
That should be the scope of handling dynamic track addition/removal which will be another bug as you said.

Comment 118

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8509100 [details] [diff] [review]
Part 2. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container

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

::: content/html/content/src/HTMLMediaElement.cpp
@@ +2773,5 @@
>    {
>      mHaveCurrentData = true;
>      if (mElement) {
>        nsRefPtr<HTMLMediaElement> deathGrip = mElement;
> +      mElement->NotifyMediaStreamTracksAvailable();

See comment 117. I am not a fan of this faking notification which obscures the code logic.

Comment 119

[Andreas Pehrson [:pehrsons]]

Attachment: Part 4. Add mochitest

JW's comments addressed.

Comment 120

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8509325 [details] [diff] [review]
Part 4. Add mochitest

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

Overall looks fine expect for some nits.

::: content/media/test/test_bug879717.html
@@ +29,5 @@
> +    " of " + videoElement.testName + ", got " + exceptionName);
> +};
> +
> +var checkDrawImageEventHandler = function(ev) {
> +  return checkDrawImage(ev.type, ev.target);

Does checkDrawImage return anything?

@@ +98,5 @@
> +    removeNodeAndSource(v3);
> +    manager.finished(token);
> +  };
> +
> +  v1.onended = function(ev) {

This function can be reused:
function onended(ev) {
  var v = ev.target;
  checkDrawImageEventHandler(ev);
  v.testFinished = true;
  checkFinished();
}

v1.onended = onended;
v2.onended = onended;
v3.onended = onended;

Comment 121

[Andreas Pehrson [:pehrsons]]

Attachment: Part 4. Add mochitest (carries r=roc)

Nits addressed.

Comment 122

[Andreas Pehrson [:pehrsons]]

Still having an issue on B2G: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=a7d5cec48867

Seems like the video element that captures a stream of gizmo.mp4 never starts to play. See the log from B2G debug at http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/7d37e990e9e7c98fef78d97701b6833cb1e20d21671f4b4b74112b9a0d34a0fd699535ab0656c3615835bbf854f48a1c58f416f59b05f905948a580e63ae0a75

Comment 123

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8510918 [details] [diff] [review]
Part 4. Add mochitest (carries r=roc)

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

::: content/media/test/test_bug879717.html
@@ +66,5 @@
> +  v1.onplay = checkDrawImageEventHandler;
> +  v2.onplay = checkDrawImageEventHandler;
> +  v3.onplay = checkDrawImageEventHandler;
> +
> +  v1.onplaying = checkDrawImageEventHandler;

Since 'onplaying' could fire many times, you might want to remove the listener so checkDrawImage runs once only.

@@ +109,5 @@
> +  document.body.appendChild(v2);
> +  document.body.appendChild(v3);
> +
> +  v1.src = media.name;
> +  v2.src = media.name;

There is only one instance of H264 decoder on B2G emulator. There is no way to play 2 gizmo.mp4 files at the same time. You should run v1 only after v2 and v3 are finished. Or you can call removeNodeAndSource() at the end of playback to release the decoder resource as soon as possible.

Comment 124

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #123)
> Comment on attachment 8510918 [details] [diff] [review]
> Part 4. Add mochitest (carries r=roc)
> 
> Review of attachment 8510918 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: content/media/test/test_bug879717.html
> @@ +66,5 @@
> > +  v1.onplay = checkDrawImageEventHandler;
> > +  v2.onplay = checkDrawImageEventHandler;
> > +  v3.onplay = checkDrawImageEventHandler;
> > +
> > +  v1.onplaying = checkDrawImageEventHandler;
> 
> Since 'onplaying' could fire many times, you might want to remove the
> listener so checkDrawImage runs once only.

In my opinion it doesn't hurt to check it multiple times.

> @@ +109,5 @@
> > +  document.body.appendChild(v2);
> > +  document.body.appendChild(v3);
> > +
> > +  v1.src = media.name;
> > +  v2.src = media.name;
> 
> There is only one instance of H264 decoder on B2G emulator. There is no way
> to play 2 gizmo.mp4 files at the same time. You should run v1 only after v2
> and v3 are finished. Or you can call removeNodeAndSource() at the end of
> playback to release the decoder resource as soon as possible.

Ah, of course. Thanks!

Comment 125

[Andreas Pehrson [:pehrsons]]

Also, how do you handle a new intermittent like the D3D crash that my test surfaces?

It's not a regression (See win8 opt): https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=00462507ee04

Comment 126

[Randell Jesup [:jesup] (needinfo me)]

(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #125)
> Also, how do you handle a new intermittent like the D3D crash that my test
> surfaces?
> 
> It's not a regression (See win8 opt):
> https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=00462507ee04

I presume from your comment that the base for that Try was m-c (or inbound), so it's something exposed by the new test.

First, is it intermittent?  The retriggers will help show this.  If it is intermittent (and low enough frequency) file a bug and move on (and See Also the bug to this one).  If it's permafail or high enough failure rate to cause block landing (at a guess I'd say this is likely, but we'll see) then make it block this bug and we can hit up the Graphics and Windows people (like :jimm), depending on the apparent cause.

I added a bunch of retriggers to see if we can characterize this better.

Comment 127

[Andreas Pehrson [:pehrsons]]

(In reply to Randell Jesup [:jesup] from comment #126)
> First, is it intermittent?  The retriggers will help show this.  If it is
> intermittent (and low enough frequency) file a bug and move on (and See Also
> the bug to this one).  If it's permafail or high enough failure rate to
> cause block landing (at a guess I'd say this is likely, but we'll see) then
> make it block this bug and we can hit up the Graphics and Windows people
> (like :jimm), depending on the apparent cause.
> 
> I added a bunch of retriggers to see if we can characterize this better.

I have confirmed that it's intermittent:
Happened for Win7 Opt (1/3) -> https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=a7d5cec48867
Happened for Win8 Opt (1/1) -> https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=00462507ee04

I don't know the failure rate. The retriggers I did got stuck on pending. From your retriggers that appears to happen only for Win8 machines, so let's see the Win7 results. Heck, I'll even throw in some more of those.

Comment 128

[Andreas Pehrson [:pehrsons]]

Attachment: Part 4. Add mochitest (carries r=roc)

Trivial fix to when we call |removeNodeAndSource()|.

Fixes the issue mentioned in comment 122: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=c60201078e7f

Comment 129

[Andreas Pehrson [:pehrsons]]

Attachment: Part 2. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container

Reverting back to using MediaStreamTracksAvailableCallback per feedback in comment 117. Also changes ready state back to HAVE_METADATA in case a video track is added after an audio track and we had already went to HAVE_CURRENT_DATA, per feedback in comment 70.

I'll put up an interdiff with attachment 8507924 [details] [diff] [review].

Comment 130

[Andreas Pehrson [:pehrsons]]

Attachment: INTERDIFF of Part 2; attachment 8507924 to attachment 8511506

Comment 131

[Andreas Pehrson [:pehrsons]]

Attachment: Part 6. Add video track before audio track for media decoder output streams

One last fix per comment 117.

Comment 132

[Andreas Pehrson [:pehrsons]]

This set of patches are green on try, except for the D3D crash mentioned earlier.

See main tests at https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=a7d5cec48867
And with the test fix for B2G in comment 128: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=c60201078e7f

Comment 133

[Andreas Pehrson [:pehrsons]]

(In reply to Randell Jesup [:jesup] from comment #126)
> First, is it intermittent?  The retriggers will help show this.  If it is
> intermittent (and low enough frequency) file a bug and move on (and See Also
> the bug to this one).  If it's permafail or high enough failure rate to
> cause block landing (at a guess I'd say this is likely, but we'll see) then
> make it block this bug and we can hit up the Graphics and Windows people
> (like :jimm), depending on the apparent cause.
> 
> I added a bunch of retriggers to see if we can characterize this better.

4/9 crashes on Win7 Opt, and 3/7 crashes on Win7 Debug. Similar numbers on Win8 most likely. XP not affected.

Let's summarize it to 50% failure rate on Win7 and Win8.

Now, what is "high enough failure rate to cause block landing"? :)

Comment 134

[Randell Jesup [:jesup] (needinfo me)]

> Now, what is "high enough failure rate to cause block landing"? :)

Typically around 10% or less will block landing...  So let's see if we can get gfx to look at this asap.  Please file a blocking bug with links to the crashes (and perhaps also search crashreporter for similar signatures)

Comment 135

[Randell Jesup [:jesup] (needinfo me)]

The D2D9 crash appears to be 

https://crash-stats.mozilla.com/report/list?product=Firefox&query_type=contains&range_unit=days&process_type=any&hang_type=any&signature=mozilla%3A%3Alayers%3A%3AD3D9SurfaceImage%3A%3AEnsureSynchronized%28%29&date=2014-10-25+20%3A00%3A00&range_value=14

So while it's not a top-crasher, it's far from unknown.

Comment 136

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8511506 [details] [diff] [review]
Part 2. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container

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

::: content/html/content/src/HTMLMediaElement.cpp
@@ +3155,5 @@
>    }
>  
> +  if (IsVideo() && mHasVideo && mMediaSize == nsIntSize(-1, -1)) {
> +    // Don't advance if we are playing video, but don't have a video frame.
> +    // Also, if video became available after advancing to HAVE_CURRENT_DATA,

s/available/unavailable/

Comment 137

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8511508 [details] [diff] [review]
Part 6. Add video track before audio track for media decoder output streams

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

::: content/media/MediaDecoderStateMachine.cpp
@@ +392,5 @@
>          mediaStream->AddTrack(TRACK_VIDEO, RATE_VIDEO, 0, video);
>          stream->mStream->DispatchWhenNotEnoughBuffered(TRACK_VIDEO,
>              GetStateMachineThread(), GetWakeDecoderRunnable());
>        }
> +      if (mInfo.HasAudio()) {

Add comments why we add video tracks before audio ones.

@@ +402,4 @@
>        stream->mStreamInitialized = true;
>      }
>  
>      if (mInfo.HasAudio()) {

To be consistent, we should also process video data first.

Comment 138

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #136)
> Comment on attachment 8511506 [details] [diff] [review]
> Part 2. Delay entering HAVE_CURRENT_DATA state until a video frame has been
> stored in the image container
> 
> Review of attachment 8511506 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: content/html/content/src/HTMLMediaElement.cpp
> @@ +3155,5 @@
> >    }
> >  
> > +  if (IsVideo() && mHasVideo && mMediaSize == nsIntSize(-1, -1)) {
> > +    // Don't advance if we are playing video, but don't have a video frame.
> > +    // Also, if video became available after advancing to HAVE_CURRENT_DATA,
> 
> s/available/unavailable/

No, available. In case we are in HAVE_CURRENT_DATA and mMediaSize is (-1,-1), the only way mHasVideo can be true is if it became true after we had advanced to HAVE_CURRENT_DATA with only audio tracks.

Comment 139

[JW Wang [:jwwang] [:jw_wang]]

I see. But "Don't advance if we are playing video, but don't have a video frame." should include the case of "if video became available after advancing to HAVE_CURRENT_DATA". Or the 2nd line can be rephrased to "if video became available after advancing to HAVE_CURRENT_DATA but before any video frames are available".

Comment 140

[Andreas Pehrson [:pehrsons]]

Attachment: Part 6. Add video track before audio track for media decoder output streams

Fixes nits per comment 137.

Comment 141

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #139)
> I see. But "Don't advance if we are playing video, but don't have a video
> frame." should include the case of "if video became available after
> advancing to HAVE_CURRENT_DATA". Or the 2nd line can be rephrased to "if
> video became available after advancing to HAVE_CURRENT_DATA but before any
> video frames are available".

It reads "Also, if video became available after advancing to HAVE_CURRENT_DATA, we need to revert to HAVE_METADATA until a video frame is available."

IMO "until a video frame is available" covers the case you mention as "but before any video frames are available".

Or did I misunderstand you?

Comment 142

[JW Wang [:jwwang] [:jw_wang]]

No, you get it right.

Comment 143

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

Comment on attachment 8511843 [details] [diff] [review]
Part 6. Add video track before audio track for media decoder output streams

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

Really we should notify about all simultaneous track changes in a single event.

Comment 144

[Andreas Pehrson [:pehrsons]]

Attachment: Part 1. Invalidate stream video frames in the regular stream state event queue (carries r=roc)

Rebased on m-c.

Comment 145

[Andreas Pehrson [:pehrsons]]

Attachment: Part 2. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container (carries r=roc)

Comment 146

[Andreas Pehrson [:pehrsons]]

Attachment: Part 3. Don't report HaveCurrentData when there are no input streams to TrackUnionStream (carries r=roc)

Comment 147

[Andreas Pehrson [:pehrsons]]

Attachment: Part 4. Add mochitest (carries r=roc)

Comment 148

[Andreas Pehrson [:pehrsons]]

Attachment: Part 5. Fix camera preview stream and wake locks from lock screen (carries r=roc)

Comment 149

[Andreas Pehrson [:pehrsons]]

Attachment: Part 6. Add video track before audio track for media decoder output streams (carries r=roc)

Comment 150

[Andreas Pehrson [:pehrsons]]

Attachment: Part 7. Don't force media size update in MetadataLoaded

Bug 1065827 regressed this patch set, because we're calling MetadataLoaded before we have a received a frame when we're playing a stream. That results in calling UpdateMediaSize(0, 0) which asserts in dom/media/tests/mochitest/test_peerConnection_replaceTrack.html at 100% repro rate:

> [729] ###!!! ASSERTION: Nothing to draw: 'aRatio.width > 0 && aRatio.height > 0 && !aRect.IsEmpty()', file /Users/pehrsons/Comoyo/gecko-dev/layout/generic/nsVideoFrame.cpp, line 161
> #01: nsDisplayVideo::BuildLayer(nsDisplayListBuilder*, mozilla::layers::LayerManager*, mozilla::ContainerLayerParameters const&) (nsVideoFrame.cpp:402, in XUL)
> #02: mozilla::ContainerState::ProcessDisplayItems(nsDisplayList*) (nsCOMPtr.h:190, in XUL)
> (...)

In order to receive a video frame from a stream we need to play it, but the state machine only allows autoplay after we end up in HAVE_METADATA.

Jean-Yves, is it ok to revert this bit of bug 1065827? UpdateMediaSize will be called as soon as the VideoFrameContainer receives a frame so forcing it in MetadataLoaded shouldn't be necessary.

Comment 151

[Randell Jesup [:jesup] (needinfo me)]

Part of the problem is that failing to update the videowidth and height on metadataloaded already is considered a bug and has been mentioned repeatedly as a problem by webrtc app developers.  Really we shouldn't call metadataloaded until we have all the data needed, including video size.  (For a stream output from a peerconnection and I think for a stream from getUserMedia, this would be on the first frame.)

Really we should never get to metadataloaded until we know the size I believe.  roc, does the spec speak to this at all or is it all assumed/inferred?  Certainly lots of people assume they can look at videoheight/width at metadataloaded.

In terms of this particular bug - I'm not certain what the right action is since I've lost the thread of what's getting changed in this patch

Comment 152

[Jean-Yves Avenard [:jya]]

Comment on attachment 8520620 [details] [diff] [review]
Part 7. Don't force media size update in MetadataLoaded

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

no you can't simply do that.
The video dimensions are supposed to be known when your loadedmetadata event is fired. Without this, the video.height and video.width would be 0

You can verify this there:
http://people.mozilla.org/~jyavenard/tests/mse_mp4/paper-init.html?chunks=1&eos_chunk=5&eos_delay=-1&delay_chunk=0&start=-1

this only loads the init segment. video.height should be 1080 and video.width should be 1920.

prior 1065827, this wasn't a problem as we had decoded and displayed the first frame before calling MetadataLoaded which had changed the dimensions elsewhere.

You shouldn't have video dimensions of 0 when MetadataLoaded is called.

I will amend a mochitest to verify that behaviour.

Comment 153

[Jean-Yves Avenard [:jya]]

(In reply to Randell Jesup [:jesup] from comment #151)
> Part of the problem is that failing to update the videowidth and height on
> metadataloaded already is considered a bug and has been mentioned repeatedly
> as a problem by webrtc app developers.  Really we shouldn't call
> metadataloaded until we have all the data needed, including video size. 
> (For a stream output from a peerconnection and I think for a stream from
> getUserMedia, this would be on the first frame.)
> 
> Really we should never get to metadataloaded until we know the size I
> believe.  roc, does the spec speak to this at all or is it all
> assumed/inferred?  Certainly lots of people assume they can look at
> videoheight/width at metadataloaded.
> 
http://www.w3.org/wiki/HTML/Elements/video
" 	The user agent has just determined the duration and dimensions of the media resource "

It's not an assumption. You must be able to read the video's height and width after loadedmetadata.
Note that the duration can be 0 however. But it has been determined as such.

Comment 154

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

(In reply to Randell Jesup [:jesup] from comment #151)
> Really we should never get to metadataloaded until we know the size I
> believe.  roc, does the spec speak to this at all or is it all
> assumed/inferred?

The spec clearly says we should have the video dimensions by the time loadedmetadata fires.

https://html.spec.whatwg.org/multipage/embedded-content.html#event-media-loadedmetadata
"The user agent has just determined the duration and dimensions of the media resource and the text tracks are ready."

Comment 155

[Andreas Pehrson [:pehrsons]]

All right, I'll fix these patches so that loadedmetadata is fired only after the first frame is received.

roc, what is the expected behavior if we in HTMLMediaElement get a stream where a video track is added after playback has started? Should we move ready state back to HAVE_NOTHING and fire loadedmetadata again when we have received a video frame?

Comment 156

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

(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #155)
> roc, what is the expected behavior if we in HTMLMediaElement get a stream
> where a video track is added after playback has started? Should we move
> ready state back to HAVE_NOTHING and fire loadedmetadata again when we have
> received a video frame?

No. We should just fire "resize" when we get the new size. We currently don't fire "resize" at all.

Comment 157

[Andreas Pehrson [:pehrsons]]

I'll break out some of the patches here to their own bugs so we can avoid some bitrotting and clean this bug up a bit.

Comment 158

[Andreas Pehrson [:pehrsons]]

Comment on attachment 8520607 [details] [diff] [review]
Part 1. Invalidate stream video frames in the regular stream state event queue (carries r=roc)

Broken out to bug 1102665.

Comment 159

[Andreas Pehrson [:pehrsons]]

Comment on attachment 8520610 [details] [diff] [review]
Part 3. Don't report HaveCurrentData when there are no input streams to TrackUnionStream (carries r=roc)

Broken out to bug 1102669.

Comment 160

[Andrew Osmond [:aosmond] (he/him)]

Comment on attachment 8520613 [details] [diff] [review]
Part 5. Fix camera preview stream and wake locks from lock screen (carries r=roc)

Broken out into bug 1102986.

Comment 161

[Andreas Pehrson [:pehrsons]]

Comment on attachment 8520614 [details] [diff] [review]
Part 6. Add video track before audio track for media decoder output streams (carries r=roc)

Dealing with this one in bug 1103848.

Comment 162

[Andreas Pehrson [:pehrsons]]

Attachment: Part 1. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container

We're now going to HAVE_METADATA only when the video size is known.

Comment 163

[Andreas Pehrson [:pehrsons]]

Attachment: Part 2. Test that drawing a video element to canvas never throws (carries r=roc)

Changed commit message.

Comment 164

[Andreas Pehrson [:pehrsons]]

Attachment: Part 3. Test video dimensions set on loadedmetadata event

New mochitest that checks for video dimensions on loadedmetadata.

I intend to merge this to also check the resize event in bug 1103848.

Comment 165

[Andreas Pehrson [:pehrsons]]

Here's a try of this lot: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=2da1d9869681

I keep exposing intermittents... but that's good I guess.

Comment 166

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8529417 [details] [diff] [review]
Part 3. Test video dimensions set on loadedmetadata event

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

Overall looks good to me.

::: dom/media/test/test_video_dimensions.html
@@ +24,5 @@
> +    ok(!v.loadedmetadata, v.testName + " should only fire loadedmetadata once");
> +    v.loadedmetadata = true;
> +    is(v.videoWidth, test.width, v.testName + " video width should be set on loadedmetadata");
> +    is(v.videoHeight, test.height, v.testName + " video height should be set on loadedmetadata");
> +    if(v.readyState >= v.HAVE_METADATA) {

Shouldn't we always have |v.readyState >= v.HAVE_METADATA| when 'metadataloaded' is fired? Why checking it here?

Comment 167

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8529413 [details] [diff] [review]
Part 1. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container

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

::: dom/media/test/test_streams_srcObject.html
@@ +44,5 @@
>        SimpleTest.finish();
>      }
>      ++step;
>    });
> +  a.play();

Setting 'autoplay' to true help verify your change to  HTMLMediaElement::CanActivateAutoplay.

Comment 168

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #166)
> Comment on attachment 8529417 [details] [diff] [review]
> Part 3. Test video dimensions set on loadedmetadata event
> 
> Review of attachment 8529417 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Overall looks good to me.
> 
> ::: dom/media/test/test_video_dimensions.html
> @@ +24,5 @@
> > +    ok(!v.loadedmetadata, v.testName + " should only fire loadedmetadata once");
> > +    v.loadedmetadata = true;
> > +    is(v.videoWidth, test.width, v.testName + " video width should be set on loadedmetadata");
> > +    is(v.videoHeight, test.height, v.testName + " video height should be set on loadedmetadata");
> > +    if(v.readyState >= v.HAVE_METADATA) {
> 
> Shouldn't we always have |v.readyState >= v.HAVE_METADATA| when
> 'metadataloaded' is fired? Why checking it here?

Yep, you're right. I think I might have missed removing this from an earlier version when I was testing the resize event instead.

Comment 169

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #167)
> Comment on attachment 8529413 [details] [diff] [review]
> Part 1. Delay entering HAVE_CURRENT_DATA state until a video frame has been
> stored in the image container
> 
> Review of attachment 8529413 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: dom/media/test/test_streams_srcObject.html
> @@ +44,5 @@
> >        SimpleTest.finish();
> >      }
> >      ++step;
> >    });
> > +  a.play();
> 
> Setting 'autoplay' to true help verify your change to 
> HTMLMediaElement::CanActivateAutoplay.

test_bug879717.html (part 2) should cover that.

Comment 170

[Andreas Pehrson [:pehrsons]]

Attachment: Part 3. Test video dimensions set on loadedmetadata event (carries r=roc)

Per comment 166 carrying over r=roc.

Comment 171

[Andreas Pehrson [:pehrsons]]

Just one bug left blocking us; trying to be proactive with a small try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=71284468bbb2

Comment 172

[Andreas Pehrson [:pehrsons]]

\o/

Please land after bug 1111831.

We should be good here, given that nothing new landed yesterday and broke things.

Some tries:

Quite extensive on Dec 15th: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=929da264a40f
Debug only on Dec 16th: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=94f7b7681fac
Most recent (from comment 171) on Dec 17th: https://treeherder.mozilla.org/#/jobs?repo=try&revision=71284468bbb2

Comment 173

[Carsten Book [:Tomcat]]

Hi Andreas,

Part 3 failed to apply cleanly:

patching file dom/media/test/mochitest.ini
Hunk #1 FAILED at 459
1 out of 1 hunks FAILED -- saving rejects to file dom/media/test/mochitest.ini.rej

could you take a look, thanks!

Comment 174

[Andreas Pehrson [:pehrsons]]

Attachment: Part 3. Test video dimensions set on loadedmetadata event (carries r=roc)

Rebased on latest m-c carrying r=roc.

Comment 175

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/c89fec9c8b55
https://hg.mozilla.org/integration/mozilla-inbound/rev/4e2f8f3b8f6b
https://hg.mozilla.org/integration/mozilla-inbound/rev/6bd00fa70b00

Comment 176

[Ryan VanderMeulen [:RyanVM]]

Backed out for causing multiple new intermittent failures. See the deps above.
https://hg.mozilla.org/integration/mozilla-inbound/rev/7d4c52001a02

Comment 177

[Andreas Pehrson [:pehrsons]]

Attachment: Part 4. Clean up test_peerConnection_capturedVideo.html's waiting for loadedmetadata

This test had some issues running locally while I was debugging bug 1113600 with this bug's patches applied. It get's fixed by bug 1113600 but I'll take this opportunity to clean the waiting for video dimensions up.

Comment 178

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Comment on attachment 8539729 [details] [diff] [review]
Part 4. Clean up test_peerConnection_capturedVideo.html's waiting for loadedmetadata

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

Lgtm. Thanks!

::: dom/media/tests/mochitest/test_peerConnection_capturedVideo.html
@@ +23,5 @@
> +    if (v1.readyState < v1.HAVE_METADATA) {
> +      v1.onloadedmetadata = e => resolve();
> +      return;
> +    }
> +    resolve();

I'd use an else over return here, but that's purely a matter of taste.

Comment 179

[Andreas Pehrson [:pehrsons]]

Hoping you know some more about this JW. Please have a look at https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=790712f9d23e, the 6th M12 for B2G emulator:

1700 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_video_dimensions.html | Test timed out. - expected PASS

From the log, see what's going on with gizmo.mp4:

02:34:26 INFO - 1687 INFO TEST-PASS | dom/media/test/test_video_dimensions.html | [started gizmo.mp4-3] Length of array should match number of running tests
02:34:26 INFO - 1688 INFO TEST-FAIL | dom/media/test/test_video_dimensions.html | The author of the test has indicated that flaky timeouts are expected. Reason: untriaged
02:34:26 INFO - 1689 INFO Watchdog remaining tests= vp9.webm-2,gizmo.mp4-3
02:34:26 INFO - 1690 INFO TEST-PASS | dom/media/test/test_video_dimensions.html | vp9.webm (Stream) should only fire loadedmetadata once
02:34:26 INFO - 1691 INFO TEST-PASS | dom/media/test/test_video_dimensions.html | vp9.webm (Stream) video width should be set on loadedmetadata
02:34:26 INFO - 1692 INFO TEST-PASS | dom/media/test/test_video_dimensions.html | vp9.webm (Stream) video height should be set on loadedmetadata
02:34:26 INFO - 1693 INFO [finished vp9.webm-2] remaining= gizmo.mp4-3
02:34:26 INFO - 1694 INFO TEST-PASS | dom/media/test/test_video_dimensions.html | [finished vp9.webm-2] Length of array should match number of running tests
02:34:26 INFO - 1695 INFO TEST-FAIL | dom/media/test/test_video_dimensions.html | The author of the test has indicated that flaky timeouts are expected. Reason: untriaged
02:34:26 INFO - 1696 INFO TEST-PASS | dom/media/test/test_video_dimensions.html | gizmo.mp4 (Captured) should only fire loadedmetadata once
02:34:26 INFO - 1697 INFO TEST-PASS | dom/media/test/test_video_dimensions.html | gizmo.mp4 (Captured) video width should be set on loadedmetadata
02:34:26 INFO - 1698 INFO TEST-PASS | dom/media/test/test_video_dimensions.html | gizmo.mp4 (Captured) video height should be set on loadedmetadata
02:34:26 INFO - 1699 INFO Watchdog remaining tests= gizmo.mp4-3
02:34:26 INFO - 1700 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_video_dimensions.html | Test timed out. - expected PASS 


The test explicitly plays v1 (not captured) before v2 (captured), yet v2 reaches metadataloaded first. The reason it times out is probably that the video element playing the stream (vout) is paused so it doesn't reach metadataloaded and hence, doesn't tear down the video elements to allow v1 to start playing.

My best guess is that this is a bug related to the hardware decoder, but I can't really say more. What do you think? Seen this before?

Comment 180

[JW Wang [:jwwang] [:jw_wang]]

I can't find the file of test_video_dimensions.html. Is it renamed or removed?

Comment 181

[JW Wang [:jwwang] [:jw_wang]]

Sorry, I just realize it is a new file in the bug.

Comment 182

[JW Wang [:jwwang] [:jw_wang]]

It is possible that v2 is hogging the hardware decoder so that v1 can't play at all. I think you can just run v2 and vout only in this test case. It is not necessary to run v1 and v2 at the same time.

Comment 183

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #182)
> It is possible that v2 is hogging the hardware decoder so that v1 can't play
> at all. I think you can just run v2 and vout only in this test case. It is
> not necessary to run v1 and v2 at the same time.

That's what I suspect as well. But how is it possible? v1 gets its src set first, and play is called on v1 first.

In fact, v2.play() is only called in v1.onloadedmetadata so v2 should not be playing at all.

Comment 184

[JW Wang [:jwwang] [:jw_wang]]

Setting 'src' will trigger loading metadata if 'preload' is 'metadata' or 'auto' without play() being called. Since loading metadata is done in a thread pool, it is possible for v2 to get a chance to load metadata before v1 depending on the scheduling. You can add logs to see if MediaDecoderStateMachine::DecodeMetadata() is called on v2 before on v1.

Comment 185

[Andreas Pehrson [:pehrsons]]

(In reply to JW Wang [:jwwang] from comment #184)
> Setting 'src' will trigger loading metadata if 'preload' is 'metadata' or
> 'auto' without play() being called. Since loading metadata is done in a
> thread pool, it is possible for v2 to get a chance to load metadata before
> v1 depending on the scheduling. You can add logs to see if
> MediaDecoderStateMachine::DecodeMetadata() is called on v2 before on v1.

This explains a lot, thanks. I'll set preload to none and then see if we get any failures as I fix and test bug 1113600.

Comment 186

[Andreas Pehrson [:pehrsons]]

Attachment: Part 3. Test video dimensions set on loadedmetadata event (carries r=roc)

Trivial fix to avoid a race for hw on B2G, carrying forward r=roc.

Comment 187

[Andreas Pehrson [:pehrsons]]

Please land this on top of bug 1113600.

Comment 188

[Randell Jesup [:jesup] (needinfo me)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/d9db938747d2
https://hg.mozilla.org/integration/mozilla-inbound/rev/d099c153d94a
https://hg.mozilla.org/integration/mozilla-inbound/rev/19432abcb3f1
https://hg.mozilla.org/integration/mozilla-inbound/rev/f3b7db6c2164

Comment 189

[Carsten Book [:Tomcat]]

sorry had to back this out for perma test failures like https://treeherder.mozilla.org/logviewer.html#?job_id=5387259&repo=mozilla-inbound

Comment 190

[Andreas Pehrson [:pehrsons]]

(In reply to Carsten Book [:Tomcat] from comment #189)
> sorry had to back this out for perma test failures like
> https://treeherder.mozilla.org/logviewer.html#?job_id=5387259&repo=mozilla-
> inbound

Yeah, noted. Man, what are the odds. When you think you have every inch of this bug covered..

It is cursed, I tell ya.

Comment 191

[Jean-Yves Avenard [:jya]]

(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #190)
> (In reply to Carsten Book [:Tomcat] from comment #189)
> > sorry had to back this out for perma test failures like
> > https://treeherder.mozilla.org/logviewer.html#?job_id=5387259&repo=mozilla-
> > inbound
> 
> Yeah, noted. Man, what are the odds. When you think you have every inch of
> this bug covered..
> 
> It is cursed, I tell ya.

I'm seeing the same error on another ticket I'm working on (bug 1118589). There is an order / timing issue showing up with eme.
I don't believe the problem would be specific to your patch, it just exposes the eme issue.

Comment 192

[Andreas Pehrson [:pehrsons]]

Attachment: Part 1. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container (carries r=roc)

Needs a rebase to go cleanly. Carrying forward r=roc.

Comment 193

[Andreas Pehrson [:pehrsons]]

Attachment: Part 2. Test that drawing a video element to canvas never throws (carries r=roc)

Needs a rebase to go cleanly. Carrying forward r=roc.

Comment 194

[Andreas Pehrson [:pehrsons]]

Rumor has it things will work with bug 1121774: https://treeherder.mozilla.org/#/jobs?repo=try&revision=99e53b34dafb

Comment 195

[Jean-Yves Avenard [:jya]]

(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #194)
> Rumor has it things will work with bug 1121774:
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=99e53b34dafb

I have fixed the underlying issue in bug 1121342. it should be good now

Comment 196

[Andreas Pehrson [:pehrsons]]

(In reply to Jean-Yves Avenard [:jya] from comment #195)
> (In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #194)
> > Rumor has it things will work with bug 1121774:
> > https://treeherder.mozilla.org/#/jobs?repo=try&revision=99e53b34dafb
> 
> I have fixed the underlying issue in bug 1121342. it should be good now

Cool, let's see magic: https://treeherder.mozilla.org/#/jobs?repo=try&revision=02542a0e5551

Comment 197

[Andreas Pehrson [:pehrsons]]

Ok, all green. Let's hope nothing else broke while this got fixed :)

Comment 198

[Randell Jesup [:jesup] (needinfo me)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/bd5f2df95665
https://hg.mozilla.org/integration/mozilla-inbound/rev/8510279ebe86
https://hg.mozilla.org/integration/mozilla-inbound/rev/e120a5b381c2
https://hg.mozilla.org/integration/mozilla-inbound/rev/654e15b4dc9b

Comment 199

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/bd5f2df95665
https://hg.mozilla.org/mozilla-central/rev/8510279ebe86
https://hg.mozilla.org/mozilla-central/rev/e120a5b381c2
https://hg.mozilla.org/mozilla-central/rev/654e15b4dc9b

Comment 200

[Andreas Pehrson [:pehrsons]]

Comment on attachment 8550140 [details] [diff] [review]
Part 1. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container (carries r=roc)

Approval Request Comment
[Feature/regressing bug #]: Not sure, legacy?
[User impact if declined]: VideoElement's video dimensions not known on "loadedmetadata" when playing MediaStreams. VideoElements will also be able to proceed to HAVE_CURRENT_DATA before they actually have data, causing exceptions if drawn to a canvas (see description).
[Describe test coverage new/current, TBPL]: Landed on m-c, code touched by all media tests in some way.
[Risks and why]: Low-intermediate. Great coverage but there's been lots of blockers before we could land on m-c.
[String/UUID change made/needed]: None

This approval request applies to all patches on this bug.

This should go cleanly on aurora and b2g37. Running beta and b2g34 on try now to see if it's possible to uplift there.

Comment 201

[Andreas Pehrson [:pehrsons]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=0dca8a5f3b59

Unclear what dependencies we have to uplift to b2g34. Marking it wontfix.

Comment 202

[Andreas Pehrson [:pehrsons]]

I think these dependencies will do fine for beta,

Bug 1103848,
Bug 1113600,
Bug 1106963, and
Bug 1100803.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=42c4ad3d4d81

Comment 203

[Andreas Pehrson [:pehrsons]]

Comment on attachment 8550140 [details] [diff] [review]
Part 1. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container (carries r=roc)

See comment 200 and comment 202. Try on beta looks good, but we also depend on the bugs listed above.

Comment 204

[Sylvestre Ledru [:Sylvestre]]

(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #203)
> See comment 200 and comment 202. Try on beta looks good, but we also depend
> on the bugs listed above.
We had this bug for a while, why it cannot ride the train from 37?

Comment 205

[Andreas Pehrson [:pehrsons]]

(In reply to Sylvestre Ledru [:sylvestre] from comment #204)
> (In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #203)
> > See comment 200 and comment 202. Try on beta looks good, but we also depend
> > on the bugs listed above.
> We had this bug for a while, why it cannot ride the train from 37?

It's just that it's been around a good long while (I've worked on it since october, when trunk was 35) and done many many rounds on try. So even though it's a fairly large change it's a pretty safe uplift (also, we're only one week into the current beta cycle), plus the gain is large.

Comment 206

[Andreas Pehrson [:pehrsons]]

Comment on attachment 8550140 [details] [diff] [review]
Part 1. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container (carries r=roc)

I saw now that b2g37 doesn't require its own approval.

Comment 207

[Sylvestre Ledru [:Sylvestre]]

(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #205)
> (In reply to Sylvestre Ledru [:sylvestre] from comment #204)
> the gain is large.
Could you elaborate on this?

Comment 208

[Andreas Pehrson [:pehrsons]]

(In reply to Sylvestre Ledru [:sylvestre] from comment #207)
> (In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #205)
> > (In reply to Sylvestre Ledru [:sylvestre] from comment #204)
> > the gain is large.
> Could you elaborate on this?

Sure, here's what I have.

The spec (https://html.spec.whatwg.org/multipage/embedded-content.html#media-elements) says:

1.
'loadedmetadata' is fired when.. "The user agent has just determined the duration and dimensions of the media resource and the text tracks are ready."

But when playing getUserMedia and PeerConnection streams, video dimensions are consistently not known on "loadedmetadata".

2.
Ready state HAVE_CURRENT_DATA means that.. "Data for the immediate current playback position is available, (...) For example, in video this corresponds to the user agent having data from the current frame"

Though we'd consistently have a short period without current data but with a ready state of HAVE_CURRENT_DATA or higher. This would get problematic when an event handler (for let's say 'play', per this bug's description) draws the video element into a canvas.

3.
To underline the importance of 1., see bug 926753, where two people went through the hoops of signing up to bugzilla just to report on this issue.

Comment 209

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8550140 [details] [diff] [review]
Part 1. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container (carries r=roc)

I am sorry but I won't take this one for 36. Lawrence will make the call on 37.

I discussed with a few people about this bug and we think it can wait for another cycle since it has been broken for a while. Especially on the context of MSE landing, this introduces some risks.

Comment 210

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

Comment on attachment 8550140 [details] [diff] [review]
Part 1. Delay entering HAVE_CURRENT_DATA state until a video frame has been stored in the image container (carries r=roc)

I think we're early enough in Aurora to take this change. Aurora+

In order to get developer feedback, it would be good to 
a) inform the devs who reported the problem that it has been fixed and request that they test
b) inform the Dev Edition audience of the fix (maybe a hacks post?)

Comment 211

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/1112988e90ac
https://hg.mozilla.org/releases/mozilla-aurora/rev/05abbe4ec215
https://hg.mozilla.org/releases/mozilla-aurora/rev/c98d9fcee934
https://hg.mozilla.org/releases/mozilla-aurora/rev/cbfab5a8210d

Comment 212

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/1112988e90ac
https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/05abbe4ec215
https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/c98d9fcee934
https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/cbfab5a8210d

Comment 213

[Pi Wei Cheng [:piwei] (inactive)]

This issue is verified fixed on Flame 2.2 and on Flame 3.0 master.

Accessing the URL at comment 0 does NOT create an error described in comment 0 in the console/terminal.

Device: Flame 2.2 (shallow flash, 319MB mem)
BuildID: 20150121141032
Gaia: e4f9b5da3751798f9cc5d95f302c30722cc11fca
Gecko: 4a90da67661e
Version: 37.0a2 (2.2)
Firmware: V18D-1
User Agent: Mozilla/5.0 (Mobile; rv:37.0) Gecko/37.0 Firefox/37.0

Device: Flame 3.0 Master (shallow flash, 319MB mem)
BuildID: 20150122053733
Gaia: 966b3a7a13a7f0d5b86cbc9e64cb78d43ec7dba8
Gecko: 86f9d0128ccf
Version: 38.0a1 (3.0 Master)
Firmware: V18D-1
User Agent: Mozilla/5.0 (Mobile; rv:38.0) Gecko/38.0 Firefox/38.0

Comment 216

[Bartosz Dziewoński]

There still exists a similar issue with Firefox 47, with our web application that involves drawing many <video>s to many <canvas>es in a short timespan (https://commons.wikimedia.org/wiki/Special:UploadWizard). We have JavaScript error logging which indicates that multiple users are experiencing this issue in practice.

I did not manage to isolate a test case that still causes the exception, though, so I won't bother you with a useless bug report. If anyone wants to look into this, there's a description of the issue and reproduction steps at <https://phabricator.wikimedia.org/T136831>, I'll be happy to help investigate in any way possible.

Comment 217

[Randell Jesup [:jesup] (needinfo me)]

(In reply to Bartosz Dziewoński from comment #216)
> There still exists a similar issue with Firefox 47, with our web application
> that involves drawing many <video>s to many <canvas>es in a short timespan
> (https://commons.wikimedia.org/wiki/Special:UploadWizard). We have
> JavaScript error logging which indicates that multiple users are
> experiencing this issue in practice.

Were these <video> elements using a MediaStream source (via .srcObject, or .src = URL.createObject()?)  If not, then whatever you're seeing is a different issue -- this is about video elements fed from MediaStreams.

It's also unclear what you're saying went wrong - do you know what the users are experiencing?  Something didn't draw, or some event didn't fire?

> I did not manage to isolate a test case that still causes the exception,
> though, so I won't bother you with a useless bug report. If anyone wants to
> look into this, there's a description of the issue and reproduction steps at
> <https://phabricator.wikimedia.org/T136831>, I'll be happy to help
> investigate in any way possible.

Please file a new bug, even if you don't have a clean testcase. Probably start in Core::Audio/Video, and we'll triage from there.

Comment 218

[Gaikov]

I have the same issue in 61 version of firefox on Android devices

Comment 219

[Andreas Pehrson [:pehrsons]]

(In reply to Gaikov from comment #218)
> I have the same issue in 61 version of firefox on Android devices

Please file a new bug with complete/updated instructions.