[Extensions] Add coarse metrics for extension function performance

extensions/browser/extension_function_dispatcher.cc

 // Copyright 2014 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_dispatcher.h"
 
 #include <utility>
 
 #include "base/bind.h"
 #include "base/json/json_string_value_serializer.h"
@@ skipping 274 matching lines @@
                                               base::TimeTicks::Now());
   if (violation_error.empty()) {
     std::unique_ptr<base::ListValue> args(params.arguments.DeepCopy());
     NotifyApiFunctionCalled(extension->id(), params.name, std::move(args),
                             static_cast<content::BrowserContext*>(profile_id));
     UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.FunctionCalls",
                                 function->histogram_value());
     tracked_objects::ScopedProfile scoped_profile(
         FROM_HERE_WITH_EXPLICIT_FUNCTION(function->name()),
         tracked_objects::ScopedProfile::ENABLED);
+    base::ElapsedTimer timer;
     function->Run()->Execute();
+    // 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.
+    // Note: Many functions execute finish asynchronously, so this time is not
+    // always a representation of total time taken. See also
+    // Extensions.Functions.TotalExecutionTime.
+    UMA_HISTOGRAM_TIMES("Extensions.Functions.SynchronousExecutionTime",
+                        timer.Elapsed());
   } else {
     function->OnQuotaExceeded(violation_error);
   }
 }
 
 ExtensionFunctionDispatcher::ExtensionFunctionDispatcher(
     content::BrowserContext* browser_context)
     : browser_context_(browser_context), delegate_(nullptr) {}
 
 ExtensionFunctionDispatcher::~ExtensionFunctionDispatcher() {
@@ skipping 89 matching lines @@
 
     // See crbug.com/39178.
     ExtensionsBrowserClient::Get()->PermitExternalProtocolHandler();
     NotifyApiFunctionCalled(extension->id(), params.name, std::move(args),
                             browser_context_);
     UMA_HISTOGRAM_SPARSE_SLOWLY("Extensions.FunctionCalls",
                                 function->histogram_value());
     tracked_objects::ScopedProfile scoped_profile(
         FROM_HERE_WITH_EXPLICIT_FUNCTION(function->name()),
         tracked_objects::ScopedProfile::ENABLED);
+    base::ElapsedTimer timer;
     function->Run()->Execute();
+    // 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.
+    // Note: Many functions execute finish asynchronously, so this time is not
+    // always a representation of total time taken. See also
+    // Extensions.Functions.TotalExecutionTime.
+    UMA_HISTOGRAM_TIMES("Extensions.Functions.SynchronousExecutionTime",
+                        timer.Elapsed());
   } else {
     function->OnQuotaExceeded(violation_error);
   }
 
   // Note: do not access |this| after this point. We may have been deleted
   // if function->Run() ended up closing the tab that owns us.
 
   // Check if extension was uninstalled by management.uninstall.
   if (!registry->enabled_extensions().GetByID(params.extension_id))
     return;
@@ skipping 78 matching lines @@
 // static
 void ExtensionFunctionDispatcher::SendAccessDenied(
     const ExtensionFunction::ResponseCallback& callback,
     functions::HistogramValue histogram_value) {
   base::ListValue empty_list;
   callback.Run(ExtensionFunction::FAILED, empty_list,
                "Access to extension API denied.", histogram_value);
 }
 
 }  // namespace extensions