Bug 1474991 - Add new and improved performance telemetry for child process launching. r=mccr8,mconley,janerik
☠☠ backed out by b0e69b136883 ☠ ☠
authorJed Davis <jld@mozilla.com>
Thu, 22 Nov 2018 00:06:17 +0000
changeset 507384 7a480161fa0fc82f11d2ed492f9f8938a1cdf1fc
parent 507383 80116391b7fe48cb2ecc1960721d74dc2c185c6a
child 507385 8fa5e81ad8015f9bd5ba2b7497f840e4cc50b8bd
push id1905
push userffxbld-merge
push dateMon, 21 Jan 2019 12:33:13 +0000
treeherdermozilla-release@c2fca1944d8c [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmccr8, mconley, janerik
bugs1474991
milestone65.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1474991 - Add new and improved performance telemetry for child process launching. r=mccr8,mconley,janerik This patch adds some telemetry histograms: * CONTENT_PROCESS_LAUNCH_IS_SYNC - boolean, true if the content process was launched synchronously (blocking the main thread) * CONTENT_PROCESS_SYNC_LAUNCH_MS - the time consumed by sync launch; the main thread will be busy or blocked for this entire time * CONTENT_PROCESS_LAUNCH_TOTAL_MS - the total time elapsed from the start of async content process launch until the launch promise is resolved and the ContentParent can be sent IPDL messages * CONTENT_PROCESS_LAUNCH_MAINTHREAD_MS - the time consumed on the parent process main thread during async content process launch; typically this is due to ContentParent::Init. * CHILD_PROCESS_LAUNCH_MS - for any kind of Gecko child process (including plugins, GPU, etc.), the time taken in the common process launch code (which is run off-main-thread) The probes restricted to async content process launch don't have "async" in the name because that will eventually become the only kind of content process launch. Depends on D8943 Differential Revision: https://phabricator.services.mozilla.com/D8944
dom/ipc/ContentParent.cpp
dom/ipc/ContentParent.h
ipc/glue/GeckoChildProcessHost.cpp
toolkit/components/telemetry/Histograms.json
--- a/dom/ipc/ContentParent.cpp
+++ b/dom/ipc/ContentParent.cpp
@@ -2198,16 +2198,19 @@ ContentParent::AppendSandboxParams(std::
 void
 ContentParent::LaunchSubprocessInternal(
   ProcessPriority aInitialPriority,
   mozilla::Variant<bool*, RefPtr<LaunchPromise>*>&& aRetval)
 {
   AUTO_PROFILER_LABEL("ContentParent::LaunchSubprocess", OTHER);
   const bool isSync = aRetval.is<bool*>();
 
+  Telemetry::Accumulate(Telemetry::CONTENT_PROCESS_LAUNCH_IS_SYNC,
+                        static_cast<uint32_t>(isSync));
+
   auto earlyReject = [aRetval, isSync]() {
     if (isSync) {
       *aRetval.as<bool*>() = false;
     } else {
       *aRetval.as<RefPtr<LaunchPromise>*>() = LaunchPromise::CreateAndReject(
         GeckoChildProcessHost::LaunchError(), __func__);
     }
   };
@@ -2344,16 +2347,17 @@ ContentParent::LaunchSubprocessInternal(
   auto resolve = [self, this, aInitialPriority, isSync,
                   // Transfer ownership of RAII file descriptor/handle
                   // holders so that they won't be closed before the
                   // child can inherit them.
                   shm = std::move(shm),
                   prefMapHandle = std::move(prefMapHandle)
                  ](base::ProcessHandle handle) {
     AUTO_PROFILER_LABEL("ContentParent::LaunchSubprocess::resolve", OTHER);
+    const auto launchResumeTS = TimeStamp::Now();
 
     base::ProcessId procId = base::GetProcId(handle);
     Open(mSubprocess->GetChannel(), procId);
 #ifdef MOZ_CODE_COVERAGE
     Unused << SendShareCodeCoverageMutex(
       CodeCoverageHandler::Get()->GetMutexHandle(procId));
 #endif
 
@@ -2371,18 +2375,29 @@ ContentParent::LaunchSubprocessInternal(
     if (obs) {
       nsAutoString cpId;
       cpId.AppendInt(static_cast<uint64_t>(this->ChildID()));
       obs->NotifyObservers(static_cast<nsIObserver*>(this), "ipc:content-initializing", cpId.get());
     }
 
     Init();
 
-    // Launch time telemetry will return in a later patch (bug 1474991).
-    Unused << isSync;
+    if (isSync) {
+      Telemetry::AccumulateTimeDelta(
+        Telemetry::CONTENT_PROCESS_SYNC_LAUNCH_MS, mLaunchTS);
+    } else {
+      Telemetry::AccumulateTimeDelta(
+        Telemetry::CONTENT_PROCESS_LAUNCH_TOTAL_MS, mLaunchTS);
+
+      Telemetry::Accumulate(
+        Telemetry::CONTENT_PROCESS_LAUNCH_MAINTHREAD_MS,
+        static_cast<uint32_t>(((mLaunchYieldTS - mLaunchTS) +
+                               (TimeStamp::Now() - launchResumeTS))
+                              .ToMilliseconds()));
+    }
 
     return LaunchPromise::CreateAndResolve(self, __func__);
   };
 
   if (isSync) {
     bool ok = mSubprocess->LaunchAndWaitForProcessHandle(std::move(extraArgs));
     if (ok) {
       Unused << resolve(mSubprocess->GetChildProcessHandle());
@@ -2390,16 +2405,17 @@ ContentParent::LaunchSubprocessInternal(
       Unused << reject(GeckoChildProcessHost::LaunchError{});
     }
     *aRetval.as<bool*>() = ok;
   } else {
     auto* retptr = aRetval.as<RefPtr<LaunchPromise>*>();
     if (mSubprocess->AsyncLaunch(std::move(extraArgs))) {
       RefPtr<GeckoChildProcessHost::HandlePromise> ready =
         mSubprocess->WhenProcessHandleReady();
+      mLaunchYieldTS = TimeStamp::Now();
       *retptr = ready->Then(GetCurrentThreadSerialEventTarget(), __func__,
                             std::move(resolve), std::move(reject));
     } else {
       *retptr = reject(GeckoChildProcessHost::LaunchError{});
     }
   }
 }
 
@@ -2423,17 +2439,18 @@ ContentParent::ContentParent(ContentPare
                              const nsAString& aRemoteType,
                              RecordReplayState aRecordReplayState,
                              const nsAString& aRecordingFile,
                              int32_t aJSPluginID)
   : nsIContentParent()
   , mSelfRef(nullptr)
   , mSubprocess(nullptr)
   , mLaunchTS(TimeStamp::Now())
-  , mActivateTS(TimeStamp::Now())
+  , mLaunchYieldTS(mLaunchTS)
+  , mActivateTS(mLaunchTS)
   , mOpener(aOpener)
   , mRemoteType(aRemoteType)
   , mChildID(gContentChildID++)
   , mGeolocationWatchID(-1)
   , mJSPluginID(aJSPluginID)
   , mRemoteWorkerActors(0)
   , mNumDestroyingTabs(0)
   , mIsAvailable(true)
--- a/dom/ipc/ContentParent.h
+++ b/dom/ipc/ContentParent.h
@@ -1305,16 +1305,17 @@ private:
   RefPtr<ContentParent> mSelfRef;
 
   // If you add strong pointers to cycle collected objects here, be sure to
   // release these objects in ShutDownProcess.  See the comment there for more
   // details.
 
   GeckoChildProcessHost* mSubprocess;
   const TimeStamp mLaunchTS; // used to calculate time to start content process
+  TimeStamp mLaunchYieldTS; // used to calculate async launch main thread time
   TimeStamp mActivateTS;
   ContentParent* mOpener;
 
   nsString mRemoteType;
 
   ContentParentId mChildID;
   int32_t mGeolocationWatchID;
 
--- a/ipc/glue/GeckoChildProcessHost.cpp
+++ b/ipc/glue/GeckoChildProcessHost.cpp
@@ -566,16 +566,18 @@ AddAppDirToCommandLine(std::vector<std::
 
 bool
 GeckoChildProcessHost::PerformAsyncLaunch(std::vector<std::string> aExtraOpts)
 {
 #ifdef MOZ_GECKO_PROFILER
   AutoSetProfilerEnvVarsForChildProcess profilerEnvironment;
 #endif
 
+  const auto startTS = TimeStamp::Now();
+
   // - Note: this code is not called re-entrantly, nor are restoreOrig*LogName
   //   or mChildCounter touched by any other thread, so this is safe.
   ++mChildCounter;
 
   const char* origNSPRLogName = PR_GetEnv("NSPR_LOG_FILE");
   const char* origMozLogName = PR_GetEnv("MOZ_LOG_FILE");
 
   if (origNSPRLogName) {
@@ -1128,16 +1130,19 @@ GeckoChildProcessHost::PerformAsyncLaunc
   PR_Close(crashAnnotationWritePipe);
 
   MonitorAutoLock lock(mMonitor);
   mProcessState = PROCESS_CREATED;
   mHandlePromise->Resolve(process, __func__);
   lock.Notify();
 
   mLaunchOptions = nullptr;
+
+  Telemetry::AccumulateTimeDelta(Telemetry::CHILD_PROCESS_LAUNCH_MS, startTS);
+
   return true;
 }
 
 bool
 GeckoChildProcessHost::OpenPrivilegedHandle(base::ProcessId aPid)
 {
   if (mChildProcessHandle) {
     MOZ_ASSERT(aPid == base::GetProcId(mChildProcessHandle));
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -262,16 +262,27 @@
     "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "kgupta@mozilla.com"],
     "bug_numbers": [1238040],
     "expires_in_version": "70",
     "kind": "exponential",
     "high": 1073741824,
     "n_buckets": 50,
     "description": "Opaque measure of the severity of a checkerboard event"
   },
+  "CHILD_PROCESS_LAUNCH_MS" : {
+    "record_in_processes": ["main"],
+    "alert_emails": ["jld@mozilla.com", "mconley@mozilla.com"],
+    "expires_in_version": "70",
+    "bug_numbers": [1474991],
+    "kind": "exponential",
+    "high": 64000,
+    "n_buckets": 100,
+    "releaseChannelCollection": "opt-out",
+    "description": "Time spent in the generic child process launching code, which is run off-main-thread and used by all child process types"
+  },
   "COMPOSITE_TIME" : {
     "record_in_processes": ["main", "content", "gpu"],
     "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "rhunt@mozilla.com"],
     "expires_in_version": "never",
     "description": "Composite times in milliseconds",
     "kind": "exponential",
     "high": 1000,
     "n_buckets": 50
@@ -280,16 +291,58 @@
     "record_in_processes": ["main", "content", "gpu"],
     "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "rhunt@mozilla.com"],
     "expires_in_version": "never",
     "description": "Time from vsync to finishing a composite in milliseconds.",
     "kind": "exponential",
     "high": 1000,
     "n_buckets": 50
   },
+  "CONTENT_PROCESS_LAUNCH_MAINTHREAD_MS" : {
+    "record_in_processes": ["main"],
+    "alert_emails": ["jld@mozilla.com", "mconley@mozilla.com"],
+    "expires_in_version": "70",
+    "bug_numbers": [1474991],
+    "kind": "exponential",
+    "high": 64000,
+    "n_buckets": 100,
+    "releaseChannelCollection": "opt-out",
+    "description": "Time spent on the main thread during asynchronous content process launch."
+  },
+  "CONTENT_PROCESS_LAUNCH_TOTAL_MS" : {
+    "record_in_processes": ["main"],
+    "alert_emails": ["jld@mozilla.com", "mconley@mozilla.com"],
+    "expires_in_version": "70",
+    "bug_numbers": [1474991],
+    "kind": "exponential",
+    "high": 64000,
+    "n_buckets": 100,
+    "releaseChannelCollection": "opt-out",
+    "description": "Total time elapsed during asynchronous content process launch, until the process is usable for loading content."
+  },
+  "CONTENT_PROCESS_SYNC_LAUNCH_MS" : {
+    "record_in_processes": ["main"],
+    "alert_emails": ["jld@mozilla.com", "mconley@mozilla.com"],
+    "expires_in_version": "67",
+    "bug_numbers": [1474991],
+    "kind": "exponential",
+    "high": 64000,
+    "n_buckets": 100,
+    "releaseChannelCollection": "opt-out",
+    "description": "Time elapsed during synchronous content process launch until the process is usable for loading content."
+  },
+  "CONTENT_PROCESS_LAUNCH_IS_SYNC" : {
+    "record_in_processes": ["main"],
+    "alert_emails": ["jld@mozilla.com", "mconley@mozilla.com"],
+    "expires_in_version": "67",
+    "bug_numbers": [1474991],
+    "kind": "boolean",
+    "releaseChannelCollection": "opt-out",
+    "description": "Whether a content process was launched synchronously (unnecessarily delaying UI response)."
+  },
   "CONTENT_RESPONSE_DURATION" : {
     "record_in_processes": ["main", "content", "gpu"],
     "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "kgupta@mozilla.com"],
     "bug_numbers": [1261373],
     "expires_in_version": "70",
     "description": "Main thread response times for APZ notifications about input events (ms)",
     "kind" : "exponential",
     "high": 60000,