Bug 1070755: Telemetry to track total time that the main thread is blocked during plugin initialization; r=vladan (Relanding because I meant to back out a different commit for bustage, not this) CLOSED TREE
authorAaron Klotz <aklotz@mozilla.com>
Thu, 11 Dec 2014 14:00:47 -0700
changeset 219325 8eea64db9552bd83d73668e2182654145eb69209
parent 219324 5ee80f974980d05a0138765afd0472f3bae92bb0
child 219326 5288b15d22de803f6405b37c57cc2b08296d115e
push id27958
push userkwierso@gmail.com
push dateFri, 12 Dec 2014 01:30:39 +0000
treeherdermozilla-central@5288b15d22de [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersvladan
bugs1070755
milestone37.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1070755: Telemetry to track total time that the main thread is blocked during plugin initialization; r=vladan (Relanding because I meant to back out a different commit for bustage, not this) CLOSED TREE
dom/plugins/ipc/PluginInstanceParent.cpp
dom/plugins/ipc/PluginModuleParent.cpp
dom/plugins/ipc/PluginModuleParent.h
toolkit/components/telemetry/Histograms.json
toolkit/components/telemetry/Telemetry.h
--- a/dom/plugins/ipc/PluginInstanceParent.cpp
+++ b/dom/plugins/ipc/PluginInstanceParent.cpp
@@ -2,16 +2,17 @@
  * vim: sw=4 ts=4 et :
  * This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "mozilla/DebugOnly.h"
 #include <stdint.h> // for intptr_t
 
+#include "mozilla/Telemetry.h"
 #include "PluginInstanceParent.h"
 #include "BrowserStreamParent.h"
 #include "PluginBackgroundDestroyer.h"
 #include "PluginModuleParent.h"
 #include "PluginStreamParent.h"
 #include "StreamNotifyParent.h"
 #include "npfunctions.h"
 #include "nsAutoPtr.h"
@@ -140,18 +141,23 @@ PluginInstanceParent::ActorDestroy(Actor
 #endif
     }
 }
 
 NPError
 PluginInstanceParent::Destroy()
 {
     NPError retval;
-    if (!CallNPP_Destroy(&retval))
-        retval = NPERR_GENERIC_ERROR;
+    {   // Scope for timer
+        Telemetry::AutoTimer<Telemetry::BLOCKED_ON_PLUGIN_INSTANCE_DESTROY_MS>
+            timer(Module()->GetHistogramKey());
+        if (!CallNPP_Destroy(&retval)) {
+            retval = NPERR_GENERIC_ERROR;
+        }
+    }
 
 #if defined(OS_WIN)
     SharedSurfaceRelease();
     UnsubclassPluginWindow();
 #endif
 
     return retval;
 }
@@ -1299,25 +1305,30 @@ PluginInstanceParent::NPP_NewStream(NPMI
                                     NPBool seekable, uint16_t* stype)
 {
     PLUGIN_LOG_DEBUG(("%s (type=%s, stream=%p, seekable=%i)",
                       FULLFUNCTION, (char*) type, (void*) stream, (int) seekable));
 
     BrowserStreamParent* bs = new BrowserStreamParent(this, stream);
 
     NPError err;
-    if (!CallPBrowserStreamConstructor(bs,
-                                       NullableString(stream->url),
-                                       stream->end,
-                                       stream->lastmodified,
-                                       static_cast<PStreamNotifyParent*>(stream->notifyData),
-                                       NullableString(stream->headers),
-                                       NullableString(type), seekable,
-                                       &err, stype))
-        return NPERR_GENERIC_ERROR;
+    {   // Scope for timer
+        Telemetry::AutoTimer<Telemetry::BLOCKED_ON_PLUGIN_STREAM_INIT_MS>
+            timer(Module()->GetHistogramKey());
+        if (!CallPBrowserStreamConstructor(bs,
+                                           NullableString(stream->url),
+                                           stream->end,
+                                           stream->lastmodified,
+                                           static_cast<PStreamNotifyParent*>(stream->notifyData),
+                                           NullableString(stream->headers),
+                                           NullableString(type), seekable,
+                                           &err, stype)) {
+            return NPERR_GENERIC_ERROR;
+        }
+    }
 
     if (NPERR_NO_ERROR != err)
         unused << PBrowserStreamParent::Send__delete__(bs);
 
     return err;
 }
 
 NPError
