816664 - Video frames reordered in MediaStreamGraph

Status: RESOLVED FIXED

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

Comment 1

[Eric Rescorla (:ekr)]

Attachment: Video frame tainting

Comment 2

[Eric Rescorla (:ekr)]

I am seeing frame reordering during video calls with Chrome/Firefox. It's not clear why it happens in just this scenario.

The patch applied won't exactly apply against m-i trunk but it's obvious what it does. I'll also attach the output file of a sample run and some analysis output of that.

Comment 3

[Eric Rescorla (:ekr)]

Attachment: The timestamp output

Comment 4

[Eric Rescorla (:ekr)]

Attachment: analysis output

Comment 5

[Eric Rescorla (:ekr)]

Note that this creates terribly bad video when we try to call chrome from firefox.

Comment 6

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

[15:14]	ekr	oh, so timestamp is 0
[15:14]	ekr	and render_time is crap b/c I copied from the wrong offset
[15:15]	ekr	I don't think it's needed, but I guess I can fix it if needed
[15:15]	derf	Yes, on Mac, timestamp is always 0.
[15:15]	ekr	since roc ignores render_time
[15:15]	derf	The capture driver never fills it in.
[15:15]	jesup	k, thanks, good to know.
[15:15]	derf	render_time is just going to be the current system time.

Comment 7

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

FYI, the issue here as reported is that the frame number goes backwards at times; and seems to like certain values/sequences.

As this is measuring from where we replace mImage (used for NotifyPull/AddToTrack) and NotifyQueuedTrackChanges, this appears to be somewhere in the MediaStreamGraph code.

Adding Paul as well in case he has an insight.

Ekr: can you repeat this with the logs going to LOG() and turn on peerconnection and mediastreamgraph (and the conduit logging)?  (So we can see what MediaStreamGraph thinks of all this).

Comment 8

[Eric Rescorla (:ekr)]

More information. I am also seeing some sketchy segments

(gdb) p *$1
$2 = (mozilla::VideoSegment) {
  <mozilla::MediaSegmentBase<mozilla::VideoSegment, mozilla::VideoChunk>> = {
    <mozilla::MediaSegment> = {
      _vptr$MediaSegment = 0x1060ff940, 
      mDuration = -7368, 
      mType = mozilla::MediaSegment::VIDEO
    }, 
    members of mozilla::MediaSegmentBase<mozilla::VideoSegment, mozilla::VideoChunk>: 
    mChunks = {
      <nsTArray_base<nsTArrayDefaultAllocator>> = {
        mHdr = 0x11d68c440
      }, 
      <nsTArray_SafeElementAtHelper<mozilla::VideoChunk, nsTArray<mozilla::VideoChunk, nsTArrayDefaultAllocator> >> = {<No data fields>}, <No data fields>}
  }, <No data fields>}
(gdb) call $1->mChunks.Length()
$3 = 2

Comment 9

[Eric Rescorla (:ekr)]

Attachment: Gum output

Comment 10

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

Attachment: logs showing aDesiredTime going backwards

This shows how aDesiredTime can go backwards, and so invalidates the logic in MediaEngineWebRTCVideo.cpp::NotifyPull, where it calculates a delta for a frame (to avoid the graph blocking) based on the delta of aDesiredTime versus the previous aDesiredTime.

We need a new solution for determining the delta, or eliminate deltas from video streams (i.e. frames are points in times not spans of time).

Comment 11

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

Attachment: wallpaper patch for negative delta times for video frames

Wallpaper patch that should avoid the problem for now and will assert if it occurs for any reason

Comment 12

[Eric Rescorla (:ekr)]

I assume by "wallpaper" you mean that there is some more fundamental problem that we eventually need to fix?
Do we have to worry about that biting us in some other way?

Comment 13

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

The 'right' fix is to deal with time durations for video frames differently and never block a (gUM) mediastream on them.

This should be a totally safe patch.  In odd instances (negative delta) we might drop a frame.

Comment 14

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

OK, so as currently defined it's not necessarily wrong for aDesiredTime to move backward. aDesiredTime is computed based on the optimistic assumption that the stream will not be blocked after mStateComputedTime. But if later we determine the stream will actually be blocked during some of that time, we won't need as much data as we previously thought, so aDesiredTime can validly go backward.

Obviously we don't *want* the stream to be blocked, ever, but that's a separate issue.

Comment 15

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

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #14)
> OK, so as currently defined it's not necessarily wrong for aDesiredTime to
> move backward. aDesiredTime is computed based on the optimistic assumption
> that the stream will not be blocked after mStateComputedTime. But if later
> we determine the stream will actually be blocked during some of that time,
> we won't need as much data as we previously thought, so aDesiredTime can
> validly go backward.

And given this, I believe the patch Randell wrote here is correct.

Comment 16

[Timothy B. Terriberry (:derf)]

Comment on attachment 686984 [details] [diff] [review]
wallpaper patch for negative delta times for video frames

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

