Bug 1667818 - Record priority change markers - r=canaltinova
authorGerald Squelart <gsquelart@mozilla.com>
Thu, 24 Jun 2021 07:25:56 +0000
changeset 584235 9b2ffc8e850587f349301559d397a384ef5c7508
parent 584234 9e1313f55c944847aa84f5f7a57e5b8e88b167cc
child 584236 f021e635efcaa2ca1fa5a9a2f397584587ac4155
push id38562
push userapavel@mozilla.com
push dateThu, 24 Jun 2021 09:38:49 +0000
treeherdermozilla-central@9b2ffc8e8505 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerscanaltinova
bugs1667818
milestone91.0a1
first release with
nightly linux32
9b2ffc8e8505 / 91.0a1 / 20210624093849 / files
nightly linux64
9b2ffc8e8505 / 91.0a1 / 20210624093849 / files
nightly mac
9b2ffc8e8505 / 91.0a1 / 20210624093849 / files
nightly win32
9b2ffc8e8505 / 91.0a1 / 20210624093849 / files
nightly win64
9b2ffc8e8505 / 91.0a1 / 20210624093849 / files
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
releases
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1667818 - Record priority change markers - r=canaltinova In the parent process, all sub-process priority changes are recorded, with the stack. In child processes, the new priority is recorded when notified. Also record priorities during profiler state changes. This is to ensure that we always have at least one record of the priority at the end of the profile, when old priority changes may have already been discarded. Differential Revision: https://phabricator.services.mozilla.com/D118129
dom/ipc/ContentChild.cpp
dom/ipc/ContentChild.h
dom/ipc/ProcessPriorityManager.cpp
--- a/dom/ipc/ContentChild.cpp
+++ b/dom/ipc/ContentChild.cpp
@@ -306,16 +306,66 @@ using namespace mozilla::hal_sandbox;
 using namespace mozilla::ipc;
 using namespace mozilla::intl;
 using namespace mozilla::layers;
 using namespace mozilla::layout;
 using namespace mozilla::net;
 using namespace mozilla::widget;
 using mozilla::loader::PScriptCacheChild;
 
