Use verbose media logging on Chromecast

Use verbose media logging on Chromecast

On Chromecast we want media logging to be enabled on release builds by
default so that it gets recorded into device logs and sent with
feedback reports from end-users.

Review-Url: https://codereview.chromium.org/2625623002
Cr-Commit-Position: refs/heads/master@{#443150}
Committed: https://chromium.googlesource.com/chromium/src/+/0ed8a48cb50b37cf67f1ee94dd5e4742832db4bb

[servolk, 2017-01-10 02:11:43]

The CQ bit was checked by servolk@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-01-10 02:12:28]

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

[servolk, 2017-01-10 02:12:44]

Description was changed from

==========
Use verbose media logging on Chromecast

On Chromecast we want media logging to be enabled on release builds by
default so that it gets recorded into device logs and sent with
feedback reports from end-users.
==========

to

==========
Use verbose media logging on Chromecast

On Chromecast we want media logging to be enabled on release builds by
default so that it gets recorded into device logs and sent with
feedback reports from end-users.
==========

[servolk, 2017-01-10 02:12:44]

servolk@chromium.org changed reviewers:
+ esprehn@chromium.org

[commit-bot: I haz the power, 2017-01-10 05:47:20]

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

[commit-bot: I haz the power, 2017-01-10 05:47:20]

Dry run: This issue passed the CQ dry run.

[servolk, 2017-01-11 19:27:19]

On 2017/01/10 02:12:49, servolk wrote:

ping

[esprehn, 2017-01-11 21:36:56]

The only place I see that used is here:
https://cs.chromium.org/chromium/src/content/renderer/media/render_media_log....

which already turns it on #ifndef?

[servolk, 2017-01-11 21:48:27]

On 2017/01/11 21:36:56, esprehn wrote:
> The only place I see that used is here:
>
https://cs.chromium.org/chromium/src/content/renderer/media/render_media_log....
> 
> which already turns it on #ifndef?

Yes, but there it's defined as DVLOG(1) by default, so that it's a no-op on
release Chrome/Chromium builds. Here I'm overriding it to use VLOG(1) on
Chromecast (not DVLOG!), so that we get those messages by default even on
release builds on Chromecast firmware (on Chromecast these get logged into
system-wide device log and get included into feedback reports that end-users
send us when they encounter issues).

[esprehn, 2017-01-11 21:54:57]

Doesn't this produce a ton of log spam from MEDIA_LOG(ERROR, media_log_) all
over? Looking at the code this seems like it's going to make content on cast
slower?

[servolk, 2017-01-11 22:06:41]

On 2017/01/11 21:54:57, esprehn wrote:
> Doesn't this produce a ton of log spam from MEDIA_LOG(ERROR, media_log_) all
> over? Looking at the code this seems like it's going to make content on cast
> slower?

No, we are actually filtering out some of the noisiest events at
https://cs.chromium.org/chromium/src/content/renderer/media/render_media_log....,
so overall it's not too verbose (keep in mind that this is also what gets shown
in chrome://media-internals page, so both we and Chrome media team are
interested in keeping it fairly detailed, but not too noisy). We have actually
had this logging enabled in downstream Chromecast branches for a while now and
found it very useful when investigating feedback reports, we are just switching
Chromecast from M52 to M56 now and I've decided it's a good time to upstream
this change.
And AFAIK the performance of this logging have never been too bad, especially
compared to the rest of media processing.

[servolk, 2017-01-12 00:23:03]

On 2017/01/11 22:06:41, servolk wrote:
> On 2017/01/11 21:54:57, esprehn wrote:
> > Doesn't this produce a ton of log spam from MEDIA_LOG(ERROR, media_log_) all
> > over? Looking at the code this seems like it's going to make content on cast
> > slower?
> 
> No, we are actually filtering out some of the noisiest events at
>
https://cs.chromium.org/chromium/src/content/renderer/media/render_media_log....,
> so overall it's not too verbose (keep in mind that this is also what gets
shown
> in chrome://media-internals page, so both we and Chrome media team are
> interested in keeping it fairly detailed, but not too noisy). We have actually
> had this logging enabled in downstream Chromecast branches for a while now and
> found it very useful when investigating feedback reports, we are just
switching
> Chromecast from M52 to M56 now and I've decided it's a good time to upstream
> this change.
> And AFAIK the performance of this logging have never been too bad, especially
> compared to the rest of media processing.

