Bug 1763474 - Report thread wake-ups and CPU time per thread through glean, r=gerald,chutten

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

toolkit/components/glean/ipc/FOGIPC.cpp

@@ -71,6 +71,93 @@ struct ProcessingTimeMarker {
 
 namespace mozilla::glean {
 
+#ifdef NIGHTLY_BUILD
+// The 2 following static global variables are set within RecordPowerMetrics
+// so that RecordThreadCpuUse can avoid computing the Glean process type
+// (matching a label of per_process_type_labels).
+// This is useful because RecordThreadCpuUse will either be called in a loop
+// for every thread (recomputing the process type for every thread would be
+// expensive), or will be called off main thread when a thread is unregisters
+// itself (some APIs needed to compute the process type might not be available
+// off main thread).
+// It is fine to call RecordThreadCpuUse during startup before the first
+// RecordPowerMetrics call. In that case the parent process will be recorded
+// as inactive, and other processes will be ignored (content processes start
+// in the 'prealloc' type for which we don't record per-thread CPU use data).
+using LabeledCounterMetric = const impl::Labeled<impl::CounterMetric>;
+static Atomic<LabeledCounterMetric*> gCpuTimePerThreadMetric(nullptr);
+static Atomic<LabeledCounterMetric*> gWakeupsPerThreadMetric(nullptr);
+
+// These 2 macros are only meant to reduce code duplication, there is no
+// requirement of the 2 variables being set atomically as a single value.
+#  define SET_PER_THREAD_CPU_METRICS(aProcessType)                    \
+    gCpuTimePerThreadMetric = &power_cpu_ms_per_thread::aProcessType; \
+    gWakeupsPerThreadMetric = &power_wakeups_per_thread::aProcessType;
+
+#  define RESET_PER_THREAD_CPU_METRICS() \
+    gCpuTimePerThreadMetric = nullptr;   \
+    gWakeupsPerThreadMetric = nullptr;
+
+void RecordThreadCpuUse(const nsACString& aThreadName, uint64_t aCpuTimeMs,
+                        uint64_t aWakeCount) {
+  // Copy the values of the atomics to local variables so that we don't have to
+  // worry about other threads changing them during the execution of this
+  // function.
+  LabeledCounterMetric* cpuTimeMetric = gCpuTimePerThreadMetric;
+  LabeledCounterMetric* wakeupsMetric = gWakeupsPerThreadMetric;
+
+  if (!cpuTimeMetric || !wakeupsMetric) {
+    if (XRE_IsParentProcess()) {
+      // The metrics can be null for the parent process during startup,
+      // and we want to record during that time.
+      SET_PER_THREAD_CPU_METRICS(parent_inactive);
+      cpuTimeMetric = gCpuTimePerThreadMetric;
+      wakeupsMetric = gWakeupsPerThreadMetric;
+      if (!cpuTimeMetric || !wakeupsMetric) {
+        return;
+      }
+    } else {
+      // We are not interested in per-thread CPU use data for the current
+      // process type.
+      return;
+    }
+  }
+
+  nsAutoCString threadName(aThreadName);
+  for (size_t i = 0; i < threadName.Length(); ++i) {
+    const char c = threadName.CharAt(i);
+
+    // Valid characters.
+    if ((c >= '0' && c <= '9') || (c >= 'a' && c <= 'z') || c == '-' ||
+        c == '_') {
+      continue;
+    }
+
+    // Should only use lower case characters
+    if (c >= 'A' && c <= 'Z') {
+      threadName.SetCharAt(c + ('a' - 'A'), i);
+      continue;
+    }
+
+    // Replace everything else with _
+    threadName.SetCharAt('_', i);
+  }
+
+  if (aCpuTimeMs != 0 &&
+      MOZ_LIKELY(aCpuTimeMs < std::numeric_limits<int32_t>::max())) {
+    cpuTimeMetric->Get(threadName).Add(int32_t(aCpuTimeMs));
+  }
+
+  if (aWakeCount != 0 &&
+      MOZ_LIKELY(aWakeCount < std::numeric_limits<int32_t>::max())) {
+    wakeupsMetric->Get(threadName).Add(int32_t(aWakeCount));
+  }
+}
+#else  // ifdef NIGHTLY_BUILD
+#  define SET_PER_THREAD_CPU_METRICS(aProcessType)
+#  define RESET_PER_THREAD_CPU_METRICS()
+#endif
+
 void RecordPowerMetrics() {
   static uint64_t previousCpuTime = 0, previousGpuTime = 0;
 
@@ -104,23 +191,31 @@ void RecordPowerMetrics() {
         switch (cc->GetProcessPriority()) {
           case hal::PROCESS_PRIORITY_BACKGROUND:
             type.AppendLiteral(".background");
+            SET_PER_THREAD_CPU_METRICS(content_background);
             break;
           case hal::PROCESS_PRIORITY_FOREGROUND:
             type.AppendLiteral(".foreground");
+            SET_PER_THREAD_CPU_METRICS(content_foreground);
             break;
           case hal::PROCESS_PRIORITY_BACKGROUND_PERCEIVABLE:
             type.AppendLiteral(".background-perceivable");
+            RESET_PER_THREAD_CPU_METRICS();
             break;
           default:
+            RESET_PER_THREAD_CPU_METRICS();
             break;
         }
       }
+    } else {
+      RESET_PER_THREAD_CPU_METRICS();
     }
   } else if (XRE_IsParentProcess()) {
     if (nsContentUtils::GetUserIsInteracting()) {
       type.AssignLiteral("parent.active");
+      SET_PER_THREAD_CPU_METRICS(parent_active);
     } else {
       type.AssignLiteral("parent.inactive");
+      SET_PER_THREAD_CPU_METRICS(parent_inactive);
     }
     hal::WakeLockInformation info;
     GetWakeLockInfo(u"video-playing"_ns, &info);
@@ -132,6 +227,10 @@ void RecordPowerMetrics() {
         type.AppendLiteral(".playing-audio");
       }
     }
+  } else if (XRE_IsGPUProcess()) {
+    SET_PER_THREAD_CPU_METRICS(gpu_process);
+  } else {
+    RESET_PER_THREAD_CPU_METRICS();
   }
 
   if (newCpuTime) {
@@ -146,8 +245,8 @@ void RecordPowerMetrics() {
     } else {
       power::cpu_time_bogus_values.Add(1);
     }
-    PROFILER_MARKER("CPU Time", OTHER, {}, ProcessingTimeMarker, nNewCpuTime,
-                    type);
+    PROFILER_MARKER("Process CPU Time", OTHER, {}, ProcessingTimeMarker,
+                    nNewCpuTime, type);
     previousCpuTime += newCpuTime;
   }
 
