Bug 1779685 - Add useful information to profile.profileGatheringLog.events - r=florian
authorGerald Squelart <gsquelart@mozilla.com>
Wed, 20 Jul 2022 12:52:58 +0000
changeset 624505 2b1c4f14a2cfb5ccdd76d24c47ec9f2a4dd3f8bb
parent 624504 42b6aac07798c43312880bd6a2d62d27c0436f94
child 624506 2072320989562fb9e87ff8e1bf7bafd45aa5d327
push id40007
push usersmolnar@mozilla.com
push dateWed, 20 Jul 2022 21:52:02 +0000
treeherdermozilla-central@16a4302fb1a4 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersflorian
bugs1779685
milestone104.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 1779685 - Add useful information to profile.profileGatheringLog.events - r=florian This may be useful to advanced profiler users, to see how the multi-process profile gathering went. (Some information, like missing processes, could be useful to expose to all users, but this should be done in future tasks, with corresponding front-end work.) Note: There are no direct tests, as this is intended for advanced human users, and the format is not guaranteed to stay stable. Differential Revision: https://phabricator.services.mozilla.com/D151902
tools/profiler/gecko/nsProfiler.cpp
tools/profiler/gecko/nsProfiler.h
--- a/tools/profiler/gecko/nsProfiler.cpp
+++ b/tools/profiler/gecko/nsProfiler.cpp
@@ -54,16 +54,46 @@ nsProfiler::~nsProfiler() {
   if (mSymbolTableThread) {
     mSymbolTableThread->Shutdown();
   }
   ResetGathering();
 }
 
 nsresult nsProfiler::Init() { return NS_OK; }
 