+#ifdef MOZ_GECKO_PROFILER
+namespace geckoprofiler::markers {
+struct ProcessPriorityChange {
+  static constexpr Span<const char> MarkerTypeName() {
+    return MakeStringSpan("ProcessPriorityChange");
+  }
+  static void StreamJSONMarkerData(baseprofiler::SpliceableJSONWriter& aWriter,
+                                   const ProfilerString8View& aPreviousPriority,
+                                   const ProfilerString8View& aNewPriority) {
+    aWriter.StringProperty("Before", aPreviousPriority);
+    aWriter.StringProperty("After", aNewPriority);
+  }
+  static MarkerSchema MarkerTypeDisplay() {
+    using MS = MarkerSchema;
+    MS schema{MS::Location::markerChart, MS::Location::markerTable};
+    schema.AddKeyFormat("Before", MS::Format::string);
+    schema.AddKeyFormat("After", MS::Format::string);
+    schema.AddStaticLabelValue("Note",
+                               "This is a notification of the priority change "
+                               "that was done by the parent process");
+    schema.SetAllLabels(
+        "priority: {marker.data.Before} -> {marker.data.After}");
+    return schema;
+  }
+};
+
+struct ProcessPriority {
+  static constexpr Span<const char> MarkerTypeName() {
+    return MakeStringSpan("ProcessPriority");
+  }
+  static void StreamJSONMarkerData(baseprofiler::SpliceableJSONWriter& aWriter,
+                                   const ProfilerString8View& aPriority,
+                                   const ProfilingState& aProfilingState) {
+    aWriter.StringProperty("Priority", aPriority);
+    aWriter.StringProperty("Marker cause",
+                           ProfilerString8View::WrapNullTerminatedString(
+                               ProfilingStateToString(aProfilingState)));
+  }
+  static MarkerSchema MarkerTypeDisplay() {
+    using MS = MarkerSchema;
+    MS schema{MS::Location::markerChart, MS::Location::markerTable};
+    schema.AddKeyFormat("Priority", MS::Format::string);
+    schema.AddKeyFormat("Marker cause", MS::Format::string);
+    schema.SetAllLabels("priority: {marker.data.Priority}");
+    return schema;
+  }
+};
+}  // namespace geckoprofiler::markers
+#endif  // MOZ_GECKO_PROFILER
+
 namespace mozilla {
 
 namespace dom {
 
 // IPC sender for remote GC/CC logging.
 class CycleCollectWithLogsChild final : public PCycleCollectWithLogsChild {
  public:
   NS_INLINE_DECL_REFCOUNTING(CycleCollectWithLogsChild)
@@ -569,16 +619,35 @@ ContentChild::ContentChild()
       ,
       mIsForBrowser(false),
       mIsAlive(true),
       mShuttingDown(false) {
   // This process is a content process, so it's clearly running in
   // multiprocess mode!
   nsDebugImpl::SetMultiprocessMode("Child");
 
+#ifdef MOZ_GECKO_PROFILER
+  // Our static analysis doesn't allow capturing ref-counted pointers in
+  // lambdas, so we need to hide it in a uintptr_t. This is safe because this
+  // lambda will be destroyed in ~ContentChild().
+  uintptr_t self = reinterpret_cast<uintptr_t>(this);
+  profiler_add_state_change_callback(
+      AllProfilingStates(),
+      [self](ProfilingState aProfilingState) {
+        const ContentChild* selfPtr =
+            reinterpret_cast<const ContentChild*>(self);
+        PROFILER_MARKER("Process Priority", OTHER,
+                        mozilla::MarkerThreadId::MainThread(), ProcessPriority,
+                        ProfilerString8View::WrapNullTerminatedString(
+                            ProcessPriorityToString(selfPtr->mProcessPriority)),
+                        aProfilingState);
+      },
+      self);
+#endif  // MOZ_GECKO_PROFILER
+
   // When ContentChild is created, the observer service does not even exist.
   // When ContentChild::RecvSetXPCOMProcessAttributes is called (the first
   // IPDL call made on this object), shutdown may have already happened. Thus
   // we create a canary here that relies upon getting cleared if shutdown
   // happens without requiring the observer service at this time.
   if (!sShutdownCanary) {
     sShutdownCanary = new ShutdownCanary();
     ClearOnShutdown(&sShutdownCanary, ShutdownPhase::XPCOMShutdown);
@@ -588,16 +657,20 @@ ContentChild::ContentChild()
 #ifdef _MSC_VER
 #  pragma warning(push)
 #  pragma warning(                                                  \
       disable : 4722) /* Silence "destructor never returns" warning \
                        */
 #endif
 
 ContentChild::~ContentChild() {
+#ifdef MOZ_GECKO_PROFILER
+  profiler_remove_state_change_callback(reinterpret_cast<uintptr_t>(this));
+#endif  // MOZ_GECKO_PROFILER
+
 #ifndef NS_FREE_PERMANENT_DATA
   MOZ_CRASH("Content Child shouldn't be destroyed.");
 #endif
 }
 
 #ifdef _MSC_VER
 #  pragma warning(pop)
 #endif
@@ -2694,16 +2767,24 @@ mozilla::ipc::IPCResult ContentChild::Re
 mozilla::ipc::IPCResult ContentChild::RecvNotifyProcessPriorityChanged(
     const hal::ProcessPriority& aPriority) {
   nsCOMPtr<nsIObserverService> os = services::GetObserverService();
   NS_ENSURE_TRUE(os, IPC_OK());
 
   RefPtr<nsHashPropertyBag> props = new nsHashPropertyBag();
   props->SetPropertyAsInt32(u"priority"_ns, static_cast<int32_t>(aPriority));
 
+  PROFILER_MARKER("Process Priority", OTHER,
+                  mozilla::MarkerThreadId::MainThread(), ProcessPriorityChange,
+                  ProfilerString8View::WrapNullTerminatedString(
+                      ProcessPriorityToString(mProcessPriority)),
+                  ProfilerString8View::WrapNullTerminatedString(
+                      ProcessPriorityToString(aPriority)));
+  mProcessPriority = aPriority;
+
   os->NotifyObservers(static_cast<nsIPropertyBag2*>(props),
                       "ipc:process-priority-changed", nullptr);
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult ContentChild::RecvMinimizeMemoryUsage() {
   nsCOMPtr<nsIMemoryReporterManager> mgr =
       do_GetService("@mozilla.org/memory-reporter-manager;1");
--- a/dom/ipc/ContentChild.h
+++ b/dom/ipc/ContentChild.h
@@ -928,16 +928,18 @@ class ContentChild final : public PConte
   // off-main-thread.
   mozilla::Atomic<uint32_t> mPendingInputEvents;
 #endif
 
   uint32_t mNetworkLinkType = 0;
 
   // See `BrowsingContext::mEpochs` for an explanation of this field.
   uint64_t mBrowsingContextFieldEpoch = 0;
+
+  hal::ProcessPriority mProcessPriority = hal::PROCESS_PRIORITY_UNKNOWN;
 };
 
 inline nsISupports* ToSupports(mozilla::dom::ContentChild* aContentChild) {
   return static_cast<nsIDOMProcessChild*>(aContentChild);
 }
 
 }  // namespace dom
 }  // namespace mozilla
--- a/dom/ipc/ProcessPriorityManager.cpp
+++ b/dom/ipc/ProcessPriorityManager.cpp
@@ -9,16 +9,18 @@
 #include "mozilla/dom/CanonicalBrowsingContext.h"
 #include "mozilla/dom/ContentParent.h"
 #include "mozilla/dom/Element.h"
 #include "mozilla/dom/BrowserHost.h"
 #include "mozilla/dom/BrowserParent.h"
 #include "mozilla/Hal.h"
 #include "mozilla/IntegerPrintfMacros.h"
 #include "mozilla/Preferences.h"
+#include "mozilla/ProfilerMarkers.h"
+#include "mozilla/ProfilerState.h"
 #include "mozilla/Services.h"
 #include "mozilla/StaticPrefs_dom.h"
 #include "mozilla/Telemetry.h"
 #include "mozilla/Unused.h"
 #include "mozilla/Logging.h"
 #include "nsPrintfCString.h"
 #include "nsXULAppAPI.h"
 #include "nsFrameLoader.h"
@@ -86,16 +88,69 @@ static LogModule* GetPPMLog() {
             ("ProcessPriorityManager - " fmt, ##__VA_ARGS__))
 #  define LOGP(fmt, ...)                                                      \
     MOZ_LOG(GetPPMLog(), LogLevel::Debug,                                     \
             ("ProcessPriorityManager[%schild-id=%" PRIu64 ", pid=%d] - " fmt, \
              NameWithComma().get(), static_cast<uint64_t>(ChildID()), Pid(),  \
              ##__VA_ARGS__))
 #endif
 
+namespace geckoprofiler::markers {
+struct SubProcessPriorityChange {
+  static constexpr Span<const char> MarkerTypeName() {
+    return MakeStringSpan("subprocessprioritychange");
+  }
+  static void StreamJSONMarkerData(baseprofiler::SpliceableJSONWriter& aWriter,
+                                   int32_t aPid,
+                                   const ProfilerString8View& aPreviousPriority,
+                                   const ProfilerString8View& aNewPriority) {
+    aWriter.IntProperty("pid", aPid);
+    aWriter.StringProperty("Before", aPreviousPriority);
+    aWriter.StringProperty("After", aNewPriority);
+  }
+  static MarkerSchema MarkerTypeDisplay() {
+    using MS = MarkerSchema;
+    MS schema{MS::Location::markerChart, MS::Location::markerTable};
+    schema.AddKeyFormat("pid", MS::Format::integer);
+    schema.AddKeyFormat("Before", MS::Format::string);
+    schema.AddKeyFormat("After", MS::Format::string);
+    schema.SetAllLabels(
+        "priority of child {marker.data.pid}:"
+        " {marker.data.Before} -> {marker.data.After}");
+    return schema;
+  }
+};
+
+struct SubProcessPriority {
+  static constexpr Span<const char> MarkerTypeName() {
+    return MakeStringSpan("subprocesspriority");
+  }
+  static void StreamJSONMarkerData(baseprofiler::SpliceableJSONWriter& aWriter,
+                                   int32_t aPid,
+                                   const ProfilerString8View& aPriority,
+                                   const ProfilingState& aProfilingState) {
+    aWriter.IntProperty("pid", aPid);
+    aWriter.StringProperty("Priority", aPriority);
+    aWriter.StringProperty("Marker cause",
+                           ProfilerString8View::WrapNullTerminatedString(
+                               ProfilingStateToString(aProfilingState)));
+  }
+  static MarkerSchema MarkerTypeDisplay() {
+    using MS = MarkerSchema;
+    MS schema{MS::Location::markerChart, MS::Location::markerTable};
+    schema.AddKeyFormat("pid", MS::Format::integer);
+    schema.AddKeyFormat("Priority", MS::Format::string);
+    schema.AddKeyFormat("Marker cause", MS::Format::string);
+    schema.SetAllLabels(
+        "priority of child {marker.data.pid}: {marker.data.Priority}");
+    return schema;
+  }
+};
+}  // namespace geckoprofiler::markers
+
 namespace {
 
 class ParticularProcessPriorityManager;
 
 /**
  * This singleton class does the work to implement the process priority manager
  * in the main process.  This class may not be used in child processes.  (You
  * can call StaticInit, but it won't do anything, and GetSingleton() will
@@ -503,16 +558,35 @@ ParticularProcessPriorityManager::Partic
       mPriority(PROCESS_PRIORITY_UNKNOWN),
       mHoldsCPUWakeLock(false),
       mHoldsHighPriorityWakeLock(false),
       mHoldsPlayingAudioWakeLock(false),
       mHoldsPlayingVideoWakeLock(false) {
   MOZ_ASSERT(XRE_IsParentProcess());
   MOZ_RELEASE_ASSERT(!aContentParent->IsDead());
   LOGP("Creating ParticularProcessPriorityManager.");
+#ifdef MOZ_GECKO_PROFILER
+  // Our static analysis doesn't allow capturing ref-counted pointers in
+  // lambdas, so we need to hide it in a uintptr_t. This is safe because this
+  // lambda will be destroyed in ~ParticularProcessPriorityManager().
+  uintptr_t self = reinterpret_cast<uintptr_t>(this);
+  profiler_add_state_change_callback(
+      AllProfilingStates(),
+      [self](ProfilingState aProfilingState) {
+        const ParticularProcessPriorityManager* selfPtr =
+            reinterpret_cast<const ParticularProcessPriorityManager*>(self);
+        PROFILER_MARKER("Subprocess Priority", OTHER,
+                        MarkerThreadId::MainThread(), SubProcessPriority,
+                        selfPtr->Pid(),
+                        ProfilerString8View::WrapNullTerminatedString(
+                            ProcessPriorityToString(selfPtr->mPriority)),
+                        aProfilingState);
+      },
+      self);
+#endif  // MOZ_GECKO_PROFILER
 }
 
 void ParticularProcessPriorityManager::Init() {
   RegisterWakeLockObserver(this);
 
   // This process may already hold the CPU lock; for example, our parent may
   // have acquired it on our behalf.
   mHoldsCPUWakeLock = IsHoldingWakeLock(u"cpu"_ns);
@@ -533,16 +607,20 @@ bool ParticularProcessPriorityManager::I
   WakeLockInformation info;
   GetWakeLockInfo(aTopic, &info);
   return info.lockingProcesses().Contains(ChildID());
 }
 
 ParticularProcessPriorityManager::~ParticularProcessPriorityManager() {
   LOGP("Destroying ParticularProcessPriorityManager.");
 
+#ifdef MOZ_GECKO_PROFILER
+  profiler_remove_state_change_callback(reinterpret_cast<uintptr_t>(this));
+#endif  // MOZ_GECKO_PROFILER
+
   ShutDown();
 }
 
 /* virtual */
 void ParticularProcessPriorityManager::Notify(
     const WakeLockInformation& aInfo) {
   if (!mContentParent) {
     // We've been shut down.
@@ -691,16 +769,25 @@ void ParticularProcessPriorityManager::S
   if (!ProcessPriorityManagerImpl::PrefsEnabled() || !mContentParent ||
       mPriority == aPriority) {
     return;
   }
 
   LOGP("Changing priority from %s to %s.", ProcessPriorityToString(mPriority),
        ProcessPriorityToString(aPriority));
 
+  PROFILER_MARKER(
+      "Subprocess Priority", OTHER,
+      MarkerOptions(MarkerThreadId::MainThread(), MarkerStack::Capture()),
+      SubProcessPriorityChange, this->Pid(),
+      ProfilerString8View::WrapNullTerminatedString(
+          ProcessPriorityToString(mPriority)),
+      ProfilerString8View::WrapNullTerminatedString(
+          ProcessPriorityToString(aPriority)));
+
   ProcessPriority oldPriority = mPriority;
 
   mPriority = aPriority;
 
   // We skip incrementing the DOM_CONTENTPROCESS_OS_PRIORITY_RAISED if we're
   // transitioning from the PROCESS_PRIORITY_UNKNOWN level, which is where
   // we initialize at.
   if (oldPriority < mPriority && oldPriority != PROCESS_PRIORITY_UNKNOWN) {