Add logging statements to places where the frame might be dropped in WebRTC pipeline.

Add logging statements to places where the frame might be dropped in WebRTC pipeline.

BUG=b/31645554

Committed: https://crrev.com/55d932b33115ae6e3a542b822b33605a03edc324
Cr-Commit-Position: refs/heads/master@{#14457}

[sakal, 2016-09-22 11:15:23]

sakal@webrtc.org changed reviewers:
+ magjed@webrtc.org

[sakal, 2016-09-22 11:15:24]

PTAL

I am not sure if it is reasonable to log in VideoBroadcaster::OnFrame if there
are no sinks. We can remove it if you want.

[magjed_webrtc, 2016-09-22 14:38:32]

On 2016/09/22 11:15:24, sakal wrote:
> PTAL
> 
> I am not sure if it is reasonable to log in VideoBroadcaster::OnFrame if there
> are no sinks. We can remove it if you want.

I think it's fine to log in VideoBroadcaster::OnFrame if there are no sinks.

Can you also update VideoRenderFrames to log if we are buffering more than ~100
frames?

[sakal, 2016-09-23 08:41:26]

Patchset #2 (id:20001) has been deleted

[sakal, 2016-09-23 08:41:50]

Done, PTAL.

[magjed_webrtc, 2016-09-23 13:05:00]

lgtm

[sakal, 2016-09-23 13:10:52]

sakal@webrtc.org changed reviewers:
+ stefan@webrtc.org

[sakal, 2016-09-23 13:10:53]

Stefan, PTAL.

[sakal, 2016-09-23 13:11:04]

The CQ bit was checked by sakal@webrtc.org to run a CQ dry run

[commit-bot: I haz the power, 2016-09-23 13:11:19]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.webrtc.org/...

[commit-bot: I haz the power, 2016-09-23 13:30:21]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-09-23 13:30:22]

