Bug 1867599 - Add profiler logging method to JS tracer r=devtools-reviewers,nchevobbe

Differential Revision: https://phabricator.services.mozilla.com/D190576
This commit is contained in:
Nazım Can Altınova 2023-12-04 13:57:23 +00:00
Родитель 60bdcaa0eb
Коммит 6f156b8ec4
7 изменённых файлов: 443 добавлений и 52 удалений

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

@ -204,6 +204,17 @@ loader.lazyRequireGetter(
"resource://devtools/client/shared/source-map-loader/index.js",
true
);
loader.lazyRequireGetter(
this,
"openProfilerTab",
"resource://devtools/client/performance-new/shared/browser.js",
true
);
loader.lazyGetter(this, "ProfilerBackground", () => {
return ChromeUtils.import(
"resource://devtools/client/performance-new/shared/background.jsm.js"
);
});
/**
* A "Toolbox" is the component that holds all the tools for one specific
@ -656,6 +667,29 @@ Toolbox.prototype = {
}
},
/**
* Called on each new TRACING_STATE resource
*
* @param {Object} resource The TRACING_STATE resource
*/
async _onTracingStateChanged(resource) {
const { profile } = resource;
if (!profile) {
return;
}
const browser = await openProfilerTab();
const profileCaptureResult = {
type: "SUCCESS",
profile,
};
ProfilerBackground.registerProfileCaptureForBrowser(
browser,
profileCaptureResult,
null
);
},
/**
* Be careful, this method is synchronous, but highlightTool, raise, selectTool
* are all async.
@ -886,6 +920,15 @@ Toolbox.prototype = {
this.resourceCommand.TYPES.THREAD_STATE,
];
if (
Services.prefs.getBoolPref(
"devtools.debugger.features.javascript-tracing",
false
)
) {
watchedResources.push(this.resourceCommand.TYPES.TRACING_STATE);
}
if (!this.isBrowserToolbox) {
// Independently of watching network event resources for the error count icon,
// we need to start tracking network activity on toolbox open for targets such
@ -4701,6 +4744,9 @@ Toolbox.prototype = {
if (resourceType == TYPES.THREAD_STATE) {
this._onThreadStateChanged(resource);
}
if (resourceType == TYPES.TRACING_STATE) {
this._onTracingStateChanged(resource);
}
}
this.setErrorCount(errors);

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

@ -460,6 +460,11 @@ webconsole.message.commands.startTracingToWebConsole=Started tracing to Web Cons
# Label displayed when :trace command was executed and the JavaScript tracer started to log to stdout.
webconsole.message.commands.startTracingToStdout=Started tracing to stdout
# LOCALIZATION NOTE (webconsole.message.commands.startTracingToProfiler)
# Label displayed when :trace command was executed and the JavaScript tracer will open the profiler showing all the traces,
# but only on stop.
webconsole.message.commands.startTracingToProfiler=Started tracing to the Profiler. The traces will be displayed in the profiler on stop.
# LOCALIZATION NOTE (webconsole.message.commands.stopTracing)
# Label displayed when :trace command was executed and the JavaScript tracer stopped.
webconsole.message.commands.stopTracing=Stopped tracing

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

@ -375,6 +375,10 @@ function handleHelperResult(response) {
message = l10n.getStr(
"webconsole.message.commands.startTracingToWebConsole"
);
} else if (logMethod == "profiler") {
message = l10n.getStr(
"webconsole.message.commands.startTracingToProfiler"
);
} else {
throw new Error(`Unsupported tracer log method ${logMethod}`);
}

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

@ -16,6 +16,8 @@ const {
removeTracingListener,
} = require("resource://devtools/server/tracer/tracer.jsm");
const { LOG_METHODS } = require("resource://devtools/server/actors/tracer.js");
class TracingStateWatcher {
/**
* Start watching for tracing state changes for a given target actor.
@ -49,12 +51,16 @@ class TracingStateWatcher {
// When Javascript tracing is enabled or disabled.
onTracingToggled(enabled) {
const tracerActor = this.targetActor.getTargetScopedActor("tracer");
const logMethod = tracerActor?.getLogMethod() | "stdout";
const logMethod = tracerActor?.getLogMethod();
this.onAvailable([
{
resourceType: TRACING_STATE,
enabled,
logMethod,
profile:
logMethod == LOG_METHODS.PROFILER && !enabled
? tracerActor.getProfile()
: undefined,
},
]);
}

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

@ -24,10 +24,19 @@ const {
getResourceWatcher,
} = require("resource://devtools/server/actors/resources/index.js");
loader.lazyRequireGetter(
this,
"GeckoProfileCollector",
"resource://devtools/server/actors/utils/gecko-profile-collector.js",
true
);
const LOG_METHODS = {
STDOUT: "stdout",
CONSOLE: "console",
PROFILER: "profiler",
};
exports.LOG_METHODS = LOG_METHODS;
const VALID_LOG_METHODS = Object.values(LOG_METHODS);
const CONSOLE_ARGS_STYLES = [
@ -61,6 +70,8 @@ class TracerActor extends Actor {
this.flushConsoleMessages.bind(this),
CONSOLE_THROTTLING_DELAY
);
this.geckoProfileCollector = new GeckoProfileCollector();
}
destroy() {
@ -84,24 +95,7 @@ class TracerActor extends Actor {
*/
toggleTracing(options) {
if (!this.tracingListener) {
if (options.logMethod && !VALID_LOG_METHODS.includes(options.logMethod)) {
throw new Error(
`Invalid log method '${options.logMethod}'. Only supports: ${VALID_LOG_METHODS}`
);
}
if (options.prefix && typeof options.prefix != "string") {
throw new Error("Invalid prefix, only support string type");
}
this.logMethod = options.logMethod || LOG_METHODS.STDOUT;
this.tracingListener = {
onTracingFrame: this.onTracingFrame.bind(this),
onTracingInfiniteLoop: this.onTracingInfiniteLoop.bind(this),
};
addTracingListener(this.tracingListener);
startTracing({
global: this.targetActor.window || this.targetActor.workerGlobal,
prefix: options.prefix || "",
});
this.#startTracing(options);
return true;
}
this.stopTracing();
@ -109,7 +103,24 @@ class TracerActor extends Actor {
}
startTracing(logMethod = LOG_METHODS.STDOUT) {
this.logMethod = logMethod;
this.#startTracing({ logMethod });
}
#startTracing(options) {
if (options.logMethod && !VALID_LOG_METHODS.includes(options.logMethod)) {
throw new Error(
`Invalid log method '${options.logMethod}'. Only supports: ${VALID_LOG_METHODS}`
);
}
if (options.prefix && typeof options.prefix != "string") {
throw new Error("Invalid prefix, only support string type");
}
this.logMethod = options.logMethod || LOG_METHODS.STDOUT;
if (this.logMethod == LOG_METHODS.PROFILER) {
this.geckoProfileCollector.start();
}
this.tracingListener = {
onTracingFrame: this.onTracingFrame.bind(this),
onTracingInfiniteLoop: this.onTracingInfiniteLoop.bind(this),
@ -117,6 +128,7 @@ class TracerActor extends Actor {
addTracingListener(this.tracingListener);
startTracing({
global: this.targetActor.window || this.targetActor.workerGlobal,
prefix: options.prefix || "",
// Enable receiving the `currentDOMEvent` being passed to `onTracingFrame`
traceDOMEvents: true,
});
@ -132,10 +144,28 @@ class TracerActor extends Actor {
this.tracingListener = null;
}
/**
* Queried by THREAD_STATE watcher to send the gecko profiler data
* as part of THREAD STATE "stop" resource.
*
* @return {Object} Gecko profiler profile object.
*/
getProfile() {
const profile = this.geckoProfileCollector.stop();
// We only open the profile if it contains samples, otherwise it can crash the frontend.
if (profile.threads[0].samples.data.length) {
return profile;
}
return null;
}
onTracingInfiniteLoop() {
if (this.logMethod == LOG_METHODS.STDOUT) {
return true;
}
if (this.logMethod == LOG_METHODS.PROFILER) {
this.geckoProfileCollector.stop();
}
const consoleMessageWatcher = getResourceWatcher(
this.targetActor,
TYPES.CONSOLE_MESSAGE
@ -210,47 +240,61 @@ class TracerActor extends Actor {
return true;
}
// We may receive the currently processed DOM event (if this relates to one).
// In this case, log a preliminary message, which looks different to highlight it.
if (currentDOMEvent && depth == 0) {
const DOMEventArgs = [prefix + "—", currentDOMEvent];
if (this.logMethod == LOG_METHODS.CONSOLE) {
// We may receive the currently processed DOM event (if this relates to one).
// In this case, log a preliminary message, which looks different to highlight it.
if (currentDOMEvent && depth == 0) {
const DOMEventArgs = [prefix + "—", currentDOMEvent];
// Create a message object that fits Console Message Watcher expectations
this.throttledConsoleMessages.push({
arguments: DOMEventArgs,
styles: DOM_EVENT_CONSOLE_ARGS_STYLES,
level: "logTrace",
chromeContext: this.isChromeContext,
timeStamp: ChromeUtils.dateNow(),
});
}
const args = [
"—".repeat(depth + 1),
frame.implementation,
"⟶",
formatedDisplayName,
];
// Avoid logging an empty string as console.log would expand it to <empty string>
if (prefix) {
args.unshift(prefix);
}
// Create a message object that fits Console Message Watcher expectations
this.throttledConsoleMessages.push({
arguments: DOMEventArgs,
styles: DOM_EVENT_CONSOLE_ARGS_STYLES,
filename: url,
lineNumber,
columnNumber: columnNumber - columnBase,
arguments: args,
// As we log different number of arguments with/without prefix, use distinct styles
styles: prefix ? CONSOLE_ARGS_STYLES_WITH_PREFIX : CONSOLE_ARGS_STYLES,
level: "logTrace",
chromeContext: this.isChromeContext,
sourceId: script.source.id,
timeStamp: ChromeUtils.dateNow(),
});
this.throttleLogMessages();
} else if (this.logMethod == LOG_METHODS.PROFILER) {
this.geckoProfileCollector.addSample(
{
// formatedDisplayName has a lambda at the beginning, remove it.
name: formatedDisplayName.replace("λ ", ""),
url,
lineNumber,
columnNumber,
category: frame.implementation,
},
depth
);
}
const args = [
"—".repeat(depth + 1),
frame.implementation,
"⟶",
formatedDisplayName,
];
// Avoid logging an empty string as console.log would expand it to <empty string>
if (prefix) {
args.unshift(prefix);
}
// Create a message object that fits Console Message Watcher expectations
this.throttledConsoleMessages.push({
filename: url,
lineNumber,
columnNumber: columnNumber - columnBase,
arguments: args,
// As we log different number of arguments with/without prefix, use distinct styles
styles: prefix ? CONSOLE_ARGS_STYLES_WITH_PREFIX : CONSOLE_ARGS_STYLES,
level: "logTrace",
chromeContext: this.isChromeContext,
sourceId: script.source.id,
timeStamp: ChromeUtils.dateNow(),
});
this.throttleLogMessages();
return false;
}

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

@ -0,0 +1,285 @@
/* This Source Code Form is subject to the terms of the Mozilla Public
* License, v. 2.0. If a copy of the MPL was not distributed with this
* file, You can obtain one at http://mozilla.org/MPL/2.0/. */
"use strict";
// The fallback color for unexpected cases
const DEFAULT_COLOR = "grey";
// The default category for unexpected cases
const DEFAULT_CATEGORIES = [
{
name: "Mixed",
color: DEFAULT_COLOR,
subcategories: ["Other"],
},
];
// Color for each type of category/frame's implementation
const PREDEFINED_COLORS = {
interpreter: "yellow",
baseline: "orange",
ion: "blue",
wasm: "purple",
};
/**
* Utility class that collects the JS tracer data and converts it to a Gecko
* profile object.
*/
class GeckoProfileCollector {
#thread = null;
#stackMap = new Map();
#frameMap = new Map();
#categories = DEFAULT_CATEGORIES;
#currentStack = [];
#time = 0;
/**
* Initialize the profiler and be ready to receive samples.
*/
start() {
this.#reset();
this.#thread = this.#getEmptyThread();
}
/**
* Stop the record and return the gecko profiler data.
*
* @return {Object}
* The Gecko profile object.
*/
stop() {
// Create the profile to return.
const profile = this.#getEmptyProfile();
profile.meta.categories = this.#categories;
profile.threads.push(this.#thread);
// Cleanup.
this.#reset();
return profile;
}
/**
* Clear all the internal state of this class.
*/
#reset() {
this.#thread = null;
this.#stackMap = new Map();
this.#frameMap = new Map();
this.#categories = DEFAULT_CATEGORIES;
this.#currentStack = [];
this.#time = 0;
}
/**
* Initialize an empty Gecko profile object.
*
* @return {Object}
* Gecko profile object.
*/
#getEmptyProfile() {
const httpHandler = Cc[
"@mozilla.org/network/protocol;1?name=http"
].getService(Ci.nsIHttpProtocolHandler);
return {
meta: {
// Currently interval is 1, but we could change it to a lower number
// when we have durations coming from js tracer.
interval: 1,
startTime: 0,
product: Services.appinfo.name,
importedFrom: "JS Tracer",
version: 28,
presymbolicated: true,
abi: Services.appinfo.XPCOMABI,
misc: httpHandler.misc,
oscpu: httpHandler.oscpu,
platform: httpHandler.platform,
processType: Services.appinfo.processType,
categories: [],
stackwalk: 0,
toolkit: Services.appinfo.widgetToolkit,
appBuildID: Services.appinfo.appBuildID,
sourceURL: Services.appinfo.sourceURL,
physicalCPUs: 0,
logicalCPUs: 0,
CPUName: "",
markerSchema: [],
},
libs: [],
pages: [],
threads: [],
processes: [],
};
}
/**
* Generate a thread object to be stored in the Gecko profile object.
*/
#getEmptyThread() {
return {
processType: "default",
processStartupTime: 0,
processShutdownTime: null,
registerTime: 0,
unregisterTime: null,
pausedRanges: [],
name: "GeckoMain",
"eTLD+1": "JS Tracer",
isMainThread: true,
pid: Services.appinfo.processID,
tid: 0,
samples: {
schema: {
stack: 0,
time: 1,
eventDelay: 2,
},
data: [],
},
markers: {
schema: {
name: 0,
startTime: 1,
endTime: 2,
phase: 3,
category: 4,
data: 5,
},
data: [],
},
stackTable: {
schema: {
prefix: 0,
frame: 1,
},
data: [],
},
frameTable: {
schema: {
location: 0,
relevantForJS: 1,
innerWindowID: 2,
implementation: 3,
line: 4,
column: 5,
category: 6,
subcategory: 7,
},
data: [],
},
stringTable: [],
};
}
/**
* Record a new sample to be stored in the Gecko profile object.
*
* @param {Object} frame
* Object describing a frame with following attributes:
* - {String} name
* Human readable name for this frame.
* - {String} url
* URL of the running script.
* - {Number} lineNumber
* Line currently executing for this script.
* - {Number} columnNumber
* Column currently executing for this script.
* - {String} category
* Which JS implementation is being used for this frame: interpreter, baseline, ion or wasm.
* See Debugger.frame.implementation.
*/
addSample(frame, depth) {
const currentDepth = this.#currentStack.length;
if (currentDepth == depth) {
// We are in the same depth and executing another frame. Replace the
// current frame with the new one.
this.#currentStack[currentDepth] = frame;
} else if (currentDepth < depth) {
// We are going deeper in the stack. Push the new frame.
this.#currentStack.push(frame);
} else {
// We are going back in the stack. Pop frames until we reach the right depth.
this.#currentStack.length = depth;
this.#currentStack[depth] = frame;
}
const stack = this.#currentStack.reduce((prefix, stackFrame) => {
const frameIndex = this.#getOrCreateFrame(stackFrame);
return this.#getOrCreateStack(frameIndex, prefix);
}, null);
this.#thread.samples.data.push([
stack,
// We put simply 1 sample (1ms) for each frame. We can change it in the
// future if we can get the duration of the frame.
this.#time++,
0, // eventDelay
]);
}
#getOrCreateFrame(frame) {
const { frameTable, stringTable } = this.#thread;
const frameString = `${frame.name}:${frame.url}:${frame.lineNumber}:${frame.columnNumber}:${frame.category}`;
let frameIndex = this.#frameMap.get(frameString);
if (frameIndex === undefined) {
frameIndex = frameTable.data.length;
const location = stringTable.length;
// Profiler frontend except a particular string to match the source URL:
// `functionName (http://script.url/:1234:1234)`
// https://github.com/firefox-devtools/profiler/blob/dab645b2db7e1b21185b286f96dd03b77f68f5c3/src/profile-logic/process-profile.js#L518
stringTable.push(
`${frame.name} (${frame.url}:${frame.lineNumber}:${frame.columnNumber})`
);
const category = this.#getOrCreateCategory(frame.category);
frameTable.data.push([
location,
true, // relevantForJS
0, // innerWindowID
null, // implementation
frame.lineNumber, // line
frame.columnNumber, // column
category,
0, // subcategory
]);
this.#frameMap.set(frameString, frameIndex);
}
return frameIndex;
}
#getOrCreateStack(frameIndex, prefix) {
const { stackTable } = this.#thread;
const key = prefix === null ? `${frameIndex}` : `${frameIndex},${prefix}`;
let stack = this.#stackMap.get(key);
if (stack === undefined) {
stack = stackTable.data.length;
stackTable.data.push([prefix, frameIndex]);
this.#stackMap.set(key, stack);
}
return stack;
}
#getOrCreateCategory(category) {
const categories = this.#categories;
let categoryIndex = categories.findIndex(c => c.name === category);
if (categoryIndex === -1) {
categoryIndex = categories.length;
categories.push({
name: category,
color: PREDEFINED_COLORS[category] ?? DEFAULT_COLOR,
subcategories: ["Other"],
});
}
return categoryIndex;
}
}
exports.GeckoProfileCollector = GeckoProfileCollector;

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

@ -14,6 +14,7 @@ DevToolsModules(
"dbg-source.js",
"event-breakpoints.js",
"event-loop.js",
"gecko-profile-collector.js",
"inactive-property-helper.js",
"logEvent.js",
"make-debugger.js",