@@ -159,8 +258,8 @@ void RecordPowerMetrics() {
     } else {
       power::gpu_time_bogus_values.Add(1);
     }
-    PROFILER_MARKER("GPU Time", OTHER, {}, ProcessingTimeMarker, nNewGpuTime,
-                    type);
+    PROFILER_MARKER("Process GPU Time", OTHER, {}, ProcessingTimeMarker,
+                    nNewGpuTime, type);
     previousGpuTime += newGpuTime;
   }
 

toolkit/components/glean/ipc/FOGIPC.h

@@ -71,6 +71,29 @@ RefPtr<GenericPromise> FlushAndUseFOGData();
 void TestTriggerMetrics(uint32_t processType,
                         const RefPtr<dom::Promise>& promise);
 
+#ifdef NIGHTLY_BUILD
+/**
+ * This function records the CPU activity (CPU time used and wakeup count)
+ * of a specific thread. It is called only by profiler code, either multiple
+ * times in a row when RecordPowerMetrics asks the profiler to record
+ * the wakeup counts of all threads, or once when a thread is unregistered.
+ *
+ * @param aThreadName The name of the thread for which the CPU data is being
+ *                    recorded.
+ *                    The name will be converted to lower case, and characters
+ *                    that are not valid for glean labels will be replaced with
+ *                    '_'. The resulting name should be part of the
+ *                    per_thread_labels static list of labels defined in
+ *                    toolkit/components/processtools/metrics.yaml.
+ * @param aCpuTimeMs CPU time in miliseconds since the last time CPU use data
+ *                   was recorded for this thread.
+ * @param aWakeCount How many times the thread woke up since the previous time
+ *                   CPU use data was recorded for this thread.
+ */
+void RecordThreadCpuUse(const nsACString& aThreadName, uint64_t aCpuTimeMs,
+                        uint64_t aWakeCount);
+#endif
+
 void RecordPowerMetrics();
 
 }  // namespace glean

