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 id10368
push userkwierso@gmail.com
push dateFri, 12 Dec 2014 01:38:39 +0000
treeherderfx-team@5288b15d22de [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersvladan
bugs1070755
milestone37.0a1
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)