Bug 1676271 - Per-process profiling log - r=canaltinova

Differential Revision: https://phabricator.services.mozilla.com/D150560

tools/profiler/core/platform.cpp

@@ -373,6 +373,30 @@ static constexpr uint32_t StartupExtraDefaultFeatures() {
   return ProfilerFeature::FileIOAll | ProfilerFeature::IPCMessages;
 }
 
+/* static */ mozilla::baseprofiler::detail::BaseProfilerMutex
+    ProfilingLog::gMutex;
+/* static */ mozilla::UniquePtr<Json::Value> ProfilingLog::gLog;
+
+/* static */ void ProfilingLog::Init() {
+  mozilla::baseprofiler::detail::BaseProfilerAutoLock lock{gMutex};
+  MOZ_ASSERT(!gLog);
+  gLog = mozilla::MakeUniqueFallible<Json::Value>(Json::objectValue);
+  if (gLog) {
+    (*gLog)[Json::StaticString{"profilingLogBegin" TIMESTAMP_JSON_SUFFIX}] =
+        ProfilingLog::Timestamp();
+  }
+}
+
+/* static */ void ProfilingLog::Destroy() {
+  mozilla::baseprofiler::detail::BaseProfilerAutoLock lock{gMutex};
+  MOZ_ASSERT(gLog);
+  gLog = nullptr;
+}
+
+/* static */ bool ProfilingLog::IsLockedOnCurrentThread() {
+  return gMutex.IsLockedOnCurrentThread();
+}
+
 // RAII class to lock the profiler mutex.
 // It provides a mechanism to determine if it is locked or not in order for
 // memory hooks to avoid re-entering the profiler locked state.
