Report timing statistics for audio controller methods via UMA.

Report timing statistics for audio controller methods via UMA.

Logs the time taken to execute the main methods of AudioInputController
and AudioOutputController.  This timing information will be used to
determine if we can combine the audio thread and the UI thread on OSX
to (hopefully) fix http://crbug.com/158170.

BUG=158170
TEST=chrome://histograms/Media.Audio contains information.

Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=200414

[jar (doing other things), 2013-05-03 21:50:25]

This is an interesting macro.  It is plausible that it should be in
base/metrics/*.

Please add unit tests for the macro, at least to verify that it can be used
twice in the same scope (which seemed like what you were hoping for).

Ilya: WDYT of the macro in the header for an UMA timer?  I suspect it actually
is a common pattern.  I have to think about whether there is a nicer way to do
it...

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_timer.h
File media/base/scoped_uma_timer.h (right):

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_time...
media/base/scoped_uma_timer.h:14: class ScopedHistogramTimer { \
Since you messed with __LINE__ on line 22 so that you can have two of these in a
single scope, you presumably also need to do so here if you want it to work:

class ScopedHistogramTimer##__LINE__

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_time...
media/base/scoped_uma_timer.h:16: ScopedHistogramTimer() :
constructed_(base::Time::Now()) {} \
You should use TimeTicks, as it is guaranteed monotonic.

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_time...
media/base/scoped_uma_timer.h:21: base::Time constructed_; \
nit: You probably should have NO_DEFAULT_COPY_OR_ASSIGN as is done in all
classes without a compelling reason to contrary.

[DaleCurtis, 2013-05-03 23:16:56]

I'm happy to move this to base/metrics/ if desired.  Not sure what kind of
unittest I'd add now that multiple copies aren't allowed in the same scope.  Did
you have anything else in mind?

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_timer.h
File media/base/scoped_uma_timer.h (right):

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_time...
media/base/scoped_uma_timer.h:14: class ScopedHistogramTimer { \
On 2013/05/03 21:50:26, jar wrote:
> Since you messed with __LINE__ on line 22 so that you can have two of these in
a
> single scope, you presumably also need to do so here if you want it to work:
> 
> class ScopedHistogramTimer##__LINE__

Ah, right.  Actually none of this works at all.  In order to get unique names I
need another two macros essentially.

I don't think it actually makes sense to allow two of these within the same
scope.  Without the ##LINE business you can still do

SCOPED_UMA_HISTOGRAM_TIMER("global");
{
  SCOPED_UMA_HISTOGRAM_TIMER("local");
}

So I'm just going to remove it and make the variable name easier to understand
if that mistake is made.

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_time...
media/base/scoped_uma_timer.h:16: ScopedHistogramTimer() :
constructed_(base::Time::Now()) {} \
On 2013/05/03 21:50:26, jar wrote:
> You should use TimeTicks, as it is guaranteed monotonic.

TimeTicks is a kind of expensive per the comment in base/time.h.  On Linux it's
the same as Now(), on Windows Now() occasionally calls TimeTicks::Now(), and Mac
uses a whole different routine for TimeTicks::Now().

Do you think these concerns are valid?

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_time...
media/base/scoped_uma_timer.h:21: base::Time constructed_; \
On 2013/05/03 21:50:26, jar wrote:
> nit: You probably should have NO_DEFAULT_COPY_OR_ASSIGN as is done in all
> classes without a compelling reason to contrary.

Done.

[DaleCurtis, 2013-05-03 23:17:42]

(reasons for why more macros are needed:
http://stackoverflow.com/questions/10379691/creating-macro-using-line-for-dif...
)

[scherkus (not reviewing), 2013-05-03 23:31:48]

the histograms themselves Look Good -- I agree that if we sort out the macro
wonkiness this could be useful inside base/metrics/ itself

[jar (doing other things), 2013-05-04 08:58:31]

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_timer.h
File media/base/scoped_uma_timer.h (right):

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_time...
media/base/scoped_uma_timer.h:14: class ScopedHistogramTimer { \
<Doh>... I feel embarrassed.. I used to be a real expert at this stuff... and it
is lame for me to have forgotten.

It will be nice to get it working in a scope, so then you can do:

SCOPED_HIST_TIME("Whole task");
DoStart();
SCOPED_HIST_TIME("last.part")
FinishUp();



On 2013/05/03 23:16:57, DaleCurtis wrote:
> On 2013/05/03 21:50:26, jar wrote:
> > Since you messed with __LINE__ on line 22 so that you can have two of these
in
> a
> > single scope, you presumably also need to do so here if you want it to work:
> > 
> > class ScopedHistogramTimer##__LINE__
> 
> Ah, right.  Actually none of this works at all.  In order to get unique names
I
> need another two macros essentially.
> 
> I don't think it actually makes sense to allow two of these within the same
> scope.  Without the ##LINE business you can still do
> 
> SCOPED_UMA_HISTOGRAM_TIMER("global");
> {
>   SCOPED_UMA_HISTOGRAM_TIMER("local");
> }
> 
> So I'm just going to remove it and make the variable name easier to understand
> if that mistake is made.

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_time...
media/base/scoped_uma_timer.h:16: ScopedHistogramTimer() :
constructed_(base::Time::Now()) {} \
Definately use TimeTicks, not Time

Performance is not that bad at all, and correctness trumps performance (...and
we did have a LOT of trouble with this until we consistently migrated to only
using TimeTicks in a wide variety of cases).

On 2013/05/03 23:16:57, DaleCurtis wrote:
> On 2013/05/03 21:50:26, jar wrote:
> > You should use TimeTicks, as it is guaranteed monotonic.
> 
> TimeTicks is a kind of expensive per the comment in base/time.h.  On Linux
it's
> the same as Now(), on Windows Now() occasionally calls TimeTicks::Now(), and
Mac
> uses a whole different routine for TimeTicks::Now().
> 
> Do you think these concerns are valid?

[Ilya Sherman, 2013-05-06 23:36:14]

On 2013/05/03 21:50:25, jar wrote:
> Ilya: WDYT of the macro in the header for an UMA timer?  I suspect it actually
> is a common pattern.  I have to think about whether there is a nicer way to do
> it...

I'm not opposed to including this macro in //base/metrics, but most of the
timing metrics that I've personally seen have dealt with asynchronous events,
since hopefully any individual task doesn't block a thread for long enough for
us to be interested in measuring its runtime.  Maybe that's a bias from mostly
working on the UI thread, though -- if you've got a worker pool with threads
that end up dedicated to a task, then I could see this being pretty handy.

[DaleCurtis, 2013-05-07 20:08:51]

PTAL.  I also renamed a couple bits for uniformity.

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_timer.h
File media/base/scoped_uma_timer.h (right):

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_time...
media/base/scoped_uma_timer.h:14: class ScopedHistogramTimer { \
On 2013/05/04 08:58:31, jar wrote:
> <Doh>... I feel embarrassed.. I used to be a real expert at this stuff... and
it
> is lame for me to have forgotten.
> 
> It will be nice to get it working in a scope, so then you can do:
> 
> SCOPED_HIST_TIME("Whole task");
> DoStart();
> SCOPED_HIST_TIME("last.part")
> FinishUp();
> 
> 
> 
> On 2013/05/03 23:16:57, DaleCurtis wrote:
> > On 2013/05/03 21:50:26, jar wrote:
> > > Since you messed with __LINE__ on line 22 so that you can have two of
these
> in
> > a
> > > single scope, you presumably also need to do so here if you want it to
work:
> > > 
> > > class ScopedHistogramTimer##__LINE__
> > 
> > Ah, right.  Actually none of this works at all.  In order to get unique
names
> I
> > need another two macros essentially.
> > 
> > I don't think it actually makes sense to allow two of these within the same
> > scope.  Without the ##LINE business you can still do
> > 
> > SCOPED_UMA_HISTOGRAM_TIMER("global");
> > {
> >   SCOPED_UMA_HISTOGRAM_TIMER("local");
> > }
> > 
> > So I'm just going to remove it and make the variable name easier to
understand
> > if that mistake is made.
> 

Done.

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_time...
media/base/scoped_uma_timer.h:16: ScopedHistogramTimer() :
constructed_(base::Time::Now()) {} \
On 2013/05/04 08:58:31, jar wrote:
> Definately use TimeTicks, not Time
> 
> Performance is not that bad at all, and correctness trumps performance (...and
> we did have a LOT of trouble with this until we consistently migrated to only
> using TimeTicks in a wide variety of cases).
> 
> On 2013/05/03 23:16:57, DaleCurtis wrote:
> > On 2013/05/03 21:50:26, jar wrote:
> > > You should use TimeTicks, as it is guaranteed monotonic.
> > 
> > TimeTicks is a kind of expensive per the comment in base/time.h.  On Linux
> it's
> > the same as Now(), on Windows Now() occasionally calls TimeTicks::Now(), and
> Mac
> > uses a whole different routine for TimeTicks::Now().
> > 
> > Do you think these concerns are valid?
> 

Done.

[DaleCurtis, 2013-05-08 00:01:30]

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_timer.h
File media/base/scoped_uma_timer.h (right):

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_time...
media/base/scoped_uma_timer.h:21: base::Time constructed_; \
On 2013/05/03 23:16:57, DaleCurtis wrote:
> On 2013/05/03 21:50:26, jar wrote:
> > nit: You probably should have NO_DEFAULT_COPY_OR_ASSIGN as is done in all
> > classes without a compelling reason to contrary.
> 
> Done.

Actually removed in the latest patch set.  VC++ won't expand the macro with the
unique ##key appended to it.  I couldn't find a workaround and keeping it
doesn't seem worth the effort.

[jar (doing other things), 2013-05-08 00:55:23]

FYI: If you wanted it to work, the following should do the trick.  I used to
know this stuff very well (I wrote a C preprocessor).

The "trick" is that args that are used with ## or # are *not* macro expanded. 
Hence you need to do one round of macro expanding before calling the real paster
:-/.

Maybe the cleverness is not worth it (and you'd need to use fancier names for
the macros to help avoid any chance of a conflict with names in code.  "PASTE"
is too short :-(.  )

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_timer.h
File media/base/scoped_uma_timer.h (right):

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_time...
media/base/scoped_uma_timer.h:21: base::Time constructed_; \
On 2013/05/08 00:01:30, DaleCurtis wrote:
> On 2013/05/03 23:16:57, DaleCurtis wrote:
> > On 2013/05/03 21:50:26, jar wrote:
> > > nit: You probably should have NO_DEFAULT_COPY_OR_ASSIGN as is done in all
> > > classes without a compelling reason to contrary.
> > 
> > Done.
> 
> Actually removed in the latest patch set.  VC++ won't expand the macro with
the
> unique ##key appended to it.  I couldn't find a workaround and keeping it
> doesn't seem worth the effort.


If you're interested, the following should work (if my preprocessor jui-jitsu
skills are intact):

#define EXPAND_THEN_PASTE(a, b) PASTE(a, b)
#define PASTE(a, b) a##b

#define SCOPED_UMA_HISTOGRAM_TIMER(name) \
    class EXPAND_THEN_PASTE(ScopedHistogramTimer, __LINE__) { \
...
} EXPAND_THEN_PASTE(scoped_uma_timer, __LINE__)

[DaleCurtis, 2013-05-08 01:34:04]

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_timer.h
File media/base/scoped_uma_timer.h (right):

https://codereview.chromium.org/14827002/diff/5001/media/base/scoped_uma_time...
media/base/scoped_uma_timer.h:21: base::Time constructed_; \
On 2013/05/08 00:55:23, jar wrote:
> On 2013/05/08 00:01:30, DaleCurtis wrote:
> > On 2013/05/03 23:16:57, DaleCurtis wrote:
> > > On 2013/05/03 21:50:26, jar wrote:
> > > > nit: You probably should have NO_DEFAULT_COPY_OR_ASSIGN as is done in
all
> > > > classes without a compelling reason to contrary.
> > > 
> > > Done.
> > 
> > Actually removed in the latest patch set.  VC++ won't expand the macro with
> the
> > unique ##key appended to it.  I couldn't find a workaround and keeping it
> > doesn't seem worth the effort.
> 
> 
> If you're interested, the following should work (if my preprocessor jui-jitsu
> skills are intact):
> 
> #define EXPAND_THEN_PASTE(a, b) PASTE(a, b)
> #define PASTE(a, b) a##b
> 
> #define SCOPED_UMA_HISTOGRAM_TIMER(name) \
>     class EXPAND_THEN_PASTE(ScopedHistogramTimer, __LINE__) { \
> ...
> } EXPAND_THEN_PASTE(scoped_uma_timer, __LINE__)

Sorry for the confusion, my above comment about VC++ refer specifically to the
DISALLOW_COPY_AND_ASSIGN(xx##yy) usage, which isn't expanded correctly w/ the
macro hops from SCOPED_UMA_HISTOGRAM_TIMER() -> ...EXPANDER() -> ...UNIQUE(). 
Everything else works correctly in the latest patch set.  Even switching to your
EXPAND_THEN_PASTE macro doesn't resolve this issue with VC++ and the DISALLOW
macro (both approaches work fine in clang).

[DaleCurtis, 2013-05-09 20:06:45]

Ping.  Any more comments?  I'd like to merge this to M28 (possibly M27 if I can
finagle it) so we can get stable channel numbers sooner rather than later.

[scherkus (not reviewing), 2013-05-09 20:07:58]

lgtm from me -- deferring to jar@ for the macro / histrogram magic

[jar (doing other things), 2013-05-14 01:43:57]

https://codereview.chromium.org/14827002/diff/22001/tools/metrics/histograms/...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/14827002/diff/22001/tools/metrics/histograms/...
tools/metrics/histograms/histograms.xml:1015: <histogram
name="Media.AudioInputController.CloseTime" units="ms">
nit: These all look almost the same... and you can use the XML feature in this
file to wirte them very compactly.  Just define one histogram:
histogram name="Media.AudioInputController" units="ms">
  <summary>
  Measures the time taken for AudioInputController::
  </summary>
  </histogram>

Then define a FieldTrial  with separator="." and extensions containing:
"CloseTime"   "DoClose()."
"CreateTime"  "DoCreate()."
...
"PlayTime"   "DoPlay().  Technically only the worker method
AudioOutputController::PollAndStartIfDataReady()."

Take a look at <FieldTrial...> later in the file.

[jar (doing other things), 2013-05-14 01:45:02]

.... oh and the "macro magic" LGTM.  Let's see if other folks ask of this before
we pull it into base.

Please consider the xml suggestions.

[Alexei Svitkine (slow), 2013-05-14 15:55:43]

https://codereview.chromium.org/14827002/diff/22001/media/base/scoped_histogr...
File media/base/scoped_histogram_timer.h (right):

https://codereview.chromium.org/14827002/diff/22001/media/base/scoped_histogr...
media/base/scoped_histogram_timer.h:25: UMA_HISTOGRAM_TIMES(name,
base::TimeTicks::Now() - constructed_); \
Please extract base::TimeTicks::Now() - contructed_ into a local variable,
before invoking a macro on it.

Otherwise, depending on the implementation of the macro, the expression may be
evaluated multiple times, which is bad when it's calling a function. (I'm not
sure if it's actually a problem with this macro, but it's better be safe even if
it isn't, in case the implementation changes).

[jar (doing other things), 2013-05-14 16:19:22]

https://codereview.chromium.org/14827002/diff/22001/media/base/scoped_histogr...
File media/base/scoped_histogram_timer.h (right):

https://codereview.chromium.org/14827002/diff/22001/media/base/scoped_histogr...
media/base/scoped_histogram_timer.h:25: UMA_HISTOGRAM_TIMES(name,
base::TimeTicks::Now() - constructed_); \
On 2013/05/14 15:55:43, Alexei Svitkine wrote:
> Please extract base::TimeTicks::Now() - contructed_ into a local variable,
> before invoking a macro on it.
> 
> Otherwise, depending on the implementation of the macro, the expression may be
> evaluated multiple times, which is bad when it's calling a function. (I'm not
> sure if it's actually a problem with this macro, but it's better be safe even
if
> it isn't, in case the implementation changes).

Good suggestion.  In this case the given arg is the sample, and is evaluated
exactly once (before being passed to a method).

It is still probably a good enough habit that it should done (so no one else
worries).

[DaleCurtis, 2013-05-15 01:30:31]

jar: PTAL at histograms.xml to make sure I did that right.  Thanks!

https://codereview.chromium.org/14827002/diff/22001/media/base/scoped_histogr...
File media/base/scoped_histogram_timer.h (right):

https://codereview.chromium.org/14827002/diff/22001/media/base/scoped_histogr...
media/base/scoped_histogram_timer.h:25: UMA_HISTOGRAM_TIMES(name,
base::TimeTicks::Now() - constructed_); \
On 2013/05/14 16:19:22, jar wrote:
> On 2013/05/14 15:55:43, Alexei Svitkine wrote:
> > Please extract base::TimeTicks::Now() - contructed_ into a local variable,
> > before invoking a macro on it.
> > 
> > Otherwise, depending on the implementation of the macro, the expression may
be
> > evaluated multiple times, which is bad when it's calling a function. (I'm
not
> > sure if it's actually a problem with this macro, but it's better be safe
even
> if
> > it isn't, in case the implementation changes).
> 
> Good suggestion.  In this case the given arg is the sample, and is evaluated
> exactly once (before being passed to a method).
> 
> It is still probably a good enough habit that it should done (so no one else
> worries).

Done.

https://codereview.chromium.org/14827002/diff/22001/tools/metrics/histograms/...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/14827002/diff/22001/tools/metrics/histograms/...
tools/metrics/histograms/histograms.xml:1015: <histogram
name="Media.AudioInputController.CloseTime" units="ms">
On 2013/05/14 01:43:57, jar wrote:
> nit: These all look almost the same... and you can use the XML feature in this
> file to wirte them very compactly.  Just define one histogram:
> histogram name="Media.AudioInputController" units="ms">
>   <summary>
>   Measures the time taken for AudioInputController::
>   </summary>
>   </histogram>
> 
> Then define a FieldTrial  with separator="." and extensions containing:
> "CloseTime"   "DoClose()."
> "CreateTime"  "DoCreate()."
> ...
> "PlayTime"   "DoPlay().  Technically only the worker method
> AudioOutputController::PollAndStartIfDataReady()."
> 
> Take a look at <FieldTrial...> later in the file.

Done.

[jar (doing other things), 2013-05-15 01:47:49]

The histogram.xml changes in patch 5 LGTM.

Please consider the comment below before landing.

https://codereview.chromium.org/14827002/diff/34001/media/audio/audio_output_...
File media/audio/audio_output_controller.cc (right):

https://codereview.chromium.org/14827002/diff/34001/media/audio/audio_output_...
media/audio/audio_output_controller.cc:339:
base::TimeDelta::FromMilliseconds(1000),
This only goes to 1 second.  That is a really short time, especially when OSs
get busy.  I'd strongly suggest something more like 1 minute, or 10 minutes as
the max.

[Alexei Svitkine (slow), 2013-05-15 14:35:42]

LGTM

[DaleCurtis, 2013-05-15 17:32:23]

https://codereview.chromium.org/14827002/diff/34001/media/audio/audio_output_...
File media/audio/audio_output_controller.cc (right):

https://codereview.chromium.org/14827002/diff/34001/media/audio/audio_output_...
media/audio/audio_output_controller.cc:339:
base::TimeDelta::FromMilliseconds(1000),
On 2013/05/15 01:47:49, jar wrote:
> This only goes to 1 second.  That is a really short time, especially when OSs
> get busy.  I'd strongly suggest something more like 1 minute, or 10 minutes as
> the max.

The loop is bounded by 683ms on Windows, and 20ms elsewhere, so I'd expect most
cases to fall below 1s. Do results outside of the range get thrown away?
Anything greater isn't really important since we know its a glitch if
time_since_start > kMaxWait.

[DaleCurtis, 2013-05-15 20:48:00]

CQ'ing patch set 5. Depending on your answer to my Q, we can adjust the max time
in a follow up CL w/ davemoore@

[commit-bot: I haz the power, 2013-05-15 20:49:06]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/dalecurtis@chromium.org/14827002/34001

[commit-bot: I haz the power, 2013-05-15 21:05:13]

Sorry for I got bad news for ya.
Compile failed with a clobber build on ios_dbg_simulator.
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=ios_dbg_si...
Your code is likely broken or HEAD is junk. Please ensure your
code is not broken then alert the build sheriffs.
Look at the try server FAQ for more details.

[DaleCurtis, 2013-05-15 21:08:56]

Whoops, elapsed has units TimeDelta not TimeTicks. Shame on me.

[commit-bot: I haz the power, 2013-05-15 21:09:16]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/dalecurtis@chromium.org/14827002/56001

[commit-bot: I haz the power, 2013-05-16 02:05:06]

Change committed as 200414