[Extensions] Add more fine-grained extension performance metrics

extensions/browser/extension_function.cc

Index: extensions/browser/extension_function.cc
diff --git a/extensions/browser/extension_function.cc b/extensions/browser/extension_function.cc
index ccbd833400cc18177a6380a8fd1f82bac95bada4..ad5930daaea8b6b1e2b5a2f476d5aabe9eb9a2f4 100644
--- a/extensions/browser/extension_function.cc
+++ b/extensions/browser/extension_function.cc
@@ -11,6 +11,7 @@
 #include "base/memory/ptr_util.h"
 #include "base/memory/singleton.h"
 #include "base/metrics/histogram_macros.h"
+#include "base/metrics/sparse_histogram.h"
 #include "base/synchronization/lock.h"
 #include "content/public/browser/notification_source.h"
 #include "content/public/browser/notification_types.h"
@@ -33,6 +34,48 @@ using extensions::Feature;
 
 namespace {
 
+// Logs UMA about the performance for a given extension function run.
+void LogUma(bool success,
+            base::TimeDelta elapsed_time,
+            extensions::functions::HistogramValue histogram_value) {
+  // Note: Certain functions perform actions that are inherently slow - such as
+  // anything waiting on user action. As such, we can't always assume that a
+  // long execution time equates to a poorly-performing function.
+  if (success) {
+    if (elapsed_time < base::TimeDelta::FromMilliseconds(1)) {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.SucceededLessThan1ms",

[Devlin, 2016/06/21 00:42:18]

I stole UMA_HISTOGRAM_SPARSE_SLOWLY from ExtensionFunctionDispatcher, where we
record which extension functions are called. [1]  I'm assuming that if it is the
right choice there, it's the right choice here, but reading the comments for the
macros, it seems like either SPARSE_SLOWLY or ENUMERATION would probably work. 
Mark, do you know if one is better than the other in one or both of these
places?

[1]
https://chromium.googlesource.com/chromium/src/+/7d873db838bd65a60ac84a236a48...

[Mark P, 2016/06/22 21:48:01]

Sparse is best used for histograms when not many distinct buckets are going to
be used _and_ the behavior isn't in a tight inner loop.  It's probably
reasonable here and in the code you cite.  Enumerated histograms take a lot more
memory because we preallocate all possible bucket (in this case all possible
extension function, oy).

[Devlin, 2016/06/22 22:40:53]

Cool, so sounds like this is the right one. :)

+                                  histogram_value);
+    } else if (elapsed_time < base::TimeDelta::FromMilliseconds(5)) {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.Succeeded1msTo5ms",
+                                  histogram_value);
+    } else if (elapsed_time < base::TimeDelta::FromMilliseconds(10)) {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.Succeeded5msTo10ms",
+                                  histogram_value);
+    } else {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.SucceededOver10ms",
+                                  histogram_value);
+    }
+    UMA_HISTOGRAM_TIMES("Extensions.Functions.SucceededTotalExecutionTime",
+                        elapsed_time);
+  } else {
+    if (elapsed_time < base::TimeDelta::FromMilliseconds(1)) {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.FailedLessThan1ms",
+                                  histogram_value);
+    } else if (elapsed_time < base::TimeDelta::FromMilliseconds(5)) {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.Failed1msTo5ms",
+                                  histogram_value);
+    } else if (elapsed_time < base::TimeDelta::FromMilliseconds(10)) {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.Failed5msTo10ms",
+                                  histogram_value);
+    } else {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.FailedOver10ms",
+                                  histogram_value);
+    }
+    UMA_HISTOGRAM_TIMES("Extensions.Functions.FailedTotalExecutionTime",
+                        elapsed_time);
+  }
+}
+
 class ArgumentListResponseValue
     : public ExtensionFunction::ResponseValueObject {
  public:
@@ -419,20 +462,7 @@ void ExtensionFunction::SendResponseImpl(bool success) {
     results_.reset(new base::ListValue());
 
   response_callback_.Run(type, *results_, GetError(), histogram_value());
-
-  // TODO(devlin): Once we have a baseline metric for how long functions take,
-  // we can create a handful of buckets and record the function name so that we
-  // can find what the fastest/slowest are. See crbug.com/608561.
-  // Note: Certain functions perform actions that are inherently slow - such as
-  // anything waiting on user action. As such, we can't always assume that a
-  // long execution time equates to a poorly-performing function.
-  if (success) {
-    UMA_HISTOGRAM_TIMES("Extensions.Functions.SucceededTotalExecutionTime",
-                        timer_.Elapsed());
-  } else {
-    UMA_HISTOGRAM_TIMES("Extensions.Functions.FailedTotalExecutionTime",
-                        timer_.Elapsed());
-  }
+  LogUma(success, timer_.Elapsed(), histogram_value_);
 }
 
 void ExtensionFunction::OnRespondingLater(ResponseValue value) {