Log audio splice sanitizer warnings and errors to media-internals

Log audio splice sanitizer warnings and errors to media-internals

Plumbs a MediaLog into AudioSplicer's AudioStreamSanitizers and uses it
to log warnings and errors to chrome://media-internals. This should
help ease of diagnosis of potentially badly muxed frame timestamps
and durations. Previously, a repro on a Debug build and inspection
of DVLOG()s was required to get similar logs.

BUG=505931, 490144
R=dalecurtis@chromium.org,chcunningham@chromium.org,xhwang@chromium.org
TEST=repro of bug 505931's audio-only gap tolerance decode error shows log in media-internals.

Committed: https://crrev.com/e27df71fa3f038ca2a25f457560036ae861b4679
Cr-Commit-Position: refs/heads/master@{#338233}

[wolenetz, 2015-07-09 19:28:19]

wolenetz@chromium.org changed reviewers:
+ xhwang@chromium.org

[wolenetz, 2015-07-09 19:28:20]

Please take a look at patch set 1:
dalecurtis@: everything, committer, splicer creator
xhwang@: please review from perspective of media-internals potential log spam
chcunningham@: everything, too (MSE-related)

Thanks!

More details:

I tried the magine.com repro from bug 490144 (only for a few minutes) and found
no repro, though that's less indicative that bug has been fixed since it took
many hours to repro a decode error previously. None of the new media-internals
log entries occurred during this repro attempt.

Not all the new logs have been tested, but at least one of the decode errors and
one of the warnings occurred during a repro of bug 505931's audio-only stream
(using shaka player):

...
00:00:00 949	event	PLAY
00:00:00 949	seek_target	1304211
00:00:00 949	pipeline_state	kSeeking
00:00:00 950	pipeline_state	kPlaying
00:00:09 565	info	Audio codec: mp4a.40.2
00:00:16 739	debug	Audio splicer inserting silence for small gap of 316us at
time 1304226961684us.
00:00:18 558	info	Audio codec: mp4a.40.2
00:00:29 565	info	Audio codec: mp4a.40.2
00:00:30 564	info	Audio codec: mp4a.40.2
00:00:39 566	info	Audio codec: mp4a.40.2
00:00:46 761	error	Audio splicing failed: coded frame timestamp differs from
expected timestamp 1304256978011us by 58989us, more than threshold of +/-50ms.
Expected timestamp is based on decoded frames and frame rate.
00:00:46 761	error	audio decode error during playing
00:00:46 761	pipeline_error	pipeline: decode error
00:00:46 762	pipeline_state	kStopping
00:00:46 763	pipeline_state	kStopped

https://codereview.chromium.org/1229123002/diff/1/media/base/audio_splicer.cc
File media/base/audio_splicer.cc (right):

https://codereview.chromium.org/1229123002/diff/1/media/base/audio_splicer.cc...
media/base/audio_splicer.cc:192: DVLOG(1) << "Gap detected @ " <<
expected_timestamp.InMicroseconds()
I'm keeping the warnings DVLOGged for now, since they are capped per-sanitizer
instance at max 5 in media-internals.

[DaleCurtis, 2015-07-09 21:14:59]

Nice work! lgtm

[wolenetz, 2015-07-09 21:29:27]

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

[xhwang, 2015-07-09 21:31:00]

Looking good. Just a few questions.

https://codereview.chromium.org/1229123002/diff/1/media/base/audio_splicer.cc
File media/base/audio_splicer.cc (right):

https://codereview.chromium.org/1229123002/diff/1/media/base/audio_splicer.cc...
media/base/audio_splicer.cc:31: static const int kMaxSanitizerWarningLogs = 5;
nit: here and on line 24, not need to use "static" as namespace level consts are
automatically static.

https://codereview.chromium.org/1229123002/diff/1/media/base/audio_splicer.cc...
media/base/audio_splicer.cc:156: << "us";
Is it necessary to use "us" in the last part? I found "1304226961684us" not very
readable. But it's fine if you really need that precision.

https://codereview.chromium.org/1229123002/diff/1/media/base/audio_splicer.cc...
media/base/audio_splicer.cc:283: have_all_pre_splice_buffers_(false) {
How often do these logs happen in normal cases? Are they only happening on
websites with badly muxed content? 

We only store 128 logs per process [1]. We'll need to figure out some better way
to store logs when we have more and more logs overtime. For example, we could
keep only non-debug events.

[1]
https://code.google.com/p/chromium/codesearch#chromium/src/content/browser/me...

[commit-bot: I haz the power, 2015-07-09 21:31:05]

Dry run: CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1229123002/1

[commit-bot: I haz the power, 2015-07-09 21:46:21]

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

[commit-bot: I haz the power, 2015-07-09 21:46:22]

Dry run: Try jobs failed on following builders:
  android_compile_dbg on tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/android_compile...)
  cast_shell_linux on tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/cast_shell_linu...)
  mac_chromium_rel_ng on tryserver.chromium.mac (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.mac/builders/mac_chromium_rel_...)

(exceeded global retry quota)

[wolenetz, 2015-07-09 22:45:00]

Patch set 2 is ready for review:

https://codereview.chromium.org/1229123002/diff/1/media/base/audio_splicer.cc
File media/base/audio_splicer.cc (right):

https://codereview.chromium.org/1229123002/diff/1/media/base/audio_splicer.cc...
media/base/audio_splicer.cc:31: static const int kMaxSanitizerWarningLogs = 5;
On 2015/07/09 21:30:59, xhwang wrote:
> nit: here and on line 24, not need to use "static" as namespace level consts
are
> automatically static.

