Adds time measurement of WebRtcAudioRenderer::Render

Adds time measurement of AudioOutputDevice::AudioThreadCallback::Process

BUG=NONE
TEST=Manually tested WebRTC clients and verified new UMA after close.

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

[henrika (OOO until Aug 14), 2014-09-17 13:50:58]

henrika@chromium.org changed reviewers:
+ tommi@chromium.org, xians@chromium.org

[henrika (OOO until Aug 14), 2014-09-17 13:52:11]

Just an idea to get a better view of on which platforms we have render-side
issues (which can cause glitches).

Example from ML session (Linux):

Histogram: Media.AudioOutputDevice.ProcessTime recorded 5064 samples, average =
0.0 (flags = 0x1)
0   ------------------------------------------------------------------------O
(5014 = 99.0%)
1   -O                                                                       
(49 = 1.0%) {99.0%}
2   ... 
12  O                                                                         (1
= 0.0%) {100.0%}
14  ...

[tommi (sloooow) - chröme, 2014-09-17 14:06:56]

lgtm

[henrika (OOO until Aug 14), 2014-09-17 14:23:05]

henrika@chromium.org changed reviewers:
+ asvitkine@chromium.org

[henrika (OOO until Aug 14), 2014-09-17 14:23:34]

+Alexei for the XML-part.

[Alexei Svitkine (slow), 2014-09-17 14:24:42]

lgtm

[no longer working on chromium, 2014-09-17 14:28:39]

Do you really want to log each callback for all clients?

The numbers might not tell anything at all since different clients expect
different time intervals between callbacks.

[no longer working on chromium, 2014-09-17 14:54:51]

https://codereview.chromium.org/577953002/diff/20001/media/audio/audio_output...
File media/audio/audio_output_device.cc (right):

https://codereview.chromium.org/577953002/diff/20001/media/audio/audio_output...
media/audio/audio_output_device.cc:294:
SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputDevice.ProcessTime");
I would suggest moving the code to webrtc_audio_renderer.cc, and how about
logging it every 10 callbacks (every 100ms)?

[henrika (OOO until Aug 14), 2014-09-17 14:59:49]

Good comments Shijing. Let me rethink and come back tomorrow.

[henrika (OOO until Aug 14), 2014-09-18 10:56:47]

https://codereview.chromium.org/577953002/diff/20001/media/audio/audio_output...
File media/audio/audio_output_device.cc (right):

https://codereview.chromium.org/577953002/diff/20001/media/audio/audio_output...
media/audio/audio_output_device.cc:294:
SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputDevice.ProcessTime");
I could move it but AFAIK it is not possible to log at a lower frequency due to
the design of SCOPED_UMA_HISTOGRAM_TIMER. It will only measure the elapsed time
int scope and I can't figure out a way to do so and at the same time check a
counter. If so, I would have to add my time measurement manually instead.

[henrika (OOO until Aug 14), 2014-09-18 11:03:16]

https://codereview.chromium.org/577953002/diff/20001/media/audio/audio_output...
File media/audio/audio_output_device.cc (right):

https://codereview.chromium.org/577953002/diff/20001/media/audio/audio_output...
media/audio/audio_output_device.cc:294:
SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputDevice.ProcessTime");
Let me see if I can do something without the macro instead.

[henrika (OOO until Aug 14), 2014-09-18 12:10:16]

Patchset #4 (id:60001) has been deleted

[henrika (OOO until Aug 14), 2014-09-18 12:18:50]

xians@: PTAL

[no longer working on chromium, 2014-09-18 17:35:42]

https://codereview.chromium.org/577953002/diff/80001/content/renderer/media/w...
File content/renderer/media/webrtc_audio_renderer.cc (right):

https://codereview.chromium.org/577953002/diff/80001/content/renderer/media/w...
content/renderer/media/webrtc_audio_renderer.cc:429: base::TimeTicks start_time
= base::TimeTicks::Now() ;
Render() is triggered by callbacks from the device, on Linux and Mac, the
callback is every 10ms, while on windows it is not strictly 10ms, and on
Android, it is at least 20ms. It means that the time we are measuring might be
more than 1 callback into webrtc on Windows and Android.

I am not sure how UMA_HISTOGRAM_TIMES is implemented, but in case the above
information matters, you probably should move the code into SourceCallback.

[henrika (OOO until Aug 14), 2014-09-19 13:13:54]

https://codereview.chromium.org/577953002/diff/80001/content/renderer/media/w...
File content/renderer/media/webrtc_audio_renderer.cc (right):

https://codereview.chromium.org/577953002/diff/80001/content/renderer/media/w...
content/renderer/media/webrtc_audio_renderer.cc:429: base::TimeTicks start_time
= base::TimeTicks::Now() ;
Will move it to SourceCallback. Thanks.

[henrika (OOO until Aug 14), 2014-09-19 13:21:24]

xians, PTAL.

[no longer working on chromium, 2014-09-19 13:51:37]

lgtm if you fix the name of the uma stat.

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

https://codereview.chromium.org/577953002/diff/100001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:37688: +<histogram
name="WebRTC.AudioRenderTimes" units="milliseconds">
I think it should be WebRTC.AudioRenderTime here :)

[henrika (OOO until Aug 14), 2014-09-19 13:58:54]

Discussed off-line. WebRTC.AudioRenderTime is already in use (deprecated) and I
did not dare removing it or reuse. Will keep as is.

[henrika (OOO until Aug 14), 2014-09-19 13:59:00]

The CQ bit was checked by henrika@chromium.org

[commit-bot: I haz the power, 2014-09-19 14:00:23]

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

[commit-bot: I haz the power, 2014-09-19 14:57:42]

Committed patchset #5 (id:100001) as 12e2d0581135ea10bce420b0e368ea7a07f3769d

[commit-bot: I haz the power, 2014-09-19 14:58:31]

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