Add UMA histograms for time spent getting WebRTC audio render data.

Add UMA histograms for time spent getting WebRTC audio render data.

Adding:
* Media.Audio.Render.GetSourceDataTime.WebRTC
* Media.Audio.Render.GetSourceDataTimeMax.WebRTC

Deprecating WebRTC.AudioRenderTimes. It is replaces by Media.Audio.Render.GetSourceDataTime.WebRTC which logs every render call (instead of every 10 calls) and provides higher resolution.

The Max histogram logs the max time during a session (between Start() and Stop()).

This will better help show how often there is missed realtime deadlines on the process boundary due to WebRTC not delivering data in time. Plus a general picture of WebRTC's data delivery performance.

The new name allows adding this data for other sources under a common naming.

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

[Henrik Grunell, 2016-08-22 14:59:42]

Description was changed from

==========
Add UMA histograms for max and average times spent getting WebRTC audio render
data.

BUG=
==========

to

==========
Add UMA histograms for max and average times spent getting WebRTC audio render
data.

This will help show how often there is missed realtime deadlines on the process
boundary due to WebRTC not delivering data in time. Plus a general picture of
WebRTC's data delivery.
==========

[Henrik Grunell, 2016-08-22 14:59:43]

grunell@chromium.org changed reviewers:
+ dalecurtis@chromium.org, olka@chromium.org

[Henrik Grunell, 2016-08-22 15:00:00]

Description was changed from

==========
Add UMA histograms for max and average times spent getting WebRTC audio render
data.

This will help show how often there is missed realtime deadlines on the process
boundary due to WebRTC not delivering data in time. Plus a general picture of
WebRTC's data delivery.
==========

to

==========
Add UMA histograms for max and average times spent getting WebRTC audio render
data.

This will help show how often there is missed realtime deadlines on the process
boundary due to WebRTC not delivering data in time. Plus a general picture of
WebRTC's data delivery performance.
==========

[Henrik Grunell, 2016-08-22 15:14:54]

Patchset #1 (id:1) has been deleted

[Henrik Grunell, 2016-08-22 15:17:38]

grunell@chromium.org changed reviewers:
+ isherman@chromium.org

[Henrik Grunell, 2016-08-22 15:22:00]

Olga: All
Dale: Owner of content/renderer/media
Ilya: histograms.xml

https://codereview.chromium.org/2264073002/diff/20001/content/renderer/media/...
File content/renderer/media/webrtc_audio_renderer.cc (right):

https://codereview.chromium.org/2264073002/diff/20001/content/renderer/media/...
content/renderer/media/webrtc_audio_renderer.cc:505:
base::TimeDelta::FromMicroseconds(100),
I'm not sure if microseconds precision is possible with this macro?

[DaleCurtis, 2016-08-22 17:32:20]

https://codereview.chromium.org/2264073002/diff/20001/content/renderer/media/...
File content/renderer/media/webrtc_audio_renderer.cc (right):

https://codereview.chromium.org/2264073002/diff/20001/content/renderer/media/...
content/renderer/media/webrtc_audio_renderer.cc:491: base::TimeDelta elapsed =
base::TimeTicks::Now() - start_time;
This will skew if you catch it between a suspend/resume cycle. Is that okay? If
not you'll need to invalidate this measure when OnSuspend() || OnResume() are
called (but not on Android; where suspend/resume mean something different :| ).

https://codereview.chromium.org/2264073002/diff/20001/content/renderer/media/...
content/renderer/media/webrtc_audio_renderer.cc:505:
base::TimeDelta::FromMicroseconds(100),
On 2016/08/22 at 15:21:59, Henrik Grunell wrote:
> I'm not sure if microseconds precision is possible with this macro?

Yeah, the best you can do is milliseconds. The macro code explicitly calls
InMilliseconds().

[Ilya Sherman, 2016-08-22 21:17:47]

From the CL description: "This will help show how often there is missed realtime
deadlines on the process boundary due to WebRTC not delivering data in time."

Could you measure this directly, rather than indirectly?