Good point. Further, to prevent (and give build err if it happens) aliasing
perhaps of some other [media::]kMinGapSize or [media::]kMaxSanitizerWarningLogs,
and since it's deprecated to use static at namespace level to make local to
source file, I'll use anonymous namespace scope. And I see no reason to also not
make these an enum, and to move AccurateTimeStart and CreateAudioBufferWrapper
into the anonymous namespace.

https://codereview.chromium.org/1229123002/diff/1/media/base/audio_splicer.cc...
media/base/audio_splicer.cc:156: << "us";
On 2015/07/09 21:30:59, xhwang wrote:
> Is it necessary to use "us" in the last part? I found "1304226961684us" not
very
> readable. But it's fine if you really need that precision.

That high time timestamp (~15 days) is not a common occurrence in normal streams
(though is supported, of course). There have been issues in our stack with the
default TimeDelta() operator<< granularity not showing more precision than 10s
of milliseconds, when sometimes off-by-one-microsecond is enough to trigger a
different code path. Yes, I think it's necessary in the cases in this CL. I
prefer to indicate units, and think "us" is better than " microseconds" in the
context of reducing log spam. I'm uncertain that "µs" would work everywhere, so
chose the fairly common "us" abbreviation for microseconds.

https://codereview.chromium.org/1229123002/diff/1/media/base/audio_splicer.cc...
media/base/audio_splicer.cc:283: have_all_pre_splice_buffers_(false) {
On 2015/07/09 21:30:59, xhwang wrote:
> How often do these logs happen in normal cases? Are they only happening on
> websites with badly muxed content? 
> 
> We only store 128 logs per process [1]. We'll need to figure out some better
way
> to store logs when we have more and more logs overtime. For example, we could
> keep only non-debug events.
> 
> [1]
>
https://code.google.com/p/chromium/codesearch#chromium/src/content/browser/me...

If content is muxed correctly, and if the splicer is behaving as intended, there
should not be any of these messages. I played a few minutes of YT live and
recorded video and found none of the logs were triggered.

If spam becomes an issue, we could elevate the num_warning_logs_ counter to be a
pointer to a shared counter across an AudioSplicer instance, or even better, a
counter specific to an AudioRendererImpl instance (so long as the counter is
always accessed on the same thread).

I was also thinking similarly that we should do perhaps some log entry
coalescing (like devtools), where we keep a count of consecutive messages of the
same type beyond some cap (and only keep details per entry for those encountered
below a cap), and have a cap on message types across the player instance. This
would be a larger refactoring.

Also, bug 492833 tracks adding some specific media-internals properties around
audio-splicer behavior that we could use along with a shared cap to give greater
depth of splicer function detail without spamming the log.

In short, yes there could be spam for badly muxed streams. I don't expect common
streams to be so badly muxed (since we would have likely heard more complaints
about audio_splicer decode errors). We don't have UMA to confirm these
expectations though.

I also like your idea of selectively dropping [INFO and] DEBUG log messages (if
we start to run out of space, perhaps). sgtm :)

[wolenetz, 2015-07-09 22:48:43]

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

[wolenetz, 2015-07-09 22:48:44]

The patchset sent to the CQ was uploaded after l-g-t-m from
dalecurtis@chromium.org
Link to the patchset: https://codereview.chromium.org/1229123002/#ps20001
(title: "Address xhwang@'s comments and fix the unit test")

[commit-bot: I haz the power, 2015-07-09 22:51:29]

Dry run: CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1229123002/20001

[xhwang, 2015-07-09 22:59:36]

lgtm

https://codereview.chromium.org/1229123002/diff/1/media/base/audio_splicer.cc
File media/base/audio_splicer.cc (right):

https://codereview.chromium.org/1229123002/diff/1/media/base/audio_splicer.cc...
media/base/audio_splicer.cc:31: static const int kMaxSanitizerWarningLogs = 5;
On 2015/07/09 22:45:00, wolenetz wrote:
> On 2015/07/09 21:30:59, xhwang wrote:
> > nit: here and on line 24, not need to use "static" as namespace level consts
> are
> > automatically static.
> 
> Good point. Further, to prevent (and give build err if it happens) aliasing
> perhaps of some other [media::]kMinGapSize or
[media::]kMaxSanitizerWarningLogs,
> and since it's deprecated to use static at namespace level to make local to
> source file, I'll use anonymous namespace scope. And I see no reason to also
not
> make these an enum, and to move AccurateTimeStart and CreateAudioBufferWrapper
> into the anonymous namespace.

The last time I looked at this, there's pretty much no difference between an
integer constant and an enum. Personally I like const int better, but this is up
to you :)

[chcunningham, 2015-07-09 23:31:57]

lgtm

Woot, love these media logs changes.

[wolenetz, 2015-07-09 23:46:24]

The CQ bit was unchecked by wolenetz@chromium.org

[wolenetz, 2015-07-10 02:03:54]

The CQ bit was checked by wolenetz@chromium.org

[wolenetz, 2015-07-10 02:06:32]

On 2015/07/09 23:31:57, chcunningham wrote:
> lgtm
> 
> Woot, love these media logs changes.

Thanks for the reviews!

[commit-bot: I haz the power, 2015-07-10 02:06:58]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1229123002/20001

[commit-bot: I haz the power, 2015-07-10 03:06:49]

Committed patchset #2 (id:20001)

[commit-bot: I haz the power, 2015-07-10 03:08:37]

Patchset 2 (id:??) landed as
https://crrev.com/e27df71fa3f038ca2a25f457560036ae861b4679
Cr-Commit-Position: refs/heads/master@{#338233}