::: content/media/webrtc/MediaEngineWebRTCVideo.cpp
@@ +14,5 @@
>  #define LOG(msg) PR_LOG(GetMediaManagerLog(), PR_LOG_DEBUG, msg)
>  #else
>  #define LOG(msg)
>  #endif
> +#define LOG_ALL_FRAMES 1

Do we actually want to check this line in?

@@ +115,2 @@
>  #endif
> +  // Don't append if we've already provided a frame that supposedly goes past the current aDesiredTime

If this is the correct thing to do, perhaps we should fix MediaStreamGraphImpl::ExtractPendingInput() to not call NotifyPull() in the first place if it already has enough data, instead of making every MediaStreamListener implementation check this.

Comment 17

[Eric Rescorla (:ekr)]

Attachment: , test case

Comment 18

[Eric Rescorla (:ekr)]

Comment on attachment 687587 [details] [diff] [review]
, test case

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

To exercise this test case, go to: http://mozilla.github.com/webrtc-landing/gum_test.html
Click "audio and video" and it will crash at the assert.
Note the Video works.

Comment 19

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

Attachment: Don't call NotifyPull if we already have enough data

Completely untested.

If we take this, we shouldn't need the duration > 0 check in Randell's patch; since the WebRTC NotifyPull should always fill mBuffer up to the last aDesiredTime (at least), a NotifyPull with a smaller aDesiredTime would simply be skipped by this patch.

Comment 20

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

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #14)
> Obviously we don't *want* the stream to be blocked, ever, but that's a
> separate issue.

I filed bug 817455 to investigate this.

Comment 21

[Eric Rescorla (:ekr)]

Paul,

Can you please take this bug over. The current consensus is that there are four things that are
needed:

1. Randell's patch.
2. Tim's proposed patch to ditch all but the last video frame in NotifyQueuedTrackChanges
3. Roc's patch.
4. Investigation of why the heck this is happening in the first place and a fix for it (see c19
and now bug 817455)

What's needed here is to review/cleanup/test items 1-3 and then do item #4 and propose a fix.
The concern is that if we just do 1-3, we won't have video time run backwards but we will
have lousy framerates

Roc has agreed to backstop you if you get stuck.

Comment 22

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

(In reply to Timothy B. Terriberry (:derf) from comment #16)
> Comment on attachment 686984 [details] [diff] [review]
> wallpaper patch for negative delta times for video frames
> 
> Review of attachment 686984 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: content/media/webrtc/MediaEngineWebRTCVideo.cpp
> @@ +14,5 @@
> >  #define LOG(msg) PR_LOG(GetMediaManagerLog(), PR_LOG_DEBUG, msg)
> >  #else
> >  #define LOG(msg)
> >  #endif
> > +#define LOG_ALL_FRAMES 1
> 
> Do we actually want to check this line in?

Probably.  We're logging all the audio frames.  And having this on in debug builds lets us do a better job tracking down problems.

Perhaps we'll turn it off again later, or we could move it to a different log, but it's ok for now.

Comment 23

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

Comment on attachment 687589 [details] [diff] [review]
Don't call NotifyPull if we already have enough data

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

Hmmm... Didn't know nsWindow.cpp was so involved in MediaStreamGraphs.  :-)
I agree the concept of not pulling when we don't actually want any new data is a good one.

Comment 24

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

Attachment: actual patch

Comment 25

[Paul Adenot (:padenot)]

Regarding comment 19, roc's patch does not remove the need to jesup's check for the positiveness of |delta|. I still see negative delta, and that asserts later.

Comment 26

[Timothy B. Terriberry (:derf)]

(In reply to Paul ADENOT (:padenot) from comment #25)
> Regarding comment 19, roc's patch does not remove the need to jesup's check
> for the positiveness of |delta|. I still see negative delta, and that
> asserts later.

Can you figure out why that is and explain it here?

Comment 27

[Paul Adenot (:padenot)]

That is what I'm doing right now, but that implies understanding a lot of MediaStream magic.

Comment 28

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

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

Comment 29

[(no longer active)]

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

Comment 30

[Timothy B. Terriberry (:derf)]

Comment on attachment 686984 [details] [diff] [review]
wallpaper patch for negative delta times for video frames

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

Given the lack of progress on this bug, I suppose we can check in the wall-paper for now, but please leave the bug open afterwards until we actually understand what is going on.

Comment 31

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/7d6255d1c547

Comment 32

[Josh Matthews [:jdm]]

Backed out as part of a set of patches suspected of causing permaorange Android 2.2 opt m2 and m3:
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/d2552e3d3ed6
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/e497c2e40dc6
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/22e38c3125e9

Comment 33

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

reland:
https://hg.mozilla.org/integration/mozilla-inbound/rev/fc263eb8a7db

Comment 34

[Ryan VanderMeulen [:RyanVM]]

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

Comment 35

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

per roc's comment 14, we do actually understand what's going on here.  It may be unexpected, and probably should be commented more in MediaStreamGraph.h:NotifyPull(), and we should consider if a second NotifyPull call with an earlier time is actually a useful thing for the callee, but we do understand this and given the current MSG implementation, this is being handled correctly now.