[Extensions] Add coarse metrics for extension function performance

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/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/common/error_utils.h"
 #include "extensions/common/extension_api.h"
@@ skipping 376 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,

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

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)

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

Done.

+  // we can create a handful of buckets and record the function name so that we
+  // can find what the fastest/slowest are.
+  // Note: Certain functions perform actions that are inherantly slow - such as

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

nit: inherently

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

whoops, done.

+  // anything waiting on user action. As such, we can't always assume that a
+  // long execution time equates to a poorly-performing function.
+  UMA_HISTOGRAM_TIMES("Extensions.Functions.TotalExecutionTime",

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

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]

Sounds reasonable.  Done.

+                      timer_.Elapsed());
 }
 
 void ExtensionFunction::OnRespondingLater(ResponseValue value) {
   SendResponse(value->Apply());
 }
 
 UIThreadExtensionFunction::UIThreadExtensionFunction()
     : context_(nullptr),
       render_frame_host_(nullptr),
       delegate_(nullptr) {
@@ skipping 140 matching lines @@
 ExtensionFunction::ResponseAction SyncIOThreadExtensionFunction::Run() {
   return RespondNow(RunSync() ? ArgumentList(std::move(results_))
                               : Error(error_));
 }
 
 // static
 bool SyncIOThreadExtensionFunction::ValidationFailure(
     SyncIOThreadExtensionFunction* function) {
   return false;
 }