If you are curious, here is an example of what a short (~1 min) YouTube playback
looks like:

[1:1:0111/160534.971997:VERBOSE1:render_media_log.cc(30)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kCreated"}
[1:1:0111/160534.972729:VERBOSE1:render_media_log.cc(30)] MediaEvent:
WEBMEDIAPLAYER_CREATED {}
[1:1:0111/160534.977673:VERBOSE1:render_media_log.cc(30)] MediaEvent: LOAD
{"url":"blob:https://www.youtube.com/36a8d07a-001c-40c4-aacc-6effaa34989b"}
[1:16:0111/160535.004148:VERBOSE1:render_media_log.cc(30)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kStarting"}
[1:1:0111/160535.206943:VERBOSE1:render_media_log.cc(30)] MediaEvent:
DURATION_SET {"duration":84.0}
[1:1:0111/160535.217540:VERBOSE1:render_media_log.cc(30)] MediaEvent:
DURATION_SET {"duration":83.921}
[1:16:0111/160535.483478:VERBOSE1:render_media_log.cc(30)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kPlaying"}
[1:1:0111/160535.833418:VERBOSE1:render_media_log.cc(30)] MediaEvent: PLAY {}
[1:1:0111/160606.942353:VERBOSE1:render_media_log.cc(30)] MediaEvent:
DURATION_SET {"duration":83.941}
[1:16:0111/160710.324878:VERBOSE1:render_media_log.cc(30)] MediaEvent: ENDED {}
[1:1:0111/160710.328100:VERBOSE1:render_media_log.cc(30)] MediaEvent: PAUSE {}
[1:16:0111/160715.884850:VERBOSE1:render_media_log.cc(30)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kStopping"}
[1:16:0111/160715.898521:VERBOSE1:render_media_log.cc(30)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kStopped"}
[1:1:0111/160715.899707:VERBOSE1:render_media_log.cc(30)] MediaEvent:
WEBMEDIAPLAYER_DESTROYED {}

(actually there's a bit more noise atm due to recently introduced
WATCH_TIME_UPDATE events, but I've just created a CL to take care of that:
https://codereview.chromium.org/2625233003/).

And of course this is actually most valueable in case of playback problems,
where one the last mediaevents typically indicates why the playback has failed.

[esprehn, 2017-01-12 00:27:21]

lgtm

[servolk, 2017-01-12 00:28:57]

The CQ bit was checked by servolk@chromium.org

[commit-bot: I haz the power, 2017-01-12 00:30:32]

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

[commit-bot: I haz the power, 2017-01-12 04:06:32]

CQ is committing da patch.

Bot data: {"patchset_id": 1, "attempt_start_ts": 1484180937142370, "parent_rev":
"8ad860dc81fee7d9808a7a74d5cf64e9ef1b1cf8", "commit_rev":
"0ed8a48cb50b37cf67f1ee94dd5e4742832db4bb"}

[commit-bot: I haz the power, 2017-01-12 04:07:57]

Description was changed from

==========
Use verbose media logging on Chromecast

On Chromecast we want media logging to be enabled on release builds by
default so that it gets recorded into device logs and sent with
feedback reports from end-users.
==========

to

==========
Use verbose media logging on Chromecast

On Chromecast we want media logging to be enabled on release builds by
default so that it gets recorded into device logs and sent with
feedback reports from end-users.

Review-Url: https://codereview.chromium.org/2625623002
Cr-Commit-Position: refs/heads/master@{#443150}
Committed:
https://chromium.googlesource.com/chromium/src/+/0ed8a48cb50b37cf67f1ee94dd5e...
==========

[commit-bot: I haz the power, 2017-01-12 04:07:58]

Committed patchset #1 (id:1) as
https://chromium.googlesource.com/chromium/src/+/0ed8a48cb50b37cf67f1ee94dd5e...