+template <typename JsonLogObjectUpdater>
+void nsProfiler::Log(JsonLogObjectUpdater&& aJsonLogObjectUpdater) {
+  if (mGatheringLog) {
+    MOZ_ASSERT(mGatheringLog->isObject());
+    std::forward<JsonLogObjectUpdater>(aJsonLogObjectUpdater)(*mGatheringLog);
+    MOZ_ASSERT(mGatheringLog->isObject());
+  }
+}
+
+template <typename JsonArrayAppender>
+void nsProfiler::LogEvent(JsonArrayAppender&& aJsonArrayAppender) {
+  Log([&](Json::Value& aRoot) {
+    Json::Value& events = aRoot[Json::StaticString{"events"}];
+    if (!events.isArray()) {
+      events = Json::Value{Json::arrayValue};
+    }
+    Json::Value newEvent{Json::arrayValue};
+    newEvent.append(ProfilingLog::Timestamp());
+    std::forward<JsonArrayAppender>(aJsonArrayAppender)(newEvent);
+    MOZ_ASSERT(newEvent.isArray());
+    events.append(std::move(newEvent));
+  });
+}
+
+void nsProfiler::LogEventLiteralString(const char* aEventString) {
+  LogEvent([&](Json::Value& aEvent) {
+    aEvent.append(Json::StaticString{aEventString});
+  });
+}
+
 static nsresult FillVectorFromStringArray(Vector<const char*>& aVector,
                                           const nsTArray<nsCString>& aArray) {
   if (NS_WARN_IF(!aVector.reserve(aArray.Length()))) {
     return NS_ERROR_OUT_OF_MEMORY;
   }
   for (auto& entry : aArray) {
     aVector.infallibleAppend(entry.get());
   }
@@ -755,22 +785,31 @@ nsProfiler::GetBufferInfo(uint32_t* aCur
 }
 
 bool nsProfiler::SendProgressRequest(PendingProfile& aPendingProfile) {
   RefPtr<ProfilerParent::SingleProcessProgressPromise> progressPromise =
       ProfilerParent::RequestGatherProfileProgress(aPendingProfile.childPid);
   if (!progressPromise) {
     LOG("RequestGatherProfileProgress(%u) -> null!",
         unsigned(aPendingProfile.childPid));
+    LogEvent([&](Json::Value& aEvent) {
+      aEvent.append(
+          Json::StaticString{"Failed to send progress request to pid:"});
+      aEvent.append(Json::Value::UInt64(aPendingProfile.childPid));
+    });
     // Failed to send request.
     return false;
   }
 
   DEBUG_LOG("RequestGatherProfileProgress(%u) sent...",
             unsigned(aPendingProfile.childPid));
+  LogEvent([&](Json::Value& aEvent) {
+    aEvent.append(Json::StaticString{"Requested progress from pid:"});
+    aEvent.append(Json::Value::UInt64(aPendingProfile.childPid));
+  });
   aPendingProfile.lastProgressRequest = TimeStamp::Now();
   progressPromise->Then(
       GetMainThreadSerialEventTarget(), __func__,
       [self = RefPtr<nsProfiler>(this),
        childPid = aPendingProfile.childPid](GatherProfileProgress&& aResult) {
         if (!self->mGathering) {
           return;
         }
@@ -781,16 +820,26 @@ bool nsProfiler::SendProgressRequest(Pen
             unsigned(childPid),
             ProportionValue::FromUnderlyingType(
                 aResult.progressProportionValueUnderlyingType())
                     .ToDouble() *
                 100.0,
             aResult.progressLocation().Data(),
             unsigned(self->mPendingProfiles.length()),
             pendingProfile ? "including" : "excluding", unsigned(childPid));
+        self->LogEvent([&](Json::Value& aEvent) {
+          aEvent.append(
+              Json::StaticString{"Got response from pid, with progress:"});
+          aEvent.append(Json::Value::UInt64(childPid));
+          aEvent.append(
+              Json::Value{ProportionValue::FromUnderlyingType(
+                              aResult.progressProportionValueUnderlyingType())
+                              .ToDouble() *
+                          100.0});
+        });
         if (pendingProfile) {
           // We have a progress report for a still-pending profile.
           pendingProfile->lastProgressResponse = TimeStamp::Now();
           // Has it actually made progress?
           if (aResult.progressProportionValueUnderlyingType() !=
               pendingProfile->progressProportion.ToUnderlyingType()) {
             pendingProfile->lastProgressChange =
                 pendingProfile->lastProgressResponse;
@@ -808,16 +857,22 @@ bool nsProfiler::SendProgressRequest(Pen
           return;
         }
         PendingProfile* pendingProfile = self->GetPendingProfile(childPid);
         LOG("RequestGatherProfileProgress(%u) rejection: %d "
             "(%u were pending, %s %u)",
             unsigned(childPid), (int)aReason,
             unsigned(self->mPendingProfiles.length()),
             pendingProfile ? "including" : "excluding", unsigned(childPid));
+        self->LogEvent([&](Json::Value& aEvent) {
+          aEvent.append(Json::StaticString{
+              "Got progress request rejection from pid, with reason:"});
+          aEvent.append(Json::Value::UInt64(childPid));
+          aEvent.append(Json::Value::UInt{static_cast<unsigned>(aReason)});
+        });
         if (pendingProfile) {
           // Failure response, assume the child process is gone.
           MOZ_ASSERT(self->mPendingProfiles.begin() <= pendingProfile &&
                      pendingProfile < self->mPendingProfiles.end());
           self->mPendingProfiles.erase(pendingProfile);
           if (self->mPendingProfiles.empty()) {
             // We've got all of the async profiles now. Let's finish off the
             // profile and resolve the Promise.
@@ -922,16 +977,23 @@ bool nsProfiler::SendProgressRequest(Pen
   }
 
   DEBUG_LOG("GatheringTimerCallback() - Timeout!");
   self->mGatheringTimer = nullptr;
   if (!profiler_is_active() || !self->mGathering) {
     // Not gathering anymore.
     return;
   }
+  self->LogEvent([&](Json::Value& aEvent) {
+    aEvent.append(Json::StaticString{
+        "No progress made recently, giving up; pending pids:"});
+    for (const PendingProfile& pendingProfile : self->mPendingProfiles) {
+      aEvent.append(Json::Value::UInt64(pendingProfile.childPid));
+    }
+  });
   NS_WARNING("Profiler failed to gather profiles from all sub-processes");
   // We have really reached a timeout while gathering, finish now.
   // TODO: Add information about missing processes.
   self->FinishGathering();
 }
 
 void nsProfiler::RestartGatheringTimer() {
   if (mGatheringTimer) {
@@ -1050,16 +1112,17 @@ RefPtr<nsProfiler::GatheringPromise> nsP
   // Do this before the call to profiler_stream_json_for_this_process() because
   // that call is slow and we want to let the other processes grab their
   // profiles as soon as possible.
   nsTArray<ProfilerParent::SingleProcessProfilePromiseAndChildPid> profiles =
       ProfilerParent::GatherProfiles();
 
   MOZ_ASSERT(mPendingProfiles.empty());
   if (!mPendingProfiles.reserve(profiles.Length())) {
+    ResetGathering();
     return GatheringPromise::CreateAndReject(NS_ERROR_NOT_AVAILABLE, __func__);
   }
 
   mWriter.emplace();
 
   UniquePtr<ProfilerCodeAddressService> service =
       profiler_code_address_service_for_presymbolication();
 
@@ -1067,27 +1130,45 @@ RefPtr<nsProfiler::GatheringPromise> nsP
   mWriter->Start();
   if (!profiler_stream_json_for_this_process(*mWriter, aSinceTime,
                                              /* aIsShuttingDown */ false,
                                              service.get())) {
     // The profiler is inactive. This either means that it was inactive even
     // at the time that ProfileGatherer::Start() was called, or that it was
     // stopped on a different thread since that call. Either way, we need to
     // reject the promise and stop gathering.
+    ResetGathering();
     return GatheringPromise::CreateAndReject(NS_ERROR_NOT_AVAILABLE, __func__);
   }
 
+  LogEvent([&](Json::Value& aEvent) {
+    aEvent.append(
+        Json::StaticString{"Generated parent process profile, size:"});
+    aEvent.append(Json::Value::UInt64{mWriter->ChunkedWriteFunc().Length()});
+  });
+
   mWriter->StartArrayProperty("processes");
 
   // If we have any process exit profiles, add them immediately.
-  Vector<nsCString> exitProfiles = profiler_move_exit_profiles();
-  for (auto& exitProfile : exitProfiles) {
-    if (!exitProfile.IsEmpty()) {
-      mWriter->Splice(exitProfile);
+  if (Vector<nsCString> exitProfiles = profiler_move_exit_profiles();
+      !exitProfiles.empty()) {
+    for (auto& exitProfile : exitProfiles) {
+      if (!exitProfile.IsEmpty()) {
+        mWriter->Splice(exitProfile);
+      }
     }
+
+    LogEvent([&](Json::Value& aEvent) {
+      aEvent.append(Json::StaticString{
+          "Processed all exit profiles, total size so far:"});
+      aEvent.append(Json::Value::UInt64{mWriter->ChunkedWriteFunc().Length()});
+    });
+  } else {
+    // There are no pending profiles, we're already done.
+    LogEventLiteralString("No exit profiles.");
   }
 
   mPromiseHolder.emplace();
   RefPtr<GatheringPromise> promise = mPromiseHolder->Ensure(__func__);
 
   // Keep the array property "processes" and the root object in mWriter open
   // until FinishGathering() is called. As profiles from the other processes
   // come in, they will be inserted and end up in the right spot.
@@ -1112,47 +1193,68 @@ RefPtr<nsProfiler::GatheringPromise> nsP
     Unused << NS_NewTimerWithFuncCallback(
         getter_AddRefs(mGatheringTimer), GatheringTimerCallback, this,
         childTimeoutMs, nsITimer::TYPE_ONE_SHOT_LOW_PRIORITY,
         "nsProfilerGatheringTimer", GetMainThreadSerialEventTarget());
 
     MOZ_ASSERT(mPendingProfiles.capacity() >= profiles.Length());
     for (const auto& profile : profiles) {
       mPendingProfiles.infallibleAppend(PendingProfile{profile.childPid});
+      LogEvent([&](Json::Value& aEvent) {
+        aEvent.append(Json::StaticString{"Waiting for pending profile, pid:"});
+        aEvent.append(Json::Value::UInt64(profile.childPid));
+      });
       profile.profilePromise->Then(
           GetMainThreadSerialEventTarget(), __func__,
           [self = RefPtr<nsProfiler>(this),
            childPid = profile.childPid](mozilla::ipc::Shmem&& aResult) {
             PendingProfile* pendingProfile = self->GetPendingProfile(childPid);
             LOG("GatherProfile(%u) response: %u bytes (%u were pending, %s %u)",
                 unsigned(childPid), unsigned(aResult.Size<char>()),
                 unsigned(self->mPendingProfiles.length()),
                 pendingProfile ? "including" : "excluding", unsigned(childPid));
             if (aResult.IsReadable()) {
+              self->LogEvent([&](Json::Value& aEvent) {
+                aEvent.append(
+                    Json::StaticString{"Got profile from pid, with size:"});
+                aEvent.append(Json::Value::UInt64(childPid));
+                aEvent.append(Json::Value::UInt64{aResult.Size<char>()});
+              });
               const nsDependentCSubstring profileString(
                   aResult.get<char>(), aResult.Size<char>() - 1);
               self->GatheredOOPProfile(childPid, profileString);
             } else {
               // This can happen if the child failed to allocate
               // the Shmem (or maliciously sent an invalid Shmem).
+              self->LogEvent([&](Json::Value& aEvent) {
+                aEvent.append(Json::StaticString{"Got failure from pid:"});
+                aEvent.append(Json::Value::UInt64(childPid));
+              });
               self->GatheredOOPProfile(childPid, ""_ns);
             }
           },
           [self = RefPtr<nsProfiler>(this),
            childPid = profile.childPid](ipc::ResponseRejectReason&& aReason) {
             PendingProfile* pendingProfile = self->GetPendingProfile(childPid);
             LOG("GatherProfile(%u) rejection: %d (%u were pending, %s %u)",
                 unsigned(childPid), (int)aReason,
                 unsigned(self->mPendingProfiles.length()),
                 pendingProfile ? "including" : "excluding", unsigned(childPid));
+            self->LogEvent([&](Json::Value& aEvent) {
+              aEvent.append(
+                  Json::StaticString{"Got rejection from pid, with reason:"});
+              aEvent.append(Json::Value::UInt64(childPid));
+              aEvent.append(Json::Value::UInt{static_cast<unsigned>(aReason)});
+            });
             self->GatheredOOPProfile(childPid, ""_ns);
           });
     }
   } else {
     // There are no pending profiles, we're already done.
+    LogEventLiteralString("No pending child profiles.");
     FinishGathering();
   }
 
   return promise;
 }
 
 RefPtr<nsProfiler::SymbolTablePromise> nsProfiler::GetSymbolTableMozPromise(
     const nsACString& aDebugPath, const nsACString& aBreakpadID) {
@@ -1198,16 +1300,20 @@ void nsProfiler::FinishGathering() {
   MOZ_RELEASE_ASSERT(NS_IsMainThread());
   MOZ_RELEASE_ASSERT(mWriter.isSome());
   MOZ_RELEASE_ASSERT(mPromiseHolder.isSome());
 
   // Close the "processes" array property.
   mWriter->EndArray();
 
   if (mGatheringLog) {
+    LogEvent([&](Json::Value& aEvent) {
+      aEvent.append(Json::StaticString{"Finished gathering, total size:"});
+      aEvent.append(Json::Value::UInt64{mWriter->ChunkedWriteFunc().Length()});
+    });
     (*mGatheringLog)[Json::StaticString{
         "profileGatheringLogEnd" TIMESTAMP_JSON_SUFFIX}] =
         ProfilingLog::Timestamp();
     mWriter->StartObjectProperty("profileGatheringLog");
     {
       nsAutoCString pid;
       pid.AppendInt(int64_t(profiler_current_process_id().ToNumber()));
       Json::String logString = mGatheringLog->toStyledString();
--- a/tools/profiler/gecko/nsProfiler.h
+++ b/tools/profiler/gecko/nsProfiler.h
@@ -77,16 +77,27 @@ class nsProfiler final : public nsIProfi
 
     explicit PendingProfile(base::ProcessId aChildPid) : childPid(aChildPid) {}
   };
 
   PendingProfile* GetPendingProfile(base::ProcessId aChildPid);
   // Returns false if the request could not be sent.
   bool SendProgressRequest(PendingProfile& aPendingProfile);
 
+  // If the log is active, call aJsonLogObjectUpdater(Json::Value&) on the log's
+  // root object.
+  template <typename JsonLogObjectUpdater>
+  void Log(JsonLogObjectUpdater&& aJsonLogObjectUpdater);
+  // If the log is active, call aJsonArrayAppender(Json::Value&) on a Json
+  // array that already contains a timestamp, and to which event-related
+  // elements may be appended.
+  template <typename JsonArrayAppender>
+  void LogEvent(JsonArrayAppender&& aJsonArrayAppender);
+  void LogEventLiteralString(const char* aEventString);
+
   // These fields are all related to profile gathering.
   mozilla::Vector<ExitProfile> mExitProfiles;
   mozilla::Maybe<mozilla::MozPromiseHolder<GatheringPromise>> mPromiseHolder;
   nsCOMPtr<nsIThread> mSymbolTableThread;
   mozilla::Maybe<SpliceableChunkedJSONWriter> mWriter;
   mozilla::Vector<PendingProfile> mPendingProfiles;
   bool mGathering;
   nsCOMPtr<nsITimer> mGatheringTimer;