[Extensions] Add metrics for renderer sync IPCs performance

In the renderer, extensions use sync IPCs to request port ids and
request the i18n message bundle. We're looking into fixing this, but
it'll be useful to know how much time it's taking now.

BUG=645261

Review-Url: https://codereview.chromium.org/2316093004
Cr-Commit-Position: refs/heads/master@{#417489}

chrome/renderer/extensions/tabs_custom_bindings.cc

@@ -9,6 +9,7 @@
 #include <string>
 
 #include "base/bind.h"
+#include "base/metrics/histogram_macros.h"
 #include "content/public/renderer/render_frame.h"
 #include "extensions/common/extension_messages.h"
 #include "extensions/renderer/script_context.h"
@@ -48,9 +49,12 @@ void TabsCustomBindings::OpenChannelToTab(
   std::string extension_id = *v8::String::Utf8Value(args[2]);
   std::string channel_name = *v8::String::Utf8Value(args[3]);
   int port_id = -1;
-  render_frame->Send(new ExtensionHostMsg_OpenChannelToTab(
-      render_frame->GetRoutingID(), info, extension_id, channel_name,
-      &port_id));
+  {
+    SCOPED_UMA_HISTOGRAM_TIMER("Extensions.Messaging.GetPortIdSyncTime.Tab");
+    render_frame->Send(new ExtensionHostMsg_OpenChannelToTab(
+        render_frame->GetRoutingID(), info, extension_id, channel_name,
+        &port_id));
+  }
   args.GetReturnValue().Set(static_cast<int32_t>(port_id));
 }
 

extensions/renderer/i18n_custom_bindings.cc

@@ -12,6 +12,7 @@
 #include "base/bind.h"
 #include "base/macros.h"
 #include "base/memory/ptr_util.h"
+#include "base/metrics/histogram_macros.h"
 #include "content/public/child/v8_value_converter.h"
 #include "content/public/renderer/render_frame.h"
 #include "content/public/renderer/render_thread.h"
@@ -201,8 +202,11 @@ void I18NCustomBindings::GetL10nMessage(
 
     L10nMessagesMap messages;
     // A sync call to load message catalogs for current extension.
-    render_frame->Send(
-        new ExtensionHostMsg_GetMessageBundle(extension_id, &messages));
+    {
+      SCOPED_UMA_HISTOGRAM_TIMER("Extensions.SyncGetMessageBundle");
+      render_frame->Send(
+          new ExtensionHostMsg_GetMessageBundle(extension_id, &messages));
+    }
 
     // Save messages we got.
     ExtensionToL10nMessagesMap& l10n_messages_map =

extensions/renderer/runtime_custom_bindings.cc

@@ -9,6 +9,7 @@
 #include <memory>
 
 #include "base/bind.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/values.h"
 #include "content/public/child/v8_value_converter.h"
 #include "content/public/renderer/render_frame.h"
@@ -66,10 +67,14 @@ void RuntimeCustomBindings::OpenChannelToExtension(
   bool include_tls_channel_id =
       args.Length() > 2 ? args[2]->BooleanValue() : false;
   int port_id = -1;
-  // TODO(devlin): This file is littered with sync IPCs. Yuck.
-  renderframe->Send(new ExtensionHostMsg_OpenChannelToExtension(
-      renderframe->GetRoutingID(), info, channel_name, include_tls_channel_id,
-      &port_id));
+  {
+    SCOPED_UMA_HISTOGRAM_TIMER(
+        "Extensions.Messaging.GetPortIdSyncTime.Extension");
+    // TODO(devlin): This file is littered with sync IPCs. Yuck.
+    renderframe->Send(new ExtensionHostMsg_OpenChannelToExtension(
+        renderframe->GetRoutingID(), info, channel_name, include_tls_channel_id,
+        &port_id));
+  }
   args.GetReturnValue().Set(static_cast<int32_t>(port_id));
 }
 
@@ -90,8 +95,12 @@ void RuntimeCustomBindings::OpenChannelToNativeApp(
   std::string native_app_name = *v8::String::Utf8Value(args[0]);
 
   int port_id = -1;
-  render_frame->Send(new ExtensionHostMsg_OpenChannelToNativeApp(
-      render_frame->GetRoutingID(), native_app_name, &port_id));
+  {
+    SCOPED_UMA_HISTOGRAM_TIMER(
+        "Extensions.Messaging.GetPortIdSyncTime.NativeApp");
+    render_frame->Send(new ExtensionHostMsg_OpenChannelToNativeApp(
+        render_frame->GetRoutingID(), native_app_name, &port_id));
+  }
   args.GetReturnValue().Set(static_cast<int32_t>(port_id));
 }
 

tools/metrics/histograms/histograms.xml

@@ -15858,6 +15858,15 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   <summary>The manifest version of each loaded extension.</summary>
 </histogram>
 
+<histogram name="Extensions.Messaging.GetPortIdSyncTime" units="ms">
+  <owner>rdevlin.cronin@chromium.org</owner>
+  <summary>
+    The amount of synchronous time taken for the renderer to request an
+    extension message port id from the browser when a new channel is first
+    opened by an extension.
+  </summary>
+</histogram>
+
 <histogram name="Extensions.NetworkDelay" units="ms">
   <owner>battre@chromium.org</owner>
   <summary>Time that network requests were blocked due to extensions.</summary>
@@ -16567,6 +16576,14 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram name="Extensions.SyncGetMessageBundle" units="ms">
+  <owner>rdevlin.cronin@chromium.org</owner>
+  <summary>
+    The amount of synchronous time spent retrieving an extension's message
+    bundle (the collection of its i18n resources) from the browser.
+  </summary>
+</histogram>
+
 <histogram name="Extensions.ThrottledNetworkRequestDelay" units="ms">
   <owner>rdevlin.cronin@chromium.org</owner>
   <summary>
@@ -100605,6 +100622,13 @@ To add a new entry, add it with any value and run test to compute valid value.
   <affected-histogram name="Extensions.Functions.SucceededTime"/>
 </histogram_suffixes>
 
+<histogram_suffixes name="ExtensionMessagingPortType" separator=".">
+  <suffix name="Extension" label="A port opened to an extension context."/>
+  <suffix name="NativeApp" label="A port opened to a native application."/>
+  <suffix name="Tab" label="A port opened to a tab context."/>
+  <affected-histogram name="Extensions.Messaging.GetPortIdSyncTime"/>
+</histogram_suffixes>
+
 <histogram_suffixes name="ExtensionsDatabaseOpen" separator=".">
   <suffix name="Rules" label="Rules backing stores"/>
   <suffix name="Settings" label="Settings backing stores"/>