toolkit/components/glean/tests/gtest/TestFog.cpp

@@ -39,10 +39,13 @@ TEST(FOG, FogInitDoesntCrash)
   Preferences::SetInt("telemetry.fog.test.localhost_port", -1);
   const nsCString empty;
   ASSERT_EQ(NS_OK, fog_init(&empty, &empty));
+  ASSERT_EQ(NS_OK, fog_test_reset(&empty, &empty));
 }
 
 extern "C" void Rust_MeasureInitializeTime();
-TEST(FOG, TestMeasureInitializeTime)
+// Disabled because this depends on the preinit buffer not overflowing,
+// which currently can't be guaranteed. See bug 1756057 for how to fix it.
+TEST(FOG, DISABLED_TestMeasureInitializeTime)
 { Rust_MeasureInitializeTime(); }
 
 TEST(FOG, BuiltinPingsRegistered)

toolkit/components/processtools/metrics.yaml

@@ -157,3 +157,143 @@ power:
       - florian@mozilla.com
     expires: never
     telemetry_mirror: POWER_TOTAL_THREAD_WAKEUPS
+
+power.wakeups_per_thread:
+  parent_active: &per_thread_wakeups
+    type: labeled_counter
+    description: >
+      How many times threads woke up and could have woken up a CPU core.
+      Broken down by thread name for a given process type.
+    bugs:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1763474
+    data_reviews:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1763474
+    data_sensitivity:
+      - technical
+    notification_emails:
+      - florian@mozilla.com
+    expires: never
+    labels: &per_thread_labels
+      - asynclogger
+      - audioipc
+      - audioipc_callback_rpc
+      - audioipc_client_callback
+      - audioipc_client_rpc
+      - audioipc_devicecollection_rpc
+      - audioipc_server_callback
+      - audioipc_server_rpc
+      - backgroundthreadpool
+      - bgiothreadpool
+      - bgreadurls
+      - bhmgr_monitor
+      - bhmgr_processor
+      - cameras_ipc
+      - capturethread
+      - classifier_update
+      - com_mta
+      - compositor
+      - cookie
+      - cubeboperation
+      - datachannel_io
+      - dns_resolver
+      - dom_worker
+      - domcachethread
+      - extensionprotocolhandler
+      - font_loader
+      - fontenumthread
+      - fs_broker
+      - geckomain
+      - gmpthread
+      - graphrunner
+      - html5_parser
+      - imagebridgechld
+      - imageio
+      - indexeddb
+      - initfontlist
+      - inotifyeventthread
+      - ipc_i_o_child
+      - ipc_i_o_parent
+      - ipc_launch
+      - ipdl_background
+      - js_watchdog
+      - jump_list
+      - libwebrtcmodulethread
+      - link_monitor
+      - ls_thread
+      - mediacache
+      - mediadecoderstatemachine
+      - mediapdecoder
+      - mediasupervisor
+      - mediatimer
+      - mediatrackgrph
+      - memorypoller
+      - mozstorage
+      - mtransport
+      - netlink_monitor
+      - pacerthread
+      - permission
+      - playeventsound
+      - processhangmon
+      - profilerchild
+      - proxyresolution
+      - quotamanager_io
+      - registerfonts
+      - remotebackbuffer
+      - remotelzystream
+      - remvidchild
+      - renderer
+      - sandboxreporter
+      - savescripts
+      - socket_thread
+      - softwarevsyncthread
+      - ssl_cert
+      - startupcache
+      - streamtrans
+      - stylethread
+      - swcomposite
+      - taskcontroller
+      - timer
+      - toastbgthread
+      - trr_background
+      - untrusted_modules
+      - url_classifier
+      - videocapture
+      - vsynciothread
+      - webrtccallthread
+      - webrtcworker
+      - wincompositor
+      - windowsvsyncthread
+      - winwindowocclusioncalc
+      - worker_launcher
+      - wrrenderbackend
+      - wrscenebuilder
+      - wrscenebuilderlp
+      - wrworker
+      - wrworkerlp
+
+  parent_inactive: *per_thread_wakeups
+  content_foreground: *per_thread_wakeups
+  content_background: *per_thread_wakeups
+  gpu_process: *per_thread_wakeups
+
+power.cpu_ms_per_thread:
+  parent_active: &per_thread_cpu_ms
+    type: labeled_counter
+    description: >
+      How many miliseconds of CPU time were used.
+      Broken down by thread name for a given process type.
+    bugs:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1763474
+    data_reviews:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1763474
+    data_sensitivity:
+      - technical
+    notification_emails:
+      - florian@mozilla.com
+    expires: never
+    labels: *per_thread_labels
+
+  parent_inactive: *per_thread_cpu_ms
+  content_foreground: *per_thread_cpu_ms
+  content_background: *per_thread_cpu_ms
+  gpu_process: *per_thread_cpu_ms

toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js

@@ -287,4 +287,45 @@ add_task(async () => {
     undefined,
     "no GPU time should be recorded in the __other__ label"
   );
+
+  // Now test per-thread CPU time.
+  // We don't test parentActive as the user is not marked active on infra.
+  let processTypes = [
+    "parentInactive",
+    "contentBackground",
+    "contentForeground",
+  ];
+  if (beforeProcInfo.children.some(p => p.type == "gpu")) {
+    processTypes.push("gpuProcess");
+  }
+  // The list of accepted labels is not accessible to the JS code, so test only the main thread.
+  const kThreadName = "geckomain";
+  if (AppConstants.NIGHTLY_BUILD) {
+    for (let processType of processTypes) {
+      Assert.greater(
+        Glean.powerCpuMsPerThread[processType][kThreadName].testGetValue(),
+        0,
+        `some CPU time should have been recorded for the ${processType} main thread`
+      );
+      Assert.greater(
+        Glean.powerWakeupsPerThread[processType][kThreadName].testGetValue(),
+        0,
+        `some thread wake ups should have been recorded for the ${processType} main thread`
+      );
+    }
+  } else {
+    // We are not recording per thread CPU use outside of the Nightly channel.
+    for (let processType of processTypes) {
+      Assert.equal(
+        Glean.powerCpuMsPerThread[processType][kThreadName].testGetValue(),
+        undefined,
+        `no CPU time should have been recorded for the ${processType} main thread`
+      );
+      Assert.equal(
+        Glean.powerWakeupsPerThread[processType][kThreadName].testGetValue(),
+        undefined,
+        `no thread wake ups should have been recorded for the ${processType} main thread`
+      );
+    }
+  }
 });

tools/profiler/core/ProfilerThreadRegistration.cpp

@@ -73,6 +73,9 @@ ThreadRegistration::~ThreadRegistration() {
     }
 
     profiler_mark_thread_asleep();
+#ifdef NIGHTLY_BUILD
+    mData.RecordWakeCount();
+#endif
     ThreadRegistry::Unregister(OnThreadRef{*this});
 #ifdef DEBUG
     // After ThreadRegistry::Unregister, other threads should not be able to

