Bug 1381591 - Refactor plugin initialization/performance telemetry to measure the things we care about, r=qdot data-r=rweiss

MozReview-Commit-ID: CZ6AZ64RUt9 --HG-- extra : rebase_source : a2021cad0a33bae173fa1d4f1ba8ca9dabc13149
2017-07-17 16:31:45 -04:00 · 2017-07-17 16:31:45 -04:00 · cbb52b352c
--- a/dom/plugins/ipc/PluginInstanceParent.cpp
+++ b/dom/plugins/ipc/PluginInstanceParent.cpp
@ -201,12 +201,8 @@ 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)
@ -1747,9 +1743,6 @@ PluginInstanceParent::NPP_NewStream(NPMIMEType type, NPStream* stream,
        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)) {
--- a/dom/plugins/ipc/PluginModuleParent.cpp
+++ b/dom/plugins/ipc/PluginModuleParent.cpp
@ -103,11 +103,6 @@ mozilla::plugins::SetupBridge(uint32_t aPluginId,
        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;
@ -418,17 +413,14 @@ PluginModuleContentParent::LoadModule(uint32_t aPluginId,
    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
@ -481,7 +473,6 @@ PluginModuleChromeParent::LoadModule(const char* aFilePath, uint32_t aPluginId,
            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) {
@ -498,8 +489,6 @@ PluginModuleChromeParent::LoadModule(const char* aFilePath, uint32_t aPluginId,
        parent->mShutdown = true;
        return nullptr;
    }
-    TimeStamp launchEnd = TimeStamp::Now();
-    parent->mTimeBlocked = (launchEnd - launchStart);
    return parent.forget();
 }

@ -2145,7 +2134,6 @@ PluginModuleChromeParent::NP_Initialize(NPNetscapeFuncs* bFuncs, NPPluginFuncs*
    PluginSettings settings;
    GetSettings(&settings);

-    TimeStamp callNpInitStart = TimeStamp::Now();
    if (!CallNP_Initialize(settings, error)) {
        Close();
        return NS_ERROR_FAILURE;
@ -2154,8 +2142,6 @@ PluginModuleChromeParent::NP_Initialize(NPNetscapeFuncs* bFuncs, NPPluginFuncs*
        Close();
        return NS_ERROR_FAILURE;
    }
-    TimeStamp callNpInitEnd = TimeStamp::Now();
-    mTimeBlocked += (callNpInitEnd - callNpInitStart);

    if (*error != NPERR_NO_ERROR) {
        OnInitFailure();
@ -2206,13 +2192,10 @@ PluginModuleChromeParent::NP_Initialize(NPNetscapeFuncs* bFuncs, NPError* error)
    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) {
@ -2390,18 +2373,6 @@ public:
  }
 };

-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,
@ -2453,13 +2424,6 @@ PluginModuleParent::NPP_NewInternal(NPMIMEType pluginType, NPP instance,
    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;
@ -2536,18 +2500,14 @@ PluginModuleParent::NPP_NewInternal(NPMIMEType pluginType, NPP instance,
        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) {
@ -2555,6 +2515,8 @@ PluginModuleParent::NPP_NewInternal(NPMIMEType pluginType, NPP instance,
        return NS_ERROR_FAILURE;
    }

+    Telemetry::ScalarAdd(Telemetry::ScalarID::BROWSER_USAGE_PLUGIN_INSTANTIATED, 1);
+
    UpdatePluginTimeout();

    return NS_OK;
@ -2911,7 +2873,6 @@ PluginModuleChromeParent::InitializeInjector()
                          NS_LITERAL_CSTRING(FLASH_PLUGIN_PREFIX)))
        return;

-    TimeStamp th32Start = TimeStamp::Now();
    mFinishInitTask = mChromeTaskFactory.NewTask<FinishInjectorInitTask>();
    mFinishInitTask->Init(this);
    if (!::QueueUserWorkItem(&PluginModuleChromeParent::GetToolhelpSnapshot,
@ -2919,8 +2880,6 @@ PluginModuleChromeParent::InitializeInjector()
        mFinishInitTask = nullptr;
        return;
    }
-    TimeStamp th32End = TimeStamp::Now();
-    mTimeBlocked += (th32End - th32Start);
 }

 void
--- a/dom/plugins/ipc/PluginModuleParent.h
+++ b/dom/plugins/ipc/PluginModuleParent.h
@ -115,12 +115,6 @@ public:

    void ProcessRemoteNativeEventsInInterruptCall() override;

-    nsCString GetHistogramKey() const {
-        return mPluginName + mPluginVersion;
-    }
-
-    void AccumulateModuleInitBlockedTime();
-
    virtual nsresult GetRunID(uint32_t* aRunID) override;
    virtual void SetHasLocalInstance() override {
        mHadLocalInstance = true;
@ -323,7 +317,6 @@ protected:
    nsNPAPIPlugin* mPlugin;
    ipc::TaskFactory<PluginModuleParent> mTaskFactory;
    nsString mHangID;
-    TimeDuration mTimeBlocked;
    nsCString mPluginName;
    nsCString mPluginVersion;
    int32_t mSandboxLevel;
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@ -11201,56 +11201,6 @@
    "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",
--- a/toolkit/components/telemetry/Scalars.yaml
+++ b/toolkit/components/telemetry/Scalars.yaml
@ -247,6 +247,20 @@ browser.usage:
    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: