Bug 1747138 - Breakdown CPU and GPU time by process type, r=chutten,gsvelto

Differential Revision: https://phabricator.services.mozilla.com/D134441
This commit is contained in:
Florian Quèze 2022-02-03 20:37:21 +00:00
Родитель 257a6beb7b
Коммит f84ed84ce8
12 изменённых файлов: 520 добавлений и 34 удалений

Просмотреть файл

@ -81,6 +81,7 @@
#include "mozilla/EventQueue.h"
#include "mozilla/EventStateManager.h"
#include "mozilla/FlushType.h"
#include "mozilla/FOGIPC.h"
#include "mozilla/HTMLEditor.h"
#include "mozilla/HangAnnotations.h"
#include "mozilla/IMEStateManager.h"
@ -10117,8 +10118,14 @@ nsContentUtils::UserInteractionObserver::Observe(nsISupports* aSubject,
const char* aTopic,
const char16_t* aData) {
if (!strcmp(aTopic, kUserInteractionInactive)) {
if (sUserActive && XRE_IsParentProcess()) {
glean::RecordPowerMetrics();
}
sUserActive = false;
} else if (!strcmp(aTopic, kUserInteractionActive)) {
if (!sUserActive && XRE_IsParentProcess()) {
glean::RecordPowerMetrics();
}
sUserActive = true;
} else {
NS_WARNING("Unexpected observer notification");

Просмотреть файл

@ -2839,6 +2839,12 @@ mozilla::ipc::IPCResult ContentChild::RecvNotifyProcessPriorityChanged(
ProcessPriorityToString(mProcessPriority)),
ProfilerString8View::WrapNullTerminatedString(
ProcessPriorityToString(aPriority)));
// Record FOG data before the priority change.
// Ignore the change if it's the first time we set the process priority.
if (mProcessPriority != hal::PROCESS_PRIORITY_UNKNOWN) {
glean::RecordPowerMetrics();
}
mProcessPriority = aPriority;
os->NotifyObservers(static_cast<nsIPropertyBag2*>(props),

Просмотреть файл

@ -834,6 +834,8 @@ class ContentChild final : public PContentChild,
BrowsingContext* aStartingAt,
const DispatchBeforeUnloadToSubtreeResolver& aResolver);
hal::ProcessPriority GetProcessPriority() const { return mProcessPriority; }
private:
mozilla::ipc::IPCResult RecvFlushFOGData(FlushFOGDataResolver&& aResolver);

Просмотреть файл

@ -172,6 +172,7 @@ class ProcessPriorityManagerImpl final : public nsIObserver,
static void StaticInit();
static bool PrefsEnabled();
static void SetProcessPriorityIfEnabled(int aPid, ProcessPriority aPriority);
static bool TestMode();
NS_DECL_ISUPPORTS
@ -365,6 +366,17 @@ bool ProcessPriorityManagerImpl::PrefsEnabled() {
!StaticPrefs::dom_ipc_tabs_disabled();
}
/* static */
void ProcessPriorityManagerImpl::SetProcessPriorityIfEnabled(
int aPid, ProcessPriority aPriority) {
// The preference doesn't disable the process priority manager, but only its
// effect. This way the IPCs still happen and can be used to collect telemetry
// about CPU use.
if (PrefsEnabled()) {
hal::SetProcessPriority(aPid, aPriority);
}
}
/* static */
bool ProcessPriorityManagerImpl::TestMode() {
return StaticPrefs::dom_ipc_processPriorityManager_testMode();
@ -382,20 +394,13 @@ void ProcessPriorityManagerImpl::StaticInit() {
return;
}
// If IPC tabs aren't enabled at startup, don't bother with any of this.
if (!PrefsEnabled()) {
LOG("InitProcessPriorityManager bailing due to prefs.");
// Run StaticInit() again if the prefs change. We don't expect this to
// happen in normal operation, but it happens during testing.
if (!sPrefListenersRegistered) {
sPrefListenersRegistered = true;
Preferences::RegisterCallback(PrefChangedCallback,
"dom.ipc.processPriorityManager.enabled");
Preferences::RegisterCallback(PrefChangedCallback,
"dom.ipc.tabs.disabled");
}
return;
// Run StaticInit() again if the prefs change. We don't expect this to
// happen in normal operation, but it happens during testing.
if (!sPrefListenersRegistered) {
sPrefListenersRegistered = true;
Preferences::RegisterCallback(PrefChangedCallback,
"dom.ipc.processPriorityManager.enabled");
Preferences::RegisterCallback(PrefChangedCallback, "dom.ipc.tabs.disabled");
}
sInitialized = true;
@ -426,7 +431,7 @@ void ProcessPriorityManagerImpl::Init() {
// The parent process's priority never changes; set it here and then forget
// about it. We'll manage only subprocesses' priorities using the process
// priority manager.
hal::SetProcessPriority(getpid(), PROCESS_PRIORITY_PARENT_PROCESS);
SetProcessPriorityIfEnabled(getpid(), PROCESS_PRIORITY_PARENT_PROCESS);
nsCOMPtr<nsIObserverService> os = services::GetObserverService();
if (os) {
@ -762,8 +767,7 @@ void ParticularProcessPriorityManager::SetPriorityNow(
return;
}
if (!ProcessPriorityManagerImpl::PrefsEnabled() || !mContentParent ||
mPriority == aPriority) {
if (!mContentParent || mPriority == aPriority) {
return;
}
@ -794,7 +798,7 @@ void ParticularProcessPriorityManager::SetPriorityNow(
Telemetry::ScalarID::DOM_CONTENTPROCESS_OS_PRIORITY_LOWERED, 1);
}
hal::SetProcessPriority(Pid(), mPriority);
ProcessPriorityManagerImpl::SetProcessPriorityIfEnabled(Pid(), mPriority);
if (oldPriority != mPriority) {
ProcessPriorityManagerImpl::GetSingleton()->NotifyProcessPriorityChanged(

Просмотреть файл

@ -14,6 +14,9 @@ add_task(async function setupTestingPref() {
});
});
const ALL_SCALAR = "media.video_hardware_decoding_support";
const HD_SCALAR = "media.video_hd_hardware_decoding_support";
add_task(async function testVideoCodecs() {
// There are still other video codecs, but we only care about these popular
// codec types.
@ -24,8 +27,6 @@ add_task(async function testVideoCodecs() {
{ fileName: "av1.mp4", type: "video/av1" },
{ fileName: "bunny_hd_5s.mp4", type: "video/avc", hd: true },
];
const ALL_SCALAR = "media.video_hardware_decoding_support";
const HD_SCALAR = "media.video_hd_hardware_decoding_support";
for (const file of testFiles) {
const { fileName, type, hd } = file;
@ -76,7 +77,12 @@ add_task(async function testAudioCodecs() {
await audio.play();
let snapshot = Services.telemetry.getSnapshotForKeyedScalars("main", false)
.parent;
ok(!snapshot, `Did not record scalar for ${file}`);
ok(
!snapshot ||
(!snapshot.hasOwnProperty(ALL_SCALAR) &&
!snapshot.hasOwnProperty(HD_SCALAR)),
`Did not record scalar for ${file}`
);
audio.src = "";
}
});

Просмотреть файл

@ -6,6 +6,7 @@
#include "Hal.h"
#include "base/process_util.h"
#include "mozilla/FOGIPC.h"
#include "mozilla/HalWakeLock.h"
#include "mozilla/Services.h"
#include "mozilla/StaticPtr.h"
@ -199,6 +200,14 @@ void ModifyWakeLock(const nsAString& aTopic, hal::WakeLockControl aLockAdjust,
WakeLockState oldState =
ComputeWakeLockState(totalCount.numLocks, totalCount.numHidden);
if (ComputeWakeLockState(totalCount.numLocks + aLockAdjust,
totalCount.numHidden + aHiddenAdjust) != oldState &&
(aTopic.Equals(u"video-playing"_ns) ||
aTopic.Equals(u"audio-playing"_ns))) {
glean::RecordPowerMetrics();
}
bool processWasLocked = processCount.numLocks > 0;
processCount.numLocks += aLockAdjust;
@ -235,6 +244,13 @@ void GetWakeLockInfo(const nsAString& aTopic,
return;
}
if (!sLockTable) {
// This can happen during some gtests.
NS_WARNING("Attempting to get wake lock information before initialization");
*aWakeLockInfo = WakeLockInformation();
return;
}
ProcessLockTable* table = sLockTable->Get(aTopic);
if (!table) {
*aWakeLockInfo = WakeLockInfoFromLockCount(aTopic, LockCount());

Просмотреть файл

@ -14,6 +14,7 @@
#include "mozilla/gfx/GPUChild.h"
#include "mozilla/gfx/GPUParent.h"
#include "mozilla/gfx/GPUProcessManager.h"
#include "mozilla/Hal.h"
#include "mozilla/MozPromise.h"
#include "mozilla/net/SocketProcessChild.h"
#include "mozilla/net/SocketProcessParent.h"
@ -43,15 +44,68 @@ using FlushFOGDataPromise = mozilla::dom::ContentParent::FlushFOGDataPromise;
namespace mozilla {
namespace glean {
static void RecordPowerMetrics() {
void RecordPowerMetrics() {
static uint64_t previousCpuTime = 0, previousGpuTime = 0;
uint64_t cpuTime;
uint64_t cpuTime, newCpuTime = 0;
if (NS_SUCCEEDED(GetCpuTimeSinceProcessStartInMs(&cpuTime)) &&
cpuTime > previousCpuTime) {
uint64_t newCpuTime = cpuTime - previousCpuTime;
previousCpuTime += newCpuTime;
newCpuTime = cpuTime - previousCpuTime;
}
uint64_t gpuTime, newGpuTime = 0;
if (NS_SUCCEEDED(GetGpuTimeSinceProcessStartInMs(&gpuTime)) &&
gpuTime > previousGpuTime) {
newGpuTime = gpuTime - previousGpuTime;
}
if (!newCpuTime && !newGpuTime) {
// Nothing to record.
return;
}
// Compute the process type string.
nsAutoCString type(XRE_GetProcessTypeString());
if (XRE_IsContentProcess()) {
auto* cc = dom::ContentChild::GetSingleton();
if (cc) {
type.Assign(dom::RemoteTypePrefix(cc->GetRemoteType()));
if (StringBeginsWith(type, WEB_REMOTE_TYPE)) {
type.AssignLiteral("web");
switch (cc->GetProcessPriority()) {
case hal::PROCESS_PRIORITY_BACKGROUND:
type.AppendLiteral(".background");
break;
case hal::PROCESS_PRIORITY_FOREGROUND:
type.AppendLiteral(".foreground");
break;
case hal::PROCESS_PRIORITY_BACKGROUND_PERCEIVABLE:
type.AppendLiteral(".background-perceivable");
break;
default:
break;
}
}
}
} else if (XRE_IsParentProcess()) {
if (nsContentUtils::GetUserIsInteracting()) {
type.AssignLiteral("parent.active");
} else {
type.AssignLiteral("parent.inactive");
}
hal::WakeLockInformation info;
GetWakeLockInfo(u"video-playing"_ns, &info);
if (info.numLocks() != 0 && info.numHidden() < info.numLocks()) {
type.AppendLiteral(".playing-video");
} else {
GetWakeLockInfo(u"audio-playing"_ns, &info);
if (info.numLocks()) {
type.AppendLiteral(".playing-audio");
}
}
}
if (newCpuTime) {
// The counters are reset at least once a day. Assuming all cores are used
// continuously, an int32 can hold the data for 24.85 cores.
// This should be fine for now, but may overflow in the future.
@ -61,19 +115,18 @@ static void RecordPowerMetrics() {
nNewCpuTime = std::numeric_limits<int32_t>::max();
}
power::total_cpu_time_ms.Add(nNewCpuTime);
power::cpu_time_per_process_type_ms.Get(type).Add(nNewCpuTime);
previousCpuTime += newCpuTime;
}
uint64_t gpuTime;
if (NS_SUCCEEDED(GetGpuTimeSinceProcessStartInMs(&gpuTime)) &&
gpuTime > previousGpuTime) {
uint64_t newGpuTime = gpuTime - previousGpuTime;
previousGpuTime += newGpuTime;
if (newGpuTime) {
int32_t nNewGpuTime = int32_t(newGpuTime);
if (newGpuTime > std::numeric_limits<int32_t>::max()) {
nNewGpuTime = std::numeric_limits<int32_t>::max();
}
power::total_gpu_time_ms.Add(int32_t(nNewGpuTime));
power::total_gpu_time_ms.Add(nNewGpuTime);
power::gpu_time_per_process_type_ms.Get(type).Add(nNewGpuTime);
previousGpuTime += newGpuTime;
}
}

Просмотреть файл

@ -71,6 +71,8 @@ RefPtr<GenericPromise> FlushAndUseFOGData();
void TestTriggerMetrics(uint32_t processType,
const RefPtr<dom::Promise>& promise);
void RecordPowerMetrics();
} // namespace glean
} // namespace mozilla

Просмотреть файл

@ -13,6 +13,55 @@
$schema: moz://mozilla.org/schemas/glean/metrics/2-0-0
power:
cpu_time_per_process_type_ms:
type: labeled_counter
description: >
CPU time used by each process type in ms.
bugs:
- https://bugzilla.mozilla.org/show_bug.cgi?id=1747138
data_reviews:
- https://bugzilla.mozilla.org/show_bug.cgi?id=1747138
data_sensitivity:
- technical
notification_emails:
- florian@mozilla.com
expires: never
labels: &per_process_type_labels
- parent.active
- parent.active.playing-audio
- parent.active.playing-video
- parent.inactive
- parent.inactive.playing-audio
- parent.inactive.playing-video
- prealloc
- privilegedabout
- rdd
- socket
- web.background
- web.background-perceivable
- web.foreground
- extension
- gpu
- gmplugin
- utility
telemetry_mirror: POWER_CPU_TIME_PER_PROCESS_TYPE_MS
gpu_time_per_process_type_ms:
type: labeled_counter
description: >
GPU time used by each process type in ms.
bugs:
- https://bugzilla.mozilla.org/show_bug.cgi?id=1747138
data_reviews:
- https://bugzilla.mozilla.org/show_bug.cgi?id=1747138
data_sensitivity:
- technical
notification_emails:
- florian@mozilla.com
expires: never
labels: *per_process_type_labels
telemetry_mirror: POWER_GPU_TIME_PER_PROCESS_TYPE_MS
total_cpu_time_ms:
type: counter
description: >
@ -46,5 +95,3 @@ power:
- florian@mozilla.com
expires: never
telemetry_mirror: POWER_TOTAL_GPU_TIME_MS
no_lint:
- COMMON_PREFIX

Просмотреть файл

@ -5,5 +5,6 @@ prefs=
support-files =
dummy.html
[browser_test_powerMetrics.js]
[browser_test_procinfo.js]
skip-if = (ccov && os == "linux") # https://bugzilla.mozilla.org/show_bug.cgi?id=1608080

Просмотреть файл

@ -0,0 +1,290 @@
/* Any copyright is dedicated to the Public Domain.
* http://creativecommons.org/publicdomain/zero/1.0/ */
"use strict";
/**
* Return a web-based URL for a given file based on the testing directory.
* @param {String} fileName
* file that caller wants its web-based url
*/
function GetTestWebBasedURL(fileName) {
return (
getRootDirectory(gTestPath).replace(
"chrome://mochitests/content",
"http://example.org"
) + fileName
);
}
const kNS_PER_MS = 1000000;
function printProcInfo(procInfo) {
info(
` pid: ${procInfo.pid}, type = parent, cpu time = ${procInfo.cpuTime /
kNS_PER_MS}ms`
);
for (let child of procInfo.children) {
info(
` pid: ${child.pid}, type = ${child.type}, cpu time = ${child.cpuTime /
kNS_PER_MS}ms`
);
}
}
// It would be nice to have an API to list all the statically defined labels of
// a labeled_counter. Hopefully bug 1672273 will help with this.
const kGleanProcessTypeLabels = [
"parent.active",
"parent.active.playing-audio",
"parent.active.playing-video",
"parent.inactive",
"parent.inactive.playing-audio",
"parent.inactive.playing-video",
"prealloc",
"privilegedabout",
"rdd",
"socket",
"web.background",
"web.background-perceivable",
"web.foreground",
"extension",
"gpu",
"gmplugin",
"utility",
"__other__",
];
async function getChildCpuTime(pid) {
return (await ChromeUtils.requestProcInfo()).children.find(p => p.pid == pid)
.cpuTime;
}
add_task(async () => {
// Temporarily open a new foreground tab to make the current tab a background
// tab, and burn some CPU time in it while it's in the background.
const kBusyWaitForMs = 50;
let cpuTimeSpentOnBackgroundTab;
let firstBrowser = gBrowser.selectedTab.linkedBrowser;
let processPriorityChangedPromise = BrowserTestUtils.contentTopicObserved(
firstBrowser.browsingContext,
"ipc:process-priority-changed"
);
await BrowserTestUtils.withNewTab(
GetTestWebBasedURL("dummy.html"),
async () => {
await processPriorityChangedPromise;
// We can't be sure that a busy loop lasting for a specific duration
// will use the same amount of CPU time, as that would require a core
// to be fully available for our busy loop, which is unlikely on single
// core hardware.
// To be able to have a predictable amount of CPU time used, we need to
// check using ChromeUtils.requestProcInfo how much CPU time has actually
// been spent.
let pid = firstBrowser.frameLoader.remoteTab.osPid;
let initalCpuTime = await getChildCpuTime(pid);
let afterCpuTime;
do {
await SpecialPowers.spawn(
firstBrowser,
[kBusyWaitForMs],
async kBusyWaitForMs => {
let startTime = Date.now();
while (Date.now() - startTime < 10) {
// Burn CPU time...
}
}
);
afterCpuTime = await getChildCpuTime(pid);
} while (afterCpuTime - initalCpuTime < kBusyWaitForMs * kNS_PER_MS);
cpuTimeSpentOnBackgroundTab = Math.floor(
(afterCpuTime - initalCpuTime) / kNS_PER_MS
);
}
);
let beforeProcInfo = await ChromeUtils.requestProcInfo();
await Services.fog.testFlushAllChildren();
let cpuTimeByType = {},
gpuTimeByType = {};
for (let label of kGleanProcessTypeLabels) {
cpuTimeByType[label] = Glean.power.cpuTimePerProcessTypeMs[
label
].testGetValue();
gpuTimeByType[label] = Glean.power.gpuTimePerProcessTypeMs[
label
].testGetValue();
}
let totalCpuTime = Glean.power.totalCpuTimeMs.testGetValue();
let totalGpuTime = Glean.power.totalGpuTimeMs.testGetValue();
let afterProcInfo = await ChromeUtils.requestProcInfo();
info("CPU time from ProcInfo before calling testFlushAllChildren:");
printProcInfo(beforeProcInfo);
info("CPU time for each label:");
let totalCpuTimeByType = 0;
for (let label of kGleanProcessTypeLabels) {
totalCpuTimeByType += cpuTimeByType[label] ?? 0;
info(` ${label} = ${cpuTimeByType[label]}`);
}
info("CPU time from ProcInfo after calling testFlushAllChildren:");
printProcInfo(afterProcInfo);
Assert.equal(
totalCpuTimeByType,
totalCpuTime,
"The sum of CPU time used by all process types should match totalCpuTimeMs"
);
// In infra the parent process time will be reported as parent.inactive,
// but when running the test locally the user might move the mouse a bit.
let parentTime =
(cpuTimeByType["parent.active"] || 0) +
(cpuTimeByType["parent.inactive"] || 0);
Assert.greaterOrEqual(
parentTime,
Math.floor(beforeProcInfo.cpuTime / kNS_PER_MS),
"reported parent cpu time should be at least what the first requestProcInfo returned"
);
Assert.lessOrEqual(
parentTime,
Math.ceil(afterProcInfo.cpuTime / kNS_PER_MS),
"reported parent cpu time should be at most what the second requestProcInfo returned"
);
kGleanProcessTypeLabels
.filter(label => label.startsWith("parent.") && label.includes(".playing-"))
.forEach(label => {
Assert.strictEqual(
cpuTimeByType[label],
undefined,
`no media was played so the CPU time for ${label} should be undefined`
);
});
if (beforeProcInfo.children.some(p => p.type == "preallocated")) {
Assert.greaterOrEqual(
cpuTimeByType.prealloc,
Math.floor(
beforeProcInfo.children.reduce(
(time, p) => time + (p.type == "preallocated" ? p.cpuTime : 0),
0
) / kNS_PER_MS
),
"reported cpu time for preallocated content processes should be at least the sum of what the first requestProcInfo returned."
);
// We can't compare with the values returned by the second requestProcInfo
// call because one preallocated content processes has been turned into
// a normal content process when we opened a tab.
} else {
info(
"no preallocated content process existed when we started our test, but some might have existed before"
);
}
if (beforeProcInfo.children.some(p => p.type == "privilegedabout")) {
Assert.greaterOrEqual(
cpuTimeByType.privilegedabout,
1,
"we used some CPU time in a foreground tab, but don't know how much as the process might have started as preallocated"
);
}
for (let label of [
"rdd",
"socket",
"extension",
"gpu",
"gmplugin",
"utility",
]) {
if (!kGleanProcessTypeLabels.includes(label)) {
Assert.ok(
false,
`coding error in the test, ${label} isn't part of ${kGleanProcessTypeLabels.join(
", "
)}`
);
}
if (beforeProcInfo.children.some(p => p.type == label)) {
Assert.greaterOrEqual(
cpuTimeByType[label],
Math.floor(
beforeProcInfo.children.find(p => p.type == label).cpuTime /
kNS_PER_MS
),
"reported cpu time for " +
label +
" process should be at least what the first requestProcInfo returned."
);
Assert.lessOrEqual(
cpuTimeByType[label],
Math.ceil(
afterProcInfo.children.find(p => p.type == label).cpuTime / kNS_PER_MS
),
"reported cpu time for " +
label +
" process should be at most what the second requestProcInfo returned."
);
} else {
info(
"no " +
label +
" process existed when we started our test, but some might have existed before"
);
}
}
Assert.greaterOrEqual(
cpuTimeByType["web.background"],
cpuTimeSpentOnBackgroundTab,
"web.background should be at least the time we spent."
);
Assert.greaterOrEqual(
cpuTimeByType["web.foreground"],
1,
"we used some CPU time in a foreground tab, but don't know how much"
);
// We only have web.background-perceivable CPU time if a muted video was
// played in a background tab.
Assert.strictEqual(
cpuTimeByType["web.background-perceivable"],
undefined,
"CPU time should only be recorded in the web.background-perceivable label"
);
// __other__ should be undefined, if it is not, we have a missing label in the metrics.yaml file.
Assert.strictEqual(
cpuTimeByType.__other__,
undefined,
"no CPU time should be recorded in the __other__ label"
);
info("GPU time for each label:");
let totalGpuTimeByType = undefined;
for (let label of kGleanProcessTypeLabels) {
if (gpuTimeByType[label] !== undefined) {
totalGpuTimeByType = (totalGpuTimeByType || 0) + gpuTimeByType[label];
}
info(` ${label} = ${gpuTimeByType[label]}`);
}
Assert.equal(
totalGpuTimeByType,
totalGpuTime,
"The sum of GPU time used by all process types should match totalGpuTimeMs"
);
// __other__ should be undefined, if it is not, we have a missing label in the metrics.yaml file.
Assert.strictEqual(
gpuTimeByType.__other__,
undefined,
"no GPU time should be recorded in the __other__ label"
);
});

Просмотреть файл

@ -7414,6 +7414,58 @@ contextual.services.quicksuggest:
- main
power:
cpu_time_per_process_type_ms:
bug_numbers:
- 1747138
description: >
CPU time used by each process type in ms.
expires: never
kind: uint
notification_emails:
- florian@mozilla.com
release_channel_collection: opt-out
products:
- 'firefox'
record_in_processes:
- 'all'
keyed: true
keys: &per_process_type_keys
- parent.active
- parent.active.playing-audio
- parent.active.playing-video
- parent.inactive
- parent.inactive.playing-audio
- parent.inactive.playing-video
- prealloc
- privilegedabout
- rdd
- socket
- web.background
- web.background-perceivable
- web.foreground
- extension
- gpu
- gmplugin
- utility
gpu_time_per_process_type_ms:
bug_numbers:
- 1747138
description: >
GPU time used by each process type in ms.
expires: never
kind: uint
notification_emails:
- florian@mozilla.com
release_channel_collection: opt-out
products:
- 'firefox'
record_in_processes:
- 'main'
- 'gpu'
keyed: true
keys: *per_process_type_keys
total_cpu_time_ms:
bug_numbers:
- 1736040