@@ -382,10 +406,12 @@ class MOZ_RAII PSAutoLock {
   PSAutoLock()
       : mLock([]() -> mozilla::baseprofiler::detail::BaseProfilerMutex& {
           // In DEBUG builds, *before* we attempt to lock gPSMutex, we want to
-          // check that the ThreadRegistry and ThreadRegistration mutexes are
-          // *not* locked on this thread, to avoid inversion deadlocks.
+          // check that the ThreadRegistry, ThreadRegistration, and ProfilingLog
+          // mutexes are *not* locked on this thread, to avoid inversion
+          // deadlocks.
           MOZ_ASSERT(!ThreadRegistry::IsRegistryMutexLockedOnCurrentThread());
           MOZ_ASSERT(!ThreadRegistration::IsDataMutexLockedOnCurrentThread());
+          MOZ_ASSERT(!ProfilingLog::IsLockedOnCurrentThread());
           return gPSMutex;
         }()) {}
 
@@ -776,6 +802,8 @@ class ActivePS {
             NewSamplerThread(aLock, mGeneration, aInterval, aFeatures)),
         mIsPaused(false),
         mIsSamplingPaused(false) {
+    ProfilingLog::Init();
+
     // Deep copy and lower-case aFilters.
     MOZ_ALWAYS_TRUE(mFilters.resize(aFilterCount));
     MOZ_ALWAYS_TRUE(mFiltersLowered.resize(aFilterCount));
@@ -852,6 +880,8 @@ class ActivePS {
       // We still control the chunk manager, remove it from the core buffer.
       profiler_get_core_buffer().ResetChunkManager();
     }
+
+    ProfilingLog::Destroy();
   }
 
   bool ThreadSelected(const char* aThreadName) {
@@ -3303,6 +3333,20 @@ static void locked_profiler_stream_json_for_this_process(
   }
   aWriter.EndArray();
 
+  ProfilingLog::Access([&](Json::Value& aProfilingLogObject) {
+    aProfilingLogObject[Json::StaticString{
+        "profilingLogEnd" TIMESTAMP_JSON_SUFFIX}] = ProfilingLog::Timestamp();
+
+    aWriter.StartObjectProperty("profilingLog");
+    {
+      nsAutoCString pid;
+      pid.AppendInt(int64_t(profiler_current_process_id().ToNumber()));
+      Json::String logString = aProfilingLogObject.toStyledString();
+      aWriter.SplicedJSONProperty(pid, logString);
+    }
+    aWriter.EndObject();
+  });
+
   const double collectionEndMs = profiler_time();
 
   // Record timestamps for the collection into the buffer, so that consumers

tools/profiler/core/platform.h

@@ -31,7 +31,9 @@
 
 #include "PlatformMacros.h"
 
+#include "json/json.h"
 #include "mozilla/Atomics.h"
+#include "mozilla/BaseProfilerDetail.h"
 #include "mozilla/Logging.h"
 #include "mozilla/MathAlgorithms.h"
 #include "mozilla/ProfileBufferEntrySerialization.h"
@@ -73,6 +75,58 @@ extern mozilla::LazyLogModule gProfilerLog;
 
 typedef uint8_t* Address;
 
+// Profiling log stored in a Json::Value. The actual log only exists while the
+// profiler is running, and will be inserted at the end of the JSON profile.
+class ProfilingLog {
+ public:
+  // These will be called by ActivePS when the profiler starts/stops.
+  static void Init();
+  static void Destroy();
+
+  // Access the profiling log JSON object, in order to modify it.
+  // Only calls the given function if the profiler is active.
+  // Thread-safe. But `aF` must not call other locking profiler functions.
+  // This is intended to capture some internal logging that doesn't belong in
+  // other places like markers. The log is accessible through the JS console on
+  // profiler.firefox.com, in the `profile.profilingLog` object; the data format
+  // is intentionally not defined, and not intended to be shown in the
+  // front-end.
+  // Please use caution not to output too much data.
+  template <typename F>
+  static void Access(F&& aF) {
+    mozilla::baseprofiler::detail::BaseProfilerAutoLock lock{gMutex};
+    if (gLog) {
+      std::forward<F>(aF)(*gLog);
+    }
+  }
+
+#define DURATION_JSON_SUFFIX "_ms"
+
+  // Convert a TimeDuration to the value to be stored in the log.
+  // Use DURATION_JSON_SUFFIX as suffix in the property name.
+  static Json::Value Duration(const mozilla::TimeDuration& aDuration) {
+    return Json::Value{aDuration.ToMilliseconds()};
+  }
+
+#define TIMESTAMP_JSON_SUFFIX "_TSms"
+
+  // Convert a TimeStamp to the value to be stored in the log.
+  // Use TIMESTAMP_JSON_SUFFIX as suffix in the property name.
+  static Json::Value Timestamp(
+      const mozilla::TimeStamp& aTimestamp = mozilla::TimeStamp::Now()) {
+    if (aTimestamp.IsNull()) {
+      return Json::Value{0.0};
+    }
+    return Duration(aTimestamp - mozilla::TimeStamp::ProcessCreation());
+  }
+
+  static bool IsLockedOnCurrentThread();
+
+ private:
+  static mozilla::baseprofiler::detail::BaseProfilerMutex gMutex;
+  static mozilla::UniquePtr<Json::Value> gLog;
+};
+
 // ----------------------------------------------------------------------------
 // Miscellaneous
 

tools/profiler/moz.build

@@ -106,6 +106,7 @@ if CONFIG["MOZ_GECKO_PROFILER"]:
         "/mozglue/linker",
         "/netwerk/base",
         "/netwerk/protocol/http",
+        "/toolkit/components/jsoncpp/include",
         "/toolkit/crashreporter/google-breakpad/src",
         "/tools/profiler/core/",
         "/tools/profiler/gecko/",
@@ -196,6 +197,10 @@ if CONFIG["COMPILE_ENVIRONMENT"]:
         "!profiler_ffi_generated.h",
     ]
 
+USE_LIBS += [
+    "jsoncpp",
+]
+
 FINAL_LIBRARY = "xul"
 
 if CONFIG["ENABLE_TESTS"]:

tools/profiler/tests/browser/browser_test_profile_fission.js

@@ -32,6 +32,7 @@ add_task(async function test_profile_fission_no_private_browsing() {
     BrowserTestUtils.loadURI(contentBrowser, url);
     await BrowserTestUtils.browserLoaded(contentBrowser, false, url);
 
+    const parentPid = Services.appinfo.processID;
     const contentPid = await SpecialPowers.spawn(contentBrowser, [], () => {
       return Services.appinfo.processID;
     });
@@ -86,6 +87,29 @@ add_task(async function test_profile_fission_no_private_browsing() {
       }
     }
     Assert.equal(pageFound, true);
+
+    info("Check that the profiling logs exist with the expected properties.");
+    Assert.equal(typeof profile.profilingLog, "object");
+    Assert.equal(typeof profile.profilingLog[parentPid], "object");
+    Assert.equal(
+      typeof profile.profilingLog[parentPid].profilingLogBegin_TSms,
+      "number"
+    );
+    Assert.equal(
+      typeof profile.profilingLog[parentPid].profilingLogEnd_TSms,
+      "number"
+    );
+
+    Assert.equal(typeof contentProcess.profilingLog, "object");
+    Assert.equal(typeof contentProcess.profilingLog[contentPid], "object");
+    Assert.equal(
+      typeof contentProcess.profilingLog[contentPid].profilingLogBegin_TSms,
+      "number"
+    );
+    Assert.equal(
+      typeof contentProcess.profilingLog[contentPid].profilingLogEnd_TSms,
+      "number"
+    );
   } finally {
     await BrowserTestUtils.closeWindow(win);
   }

tools/profiler/tests/gtest/GeckoProfiler.cpp

@@ -1502,6 +1502,22 @@ static void JSONRootCheck(const Json::Value& aRoot,
       JSONRootCheck(process, aWithMainThread);
     }
   }
+
+  GET_JSON(profilingLog, aRoot["profilingLog"], Object);
+  EXPECT_EQ(profilingLog.size(), 1u);
+  for (auto it = profilingLog.begin(); it != profilingLog.end(); ++it) {
+    // The key should be a pid.
+    const auto key = it.name();
+    for (const auto letter : key) {
+      EXPECT_GE(letter, '0');
+      EXPECT_LE(letter, '9');
+    }
+    // And the value should be an object.
+    GET_JSON(logForPid, profilingLog[key], Object);
+    // Its content is not defined, but we expect at least these:
+    EXPECT_HAS_JSON(logForPid["profilingLogBegin_TSms"], Double);
+    EXPECT_HAS_JSON(logForPid["profilingLogEnd_TSms"], Double);
+  }
 }
 
 // Check that various expected top properties are in the JSON, and then call the