tools/profiler/core/ProfilerThreadRegistrationData.cpp

@@ -6,6 +6,8 @@
 
 #include "mozilla/ProfilerThreadRegistrationData.h"
 
+#include "mozilla/FOGIPC.h"
+#include "mozilla/glean/GleanMetrics.h"
 #include "mozilla/ProfilerMarkers.h"
 #include "js/AllocationRecording.h"
 #include "js/ProfilingStack.h"
@@ -17,6 +19,40 @@
 #  include <pthread.h>
 #endif
 
+#ifdef NIGHTLY_BUILD
+namespace geckoprofiler::markers {
+
+using namespace mozilla;
+
+struct ThreadCpuUseMarker {
+  static constexpr Span<const char> MarkerTypeName() {
+    return MakeStringSpan("ThreadCpuUse");
+  }
+  static void StreamJSONMarkerData(baseprofiler::SpliceableJSONWriter& aWriter,
+                                   ProfilerThreadId aThreadId,
+                                   int64_t aCpuTimeMs, int64_t aWakeUps,
+                                   const ProfilerString8View& aThreadName) {
+    aWriter.IntProperty("threadId", static_cast<int64_t>(aThreadId.ToNumber()));
+    aWriter.IntProperty("time", aCpuTimeMs);
+    aWriter.IntProperty("wakeups", aWakeUps);
+    aWriter.StringProperty("label", aThreadName);
+  }
+  static MarkerSchema MarkerTypeDisplay() {
+    using MS = MarkerSchema;
+    MS schema{MS::Location::MarkerChart, MS::Location::MarkerTable};
+    schema.AddKeyLabelFormat("time", "CPU Time", MS::Format::Milliseconds);
+    schema.AddKeyLabelFormat("wakeups", "Wake ups", MS::Format::Integer);
+    schema.SetTooltipLabel("{marker.name} - {marker.data.label}");
+    schema.SetTableLabel(
+        "{marker.name} - {marker.data.label}: {marker.data.time} of CPU time, "
+        "{marker.data.wakeups} wake ups");
+    return schema;
+  }
+};
+
+}  // namespace geckoprofiler::markers
+#endif
+
 namespace mozilla::profiler {
 
 ThreadRegistrationData::ThreadRegistrationData(const char* aName,
@@ -214,4 +250,59 @@ void ThreadRegistrationLockedRWOnThread::PollJSSampling() {
   }
 }
 
+#ifdef NIGHTLY_BUILD
+void ThreadRegistrationUnlockedConstReaderAndAtomicRW::RecordWakeCount() const {
+  baseprofiler::detail::BaseProfilerAutoLock lock(mRecordWakeCountMutex);
+
+  uint64_t newWakeCount = mWakeCount - mAlreadyRecordedWakeCount;
+  if (newWakeCount == 0 && mSleep != AWAKE) {
+    // If no new wake-up was counted, and the thread is not marked awake,
+    // we can be pretty sure there is no CPU activity to record.
+    // Threads that are never annotated as asleep/awake (typically rust threads)
+    // start as awake.
+    return;
+  }
+
+  uint64_t cpuTimeNs;
+  if (!GetCpuTimeSinceThreadStartInNs(&cpuTimeNs, PlatformDataCRef())) {
+    cpuTimeNs = 0;
+  }
+
+  constexpr uint64_t NS_PER_MS = 1'000'000;
+  uint64_t cpuTimeMs = cpuTimeNs / NS_PER_MS;
+
+  uint64_t newCpuTimeMs = MOZ_LIKELY(cpuTimeMs > mAlreadyRecordedCpuTimeInMs)
+                              ? cpuTimeMs - mAlreadyRecordedCpuTimeInMs
+                              : 0;
+
+  if (!newWakeCount && !newCpuTimeMs) {
+    // Nothing to report, avoid computing the Glean friendly thread name.
+    return;
+  }
+
+  nsAutoCString threadName(mInfo.Name());
+  // Trim the trailing number of threads that are part of a thread pool.
+  for (size_t length = threadName.Length(); length > 0; --length) {
+    const char c = threadName.CharAt(length - 1);
+    if ((c < '0' || c > '9') && c != '#' && c != ' ') {
+      if (length != threadName.Length()) {
+        threadName.SetLength(length);
+      }
+      break;
+    }
+  }
+
+  mozilla::glean::RecordThreadCpuUse(threadName, newCpuTimeMs, newWakeCount);
+
+  // The thread id is provided as part of the payload because this call is
+  // inside a ThreadRegistration data function, which could be invoked with
+  // the ThreadRegistry locked. We cannot call any function/option that could
+  // attempt to lock the ThreadRegistry again, like MarkerThreadId.
+  PROFILER_MARKER("Thread CPU use", OTHER, {}, ThreadCpuUseMarker,
+                  mInfo.ThreadId(), newCpuTimeMs, newWakeCount, threadName);
+  mAlreadyRecordedCpuTimeInMs = cpuTimeMs;
+  mAlreadyRecordedWakeCount += newWakeCount;
+}
+#endif
+
 }  // namespace mozilla::profiler

