[Extensions] Add coarse metrics for extension function performance

[Extensions] Add coarse metrics for extension function performance

Add metrics for extension function performance for overall and
synchronous execution time.
After these stew awhile, I'll add bucketed metrics that can capture
specific extension metrics (see bug for more details).

BUG=608561
Committed: https://crrev.com/f46fe266479fc6e1b133a80ad4ff95f15e064be7
Cr-Commit-Position: refs/heads/master@{#391389}

[Devlin, 2016-05-03 00:42:56]

Patchset #1 (id:1) has been deleted

[Devlin, 2016-05-03 00:43:48]

rdevlin.cronin@chromium.org changed reviewers:
+ lazyboy@chromium.org, mpearson@chromium.org

[Devlin, 2016-05-03 00:43:49]

Istiaque and Mark, mind taking a look?

Mark, please also see comment in histograms.xml.

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

https://codereview.chromium.org/1939413002/diff/20001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:13592: +<histogram
name="Extensions.Functions.SynchronousExecutionTime" units="ms">
Mark: I see other places that use TimeTicks/TimeDelta (based on us) using
UMA_HISTOGRAM_TIMES() with units ms, but it's unclear from the documentation if
it should be ms or us as the units.  Can you confirm?  (I briefly tried to dive
into the UMA_HISTOGRAM_TIMES macro, but got quickly lost.)

[lazyboy, 2016-05-03 01:00:01]

https://codereview.chromium.org/1939413002/diff/20001/extensions/browser/exte...
File extensions/browser/extension_function.cc (right):

https://codereview.chromium.org/1939413002/diff/20001/extensions/browser/exte...
extensions/browser/extension_function.cc:411: // TODO(devlin): Once we have a
baseline metric for how long functions take,
Addition to the notes, I think referring to the bug (608561) here would be
helpful for the reader to get more context.
(Or if you want to track this second stage bucketing thing in a separate bug)

https://codereview.chromium.org/1939413002/diff/20001/extensions/browser/exte...
extensions/browser/extension_function.cc:414: // Note: Certain functions perform
actions that are inherantly slow - such as
nit: inherently

https://codereview.chromium.org/1939413002/diff/20001/extensions/browser/exte...
extensions/browser/extension_function.cc:417:
UMA_HISTOGRAM_TIMES("Extensions.Functions.TotalExecutionTime",
Should we also categorize based on |success|? I'd imagine failed times would be
much smaller than the succeeded ones.

[Devlin, 2016-05-03 17:03:36]

https://codereview.chromium.org/1939413002/diff/20001/extensions/browser/exte...
File extensions/browser/extension_function.cc (right):

https://codereview.chromium.org/1939413002/diff/20001/extensions/browser/exte...
extensions/browser/extension_function.cc:411: // TODO(devlin): Once we have a
baseline metric for how long functions take,
On 2016/05/03 01:00:01, lazyboy wrote:
> Addition to the notes, I think referring to the bug (608561) here would be
> helpful for the reader to get more context.
> (Or if you want to track this second stage bucketing thing in a separate bug)

Done.

https://codereview.chromium.org/1939413002/diff/20001/extensions/browser/exte...
extensions/browser/extension_function.cc:414: // Note: Certain functions perform
actions that are inherantly slow - such as
On 2016/05/03 01:00:01, lazyboy wrote:
> nit: inherently

whoops, done.

https://codereview.chromium.org/1939413002/diff/20001/extensions/browser/exte...
extensions/browser/extension_function.cc:417:
UMA_HISTOGRAM_TIMES("Extensions.Functions.TotalExecutionTime",
On 2016/05/03 01:00:01, lazyboy wrote:
> Should we also categorize based on |success|? I'd imagine failed times would
be
> much smaller than the succeeded ones.

Sounds reasonable.  Done.

[lazyboy, 2016-05-03 17:29:26]

extensions LGTM

[Mark P, 2016-05-03 18:30:39]

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

https://codereview.chromium.org/1939413002/diff/20001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:13592: +<histogram
name="Extensions.Functions.SynchronousExecutionTime" units="ms">
On 2016/05/03 00:43:49, Devlin wrote:
> Mark: I see other places that use TimeTicks/TimeDelta (based on us) using
> UMA_HISTOGRAM_TIMES() with units ms, but it's unclear from the documentation
if
> it should be ms or us as the units.  Can you confirm?  (I briefly tried to
dive
> into the UMA_HISTOGRAM_TIMES macro, but got quickly lost.)

All the UMA_HISTOGRAM_TIMES macros use milliseconds.
It's true that TimeTicks/TimeDelta can give you more accuracy, but the
histograms macros don't use or record it.
Let me know if you saw something where you think someone is expecting a
histogram to be providing microsecond-based measurements.  That may be a bug.

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

https://codereview.chromium.org/1939413002/diff/40001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:13596: +    succeeded from the time the
extension function is called to the time the
succeed -> failed

https://codereview.chromium.org/1939413002/diff/40001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:13597: +    function responds. Note that
since some extension functions are inherently
Is it possible to fail without responding (e.g., a timeout)?

https://codereview.chromium.org/1939413002/diff/40001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:13614: +<histogram
name="Extensions.Functions.SynchronousExecutionTime" units="ms">
I see this is recorded in two places in the code.  Are you sure you want both
places a function can be executed to be summed into the same histogram?  (Are
they conceptually the same?)

[Devlin, 2016-05-03 20:43:01]

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

https://codereview.chromium.org/1939413002/diff/40001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:13596: +    succeeded from the time the
extension function is called to the time the
On 2016/05/03 18:30:39, Mark P wrote:
> succeed -> failed

Done.

https://codereview.chromium.org/1939413002/diff/40001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:13597: +    function responds. Note that
since some extension functions are inherently
On 2016/05/03 18:30:39, Mark P wrote:
> Is it possible to fail without responding (e.g., a timeout)?

Theoretically, we should always respond.  If we don't, it's a bug (and maybe
these and following metrics could help track it down).

https://codereview.chromium.org/1939413002/diff/40001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:13614: +<histogram
name="Extensions.Functions.SynchronousExecutionTime" units="ms">
On 2016/05/03 18:30:39, Mark P wrote:
> I see this is recorded in two places in the code.  Are you sure you want both
> places a function can be executed to be summed into the same histogram?  (Are
> they conceptually the same?)

Yep, they are conceptually the same.

[Mark P, 2016-05-03 21:37:53]

histograms.xml lgtm

[Devlin, 2016-05-03 21:54:49]

The CQ bit was checked by rdevlin.cronin@chromium.org

[Devlin, 2016-05-03 21:54:50]

The patchset sent to the CQ was uploaded after l-g-t-m from lazyboy@chromium.org
Link to the patchset: https://codereview.chromium.org/1939413002/#ps60001
(title: "Mark's")

[commit-bot: I haz the power, 2016-05-03 21:55:39]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1939413002/60001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1939413002/60001

[commit-bot: I haz the power, 2016-05-03 23:15:54]

Committed patchset #3 (id:60001)

[commit-bot: I haz the power, 2016-05-03 23:17:26]

Description was changed from

==========
[Extensions] Add coarse metrics for extension function performance

Add metrics for extension function performance for overall and
synchronous execution time.
After these stew awhile, I'll add bucketed metrics that can capture
specific extension metrics (see bug for more details).

BUG=608561
==========

to

==========
[Extensions] Add coarse metrics for extension function performance

Add metrics for extension function performance for overall and
synchronous execution time.
After these stew awhile, I'll add bucketed metrics that can capture
specific extension metrics (see bug for more details).

BUG=608561

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

[commit-bot: I haz the power, 2016-05-03 23:17:27]

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