Bug 1381591 - Refactor plugin initialization/performance telemetry to measure the things we care about, r=qdot data-r=rweiss
authorBenjamin Smedberg <benjamin@smedbergs.us>
Mon, 17 Jul 2017 16:31:45 -0400
changeset 414426 1538eed11e2dee98e05f3ea05fb11b2118d52eae
parent 414425 89365bc6bf4a5bdd4718f8e5fe2724693f26a3b5
child 414427 cbed2a3a2feb1f39221275f06f4e50e6f6237453
push id1490
push usermtabara@mozilla.com
push dateMon, 31 Jul 2017 14:08:16 +0000
treeherdermozilla-release@70e32e6bf15e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersqdot
bugs1381591
milestone55.0
Bug 1381591 - Refactor plugin initialization/performance telemetry to measure the things we care about, r=qdot data-r=rweiss MozReview-Commit-ID: CZ6AZ64RUt9
dom/plugins/ipc/PluginAsyncSurrogate.cpp
dom/plugins/ipc/PluginInstanceParent.cpp
dom/plugins/ipc/PluginModuleParent.cpp
dom/plugins/ipc/PluginModuleParent.h
toolkit/components/telemetry/Histograms.json
toolkit/components/telemetry/Scalars.yaml
--- a/dom/plugins/ipc/PluginAsyncSurrogate.cpp
+++ b/dom/plugins/ipc/PluginAsyncSurrogate.cpp
@@ -497,18 +497,16 @@ bool
 PluginAsyncSurrogate::WaitForInit()
 {
   if (mInitCancelled) {
     return false;
   }
   if (mAcceptCalls) {
     return true;
   }
-  Telemetry::AutoTimer<Telemetry::BLOCKED_ON_PLUGINASYNCSURROGATE_WAITFORINIT_MS>
-    timer(mParent->GetHistogramKey());
   bool result = false;
   MOZ_ASSERT(mParent);
   if (mParent->IsChrome()) {
     PluginProcessParent* process = static_cast<PluginModuleChromeParent*>(mParent)->Process();
     MOZ_ASSERT(process);
     process->SetCallRunnableImmediately(true);
     if (!process->WaitUntilConnected()) {
       return false;
--- a/dom/plugins/ipc/PluginInstanceParent.cpp
+++ b/dom/plugins/ipc/PluginInstanceParent.cpp
@@ -201,22 +201,18 @@ PluginInstanceParent::ActorDestroy(Actor
         mImageContainer->ClearAllImages();
     }
 }
 
 NPError
 PluginInstanceParent::Destroy()
 {
     NPError retval;
-    {   // Scope for timer
-        Telemetry::AutoTimer<Telemetry::BLOCKED_ON_PLUGIN_INSTANCE_DESTROY_MS>
-            timer(Module()->GetHistogramKey());
-        if (!CallNPP_Destroy(&retval)) {
-            retval = NPERR_GENERIC_ERROR;
-        }
+    if (!CallNPP_Destroy(&retval)) {
+        retval = NPERR_GENERIC_ERROR;
     }
 
 #if defined(OS_WIN)
     UnsubclassPluginWindow();
 #endif
 
     return retval;
 }
@@ -1767,19 +1763,16 @@ PluginInstanceParent::NPP_NewStream(NPMI
                                        NullableString(stream->url),
                                        stream->end,
                                        stream->lastmodified,
                                        static_cast<PStreamNotifyParent*>(stream->notifyData),
                                        NullableString(stream->headers))) {
         return NPERR_GENERIC_ERROR;
     }
 
-    Telemetry::AutoTimer<Telemetry::BLOCKED_ON_PLUGIN_STREAM_INIT_MS>
-        timer(Module()->GetHistogramKey());
-
     NPError err = NPERR_NO_ERROR;
     if (mParent->IsStartingAsync()) {
         MOZ_ASSERT(mSurrogate);
         mSurrogate->AsyncCallDeparting();
         if (SendAsyncNPP_NewStream(bs, NullableString(type), seekable)) {
             *stype = nsPluginStreamListenerPeer::STREAM_TYPE_UNKNOWN;
         } else {
             err = NPERR_GENERIC_ERROR;
--- a/dom/plugins/ipc/PluginModuleParent.cpp
+++ b/dom/plugins/ipc/PluginModuleParent.cpp
@@ -102,21 +102,16 @@ mozilla::plugins::SetupBridge(uint32_t a
     PluginModuleChromeParent::ClearInstantiationFlag();
     RefPtr<nsPluginHost> host = nsPluginHost::GetInst();
     RefPtr<nsNPAPIPlugin> plugin;
     *rv = host->GetPluginForContentProcess(aPluginId, getter_AddRefs(plugin));
     if (NS_FAILED(*rv)) {
         return true;
     }
     PluginModuleChromeParent* chromeParent = static_cast<PluginModuleChromeParent*>(plugin->GetLibrary());
-    /*
-     *  We can't accumulate BLOCKED_ON_PLUGIN_MODULE_INIT_MS until here because
-     *  its histogram key is not available until *after* NP_Initialize.
-     */
-    chromeParent->AccumulateModuleInitBlockedTime();
     *rv = chromeParent->GetRunID(runID);
     if (NS_FAILED(*rv)) {
         return true;
     }
     if (chromeParent->IsStartingAsync()) {
         chromeParent->SetContentParent(aContentParent);
     }
     if (!aForceBridgeNow && chromeParent->IsStartingAsync() &&
@@ -424,27 +419,24 @@ PluginModuleContentParent::LoadModule(ui
      * PluginModuleParent instance. That message is handled by
      * PluginModuleContentParent::Initialize, which saves the instance in
      * its module mapping. We fetch it from there after LoadPlugin finishes.
      */
     dom::ContentChild* cp = dom::ContentChild::GetSingleton();
     nsresult rv;
     uint32_t runID;
     Endpoint<PPluginModuleParent> endpoint;
-    TimeStamp sendLoadPluginStart = TimeStamp::Now();
     if (!cp->SendLoadPlugin(aPluginId, &rv, &runID, &endpoint) ||
         NS_FAILED(rv)) {
         return nullptr;
     }
     Initialize(Move(endpoint));
-    TimeStamp sendLoadPluginEnd = TimeStamp::Now();
 
     PluginModuleContentParent* parent = mapping->GetModule();
     MOZ_ASSERT(parent);
-    parent->mTimeBlocked += (sendLoadPluginEnd - sendLoadPluginStart);
 
     if (!mapping->IsChannelOpened()) {
         // mapping is linked into PluginModuleMapping::sModuleListHead and is
         // needed later, so since this function is returning successfully we
         // forget it here.
         mapping.forget();
     }
 
@@ -528,17 +520,16 @@ PluginModuleChromeParent::LoadModule(con
     PLUGIN_LOG_DEBUG_FUNCTION;
 
     nsAutoPtr<PluginModuleChromeParent> parent(
             new PluginModuleChromeParent(aFilePath, aPluginId,
                                          aPluginTag->mSandboxLevel,
                                          aPluginTag->mSupportsAsyncInit));
     UniquePtr<LaunchCompleteTask> onLaunchedRunnable(new LaunchedTask(parent));
     parent->mSubprocess->SetCallRunnableImmediately(!parent->mIsStartingAsync);
-    TimeStamp launchStart = TimeStamp::Now();
     bool launched = parent->mSubprocess->Launch(Move(onLaunchedRunnable),
                                                 aPluginTag->mSandboxLevel);
     if (!launched) {
         // We never reached open
         parent->mShutdown = true;
         return nullptr;
     }
     parent->mIsFlashPlugin = aPluginTag->mIsFlashPlugin;
@@ -547,18 +538,16 @@ PluginModuleChromeParent::LoadModule(con
     parent->mIsBlocklisted = NS_FAILED(rv) || blocklistState != 0;
     if (!parent->mIsStartingAsync) {
         int32_t launchTimeoutSecs = Preferences::GetInt(kLaunchTimeoutPref, 0);
         if (!parent->mSubprocess->WaitUntilConnected(launchTimeoutSecs * 1000)) {
             parent->mShutdown = true;
             return nullptr;
         }
     }
-    TimeStamp launchEnd = TimeStamp::Now();
-    parent->mTimeBlocked = (launchEnd - launchStart);
     return parent.forget();
 }
 
 void
 PluginModuleChromeParent::OnProcessLaunched(const bool aSucceeded)
 {
     if (!aSucceeded) {
         mShutdown = true;
@@ -2209,39 +2198,34 @@ PluginModuleChromeParent::NP_Initialize(
         // OnProcessLaunched is invoked.
         mInitOnAsyncConnect = true;
         return NS_OK;
     }
 
     PluginSettings settings;
     GetSettings(&settings);
 
-    TimeStamp callNpInitStart = TimeStamp::Now();
     // Asynchronous case
     if (mIsStartingAsync) {
         if (!SendAsyncNP_Initialize(settings)) {
             Close();
             return NS_ERROR_FAILURE;
         }
-        TimeStamp callNpInitEnd = TimeStamp::Now();
-        mTimeBlocked += (callNpInitEnd - callNpInitStart);
         return NS_OK;
     }
 
     // Synchronous case
     if (!CallNP_Initialize(settings, error)) {
         Close();
         return NS_ERROR_FAILURE;
     }
     else if (*error != NPERR_NO_ERROR) {
         Close();
         return NS_ERROR_FAILURE;
     }
-    TimeStamp callNpInitEnd = TimeStamp::Now();
-    mTimeBlocked += (callNpInitEnd - callNpInitStart);
 
     RecvNP_InitializeResult(*error);
 
     return NS_OK;
 }
 
 mozilla::ipc::IPCResult
 PluginModuleParent::RecvNP_InitializeResult(const NPError& aError)
@@ -2336,32 +2320,27 @@ PluginModuleChromeParent::NP_Initialize(
         *error = NPERR_NO_ERROR;
         return NS_OK;
     }
 #endif
 
     PluginSettings settings;
     GetSettings(&settings);
 
-    TimeStamp callNpInitStart = TimeStamp::Now();
     if (mIsStartingAsync) {
         if (!SendAsyncNP_Initialize(settings)) {
             return NS_ERROR_FAILURE;
         }
-        TimeStamp callNpInitEnd = TimeStamp::Now();
-        mTimeBlocked += (callNpInitEnd - callNpInitStart);
         return NS_OK;
     }
 
     if (!CallNP_Initialize(settings, error)) {
         Close();
         return NS_ERROR_FAILURE;
     }
-    TimeStamp callNpInitEnd = TimeStamp::Now();
-    mTimeBlocked += (callNpInitEnd - callNpInitStart);
     RecvNP_InitializeResult(*error);
     return NS_OK;
 }
 
 mozilla::ipc::IPCResult
 PluginModuleParent::RecvNP_InitializeResult(const NPError& aError)
 {
     if (aError != NPERR_NO_ERROR) {
@@ -2654,28 +2633,16 @@ class nsCaseInsensitiveUTF8StringArrayCo
 {
 public:
   template<class A, class B>
   bool Equals(const A& a, const B& b) const {
     return a.Equals(b.get(), nsCaseInsensitiveUTF8StringComparator());
   }
 };
 
-void
-PluginModuleParent::AccumulateModuleInitBlockedTime()
-{
-    if (mPluginName.IsEmpty()) {
-        GetPluginDetails();
-    }
-    Telemetry::Accumulate(Telemetry::BLOCKED_ON_PLUGIN_MODULE_INIT_MS,
-                          GetHistogramKey(),
-                          static_cast<uint32_t>(mTimeBlocked.ToMilliseconds()));
-    mTimeBlocked = TimeDuration();
-}
-
 #if defined(XP_WIN) || defined(MOZ_WIDGET_GTK)
 static void
 ForceWindowless(InfallibleTArray<nsCString>& names,
                 InfallibleTArray<nsCString>& values)
 {
     nsCaseInsensitiveUTF8StringArrayComparator comparator;
     NS_NAMED_LITERAL_CSTRING(wmodeAttributeName, "wmode");
     NS_NAMED_LITERAL_CSTRING(opaqueAttributeValue, "opaque");
@@ -2717,23 +2684,16 @@ PluginModuleParent::NPP_NewInternal(NPMI
                                     InfallibleTArray<nsCString>& names,
                                     InfallibleTArray<nsCString>& values,
                                     NPSavedData* saved, NPError* error)
 {
     MOZ_ASSERT(names.Length() == values.Length());
     if (mPluginName.IsEmpty()) {
         GetPluginDetails();
         InitQuirksModes(nsDependentCString(pluginType));
-        /** 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.
-         *  We don't accumulate its value until here because the plugin info
-         *  for its histogram key is not available until *after* NP_Initialize.
-         */
-        AccumulateModuleInitBlockedTime();
     }
 
     nsCaseInsensitiveUTF8StringArrayComparator comparator;
     NS_NAMED_LITERAL_CSTRING(srcAttributeName, "src");
     auto srcAttributeIndex = names.IndexOf(srcAttributeName, 0, comparator);
     nsAutoCString srcAttribute;
     if (srcAttributeIndex != names.NoIndex) {
         srcAttribute = values[srcAttributeIndex];
@@ -2804,19 +2764,17 @@ PluginModuleParent::NPP_NewInternal(NPMI
                                         nsDependentCString(pluginType),
                                         names, values)) {
         // |parentInstance| is automatically deleted.
         instance->pdata = nullptr;
         *error = NPERR_GENERIC_ERROR;
         return NS_ERROR_FAILURE;
     }
 
-    {   // Scope for timer
-        Telemetry::AutoTimer<Telemetry::BLOCKED_ON_PLUGIN_INSTANCE_INIT_MS>
-            timer(GetHistogramKey());
+    {
         if (mIsStartingAsync) {
             MOZ_ASSERT(surrogate);
             surrogate->AsyncCallDeparting();
             if (!SendAsyncNPP_New(parentInstance)) {
                 *error = NPERR_GENERIC_ERROR;
                 return NS_ERROR_FAILURE;
             }
             *error = NPERR_NO_ERROR;
@@ -2835,16 +2793,18 @@ PluginModuleParent::NPP_NewInternal(NPMI
 
     if (*error != NPERR_NO_ERROR) {
         if (!mIsStartingAsync) {
             NPP_Destroy(instance, 0);
         }
         return NS_ERROR_FAILURE;
     }
 
+    Telemetry::ScalarAdd(Telemetry::ScalarID::BROWSER_USAGE_PLUGIN_INSTANTIATED, 1);
+
     UpdatePluginTimeout();
 
     return NS_OK;
 }
 
 void
 PluginModuleChromeParent::UpdatePluginTimeout()
 {
@@ -3196,26 +3156,23 @@ 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();
     mFinishInitTask = mChromeTaskFactory.NewTask<FinishInjectorInitTask>();
     mFinishInitTask->Init(this);
     if (!::QueueUserWorkItem(&PluginModuleChromeParent::GetToolhelpSnapshot,
                              mFinishInitTask, WT_EXECUTEDEFAULT)) {
         mFinishInitTask = nullptr;
         return;
     }
-    TimeStamp th32End = TimeStamp::Now();
-    mTimeBlocked += (th32End - th32Start);
 }
 
 void
 PluginModuleChromeParent::DoInjection(const nsAutoHandle& aSnapshot)
 {
     DWORD pluginProcessPID = GetProcessId(Process()->GetChildProcessHandle());
     mFlashProcess1 = GetFlashChildOfPID(pluginProcessPID, aSnapshot);
     if (mFlashProcess1) {
--- a/dom/plugins/ipc/PluginModuleParent.h
+++ b/dom/plugins/ipc/PluginModuleParent.h
@@ -122,22 +122,16 @@ public:
     bool OkToCleanup() const {
         return !IsOnCxxStack();
     }
 
     void ProcessRemoteNativeEventsInInterruptCall() override;
 
     virtual bool WaitForIPCConnection() { return true; }
 
-    nsCString GetHistogramKey() const {
-        return mPluginName + mPluginVersion;
-    }
-
-    void AccumulateModuleInitBlockedTime();
-
     virtual nsresult GetRunID(uint32_t* aRunID) override;
     virtual void SetHasLocalInstance() override {
         mHadLocalInstance = true;
     }
 
     int GetQuirks() { return mQuirks; }
 
 protected:
@@ -337,17 +331,16 @@ protected:
     bool mHadLocalInstance;
     bool mClearSiteDataSupported;
     bool mGetSitesWithDataSupported;
     NPNetscapeFuncs* mNPNIface;
     NPPluginFuncs* mNPPIface;
     nsNPAPIPlugin* mPlugin;
     ipc::TaskFactory<PluginModuleParent> mTaskFactory;
     nsString mHangID;
-    TimeDuration mTimeBlocked;
     nsCString mPluginName;
     nsCString mPluginVersion;
     int32_t mSandboxLevel;
     bool mIsFlashPlugin;
 
 #ifdef MOZ_X11
     // Dup of plugin's X socket, used to scope its resources to this
     // object instead of the plugin process's lifetime
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -11090,66 +11090,16 @@
     "description": "Why e10s is enabled or disabled (0=ENABLED_BY_USER, 1=ENABLED_BY_DEFAULT, 2=DISABLED_BY_USER, 3=DISABLED_IN_SAFE_MODE, 4=DISABLED_FOR_ACCESSIBILITY, 5=DISABLED_FOR_MAC_GFX, 6=DISABLED_FOR_BIDI, 7=DISABLED_FOR_ADDONS, 8=FORCE_DISABLED, 9=DISABLED_FOR_XPLAYERS, 10=DISABLED_FOR_OS_VERSION)"
   },
   "E10S_BLOCKED_FROM_RUNNING": {
     "record_in_processes": ["main", "content"],
     "expires_in_version": "never",
     "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": {
-    "record_in_processes": ["main", "content"],
-    "alert_emails": ["perf-telemetry-alerts@mozilla.com"],
-    "expires_in_version": "never",
-    "kind": "exponential",
-    "high": 10000,
-    "n_buckets": 20,
-    "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": {
-    "record_in_processes": ["main", "content"],
-    "alert_emails": ["perf-telemetry-alerts@mozilla.com"],
-    "expires_in_version": "never",
-    "kind": "exponential",
-    "high": 10000,
-    "n_buckets": 20,
-    "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": {
-    "record_in_processes": ["main", "content"],
-    "alert_emails": ["perf-telemetry-alerts@mozilla.com"],
-    "expires_in_version": "never",
-    "kind": "exponential",
-    "high": 10000,
-    "n_buckets": 20,
-    "keyed": true,
-    "description": "Time (ms) that the main thread has been blocked on NPP_NewStream in an IPC plugin"
-  },
-  "BLOCKED_ON_PLUGINASYNCSURROGATE_WAITFORINIT_MS": {
-    "record_in_processes": ["main", "content"],
-    "alert_emails": ["perf-telemetry-alerts@mozilla.com"],
-    "expires_in_version": "50",
-    "kind": "exponential",
-    "high": 10000,
-    "n_buckets": 20,
-    "keyed": true,
-    "description": "Time (ms) that the main thread has been blocked on PluginAsyncSurrogate::WaitForInit in an IPC plugin"
-  },
-  "BLOCKED_ON_PLUGIN_INSTANCE_DESTROY_MS": {
-    "record_in_processes": ["main", "content"],
-    "alert_emails": ["perf-telemetry-alerts@mozilla.com"],
-    "expires_in_version": "never",
-    "kind": "exponential",
-    "high": 10000,
-    "n_buckets": 20,
-    "keyed": true,
-    "description": "Time (ms) that the main thread has been blocked on NPP_Destroy in an IPC plugin"
-  },
   "ONBEFOREUNLOAD_PROMPT_ACTION" : {
     "record_in_processes": ["main", "content"],
     "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" : {
--- a/toolkit/components/telemetry/Scalars.yaml
+++ b/toolkit/components/telemetry/Scalars.yaml
@@ -211,16 +211,30 @@ browser.usage:
     expires: "60"
     kind: uint
     notification_emails:
       - tom@mozilla.com
     release_channel_collection: opt-out
     record_in_processes:
       - 'all'
 
+  plugin_instantiated:
+    bug_numbers:
+      - 1381591
+    description: >-
+      The number of plugin instances that were created.
+    expires: never # Jan-2021 but we don't have a version number for that
+    kind: uint
+    notification_emails:
+      - bsmedberg@mozilla.com
+    release_channel_collection: opt-out
+    record_in_processes:
+      - 'main'
+      - 'content'
+
 # This section is for probes used to measure use of the Webextensions storage.sync API.
 storage.sync.api.usage:
   extensions_using:
     bug_numbers:
       - 1328974
     description: >
       The count of webextensions that have data stored in the chrome.storage.sync API.
       This includes extensions that have not used the storage.sync API this session.