Bug 1381591 - Refactor plugin initialization/performance telemetry to measure the things we care about, r?qdot data-r?rweiss draft
authorBenjamin Smedberg <benjamin@smedbergs.us>
Mon, 17 Jul 2017 16:31:45 -0400
changeset 610031 a8f6821267e69075fb4ff0e06571cae9c3352bf1
parent 610020 30af079927c76456ba8959c7df19d181ff7bc393
child 637744 e77058bf1ef947b75bb17ac6759d72e1c884d3fa
push id68764
push userbsmedberg@mozilla.com
push dateMon, 17 Jul 2017 20:32:05 +0000
reviewersqdot
bugs1381591
milestone56.0a1
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/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/PluginInstanceParent.cpp
+++ b/dom/plugins/ipc/PluginInstanceParent.cpp
@@ -196,22 +196,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;
 }
@@ -1742,19 +1738,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;
     bs->SetAlive();
     if (!CallNPP_NewStream(bs, NullableString(type), seekable, &err, stype)) {
         err = NPERR_GENERIC_ERROR;
     }
     if (NPERR_NO_ERROR != err) {
         Unused << PBrowserStreamParent::Send__delete__(bs);
     }
--- a/dom/plugins/ipc/PluginModuleParent.cpp
+++ b/dom/plugins/ipc/PluginModuleParent.cpp
@@ -98,21 +98,16 @@ mozilla::plugins::SetupBridge(uint32_t a
 
     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;
     }
 
     ipc::Endpoint<PPluginModuleParent> parent;
     ipc::Endpoint<PPluginModuleChild> child;
 
@@ -413,27 +408,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();
     }
 
@@ -476,35 +468,32 @@ PluginModuleChromeParent::LoadModule(con
                                      nsPluginTag* aPluginTag)
 {
     PLUGIN_LOG_DEBUG_FUNCTION;
 
     nsAutoPtr<PluginModuleChromeParent> parent(
             new PluginModuleChromeParent(aFilePath, aPluginId,
                                          aPluginTag->mSandboxLevel));
     UniquePtr<LaunchCompleteTask> onLaunchedRunnable(new LaunchedTask(parent));
-    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;
     uint32_t blocklistState;
     nsresult rv = aPluginTag->GetBlocklistState(&blocklistState);
     parent->mIsBlocklisted = NS_FAILED(rv) || blocklistState != 0;
     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;
@@ -2140,27 +2129,24 @@ PluginModuleChromeParent::NP_Initialize(
     *error = NPERR_NO_ERROR;
 
     mNPNIface = bFuncs;
     mNPPIface = pFuncs;
 
     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_ERROR_FAILURE;
     }
-    TimeStamp callNpInitEnd = TimeStamp::Now();
-    mTimeBlocked += (callNpInitEnd - callNpInitStart);
 
     if (*error != NPERR_NO_ERROR) {
         OnInitFailure();
         return NS_OK;
     }
 
     SetPluginFuncs(mNPPIface);
 
@@ -2201,23 +2187,20 @@ PluginModuleChromeParent::NP_Initialize(
 {
     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;
     }
-    TimeStamp callNpInitEnd = TimeStamp::Now();
-    mTimeBlocked += (callNpInitEnd - callNpInitStart);
 
     bool ok = true;
     if (*error == NPERR_NO_ERROR) {
         // Initialization steps for (e10s && !asyncInit) || !e10s
 #if defined XP_WIN
         // Send the info needed to join the browser process's audio session to
         // the plugin process.
         nsID id;
@@ -2385,28 +2368,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");
@@ -2448,23 +2419,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];
@@ -2531,35 +2495,33 @@ 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 (!CallSyncNPP_New(parentInstance, error)) {
-            // 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 (!CallSyncNPP_New(parentInstance, error)) {
+        // 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;
     }
 
+    Telemetry::ScalarAdd(Telemetry::ScalarID::BROWSER_USAGE_PLUGIN_INSTANTIATED, 1);
+
     UpdatePluginTimeout();
 
     return NS_OK;
 }
 
 void
 PluginModuleChromeParent::UpdatePluginTimeout()
 {
@@ -2906,26 +2868,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
@@ -110,22 +110,16 @@ public:
     }
 
     bool OkToCleanup() const {
         return !IsOnCxxStack();
     }
 
     void ProcessRemoteNativeEventsInInterruptCall() override;
 
-    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:
@@ -318,17 +312,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
@@ -11155,66 +11155,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
@@ -242,16 +242,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.