--- a/dom/plugins/ipc/PluginModuleParent.cpp
+++ b/dom/plugins/ipc/PluginModuleParent.cpp
@@ -16,16 +16,17 @@
 #include "mozilla/dom/ContentChild.h"
 #include "mozilla/dom/PCrashReporterParent.h"
 #include "mozilla/ipc/MessageChannel.h"
 #include "mozilla/plugins/BrowserStreamParent.h"
 #include "mozilla/plugins/PluginBridge.h"
 #include "mozilla/plugins/PluginInstanceParent.h"
 #include "mozilla/Preferences.h"
 #include "mozilla/Services.h"
+#include "mozilla/Telemetry.h"
 #include "mozilla/unused.h"
 #include "nsAutoPtr.h"
 #include "nsCRT.h"
 #include "nsIFile.h"
 #include "nsIObserverService.h"
 #include "nsNPAPIPlugin.h"
 #include "nsPrintfCString.h"
 #include "prsystem.h"
@@ -155,22 +156,25 @@ PluginLibrary*
 PluginModuleChromeParent::LoadModule(const char* aFilePath, uint32_t aPluginId)
 {
     PLUGIN_LOG_DEBUG_FUNCTION;
 
     int32_t prefSecs = Preferences::GetInt(kLaunchTimeoutPref, 0);
 
     // Block on the child process being launched and initialized.
     nsAutoPtr<PluginModuleChromeParent> parent(new PluginModuleChromeParent(aFilePath, aPluginId));
+    TimeStamp launchStart = TimeStamp::Now();
     bool launched = parent->mSubprocess->Launch(prefSecs * 1000);
     if (!launched) {
         // We never reached open
         parent->mShutdown = true;
         return nullptr;
     }
+    TimeStamp launchEnd = TimeStamp::Now();
+    parent->mTimeBlocked = (launchEnd - launchStart);
     parent->Open(parent->mSubprocess->GetChannel(),
                  parent->mSubprocess->GetChildProcessHandle());
 
     // Request Windows message deferral behavior on our channel. This
     // applies to the top level and all sub plugin protocols since they
     // all share the same channel.
     parent->GetIPCChannel()->SetChannelFlags(MessageChannel::REQUIRE_DEFERRED_MESSAGE_PROTECTION);
 
@@ -1373,24 +1377,35 @@ PluginModuleParent::NP_Initialize(NPNets
         *error = NPERR_GENERIC_ERROR;
         return NS_ERROR_FAILURE;
     }
 
     *error = NPERR_NO_ERROR;
     if (IsChrome()) {
         PluginSettings settings;
         GetSettings(&settings);
+        TimeStamp callNpInitStart = TimeStamp::Now();
         if (!CallNP_Initialize(settings, error)) {
             Close();
             return NS_ERROR_FAILURE;
         }
         else if (*error != NPERR_NO_ERROR) {
             Close();
             return NS_OK;
         }
+        TimeStamp callNpInitEnd = TimeStamp::Now();
+        mTimeBlocked += (callNpInitEnd - callNpInitStart);
+        /** mTimeBlocked measures the time that the main thread has been blocked
+         *  on plugin module initialization. As implemented, this is the sum of
+         *  plugin-container launch + NP_Initialize
+         */
+        Telemetry::Accumulate(Telemetry::BLOCKED_ON_PLUGIN_MODULE_INIT_MS,
+                              GetHistogramKey(),
+                              static_cast<uint32_t>(mTimeBlocked.ToMilliseconds()));
+        mTimeBlocked = TimeDuration();
     }
 
     SetPluginFuncs(pFuncs);
 
     return NS_OK;
 }
 #else
 nsresult
