[Extensions] Add more fine-grained extension performance metrics

extensions/browser/extension_function.cc

 // Copyright 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "extensions/browser/extension_function.h"
 
 #include <utility>
 
 #include "base/logging.h"
 #include "base/macros.h"
 #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"
 #include "content/public/browser/render_frame_host.h"
 #include "content/public/browser/web_contents.h"
 #include "content/public/browser/web_contents_observer.h"
 #include "extensions/browser/extension_function_dispatcher.h"
 #include "extensions/browser/extension_message_filter.h"
 #include "extensions/browser/extensions_browser_client.h"
 #include "extensions/common/error_utils.h"
 #include "extensions/common/extension_api.h"
 #include "extensions/common/extension_messages.h"
 
 using content::BrowserThread;
 using content::RenderViewHost;
 using content::WebContents;
 using extensions::ErrorUtils;
 using extensions::ExtensionAPI;
 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.SucceededTime.LessThan1ms", histogram_value);
+    } else if (elapsed_time < base::TimeDelta::FromMilliseconds(5)) {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.SucceededTime.1msTo5ms",
+                                  histogram_value);
+    } else if (elapsed_time < base::TimeDelta::FromMilliseconds(10)) {
+      UMA_HISTOGRAM_SPARSE_SLOWLY(
+          "Extensions.Functions.SucceededTime.5msTo10ms", histogram_value);
+    } else {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.SucceededTime.Over10ms",
+                                  histogram_value);
+    }
+    UMA_HISTOGRAM_TIMES("Extensions.Functions.SucceededTotalExecutionTime",
+                        elapsed_time);
+  } else {
+    if (elapsed_time < base::TimeDelta::FromMilliseconds(1)) {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.FailedTime.LessThan1ms",
+                                  histogram_value);
+    } else if (elapsed_time < base::TimeDelta::FromMilliseconds(5)) {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.FailedTime.1msTo5ms",
+                                  histogram_value);
+    } else if (elapsed_time < base::TimeDelta::FromMilliseconds(10)) {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.FailedTime.5msTo10ms",
+                                  histogram_value);
+    } else {
+      UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.Functions.FailedTime.Over10ms",
+                                  histogram_value);
+    }
+    UMA_HISTOGRAM_TIMES("Extensions.Functions.FailedTotalExecutionTime",
+                        elapsed_time);
+  }
+}
+
 class ArgumentListResponseValue
     : public ExtensionFunction::ResponseValueObject {
  public:
   ArgumentListResponseValue(const std::string& function_name,
                             const char* title,
                             ExtensionFunction* function,
                             std::unique_ptr<base::ListValue> result)
       : function_name_(function_name), title_(title) {
     if (function->GetResultList()) {
       DCHECK_EQ(function->GetResultList(), result.get())
@@ skipping 366 matching lines @@
   if (bad_message_) {
     type = BAD_MESSAGE;
     LOG(ERROR) << "Bad extension message " << name_;
   }
 
   // If results were never set, we send an empty argument list.
   if (!results_)
     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) {
   SendResponse(value->Apply());
 }
 
 UIThreadExtensionFunction::UIThreadExtensionFunction()
     : context_(nullptr),
       render_frame_host_(nullptr),
       is_from_service_worker_(false),
@@ skipping 158 matching lines @@
 ExtensionFunction::ResponseAction SyncIOThreadExtensionFunction::Run() {
   return RespondNow(RunSync() ? ArgumentList(std::move(results_))
                               : Error(error_));
 }
 
 // static
 bool SyncIOThreadExtensionFunction::ValidationFailure(
     SyncIOThreadExtensionFunction* function) {
   return false;
 }