https://codereview.chromium.org/2264073002/diff/20001/content/renderer/media/...
File content/renderer/media/webrtc_audio_renderer.cc (right):

https://codereview.chromium.org/2264073002/diff/20001/content/renderer/media/...
content/renderer/media/webrtc_audio_renderer.cc:505:
base::TimeDelta::FromMicroseconds(100),
On 2016/08/22 17:32:19, DaleCurtis wrote:
> On 2016/08/22 at 15:21:59, Henrik Grunell wrote:
> > I'm not sure if microseconds precision is possible with this macro?
> 
> Yeah, the best you can do is milliseconds. The macro code explicitly calls
> InMilliseconds().

Alternately, you could use a CUSTOM_COUNTS macro and record the time in
microseconds directly.

https://codereview.chromium.org/2264073002/diff/20001/tools/metrics/histogram...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/2264073002/diff/20001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:65802: +<histogram
name="WebRTC.AudioRenderTimesAverage" units="ms">
FWIW: If you do change the histogram to record data in microseconds, please
update the units as well.

https://codereview.chromium.org/2264073002/diff/20001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:65807: +    ms, so the average is over
100 function calls.
Keep in mind that an average implemented as a mean is very susceptible to
influence by outliers.  It seems like what you really want is to have a per-user
view of the WebRTC.AudioRenderTimes histogram (though it's not clear to me why
that histogram is sampled...).  I think it might be worth exploring server-side
processing of the existing data, rather than adding additional client-side
histograms.

[Henrik Grunell, 2016-08-23 10:42:04]

https://codereview.chromium.org/2264073002/diff/20001/content/renderer/media/...
File content/renderer/media/webrtc_audio_renderer.cc (right):

https://codereview.chromium.org/2264073002/diff/20001/content/renderer/media/...
content/renderer/media/webrtc_audio_renderer.cc:491: base::TimeDelta elapsed =
base::TimeTicks::Now() - start_time;
On 2016/08/22 17:32:19, DaleCurtis wrote:
> This will skew if you catch it between a suspend/resume cycle. Is that okay?
If
> not you'll need to invalidate this measure when OnSuspend() || OnResume() are
> called (but not on Android; where suspend/resume mean something different :|
).

Hmm, isn't it so that the ticks are updated as long as the system isn't yet
suspended, and not when suspended? I'm not sure how we can get a skew. Is there
something ambiguous going on when about to suspend?

https://codereview.chromium.org/2264073002/diff/20001/content/renderer/media/...
content/renderer/media/webrtc_audio_renderer.cc:505:
base::TimeDelta::FromMicroseconds(100),
On 2016/08/22 21:17:47, Ilya Sherman wrote:
> On 2016/08/22 17:32:19, DaleCurtis wrote:
> > On 2016/08/22 at 15:21:59, Henrik Grunell wrote:
> > > I'm not sure if microseconds precision is possible with this macro?
> > 
> > Yeah, the best you can do is milliseconds. The macro code explicitly calls
> > InMilliseconds().
> 
> Alternately, you could use a CUSTOM_COUNTS macro and record the time in
> microseconds directly.

OK, I've switched to CUSTOM_COUNTS.

https://codereview.chromium.org/2264073002/diff/20001/tools/metrics/histogram...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/2264073002/diff/20001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:65802: +<histogram
name="WebRTC.AudioRenderTimesAverage" units="ms">
On 2016/08/22 21:17:47, Ilya Sherman wrote:
> FWIW: If you do change the histogram to record data in microseconds, please
> update the units as well.

Done.

https://codereview.chromium.org/2264073002/diff/20001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:65807: +    ms, so the average is over
100 function calls.
On 2016/08/22 21:17:47, Ilya Sherman wrote:
> Keep in mind that an average implemented as a mean is very susceptible to
> influence by outliers.

Yes, and that's what we want. Ideally, we'd like to log every render call, but
that was pushed back when WebRTC.AudioRenderTimes was added quite a long time
ago. (Hence that metric measures every 10 call.) So second best is to log over a
period. We also have the max over a session to get that perspective too. And,
apart from the UMA data, we've also added tracing around this to analyze
individual users' audio rendering performance.