@@ -1413,24 +1428,27 @@ nsresult
 PluginModuleChromeParent::NP_Initialize(NPNetscapeFuncs* bFuncs, NPError* error)
 {
     nsresult rv = PluginModuleParent::NP_Initialize(bFuncs, error);
     if (NS_FAILED(rv))
         return rv;
 
     PluginSettings settings;
     GetSettings(&settings);
+    TimeStamp callNpInitStart = TimeStamp::Now();
     if (!CallNP_Initialize(settings, error)) {
         Close();
         return NS_ERROR_FAILURE;
     }
     if (*error != NPERR_NO_ERROR) {
         Close();
         return NS_OK;
     }
+    TimeStamp callNpInitEnd = TimeStamp::Now();
+    mTimeBlocked += (callNpInitEnd - callNpInitStart);
 
 #if defined XP_WIN
     // Send the info needed to join the chrome process's audio session to the
     // plugin process
     nsID id;
     nsString sessionName;
     nsString iconPath;
 
@@ -1438,16 +1456,27 @@ PluginModuleChromeParent::NP_Initialize(
                                                           iconPath)))
         unused << SendSetAudioSessionData(id, sessionName, iconPath);
 #endif
 
 #ifdef MOZ_CRASHREPORTER_INJECTOR
     InitializeInjector();
 #endif
 
