From 257c2cbade3c1f1030a705f19ecce064f98b14be Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Florian=20Qu=C3=A8ze?= Date: Fri, 22 Apr 2022 06:20:51 +0000 Subject: [PATCH] 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 | 107 ++++++++++++- toolkit/components/glean/ipc/FOGIPC.h | 23 +++ toolkit/components/processtools/metrics.yaml | 140 ++++++++++++++++++ .../browser/browser_test_powerMetrics.js | 41 +++++ .../core/ProfilerThreadRegistration.cpp | 3 + .../core/ProfilerThreadRegistrationData.cpp | 89 +++++++++++ tools/profiler/core/platform.cpp | 9 ++ .../public/ProfilerThreadRegistrationData.h | 16 ++ 8 files changed, 424 insertions(+), 4 deletions(-) diff --git a/toolkit/components/glean/ipc/FOGIPC.cpp b/toolkit/components/glean/ipc/FOGIPC.cpp index ccce538081ba..fe692271fcd0 100644 --- a/toolkit/components/glean/ipc/FOGIPC.cpp +++ b/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; +static Atomic gCpuTimePerThreadMetric(nullptr); +static Atomic 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::max())) { + cpuTimeMetric->Get(threadName).Add(int32_t(aCpuTimeMs)); + } + + if (aWakeCount != 0 && + MOZ_LIKELY(aWakeCount < std::numeric_limits::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; } diff --git a/toolkit/components/glean/ipc/FOGIPC.h b/toolkit/components/glean/ipc/FOGIPC.h index ffff3915b227..3701f7183871 100644 --- a/toolkit/components/glean/ipc/FOGIPC.h +++ b/toolkit/components/glean/ipc/FOGIPC.h @@ -71,6 +71,29 @@ RefPtr FlushAndUseFOGData(); void TestTriggerMetrics(uint32_t processType, const RefPtr& 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 diff --git a/toolkit/components/processtools/metrics.yaml b/toolkit/components/processtools/metrics.yaml index f1bfe9076478..03f101e680b5 100644 --- a/toolkit/components/processtools/metrics.yaml +++ b/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 diff --git a/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js b/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js index d94b240a6124..22113b12daf2 100644 --- a/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js +++ b/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` + ); + } + } }); diff --git a/tools/profiler/core/ProfilerThreadRegistration.cpp b/tools/profiler/core/ProfilerThreadRegistration.cpp index 7dc29828e420..c81d00573daa 100644 --- a/tools/profiler/core/ProfilerThreadRegistration.cpp +++ b/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 diff --git a/tools/profiler/core/ProfilerThreadRegistrationData.cpp b/tools/profiler/core/ProfilerThreadRegistrationData.cpp index 00c26c9927b8..0edfc6b6560c 100644 --- a/tools/profiler/core/ProfilerThreadRegistrationData.cpp +++ b/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 #endif +#ifdef NIGHTLY_BUILD +namespace geckoprofiler::markers { + +using namespace mozilla; + +struct ThreadCpuUseMarker { + static constexpr Span 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(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,57 @@ void ThreadRegistrationLockedRWOnThread::PollJSSampling() { } } +#ifdef NIGHTLY_BUILD +void ThreadRegistrationUnlockedConstReaderAndAtomicRW::RecordWakeCount() const { + 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 diff --git a/tools/profiler/core/platform.cpp b/tools/profiler/core/platform.cpp index 185c258cb055..664007234c21 100644 --- a/tools/profiler/core/platform.cpp +++ b/tools/profiler/core/platform.cpp @@ -6475,6 +6475,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() { diff --git a/tools/profiler/public/ProfilerThreadRegistrationData.h b/tools/profiler/public/ProfilerThreadRegistrationData.h index 76ad26b77bb0..037b26c14165 100644 --- a/tools/profiler/public/ProfilerThreadRegistrationData.h +++ b/tools/profiler/public/ProfilerThreadRegistrationData.h @@ -272,6 +272,15 @@ class ThreadRegistrationData { Atomic mSleep{AWAKE}; Atomic mThreadCpuTimeInNsAtLastSleep{0}; +#ifdef NIGHTLY_BUILD + // The first wake is the thread creation. + Atomic mWakeCount{1}; + // mutable to allow writing to these fields when recording glean data, + // which only happens on a single thread. + 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() {