> It seems like what you really want is to have a per-user
> view of the WebRTC.AudioRenderTimes histogram (though it's not clear to me why
> that histogram is sampled...).  I think it might be worth exploring
server-side
> processing of the existing data, rather than adding additional client-side
> histograms.

This overview is good to have, and for per user info the tracing will be very
helpful. Using WebRTC.AudioRenderTimes is not really helpful since it only
measures every 10 call. It might be time to deprecate it with the new one in
place, but I'd like to see them in parallel for a while first.

[Ilya Sherman, 2016-08-23 19:26:49]

https://codereview.chromium.org/2264073002/diff/20001/tools/metrics/histogram...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/2264073002/diff/20001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:65807: +    ms, so the average is over
100 function calls.
On 2016/08/23 10:42:04, Henrik Grunell wrote:
> On 2016/08/22 21:17:47, Ilya Sherman wrote:
> > Keep in mind that an average implemented as a mean is very susceptible to
> > influence by outliers.
> 
> Yes, and that's what we want. Ideally, we'd like to log every render call, but
> that was pushed back when WebRTC.AudioRenderTimes was added quite a long time
> ago. (Hence that metric measures every 10 call.) So second best is to log over
a
> period. We also have the max over a session to get that perspective too. And,
> apart from the UMA data, we've also added tracing around this to analyze
> individual users' audio rendering performance.

Hmm, why was there pushback to recording every render call?  Histograms are
intended to be *very* efficient.

> > It seems like what you really want is to have a per-user
> > view of the WebRTC.AudioRenderTimes histogram (though it's not clear to me
why
> > that histogram is sampled...).  I think it might be worth exploring
> server-side
> > processing of the existing data, rather than adding additional client-side
> > histograms.
> 
> This overview is good to have, and for per user info the tracing will be very
> helpful. Using WebRTC.AudioRenderTimes is not really helpful since it only
> measures every 10 call. It might be time to deprecate it with the new one in
> place, but I'd like to see them in parallel for a while first.

[Henrik Grunell, 2016-08-24 10:25:56]

Description was changed from

==========
Add UMA histograms for max and average times spent getting WebRTC audio render
data.

This will help show how often there is missed realtime deadlines on the process
boundary due to WebRTC not delivering data in time. Plus a general picture of
WebRTC's data delivery performance.
==========

to

==========
Add UMA histograms for time spent getting WebRTC audio render data.

Adding:
* Media.Audio.Render.GetSourceDataTime.WebRTC
* Media.Audio.Render.GetSourceDataTimeMax.WebRTC

Deprecating WebRTC.AudioRenderTimes. It is replaces by
Media.Audio.Render.GetSourceDataTime.WebRTC which logs every render call
(instead of every 10 calls) and provides higher resolution.

The Max histogram logs the max time during a session (between Start() and
Stop()).

This will better help show how often there is missed realtime deadlines on the
process boundary due to WebRTC not delivering data in time. Plus a general
picture of WebRTC's data delivery performance.

The new name allows adding this data for other sources under a common naming.
==========

[Henrik Grunell, 2016-08-24 10:32:17]

Ptal.

https://codereview.chromium.org/2264073002/diff/20001/tools/metrics/histogram...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/2264073002/diff/20001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:65807: +    ms, so the average is over
100 function calls.
On 2016/08/23 19:26:49, Ilya Sherman wrote:
> On 2016/08/23 10:42:04, Henrik Grunell wrote:
> > On 2016/08/22 21:17:47, Ilya Sherman wrote:
> > > Keep in mind that an average implemented as a mean is very susceptible to
> > > influence by outliers.
> > 
> > Yes, and that's what we want. Ideally, we'd like to log every render call,
but
> > that was pushed back when WebRTC.AudioRenderTimes was added quite a long
time
> > ago. (Hence that metric measures every 10 call.) So second best is to log
over
> a
> > period. We also have the max over a session to get that perspective too.
And,
> > apart from the UMA data, we've also added tracing around this to analyze
> > individual users' audio rendering performance.
> 
> Hmm, why was there pushback to recording every render call?  Histograms are
> intended to be *very* efficient.
> 