+    /** This Accumulate must be placed below the call to InitializeInjector()
+     *  because mTimeBlocked is modified in that function.
+     *  mTimeBlocked measures the time that the main thread has been blocked
+     *  on plugin module initialization. As implemented, this is the sum of
+     *  plugin-container launch + toolhelp32 snapshot + NP_Initialize
+     */
+    Telemetry::Accumulate(Telemetry::BLOCKED_ON_PLUGIN_MODULE_INIT_MS,
+                          GetHistogramKey(),
+                          static_cast<uint32_t>(mTimeBlocked.ToMilliseconds()));
+    mTimeBlocked = TimeDuration();
+
     return NS_OK;
 }
 #endif
 
 nsresult
 PluginModuleParent::NP_Shutdown(NPError* error)
 {
     PLUGIN_LOG_DEBUG_METHOD;
@@ -1551,27 +1580,31 @@ PluginModuleParent::NPP_New(NPMIMEType p
 
     if (!parentInstance->Init()) {
         delete parentInstance;
         return NS_ERROR_FAILURE;
     }
 
     instance->pdata = parentInstance;
 
-    if (!CallPPluginInstanceConstructor(parentInstance,
-                                        nsDependentCString(pluginType), mode,
-                                        names, values, error)) {
-        // |parentInstance| is automatically deleted.
-        instance->pdata = nullptr;
-        // if IPC is down, we'll get an immediate "failed" return, but
-        // without *error being set.  So make sure that the error
-        // condition is signaled to nsNPAPIPluginInstance
-        if (NPERR_NO_ERROR == *error)
-            *error = NPERR_GENERIC_ERROR;
-        return NS_ERROR_FAILURE;
+    {   // Scope for timer
+        Telemetry::AutoTimer<Telemetry::BLOCKED_ON_PLUGIN_INSTANCE_INIT_MS>
+            timer(GetHistogramKey());
+        if (!CallPPluginInstanceConstructor(parentInstance,
+                                            nsDependentCString(pluginType), mode,
+                                            names, values, error)) {
+            // |parentInstance| is automatically deleted.
+            instance->pdata = nullptr;
+            // if IPC is down, we'll get an immediate "failed" return, but
+            // without *error being set.  So make sure that the error
+            // condition is signaled to nsNPAPIPluginInstance
+            if (NPERR_NO_ERROR == *error)
+                *error = NPERR_GENERIC_ERROR;
+            return NS_ERROR_FAILURE;
+        }
     }
 
     if (*error != NPERR_NO_ERROR) {
         NPP_Destroy(instance, 0);
         return NS_ERROR_FAILURE;
     }
 
     UpdatePluginTimeout();
@@ -1908,19 +1941,22 @@ PluginModuleChromeParent::InitializeInje
     int32_t lastSlash = path.RFindCharInSet("\\/");
     if (kNotFound == lastSlash)
         return;
 
     if (!StringBeginsWith(Substring(path, lastSlash + 1),
                           NS_LITERAL_CSTRING(FLASH_PLUGIN_PREFIX)))
         return;
 
+    TimeStamp th32Start = TimeStamp::Now();
     HANDLE snapshot = CreateToolhelp32Snapshot(TH32CS_SNAPPROCESS, 0);
     if (INVALID_HANDLE_VALUE == snapshot)
         return;
+    TimeStamp th32End = TimeStamp::Now();
+    mTimeBlocked += (th32End - th32Start);
 
     DWORD pluginProcessPID = GetProcessId(Process()->GetChildProcessHandle());
     mFlashProcess1 = GetFlashChildOfPID(pluginProcessPID, snapshot);
     if (mFlashProcess1) {
         InjectCrashReporterIntoProcess(mFlashProcess1, this);
 
         mFlashProcess2 = GetFlashChildOfPID(mFlashProcess1, snapshot);
         if (mFlashProcess2) {
--- a/dom/plugins/ipc/PluginModuleParent.h
+++ b/dom/plugins/ipc/PluginModuleParent.h
@@ -11,16 +11,17 @@
 #include "mozilla/FileUtils.h"
 #include "mozilla/HangMonitor.h"
 #include "mozilla/PluginLibrary.h"
 #include "mozilla/plugins/ScopedMethodFactory.h"
 #include "mozilla/plugins/PluginProcessParent.h"
 #include "mozilla/plugins/PPluginModuleParent.h"
 #include "mozilla/plugins/PluginMessageUtils.h"
 #include "mozilla/plugins/PluginTypes.h"
+#include "mozilla/TimeStamp.h"
 #include "npapi.h"
 #include "npfunctions.h"
 #include "nsAutoPtr.h"
 #include "nsDataHashtable.h"
 #include "nsHashKeys.h"
 #include "nsIObserver.h"
 
 #ifdef MOZ_CRASHREPORTER
@@ -100,16 +101,20 @@ public:
     }
 
     bool OkToCleanup() const {
         return !IsOnCxxStack();
     }
 
     void ProcessRemoteNativeEventsInInterruptCall();
 
+    nsCString GetHistogramKey() const {
+        return mPluginName + mPluginVersion;
+    }
+
 protected:
     virtual mozilla::ipc::RacyInterruptPolicy
     MediateInterruptRace(const Message& parent, const Message& child) MOZ_OVERRIDE
     {
         return MediateRace(parent, child);
     }
 
     virtual bool
@@ -240,16 +245,17 @@ protected:
     bool mGetSitesWithDataSupported;
     const NPNetscapeFuncs* mNPNIface;
     nsNPAPIPlugin* mPlugin;
     ScopedMethodFactory<PluginModuleParent> mTaskFactory;
     nsString mPluginDumpID;
     nsString mBrowserDumpID;
     nsString mHangID;
     nsRefPtr<nsIObserver> mProfilerObserver;
+    TimeDuration mTimeBlocked;
     nsCString mPluginName;
     nsCString mPluginVersion;
 
 #ifdef MOZ_X11
     // Dup of plugin's X socket, used to scope its resources to this
     // object instead of the plugin process's lifetime
     ScopedClose mPluginXSocketFdDup;
 #endif
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -6917,16 +6917,52 @@
     "kind": "boolean",
     "description": "Whether a user who accepted e10s from the prompt is still using e10s"
   },
   "E10S_BLOCKED_FROM_RUNNING": {
     "expires_in_version": "40",
     "kind": "boolean",
     "description": "Whether the e10s pref was set but it was blocked from running due to blacklisted conditions"
   },
+  "BLOCKED_ON_PLUGIN_MODULE_INIT_MS": {
+    "expires_in_version": "40",
+    "kind": "exponential",
+    "high": "10000",
+    "n_buckets": 20,
+    "extended_statistics_ok": true,
+    "keyed": true,
+    "description": "Time (ms) that the main thread has been blocked on LoadModule and NP_Initialize in PluginModuleParent"
+  },
+  "BLOCKED_ON_PLUGIN_INSTANCE_INIT_MS": {
+    "expires_in_version": "40",
+    "kind": "exponential",
+    "high": "10000",
+    "n_buckets": 20,
+    "extended_statistics_ok": true,
+    "keyed": true,
+    "description": "Time (ms) that the main thread has been blocked on NPP_New in an IPC plugin"
+  },
+  "BLOCKED_ON_PLUGIN_STREAM_INIT_MS": {
+    "expires_in_version": "40",
+    "kind": "exponential",
+    "high": "10000",
+    "n_buckets": 20,
+    "extended_statistics_ok": true,
+    "keyed": true,
+    "description": "Time (ms) that the main thread has been blocked on NPP_NewStream in an IPC plugin"
+  },
+  "BLOCKED_ON_PLUGIN_INSTANCE_DESTROY_MS": {
+    "expires_in_version": "40",
+    "kind": "exponential",
+    "high": "10000",
+    "n_buckets": 20,
+    "extended_statistics_ok": true,
+    "keyed": true,
+    "description": "Time (ms) that the main thread has been blocked on NPP_Destroy in an IPC plugin"
+  },
   "ONBEFOREUNLOAD_PROMPT_ACTION" : {
     "expires_in_version": "45",
     "kind": "enumerated",
     "n_values": 3,
     "description": "What button a user clicked in an onbeforeunload prompt.  (Stay on Page = 0, Leave Page = 1, prompt aborted = 2)"
   },
   "ONBEFOREUNLOAD_PROMPT_COUNT" : {
     "expires_in_version": "45",
--- a/toolkit/components/telemetry/Telemetry.h
+++ b/toolkit/components/telemetry/Telemetry.h
@@ -84,50 +84,69 @@ base::Histogram* GetKeyedHistogramById(I
 /**
  * Those wrappers are needed because the VS versions we use do not support free
  * functions with default template arguments.
  */
 template<TimerResolution res>
 struct AccumulateDelta_impl
 {
   static void compute(ID id, TimeStamp start, TimeStamp end = TimeStamp::Now());
+  static void compute(ID id, const nsCString& key, TimeStamp start, TimeStamp end = TimeStamp::Now());
 };
 
 template<>
 struct AccumulateDelta_impl<Millisecond>
 {
   static void compute(ID id, TimeStamp start, TimeStamp end = TimeStamp::Now()) {
     Accumulate(id, static_cast<uint32_t>((end - start).ToMilliseconds()));
   }
+  static void compute(ID id, const nsCString& key, TimeStamp start, TimeStamp end = TimeStamp::Now()) {
+    Accumulate(id, key, static_cast<uint32_t>((end - start).ToMilliseconds()));
+  }
 };
 
 template<>
 struct AccumulateDelta_impl<Microsecond>
 {
   static void compute(ID id, TimeStamp start, TimeStamp end = TimeStamp::Now()) {
     Accumulate(id, static_cast<uint32_t>((end - start).ToMicroseconds()));
   }
+  static void compute(ID id, const nsCString& key, TimeStamp start, TimeStamp end = TimeStamp::Now()) {
+    Accumulate(id, key, static_cast<uint32_t>((end - start).ToMicroseconds()));
+  }
 };
 
 
 template<ID id, TimerResolution res = Millisecond>
 class AutoTimer {
 public:
   explicit AutoTimer(TimeStamp aStart = TimeStamp::Now() MOZ_GUARD_OBJECT_NOTIFIER_PARAM)
      : start(aStart)
   {
     MOZ_GUARD_OBJECT_NOTIFIER_INIT;
   }
 
+  explicit AutoTimer(const nsCString& aKey, TimeStamp aStart = TimeStamp::Now() MOZ_GUARD_OBJECT_NOTIFIER_PARAM)
+    : start(aStart)
+    , key(aKey)
+  {
+    MOZ_GUARD_OBJECT_NOTIFIER_INIT;
+  }
+
   ~AutoTimer() {
-    AccumulateDelta_impl<res>::compute(id, start);
+    if (key.IsEmpty()) {
+      AccumulateDelta_impl<res>::compute(id, start);
+    } else {
+      AccumulateDelta_impl<res>::compute(id, key, start);
+    }
   }
 
 private:
   const TimeStamp start;
+  const nsCString key;
   MOZ_DECL_USE_GUARD_OBJECT_NOTIFIER
 };
 
 template<ID id>
 class AutoCounter {
 public:
   explicit AutoCounter(uint32_t counterStart = 0 MOZ_GUARD_OBJECT_NOTIFIER_PARAM)
     : counter(counterStart)