Dry run: Try jobs failed on following builders:
  win_x64_clang_rel on master.tryserver.webrtc (JOB_FAILED,
http://build.chromium.org/p/tryserver.webrtc/builders/win_x64_clang_rel/build...)

[perkj_webrtc, 2016-09-26 06:46:34]

perkj@webrtc.org changed reviewers:
+ perkj@webrtc.org

[perkj_webrtc, 2016-09-26 06:46:35]

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/media/base/videobr...
File webrtc/media/base/videobroadcaster.cc (right):

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/media/base/videobr...
webrtc/media/base/videobroadcaster.cc:55: LOG(LS_INFO) << "Dropping frame
because there are no sink pairs in video "
This may soon start spitting out logs in chrome that would be hit when a
PeerConnection is created  but negotiation is not complete. I think it would be
better if you instead add logs where a sink is added to a source in the source
subclasses. If you do it here you will not know if it is a local or remote
source.

[stefan-webrtc, 2016-09-26 10:44:09]

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/modules/video_codi...
File webrtc/modules/video_coding/generic_decoder.cc (right):

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/modules/video_codi...
webrtc/modules/video_coding/generic_decoder.cc:76: if (callback != NULL) {
Can we possibly instead DCHECK on callback != nullptr?

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/video/video_stream...
File webrtc/video/video_stream_decoder.cc (right):

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/video/video_stream...
webrtc/video/video_stream_decoder.cc:90: LOG(LS_INFO) << "Dropping frame because
incoming_video_stream_ is NULL.";
AFAICT this can never happen as incoming_video_stream_ is always set. DCHECK?

[sakal, 2016-09-26 11:24:00]

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/media/base/videobr...
File webrtc/media/base/videobroadcaster.cc (right):

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/media/base/videobr...
webrtc/media/base/videobroadcaster.cc:55: LOG(LS_INFO) << "Dropping frame
because there are no sink pairs in video "
On 2016/09/26 06:46:34, perkj_webrtc wrote:
> This may soon start spitting out logs in chrome that would be hit when a
> PeerConnection is created  but negotiation is not complete. I think it would
be
> better if you instead add logs where a sink is added to a source in the source
> subclasses. If you do it here you will not know if it is a local or remote
> source.

I changed it to log VideoBroadcaster creation and adding a sink. Idea being that
if a video broadcaster is created but a sink is never added we should look into
it.

I tried adding logging to places where AddOrUpdateSink is called but it seems
like a lot of work to trace where the calls are actually coming from.

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/modules/video_codi...
File webrtc/modules/video_coding/generic_decoder.cc (right):

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/modules/video_codi...
webrtc/modules/video_coding/generic_decoder.cc:76: if (callback != NULL) {
On 2016/09/26 10:44:08, stefan-webrtc (holmer) wrote:
> Can we possibly instead DCHECK on callback != nullptr?

_receiveCallback is initiated with nullptr in the constructor and is only set
after SetUserReceiveCallback. Since it is not trivial to prove this will never
happen I would err on the side of caution. The if statement was added for a
reason probably.

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/video/video_stream...
File webrtc/video/video_stream_decoder.cc (right):

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/video/video_stream...
webrtc/video/video_stream_decoder.cc:90: LOG(LS_INFO) << "Dropping frame because
incoming_video_stream_ is NULL.";
On 2016/09/26 10:44:09, stefan-webrtc (holmer) wrote:
> AFAICT this can never happen as incoming_video_stream_ is always set. DCHECK?

It looks like this class is instantiated here:
https://cs.chromium.org/chromium/src/third_party/webrtc/video/video_receive_s...

incoming_video_stream_ is set to nullptr if config_.renderer is nullptr. Comment
on that member says "'nullptr' disables rendering of this stream.". So I guess
it is possible?

[stefan-webrtc, 2016-09-26 11:39:22]

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/modules/video_codi...
File webrtc/modules/video_coding/generic_decoder.cc (right):

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/modules/video_codi...
webrtc/modules/video_coding/generic_decoder.cc:76: if (callback != NULL) {
On 2016/09/26 11:23:59, sakal wrote:
> On 2016/09/26 10:44:08, stefan-webrtc (holmer) wrote:
> > Can we possibly instead DCHECK on callback != nullptr?
> 
> _receiveCallback is initiated with nullptr in the constructor and is only set
> after SetUserReceiveCallback. Since it is not trivial to prove this will never
> happen I would err on the side of caution. The if statement was added for a
> reason probably.

It's always set here:
https://cs.chromium.org/chromium/src/third_party/webrtc/video/video_stream_de...

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/video/video_stream...
File webrtc/video/video_stream_decoder.cc (right):

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/video/video_stream...
webrtc/video/video_stream_decoder.cc:90: LOG(LS_INFO) << "Dropping frame because
incoming_video_stream_ is NULL.";
On 2016/09/26 11:23:59, sakal wrote:
> On 2016/09/26 10:44:09, stefan-webrtc (holmer) wrote:
> > AFAICT this can never happen as incoming_video_stream_ is always set.
DCHECK?
> 
> It looks like this class is instantiated here:
>
https://cs.chromium.org/chromium/src/third_party/webrtc/video/video_receive_s...
> 
> incoming_video_stream_ is set to nullptr if config_.renderer is nullptr.
Comment
> on that member says "'nullptr' disables rendering of this stream.". So I guess
> it is possible?

Seems like it's always being set outside of Call though?
https://cs.chromium.org/chromium/src/third_party/webrtc/media/engine/webrtcvi...

If you think there are good reasons to support not attaching a renderer, then I
can live with this one. But in that case perhaps we should throttle the logs to
not show 30 logs per second for 30 fps video?

[sakal, 2016-09-27 08:38:23]

The CQ bit was checked by sakal@webrtc.org to run a CQ dry run

[commit-bot: I haz the power, 2016-09-27 08:38:27]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.webrtc.org/...

[commit-bot: I haz the power, 2016-09-27 08:49:56]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-09-27 08:49:57]

Dry run: Try jobs failed on following builders:
  linux_ubsan on master.tryserver.webrtc (JOB_FAILED,
http://build.chromium.org/p/tryserver.webrtc/builders/linux_ubsan/builds/5389)

[sakal, 2016-09-27 14:45:14]

The CQ bit was checked by sakal@webrtc.org to run a CQ dry run

[commit-bot: I haz the power, 2016-09-27 14:45:24]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.webrtc.org/...

[commit-bot: I haz the power, 2016-09-27 14:48:00]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-09-27 14:48:01]

Dry run: Try jobs failed on following builders:
  ios_arm64_dbg on master.tryserver.webrtc (JOB_FAILED,
http://build.chromium.org/p/tryserver.webrtc/builders/ios_arm64_dbg/builds/13284)

[sakal, 2016-09-27 14:50:42]

Patchset #7 (id:140001) has been deleted

[sakal, 2016-09-27 14:53:01]

The CQ bit was checked by sakal@webrtc.org to run a CQ dry run

[commit-bot: I haz the power, 2016-09-27 14:53:07]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.webrtc.org/...

[magjed_webrtc, 2016-09-27 15:06:11]

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/media/base/videobr...
File webrtc/media/base/videobroadcaster.cc (right):

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/media/base/videobr...
webrtc/media/base/videobroadcaster.cc:55: LOG(LS_INFO) << "Dropping frame
because there are no sink pairs in video "
On 2016/09/26 11:23:59, sakal wrote:
> On 2016/09/26 06:46:34, perkj_webrtc wrote:
> > This may soon start spitting out logs in chrome that would be hit when a
> > PeerConnection is created  but negotiation is not complete. I think it would
> be
> > better if you instead add logs where a sink is added to a source in the
source
> > subclasses. If you do it here you will not know if it is a local or remote
> > source.
> 
> I changed it to log VideoBroadcaster creation and adding a sink. Idea being
that
> if a video broadcaster is created but a sink is never added we should look
into
> it.
> 
> I tried adding logging to places where AddOrUpdateSink is called but it seems
> like a lot of work to trace where the calls are actually coming from.

It's probably good to have logs for VideoBroadcaster creation and adding a sink
regardless, but can't we keep this log? It's so much more explicit and obvious
if we see this log in bugreports instead of trying to track down when and how
sinks are added. Also logs are sometimes cropped, so it might not even be
possible. I don't think Chrome will spit out this log since local video is shown
before negotiation is complete, and is it really a problem if we get a few of
these logs in fringe cases? We know from the context in bugreports if local or
remote video is missing, so that's not a problem.

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/video/video_stream...
File webrtc/video/video_stream_decoder.cc (right):

https://codereview.webrtc.org/2361803003/diff/40001/webrtc/video/video_stream...
webrtc/video/video_stream_decoder.cc:90: LOG(LS_INFO) << "Dropping frame because
incoming_video_stream_ is NULL.";
On 2016/09/26 11:39:22, stefan-webrtc (holmer) wrote:
> On 2016/09/26 11:23:59, sakal wrote:
> > On 2016/09/26 10:44:09, stefan-webrtc (holmer) wrote:
> > > AFAICT this can never happen as incoming_video_stream_ is always set.
> DCHECK?
> > 
> > It looks like this class is instantiated here:
> >
>
https://cs.chromium.org/chromium/src/third_party/webrtc/video/video_receive_s...
> > 
> > incoming_video_stream_ is set to nullptr if config_.renderer is nullptr.
> Comment
> > on that member says "'nullptr' disables rendering of this stream.". So I
guess
> > it is possible?
> 
> Seems like it's always being set outside of Call though?
>
https://cs.chromium.org/chromium/src/third_party/webrtc/media/engine/webrtcvi...
> 
> If you think there are good reasons to support not attaching a renderer, then
I
> can live with this one. But in that case perhaps we should throttle the logs
to
> not show 30 logs per second for 30 fps video?

There is probably no reason to not attach a renderer so when this happens it's
probably an error. Therefore I don't think we need to throttle the logs. The
purpose of this log is to be able to find the cause from bugreports when video
is missing in either direction. We could use RTC_CHECK instead, but that seems a
bit harsh.

[commit-bot: I haz the power, 2016-09-27 16:53:47]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-09-27 16:53:48]

Dry run: Try jobs failed on following builders:
  android_arm64_rel on master.tryserver.webrtc (JOB_TIMED_OUT, no build URL)

[perkj_webrtc, 2016-09-28 15:04:59]

On 2016/09/27 15:06:11, magjed_webrtc wrote:
>
https://codereview.webrtc.org/2361803003/diff/40001/webrtc/media/base/videobr...
> File webrtc/media/base/videobroadcaster.cc (right):
> 
>
https://codereview.webrtc.org/2361803003/diff/40001/webrtc/media/base/videobr...
> webrtc/media/base/videobroadcaster.cc:55: LOG(LS_INFO) << "Dropping frame
> because there are no sink pairs in video "
> On 2016/09/26 11:23:59, sakal wrote:
> > On 2016/09/26 06:46:34, perkj_webrtc wrote:
> > > This may soon start spitting out logs in chrome that would be hit when a
> > > PeerConnection is created  but negotiation is not complete. I think it
would
> > be
> > > better if you instead add logs where a sink is added to a source in the
> source
> > > subclasses. If you do it here you will not know if it is a local or remote
> > > source.
> > 
> > I changed it to log VideoBroadcaster creation and adding a sink. Idea being
> that
> > if a video broadcaster is created but a sink is never added we should look
> into
> > it.
> > 
> > I tried adding logging to places where AddOrUpdateSink is called but it
seems
> > like a lot of work to trace where the calls are actually coming from.
> 
> It's probably good to have logs for VideoBroadcaster creation and adding a
sink
> regardless, but can't we keep this log? It's so much more explicit and obvious
> if we see this log in bugreports instead of trying to track down when and how
> sinks are added. Also logs are sometimes cropped, so it might not even be
> possible. I don't think Chrome will spit out this log since local video is
shown
> before negotiation is complete, and is it really a problem if we get a few of
> these logs in fringe cases? We know from the context in bugreports if local or
> remote video is missing, so that's not a problem.
> 
>
https://codereview.webrtc.org/2361803003/diff/40001/webrtc/video/video_stream...
> File webrtc/video/video_stream_decoder.cc (right):
> 
>
https://codereview.webrtc.org/2361803003/diff/40001/webrtc/video/video_stream...
> webrtc/video/video_stream_decoder.cc:90: LOG(LS_INFO) << "Dropping frame
because
> incoming_video_stream_ is NULL.";
> On 2016/09/26 11:39:22, stefan-webrtc (holmer) wrote:
> > On 2016/09/26 11:23:59, sakal wrote:
> > > On 2016/09/26 10:44:09, stefan-webrtc (holmer) wrote:
> > > > AFAICT this can never happen as incoming_video_stream_ is always set.
> > DCHECK?
> > > 
> > > It looks like this class is instantiated here:
> > >
> >
>
https://cs.chromium.org/chromium/src/third_party/webrtc/video/video_receive_s...
> > > 
> > > incoming_video_stream_ is set to nullptr if config_.renderer is nullptr.
> > Comment
> > > on that member says "'nullptr' disables rendering of this stream.". So I
> guess
> > > it is possible?
> > 
> > Seems like it's always being set outside of Call though?
> >
>
https://cs.chromium.org/chromium/src/third_party/webrtc/media/engine/webrtcvi...
> > 
> > If you think there are good reasons to support not attaching a renderer,
then
> I
> > can live with this one. But in that case perhaps we should throttle the logs
> to
> > not show 30 logs per second for 30 fps video?
> 
> There is probably no reason to not attach a renderer so when this happens it's
> probably an error. Therefore I don't think we need to throttle the logs. The
> purpose of this log is to be able to find the cause from bugreports when video
> is missing in either direction. We could use RTC_CHECK instead, but that seems
a
> bit harsh.

If you feel strongly that the VideoBroadCaster log is needed - can you do it so
that it does not spam the logs? Print once every second.

[perkj_webrtc, 2016-09-28 15:08:59]

lgtm

https://codereview.webrtc.org/2361803003/diff/180001/webrtc/video/video_strea...
File webrtc/video/video_stream_decoder.cc (right):

https://codereview.webrtc.org/2361803003/diff/180001/webrtc/video/video_strea...
webrtc/video/video_stream_decoder.cc:87: RTC_DCHECK(incoming_video_stream_ !=
nullptr);
nit: you don't need this type of dchecks - it will crash on
incoming_video_stream_->OnFrame

[sakal, 2016-09-29 12:00:59]

https://codereview.webrtc.org/2361803003/diff/180001/webrtc/video/video_strea...
File webrtc/video/video_stream_decoder.cc (right):

https://codereview.webrtc.org/2361803003/diff/180001/webrtc/video/video_strea...
webrtc/video/video_stream_decoder.cc:87: RTC_DCHECK(incoming_video_stream_ !=
nullptr);
On 2016/09/28 15:08:59, perkj_webrtc wrote:
> nit: you don't need this type of dchecks - it will crash on
> incoming_video_stream_->OnFrame

Done.

[stefan-webrtc, 2016-09-29 12:24:19]

Thanks for dealing with my requests, Sami.

lgtm

[sakal, 2016-09-29 12:31:18]

The CQ bit was checked by sakal@webrtc.org

[sakal, 2016-09-29 12:31:18]

The patchset sent to the CQ was uploaded after l-g-t-m from magjed@webrtc.org,
perkj@webrtc.org
Link to the patchset: https://codereview.webrtc.org/2361803003/#ps200001 (title:
"Remove the DCHECK since it will crash anyway.")

[commit-bot: I haz the power, 2016-09-29 12:31:24]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.webrtc.org/...

[commit-bot: I haz the power, 2016-09-29 12:34:29]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-09-29 12:34:30]

Try jobs failed on following builders:
  mac_compile_dbg on master.tryserver.webrtc (JOB_FAILED,
http://build.chromium.org/p/tryserver.webrtc/builders/mac_compile_dbg/builds/...)

[sakal, 2016-09-29 14:34:27]

The CQ bit was checked by sakal@webrtc.org

[commit-bot: I haz the power, 2016-09-29 14:34:32]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.webrtc.org/...

[commit-bot: I haz the power, 2016-09-29 16:34:52]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-09-29 16:34:54]

Try jobs failed on following builders:
  android_arm64_rel on master.tryserver.webrtc (JOB_TIMED_OUT, no build URL)

[sakal, 2016-09-30 12:26:41]

The CQ bit was checked by sakal@webrtc.org

[commit-bot: I haz the power, 2016-09-30 12:26:55]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.webrtc.org/...

[commit-bot: I haz the power, 2016-09-30 13:19:15]

Committed patchset #9 (id:200001)

[commit-bot: I haz the power, 2016-09-30 13:19:21]

Description was changed from

==========
Add logging statements to places where the frame might be dropped in WebRTC
pipeline.

BUG=b/31645554
==========

to

==========
Add logging statements to places where the frame might be dropped in WebRTC
pipeline.

BUG=b/31645554

Committed: https://crrev.com/55d932b33115ae6e3a542b822b33605a03edc324
Cr-Commit-Position: refs/heads/master@{#14457}
==========

[commit-bot: I haz the power, 2016-09-30 13:19:22]

Patchset 9 (id:??) landed as
https://crrev.com/55d932b33115ae6e3a542b822b33605a03edc324
Cr-Commit-Position: refs/heads/master@{#14457}

[Taylor Brandstetter, 2016-09-30 21:05:57]

deadbeef@webrtc.org changed reviewers:
+ deadbeef@webrtc.org

[Taylor Brandstetter, 2016-09-30 21:05:58]

https://codereview.webrtc.org/2361803003/diff/200001/webrtc/modules/video_cod...
File webrtc/modules/video_coding/generic_decoder.cc (right):

https://codereview.webrtc.org/2361803003/diff/200001/webrtc/modules/video_cod...
webrtc/modules/video_coding/generic_decoder.cc:62: RTC_DCHECK(callback !=
nullptr);
This DCHECK seems to be being hit by libjingle_peerconnection_android_unittest,
on a "track removal" test. Example:
https://build.chromium.org/p/client.webrtc/builders/Android32%20Tests%20%28L%...