I checked with the author and in the CL it was introduced in, and the reason
seems to have been to just err on the safe side. I've deprecated the current
histogram, and now log every call in the new one. Also renamed them to allow
adding the same data for other sources under a common naming. The logging is
done every 10 ms.

> > > It seems like what you really want is to have a per-user
> > > view of the WebRTC.AudioRenderTimes histogram (though it's not clear to me
> why
> > > that histogram is sampled...).  I think it might be worth exploring
> > server-side
> > > processing of the existing data, rather than adding additional client-side
> > > histograms.
> > 
> > This overview is good to have, and for per user info the tracing will be
very
> > helpful. Using WebRTC.AudioRenderTimes is not really helpful since it only
> > measures every 10 call. It might be time to deprecate it with the new one in
> > place, but I'd like to see them in parallel for a while first.
>

[o1ka, 2016-08-24 11:52:42]

https://codereview.chromium.org/2264073002/diff/60001/content/renderer/media/...
File content/renderer/media/webrtc_audio_renderer.cc (right):

https://codereview.chromium.org/2264073002/diff/60001/content/renderer/media/...
content/renderer/media/webrtc_audio_renderer.cc:307: if (source_render_called_)
{
No need for the flag: you can just check (!max_render_time_.is_zero());
or (max_render_time_ != base::TimeDelta).

[Henrik Grunell, 2016-08-24 12:16:09]

https://codereview.chromium.org/2264073002/diff/60001/content/renderer/media/...
File content/renderer/media/webrtc_audio_renderer.cc (right):

https://codereview.chromium.org/2264073002/diff/60001/content/renderer/media/...
content/renderer/media/webrtc_audio_renderer.cc:307: if (source_render_called_)
{
On 2016/08/24 11:52:42, o1ka wrote:
> No need for the flag: you can just check (!max_render_time_.is_zero());
> or (max_render_time_ != base::TimeDelta).

Of course. We can safely assume that the render call takes non-zero time and use
that. :) Done.

[o1ka, 2016-08-24 12:30:19]

On 2016/08/24 12:16:09, Henrik Grunell wrote:
>
https://codereview.chromium.org/2264073002/diff/60001/content/renderer/media/...
> File content/renderer/media/webrtc_audio_renderer.cc (right):
> 
>
https://codereview.chromium.org/2264073002/diff/60001/content/renderer/media/...
> content/renderer/media/webrtc_audio_renderer.cc:307: if
(source_render_called_)
> {
> On 2016/08/24 11:52:42, o1ka wrote:
> > No need for the flag: you can just check (!max_render_time_.is_zero());
> > or (max_render_time_ != base::TimeDelta).
> 
> Of course. We can safely assume that the render call takes non-zero time and
use
> that. :) Done.

lgtm

[Henrik Grunell, 2016-08-24 12:38:37]

Made another change, not sure about this.

https://codereview.chromium.org/2264073002/diff/100001/content/renderer/media...
File content/renderer/media/webrtc_audio_renderer.cc (right):

https://codereview.chromium.org/2264073002/diff/100001/content/renderer/media...
content/renderer/media/webrtc_audio_renderer.cc:487: if
(base::TimeTicks::IsHighResolution()) {
This is only applicable to Windows (as of now), with a ~15.5 ms precision in low
res. I don't know how the value is rounded or how common falling back is. I'm
hesitating to exclude the data depending on this. Maybe another histogram is a
good option? Wdyt?

[o1ka, 2016-08-24 12:43:14]

https://codereview.chromium.org/2264073002/diff/100001/content/renderer/media...
File content/renderer/media/webrtc_audio_renderer.cc (right):

https://codereview.chromium.org/2264073002/diff/100001/content/renderer/media...
content/renderer/media/webrtc_audio_renderer.cc:487: if
(base::TimeTicks::IsHighResolution()) {
On 2016/08/24 12:38:37, Henrik Grunell wrote:
> This is only applicable to Windows (as of now), with a ~15.5 ms precision in
low
> res. I don't know how the value is rounded or how common falling back is. I'm
> hesitating to exclude the data depending on this. Maybe another histogram is a
> good option? Wdyt?

I think it's fine to log it for high res only.

[DaleCurtis, 2016-08-24 17:45:16]

lgtm

https://codereview.chromium.org/2264073002/diff/20001/content/renderer/media/...
File content/renderer/media/webrtc_audio_renderer.cc (right):

https://codereview.chromium.org/2264073002/diff/20001/content/renderer/media/...
content/renderer/media/webrtc_audio_renderer.cc:491: base::TimeDelta elapsed =
base::TimeTicks::Now() - start_time;
On 2016/08/23 at 10:42:04, Henrik Grunell wrote:
> On 2016/08/22 17:32:19, DaleCurtis wrote:
> > This will skew if you catch it between a suspend/resume cycle. Is that okay?
If
> > not you'll need to invalidate this measure when OnSuspend() || OnResume()
are
> > called (but not on Android; where suspend/resume mean something different :|
).
> 
> Hmm, isn't it so that the ticks are updated as long as the system isn't yet
suspended, and not when suspended? I'm not sure how we can get a skew. Is there
something ambiguous going on when about to suspend?

If you record start_time prior to suspend and then compare against now during
resume you're going to get a massive value. It may not matter here, but it's
something to consider.

[Ilya Sherman, 2016-08-24 21:53:42]

LGTM % an optional suggestion:

https://codereview.chromium.org/2264073002/diff/100001/content/renderer/media...
File content/renderer/media/webrtc_audio_renderer.cc (right):

https://codereview.chromium.org/2264073002/diff/100001/content/renderer/media...
content/renderer/media/webrtc_audio_renderer.cc:46: const int
kRenderTimeHistogramMaxMicroseconds = 30 * 1000;  // 30 milliseconds
I somewhat suspect that this is too low an upper bound, if you want visibility
into the long tail.  And, with 50 buckets, you should be able to allow for a
much larger range within the histogram, without sacrificing much precision in
the smaller buckets.  I'd suggest an upper bound of at least 1 second -- that
would match the range of the UMA_HISTOGRAM_TIMES macro, just with both the min
and the max reduced by a factor of 10.

[Henrik Grunell, 2016-08-25 08:34:07]

https://codereview.chromium.org/2264073002/diff/100001/content/renderer/media...
File content/renderer/media/webrtc_audio_renderer.cc (right):

https://codereview.chromium.org/2264073002/diff/100001/content/renderer/media...
content/renderer/media/webrtc_audio_renderer.cc:46: const int
kRenderTimeHistogramMaxMicroseconds = 30 * 1000;  // 30 milliseconds
On 2016/08/24 21:53:41, Ilya Sherman wrote:
> I somewhat suspect that this is too low an upper bound, if you want visibility
> into the long tail.  And, with 50 buckets, you should be able to allow for a
> much larger range within the histogram, without sacrificing much precision in
> the smaller buckets.  I'd suggest an upper bound of at least 1 second -- that
> would match the range of the UMA_HISTOGRAM_TIMES macro, just with both the min
> and the max reduced by a factor of 10.

That makes sense, changed to max 1 s.

https://codereview.chromium.org/2264073002/diff/100001/content/renderer/media...
content/renderer/media/webrtc_audio_renderer.cc:487: if
(base::TimeTicks::IsHighResolution()) {
On 2016/08/24 12:43:14, o1ka wrote:
> On 2016/08/24 12:38:37, Henrik Grunell wrote:
> > This is only applicable to Windows (as of now), with a ~15.5 ms precision in
> low
> > res. I don't know how the value is rounded or how common falling back is.
I'm
> > hesitating to exclude the data depending on this. Maybe another histogram is
a
> > good option? Wdyt?
> 
> I think it's fine to log it for high res only.

Let's go for that.

[Henrik Grunell, 2016-08-25 08:34:29]

The CQ bit was checked by grunell@chromium.org

[Henrik Grunell, 2016-08-25 08:34:30]

The patchset sent to the CQ was uploaded after l-g-t-m from olka@chromium.org,
isherman@chromium.org, dalecurtis@chromium.org
Link to the patchset: https://codereview.chromium.org/2264073002/#ps120001
(title: "Code review (Ilya).")

[commit-bot: I haz the power, 2016-08-25 08:35:03]

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, 2016-08-25 11:10:28]

Description was changed from

==========
Add UMA histograms for time spent getting WebRTC audio render data.

Adding:
* Media.Audio.Render.GetSourceDataTime.WebRTC
* Media.Audio.Render.GetSourceDataTimeMax.WebRTC

Deprecating WebRTC.AudioRenderTimes. It is replaces by
Media.Audio.Render.GetSourceDataTime.WebRTC which logs every render call
(instead of every 10 calls) and provides higher resolution.

The Max histogram logs the max time during a session (between Start() and
Stop()).

This will better help show how often there is missed realtime deadlines on the
process boundary due to WebRTC not delivering data in time. Plus a general
picture of WebRTC's data delivery performance.

The new name allows adding this data for other sources under a common naming.
==========

to

==========
Add UMA histograms for time spent getting WebRTC audio render data.

Adding:
* Media.Audio.Render.GetSourceDataTime.WebRTC
* Media.Audio.Render.GetSourceDataTimeMax.WebRTC

Deprecating WebRTC.AudioRenderTimes. It is replaces by
Media.Audio.Render.GetSourceDataTime.WebRTC which logs every render call
(instead of every 10 calls) and provides higher resolution.

The Max histogram logs the max time during a session (between Start() and
Stop()).

This will better help show how often there is missed realtime deadlines on the
process boundary due to WebRTC not delivering data in time. Plus a general
picture of WebRTC's data delivery performance.

The new name allows adding this data for other sources under a common naming.
==========

[commit-bot: I haz the power, 2016-08-25 11:10:29]

Committed patchset #6 (id:120001)

[commit-bot: I haz the power, 2016-08-25 11:13:54]

Description was changed from

==========
Add UMA histograms for time spent getting WebRTC audio render data.

Adding:
* Media.Audio.Render.GetSourceDataTime.WebRTC
* Media.Audio.Render.GetSourceDataTimeMax.WebRTC

Deprecating WebRTC.AudioRenderTimes. It is replaces by
Media.Audio.Render.GetSourceDataTime.WebRTC which logs every render call
(instead of every 10 calls) and provides higher resolution.

The Max histogram logs the max time during a session (between Start() and
Stop()).

This will better help show how often there is missed realtime deadlines on the
process boundary due to WebRTC not delivering data in time. Plus a general
picture of WebRTC's data delivery performance.

The new name allows adding this data for other sources under a common naming.
==========

to

==========
Add UMA histograms for time spent getting WebRTC audio render data.

Adding:
* Media.Audio.Render.GetSourceDataTime.WebRTC
* Media.Audio.Render.GetSourceDataTimeMax.WebRTC

Deprecating WebRTC.AudioRenderTimes. It is replaces by
Media.Audio.Render.GetSourceDataTime.WebRTC which logs every render call
(instead of every 10 calls) and provides higher resolution.

The Max histogram logs the max time during a session (between Start() and
Stop()).

This will better help show how often there is missed realtime deadlines on the
process boundary due to WebRTC not delivering data in time. Plus a general
picture of WebRTC's data delivery performance.

The new name allows adding this data for other sources under a common naming.

Committed: https://crrev.com/af11e92e56cc47146ad87e641e48dcc967fea513
Cr-Commit-Position: refs/heads/master@{#414392}
==========

[commit-bot: I haz the power, 2016-08-25 11:13:55]

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