More tracing for audio rendering

In case AudioOutputDevice buffer size is not the same as hardware buffer size, AudioOutputResampler on browser side does rebuffering (fifo-based). Each time fifo edge is reached, fifo will initiate two reads one by one.

It means that AudioOuputDevice::Render() calles are NOT issued with a constant interval based on output buffer size duration. For example, for WebRTC it means Voice Engine can receive 2 calls one by one without 10 ms interval.

It may result in a missed deadline on Browser/Renderer edge, which causes audio glitch.

We want to trace these events to collect the relevant data in cases of crackling/distorted audio.

Also, a bit of tracing for mixing to see how it affects rendering performance.

BUG=

Committed: https://crrev.com/8ec171e0559a846b1c5261631914726134ec2555
Cr-Commit-Position: refs/heads/master@{#413684}

[o1ka, 2016-08-19 13:09:55]

Description was changed from

==========
Do no commit: tracing for WebRTC rendering

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

to

==========
In case AudioOutputDevice buffer size is not the same as hardware buffer size,
AudioOutputResampler on browser side does rebuffering (fifo-based). Each time
fifo edge is reached, fifo will initiate two reads one by one.

It means that AudioOuputDevice::Render() calles are NOT issued with a constant
interval based on output buffer size duration. For example, for WebRTC it means
Voice Engine can receive 2 calls one by one without 10 ms interval.

It may result in a missed deadline on Browser/Renderer edge, which causes audio
glitch.

We want to trace these events to collect the relevant data in cases of
crackling/distorted audio. 

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

[o1ka, 2016-08-19 13:13:15]

Description was changed from

==========
In case AudioOutputDevice buffer size is not the same as hardware buffer size,
AudioOutputResampler on browser side does rebuffering (fifo-based). Each time
fifo edge is reached, fifo will initiate two reads one by one.

It means that AudioOuputDevice::Render() calles are NOT issued with a constant
interval based on output buffer size duration. For example, for WebRTC it means
Voice Engine can receive 2 calls one by one without 10 ms interval.

It may result in a missed deadline on Browser/Renderer edge, which causes audio
glitch.

We want to trace these events to collect the relevant data in cases of
crackling/distorted audio. 

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

to

==========
In case AudioOutputDevice buffer size is not the same as hardware buffer size,
AudioOutputResampler on browser side does rebuffering (fifo-based). Each time
fifo edge is reached, fifo will initiate two reads one by one.

It means that AudioOuputDevice::Render() calles are NOT issued with a constant
interval based on output buffer size duration. For example, for WebRTC it means
Voice Engine can receive 2 calls one by one without 10 ms interval.

It may result in a missed deadline on Browser/Renderer edge, which causes audio
glitch.

We want to trace these events to collect the relevant data in cases of
crackling/distorted audio.

Also, a bit of tracing for mixing to see how it affects rendering performance.

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

[o1ka, 2016-08-19 13:15:00]

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

[o1ka, 2016-08-19 13:15:00]

PTAL

[o1ka, 2016-08-19 13:20:47]

https://codereview.chromium.org/2146513002/diff/20001/media/audio/audio_outpu...
File media/audio/audio_output_resampler.cc (right):

https://codereview.chromium.org/2146513002/diff/20001/media/audio/audio_outpu...
media/audio/audio_output_resampler.cc:385: TRACE_EVENT2("audio",
"OnMoreDataConverter::OnMoreData", "input buffer size",
Passing buffer sizes on each trace does not look cute, but it seems to be the
easiest and guaranteed way to get the data. Another way would be to add it to
the native log, but it requires passing log callback all the way from content.
(I'll try to come up with some more or less neat CL for that later).
Note that we can't trace it in the constructor, because at that point tracing is
usually disabled: we will ask a user to enable and record tracing when audio
glitches are observed, i.e. rendering is already ongoing.

[henrika (OOO until Aug 14), 2016-08-19 13:32:38]

LGTM

[DaleCurtis, 2016-08-19 16:49:00]

lgtm

https://codereview.chromium.org/2146513002/diff/20001/content/browser/rendere...
File content/browser/renderer_host/media/audio_sync_reader.cc (right):

https://codereview.chromium.org/2146513002/diff/20001/content/browser/rendere...
content/browser/renderer_host/media/audio_sync_reader.cc:206:
TRACE_EVENT_INSTANT0("audio", "AudioSyncReader::Read timed out",
Be neat if we could make this show up in a red color or something :)

https://codereview.chromium.org/2146513002/diff/20001/media/audio/audio_outpu...
File media/audio/audio_output_resampler.cc (right):

https://codereview.chromium.org/2146513002/diff/20001/media/audio/audio_outpu...
media/audio/audio_output_resampler.cc:385: TRACE_EVENT2("audio",
"OnMoreDataConverter::OnMoreData", "input buffer size",
On 2016/08/19 at 13:20:47, o1ka wrote:
> Passing buffer sizes on each trace does not look cute, but it seems to be the
easiest and guaranteed way to get the data. Another way would be to add it to
the native log, but it requires passing log callback all the way from content.
(I'll try to come up with some more or less neat CL for that later).
> Note that we can't trace it in the constructor, because at that point tracing
is usually disabled: we will ask a user to enable and record tracing when audio
glitches are observed, i.e. rendering is already ongoing.

Also is it useful to have this information? Isn't it displayed in
chrome://media-internals anyways?

[Henrik Grunell, 2016-08-22 08:29:06]

lgtm with one nit. You can decide how you want to do with it.

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

https://codereview.chromium.org/2146513002/diff/20001/content/renderer/media/...
content/renderer/media/webrtc_audio_device_impl.cc:99:
TRACE_EVENT_BEGIN0("audio", "VoE::PullRenderData");
Nit: VoiceEngine is kind of an implementation detail. I suggest "Pull render
data from WebRTC". Wdyt?

[Henrik Grunell, 2016-08-22 08:30:05]

Also, add bug number or remove "BUG=". Preferably the former. :)

[o1ka, 2016-08-22 08:44:31]

> Also is it useful to have this information? Isn't it displayed in
> chrome://media-internals anyways?
Good point. Yes, I think it's still useful: we have the data even when missing
media-internals info, and we don't have to manually map streams and controllers
to trace data to get buffer sizes. Tracing buffer sizes is just a little bit
of overhead, and it simplifies analysis.

[o1ka, 2016-08-22 08:55:22]

On 2016/08/22 08:29:06, Henrik Grunell wrote:
> lgtm with one nit. You can decide how you want to do with it.
> 
>
https://codereview.chromium.org/2146513002/diff/20001/content/renderer/media/...
> File content/renderer/media/webrtc_audio_device_impl.cc (right):
> 
>
https://codereview.chromium.org/2146513002/diff/20001/content/renderer/media/...
> content/renderer/media/webrtc_audio_device_impl.cc:99:
> TRACE_EVENT_BEGIN0("audio", "VoE::PullRenderData");
> Nit: VoiceEngine is kind of an implementation detail. I suggest "Pull render
> data from WebRTC". Wdyt?

All traces rely on implementation details, and you need to knows those to
interpret the results; most of the traces are methods names.
Also, if implementation changes, it's nice to have that reflected in traces. It
will help to analyze different releases without being mislead by assumption that
implementation is the same.

So, I don't think we need to hide implementation details here.

[o1ka, 2016-08-22 08:56:56]

olka@chromium.org changed reviewers:
+ perkj@chromium.org

[o1ka, 2016-08-22 08:56:57]

perkj@chromium.org: Could you RS changes in content/?

[o1ka, 2016-08-22 08:57:06]

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

[commit-bot: I haz the power, 2016-08-22 08:57:13]

Dry run: 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-22 11:04:00]

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

[commit-bot: I haz the power, 2016-08-22 11:04:02]

Dry run: This issue passed the CQ dry run.

[DaleCurtis, 2016-08-22 17:34:09]

lgtm; I've mentioned this issue in the past; to avoid this it's recommended you
choose buffer sizes that multiples of the output buffer size.

[Henrik Grunell, 2016-08-23 07:05:31]

On 2016/08/22 08:56:57, o1ka wrote:
> mailto:perkj@chromium.org: Could you RS changes in content/?

Olga, the l-g-t-m from Dale is enough. Note the
file://media/OWNERS
line in the two content OWNERS files.

[o1ka, 2016-08-23 07:10:37]

On 2016/08/23 07:05:31, Henrik Grunell wrote:
> On 2016/08/22 08:56:57, o1ka wrote:
> > mailto:perkj@chromium.org: Could you RS changes in content/?
> 
> Olga, the l-g-t-m from Dale is enough. Note the
> file://media/OWNERS
> line in the two content OWNERS files.

Ah, this chrome plugin misleads me again!

[o1ka, 2016-08-23 07:11:38]

olka@chromium.org changed reviewers:
- perkj@chromium.org

[o1ka, 2016-08-23 07:11:50]

On 2016/08/23 07:10:37, o1ka wrote:
> On 2016/08/23 07:05:31, Henrik Grunell wrote:
> > On 2016/08/22 08:56:57, o1ka wrote:
> > > mailto:perkj@chromium.org: Could you RS changes in content/?
> > 
> > Olga, the l-g-t-m from Dale is enough. Note the
> > file://media/OWNERS
> > line in the two content OWNERS files.
> 
> Ah, this chrome plugin misleads me again!

no RS needed, removing perkj from reviewers

[o1ka, 2016-08-23 07:11:58]

The CQ bit was checked by olka@chromium.org

[commit-bot: I haz the power, 2016-08-23 07:12:19]

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

[o1ka, 2016-08-23 07:16:00]

https://codereview.chromium.org/2146513002/diff/20001/content/browser/rendere...
File content/browser/renderer_host/media/audio_sync_reader.cc (right):

https://codereview.chromium.org/2146513002/diff/20001/content/browser/rendere...
content/browser/renderer_host/media/audio_sync_reader.cc:206:
TRACE_EVENT_INSTANT0("audio", "AudioSyncReader::Read timed out",
On 2016/08/19 16:49:00, DaleCurtis wrote:
> Be neat if we could make this show up in a red color or something :)
Would be really cool, but looks like they don't have that.

[commit-bot: I haz the power, 2016-08-23 07:16:24]

Description was changed from

==========
In case AudioOutputDevice buffer size is not the same as hardware buffer size,
AudioOutputResampler on browser side does rebuffering (fifo-based). Each time
fifo edge is reached, fifo will initiate two reads one by one.

It means that AudioOuputDevice::Render() calles are NOT issued with a constant
interval based on output buffer size duration. For example, for WebRTC it means
Voice Engine can receive 2 calls one by one without 10 ms interval.

It may result in a missed deadline on Browser/Renderer edge, which causes audio
glitch.

We want to trace these events to collect the relevant data in cases of
crackling/distorted audio.

Also, a bit of tracing for mixing to see how it affects rendering performance.

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

to

==========
In case AudioOutputDevice buffer size is not the same as hardware buffer size,
AudioOutputResampler on browser side does rebuffering (fifo-based). Each time
fifo edge is reached, fifo will initiate two reads one by one.

It means that AudioOuputDevice::Render() calles are NOT issued with a constant
interval based on output buffer size duration. For example, for WebRTC it means
Voice Engine can receive 2 calls one by one without 10 ms interval.

It may result in a missed deadline on Browser/Renderer edge, which causes audio
glitch.

We want to trace these events to collect the relevant data in cases of
crackling/distorted audio.

Also, a bit of tracing for mixing to see how it affects rendering performance.

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

[commit-bot: I haz the power, 2016-08-23 07:16:26]

Committed patchset #2 (id:20001)

[commit-bot: I haz the power, 2016-08-23 07:17:54]

Description was changed from

==========
In case AudioOutputDevice buffer size is not the same as hardware buffer size,
AudioOutputResampler on browser side does rebuffering (fifo-based). Each time
fifo edge is reached, fifo will initiate two reads one by one.

It means that AudioOuputDevice::Render() calles are NOT issued with a constant
interval based on output buffer size duration. For example, for WebRTC it means
Voice Engine can receive 2 calls one by one without 10 ms interval.

It may result in a missed deadline on Browser/Renderer edge, which causes audio
glitch.

We want to trace these events to collect the relevant data in cases of
crackling/distorted audio.

Also, a bit of tracing for mixing to see how it affects rendering performance.

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

to

==========
In case AudioOutputDevice buffer size is not the same as hardware buffer size,
AudioOutputResampler on browser side does rebuffering (fifo-based). Each time
fifo edge is reached, fifo will initiate two reads one by one.

It means that AudioOuputDevice::Render() calles are NOT issued with a constant
interval based on output buffer size duration. For example, for WebRTC it means
Voice Engine can receive 2 calls one by one without 10 ms interval.

It may result in a missed deadline on Browser/Renderer edge, which causes audio
glitch.

We want to trace these events to collect the relevant data in cases of
crackling/distorted audio.

Also, a bit of tracing for mixing to see how it affects rendering performance.

BUG=

Committed: https://crrev.com/8ec171e0559a846b1c5261631914726134ec2555
Cr-Commit-Position: refs/heads/master@{#413684}
==========

[commit-bot: I haz the power, 2016-08-23 07:17:55]

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