From fa5a9e12ba225446657153f278909b2d58b4886f Mon Sep 17 00:00:00 2001 From: Aaron Klotz Date: Thu, 11 Dec 2014 14:00:47 -0700 Subject: [PATCH] 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 | 33 +++++++---- dom/plugins/ipc/PluginModuleParent.cpp | 58 ++++++++++++++++---- dom/plugins/ipc/PluginModuleParent.h | 6 ++ toolkit/components/telemetry/Histograms.json | 36 ++++++++++++ toolkit/components/telemetry/Telemetry.h | 21 ++++++- 5 files changed, 131 insertions(+), 23 deletions(-) diff --git a/dom/plugins/ipc/PluginInstanceParent.cpp b/dom/plugins/ipc/PluginInstanceParent.cpp index 4889f538063e..e10758c24415 100644 --- a/dom/plugins/ipc/PluginInstanceParent.cpp +++ b/dom/plugins/ipc/PluginInstanceParent.cpp @@ -7,6 +7,7 @@ #include "mozilla/DebugOnly.h" #include // for intptr_t +#include "mozilla/Telemetry.h" #include "PluginInstanceParent.h" #include "BrowserStreamParent.h" #include "PluginBackgroundDestroyer.h" @@ -145,8 +146,13 @@ NPError PluginInstanceParent::Destroy() { NPError retval; - if (!CallNPP_Destroy(&retval)) - retval = NPERR_GENERIC_ERROR; + { // Scope for timer + Telemetry::AutoTimer + timer(Module()->GetHistogramKey()); + if (!CallNPP_Destroy(&retval)) { + retval = NPERR_GENERIC_ERROR; + } + } #if defined(OS_WIN) SharedSurfaceRelease(); @@ -1304,15 +1310,20 @@ PluginInstanceParent::NPP_NewStream(NPMIMEType type, NPStream* stream, BrowserStreamParent* bs = new BrowserStreamParent(this, stream); NPError err; - if (!CallPBrowserStreamConstructor(bs, - NullableString(stream->url), - stream->end, - stream->lastmodified, - static_cast(stream->notifyData), - NullableString(stream->headers), - NullableString(type), seekable, - &err, stype)) - return NPERR_GENERIC_ERROR; + { // Scope for timer + Telemetry::AutoTimer + timer(Module()->GetHistogramKey()); + if (!CallPBrowserStreamConstructor(bs, + NullableString(stream->url), + stream->end, + stream->lastmodified, + static_cast(stream->notifyData), + NullableString(stream->headers), + NullableString(type), seekable, + &err, stype)) { + return NPERR_GENERIC_ERROR; + } + } if (NPERR_NO_ERROR != err) unused << PBrowserStreamParent::Send__delete__(bs); diff --git a/dom/plugins/ipc/PluginModuleParent.cpp b/dom/plugins/ipc/PluginModuleParent.cpp index 906692ee7bcb..dda2a20385d9 100755 --- a/dom/plugins/ipc/PluginModuleParent.cpp +++ b/dom/plugins/ipc/PluginModuleParent.cpp @@ -21,6 +21,7 @@ #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" @@ -160,12 +161,15 @@ PluginModuleChromeParent::LoadModule(const char* aFilePath, uint32_t aPluginId) // Block on the child process being launched and initialized. nsAutoPtr 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()); @@ -1378,6 +1382,7 @@ PluginModuleParent::NP_Initialize(NPNetscapeFuncs* bFuncs, NPPluginFuncs* pFuncs if (IsChrome()) { PluginSettings settings; GetSettings(&settings); + TimeStamp callNpInitStart = TimeStamp::Now(); if (!CallNP_Initialize(settings, error)) { Close(); return NS_ERROR_FAILURE; @@ -1386,6 +1391,16 @@ PluginModuleParent::NP_Initialize(NPNetscapeFuncs* bFuncs, NPPluginFuncs* pFuncs 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(mTimeBlocked.ToMilliseconds())); + mTimeBlocked = TimeDuration(); } SetPluginFuncs(pFuncs); @@ -1418,6 +1433,7 @@ 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; @@ -1426,6 +1442,8 @@ PluginModuleChromeParent::NP_Initialize(NPNetscapeFuncs* bFuncs, NPError* 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 @@ -1443,6 +1461,17 @@ PluginModuleChromeParent::NP_Initialize(NPNetscapeFuncs* bFuncs, NPError* error) 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(mTimeBlocked.ToMilliseconds())); + mTimeBlocked = TimeDuration(); + return NS_OK; } #endif @@ -1556,17 +1585,21 @@ PluginModuleParent::NPP_New(NPMIMEType pluginType, NPP instance, 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 + 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) { @@ -1913,9 +1946,12 @@ PluginModuleChromeParent::InitializeInjector() 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); diff --git a/dom/plugins/ipc/PluginModuleParent.h b/dom/plugins/ipc/PluginModuleParent.h index 5868c181bb90..31a645e5bc06 100644 --- a/dom/plugins/ipc/PluginModuleParent.h +++ b/dom/plugins/ipc/PluginModuleParent.h @@ -16,6 +16,7 @@ #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" @@ -105,6 +106,10 @@ public: void ProcessRemoteNativeEventsInInterruptCall(); + nsCString GetHistogramKey() const { + return mPluginName + mPluginVersion; + } + protected: virtual mozilla::ipc::RacyInterruptPolicy MediateInterruptRace(const Message& parent, const Message& child) MOZ_OVERRIDE @@ -245,6 +250,7 @@ protected: nsString mBrowserDumpID; nsString mHangID; nsRefPtr mProfilerObserver; + TimeDuration mTimeBlocked; nsCString mPluginName; nsCString mPluginVersion; diff --git a/toolkit/components/telemetry/Histograms.json b/toolkit/components/telemetry/Histograms.json index c286e9151e90..005dc8de0bc4 100644 --- a/toolkit/components/telemetry/Histograms.json +++ b/toolkit/components/telemetry/Histograms.json @@ -6922,6 +6922,42 @@ "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", diff --git a/toolkit/components/telemetry/Telemetry.h b/toolkit/components/telemetry/Telemetry.h index 98df4f594a58..ae30fd7d5537 100644 --- a/toolkit/components/telemetry/Telemetry.h +++ b/toolkit/components/telemetry/Telemetry.h @@ -89,6 +89,7 @@ template 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<> @@ -97,6 +98,9 @@ struct AccumulateDelta_impl static void compute(ID id, TimeStamp start, TimeStamp end = TimeStamp::Now()) { Accumulate(id, static_cast((end - start).ToMilliseconds())); } + static void compute(ID id, const nsCString& key, TimeStamp start, TimeStamp end = TimeStamp::Now()) { + Accumulate(id, key, static_cast((end - start).ToMilliseconds())); + } }; template<> @@ -105,6 +109,9 @@ struct AccumulateDelta_impl static void compute(ID id, TimeStamp start, TimeStamp end = TimeStamp::Now()) { Accumulate(id, static_cast((end - start).ToMicroseconds())); } + static void compute(ID id, const nsCString& key, TimeStamp start, TimeStamp end = TimeStamp::Now()) { + Accumulate(id, key, static_cast((end - start).ToMicroseconds())); + } }; @@ -117,12 +124,24 @@ public: 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::compute(id, start); + if (key.IsEmpty()) { + AccumulateDelta_impl::compute(id, start); + } else { + AccumulateDelta_impl::compute(id, key, start); + } } private: const TimeStamp start; + const nsCString key; MOZ_DECL_USE_GUARD_OBJECT_NOTIFIER };