tools/profiler/core/platform.cpp

@@ -6490,6 +6490,15 @@ void profiler_record_wakeup_count(const nsACString& aProcessType) {
 
     previousThreadWakeCount += newWakeups;
   }
+
+#ifdef NIGHTLY_BUILD
+  ThreadRegistry::LockedRegistry lockedRegistry;
+  for (ThreadRegistry::OffThreadRef offThreadRef : lockedRegistry) {
+    const ThreadRegistry::UnlockedConstReaderAndAtomicRW& threadData =
+        offThreadRef.UnlockedConstReaderAndAtomicRWRef();
+    threadData.RecordWakeCount();
+  }
+#endif
 }
 
 void profiler_mark_thread_awake() {

tools/profiler/public/ProfilerThreadRegistrationData.h

@@ -40,6 +40,7 @@
 #include "js/ProfilingFrameIterator.h"
 #include "js/ProfilingStack.h"
 #include "mozilla/Atomics.h"
+#include "mozilla/BaseProfilerDetail.h"
 #include "mozilla/MemoryReporting.h"
 #include "mozilla/ProfilerThreadPlatformData.h"
 #include "mozilla/ProfilerThreadRegistrationInfo.h"
@@ -272,6 +273,14 @@ class ThreadRegistrationData {
   Atomic<int> mSleep{AWAKE};
   Atomic<uint64_t> mThreadCpuTimeInNsAtLastSleep{0};
 
+#ifdef NIGHTLY_BUILD
+  // The first wake is the thread creation.
+  Atomic<uint64_t, MemoryOrdering::Relaxed> mWakeCount{1};
+  mutable baseprofiler::detail::BaseProfilerMutex mRecordWakeCountMutex;
+  mutable uint64_t mAlreadyRecordedWakeCount = 0;
+  mutable uint64_t mAlreadyRecordedCpuTimeInMs = 0;
+#endif
+
   // Is this thread currently being profiled, and with which features?
   // Written from profiler, read from any thread.
   // Invariant: `!!mProfilingFeatures == !!mProfiledThreadData` (set together.)
@@ -339,6 +348,9 @@ class ThreadRegistrationUnlockedConstReaderAndAtomicRW
   void SetAwake() {
     MOZ_ASSERT(mSleep != AWAKE);
     mSleep = AWAKE;
+#ifdef NIGHTLY_BUILD
+    ++mWakeCount;
+#endif
   }
 
   // Returns the CPU time used by the thread since the previous call to this
@@ -355,6 +367,10 @@ class ThreadRegistrationUnlockedConstReaderAndAtomicRW
     return result;
   }
 
+#ifdef NIGHTLY_BUILD
+  void RecordWakeCount() const;
+#endif
+
   // This is called on every profiler restart. Put things that should happen
   // at that time here.
   void ReinitializeOnResume() {