You can not select more than 25 topics
Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.
454 lines
10 KiB
454 lines
10 KiB
/* |
|
MIT License http://www.opensource.org/licenses/mit-license.php |
|
*/ |
|
|
|
"use strict"; |
|
|
|
const { Tracer } = require("chrome-trace-event"); |
|
const createSchemaValidation = require("../util/create-schema-validation"); |
|
const { dirname, mkdirpSync } = require("../util/fs"); |
|
|
|
/** @typedef {import("../../declarations/plugins/debug/ProfilingPlugin").ProfilingPluginOptions} ProfilingPluginOptions */ |
|
/** @typedef {import("../util/fs").IntermediateFileSystem} IntermediateFileSystem */ |
|
|
|
const validate = createSchemaValidation( |
|
require("../../schemas/plugins/debug/ProfilingPlugin.check.js"), |
|
() => require("../../schemas/plugins/debug/ProfilingPlugin.json"), |
|
{ |
|
name: "Profiling Plugin", |
|
baseDataPath: "options" |
|
} |
|
); |
|
let inspector = undefined; |
|
|
|
try { |
|
// eslint-disable-next-line node/no-unsupported-features/node-builtins |
|
inspector = require("inspector"); |
|
} catch (e) { |
|
console.log("Unable to CPU profile in < node 8.0"); |
|
} |
|
|
|
class Profiler { |
|
constructor(inspector) { |
|
this.session = undefined; |
|
this.inspector = inspector; |
|
this._startTime = 0; |
|
} |
|
|
|
hasSession() { |
|
return this.session !== undefined; |
|
} |
|
|
|
startProfiling() { |
|
if (this.inspector === undefined) { |
|
return Promise.resolve(); |
|
} |
|
|
|
try { |
|
this.session = new inspector.Session(); |
|
this.session.connect(); |
|
} catch (_) { |
|
this.session = undefined; |
|
return Promise.resolve(); |
|
} |
|
|
|
const hrtime = process.hrtime(); |
|
this._startTime = hrtime[0] * 1000000 + Math.round(hrtime[1] / 1000); |
|
|
|
return Promise.all([ |
|
this.sendCommand("Profiler.setSamplingInterval", { |
|
interval: 100 |
|
}), |
|
this.sendCommand("Profiler.enable"), |
|
this.sendCommand("Profiler.start") |
|
]); |
|
} |
|
|
|
sendCommand(method, params) { |
|
if (this.hasSession()) { |
|
return new Promise((res, rej) => { |
|
return this.session.post(method, params, (err, params) => { |
|
if (err !== null) { |
|
rej(err); |
|
} else { |
|
res(params); |
|
} |
|
}); |
|
}); |
|
} else { |
|
return Promise.resolve(); |
|
} |
|
} |
|
|
|
destroy() { |
|
if (this.hasSession()) { |
|
this.session.disconnect(); |
|
} |
|
|
|
return Promise.resolve(); |
|
} |
|
|
|
stopProfiling() { |
|
return this.sendCommand("Profiler.stop").then(({ profile }) => { |
|
const hrtime = process.hrtime(); |
|
const endTime = hrtime[0] * 1000000 + Math.round(hrtime[1] / 1000); |
|
if (profile.startTime < this._startTime || profile.endTime > endTime) { |
|
// In some cases timestamps mismatch and we need to adjust them |
|
// Both process.hrtime and the inspector timestamps claim to be relative |
|
// to a unknown point in time. But they do not guarantee that this is the |
|
// same point in time. |
|
const duration = profile.endTime - profile.startTime; |
|
const ownDuration = endTime - this._startTime; |
|
const untracked = Math.max(0, ownDuration - duration); |
|
profile.startTime = this._startTime + untracked / 2; |
|
profile.endTime = endTime - untracked / 2; |
|
} |
|
return { profile }; |
|
}); |
|
} |
|
} |
|
|
|
/** |
|
* an object that wraps Tracer and Profiler with a counter |
|
* @typedef {Object} Trace |
|
* @property {Tracer} trace instance of Tracer |
|
* @property {number} counter Counter |
|
* @property {Profiler} profiler instance of Profiler |
|
* @property {Function} end the end function |
|
*/ |
|
|
|
/** |
|
* @param {IntermediateFileSystem} fs filesystem used for output |
|
* @param {string} outputPath The location where to write the log. |
|
* @returns {Trace} The trace object |
|
*/ |
|
const createTrace = (fs, outputPath) => { |
|
const trace = new Tracer(); |
|
const profiler = new Profiler(inspector); |
|
if (/\/|\\/.test(outputPath)) { |
|
const dirPath = dirname(fs, outputPath); |
|
mkdirpSync(fs, dirPath); |
|
} |
|
const fsStream = fs.createWriteStream(outputPath); |
|
|
|
let counter = 0; |
|
|
|
trace.pipe(fsStream); |
|
// These are critical events that need to be inserted so that tools like |
|
// chrome dev tools can load the profile. |
|
trace.instantEvent({ |
|
name: "TracingStartedInPage", |
|
id: ++counter, |
|
cat: ["disabled-by-default-devtools.timeline"], |
|
args: { |
|
data: { |
|
sessionId: "-1", |
|
page: "0xfff", |
|
frames: [ |
|
{ |
|
frame: "0xfff", |
|
url: "webpack", |
|
name: "" |
|
} |
|
] |
|
} |
|
} |
|
}); |
|
|
|
trace.instantEvent({ |
|
name: "TracingStartedInBrowser", |
|
id: ++counter, |
|
cat: ["disabled-by-default-devtools.timeline"], |
|
args: { |
|
data: { |
|
sessionId: "-1" |
|
} |
|
} |
|
}); |
|
|
|
return { |
|
trace, |
|
counter, |
|
profiler, |
|
end: callback => { |
|
trace.push("]"); |
|
// Wait until the write stream finishes. |
|
fsStream.on("close", () => { |
|
callback(); |
|
}); |
|
// Tear down the readable trace stream. |
|
trace.push(null); |
|
} |
|
}; |
|
}; |
|
|
|
const pluginName = "ProfilingPlugin"; |
|
|
|
class ProfilingPlugin { |
|
/** |
|
* @param {ProfilingPluginOptions=} options options object |
|
*/ |
|
constructor(options = {}) { |
|
validate(options); |
|
this.outputPath = options.outputPath || "events.json"; |
|
} |
|
|
|
apply(compiler) { |
|
const tracer = createTrace( |
|
compiler.intermediateFileSystem, |
|
this.outputPath |
|
); |
|
tracer.profiler.startProfiling(); |
|
|
|
// Compiler Hooks |
|
Object.keys(compiler.hooks).forEach(hookName => { |
|
const hook = compiler.hooks[hookName]; |
|
if (hook) { |
|
hook.intercept(makeInterceptorFor("Compiler", tracer)(hookName)); |
|
} |
|
}); |
|
|
|
Object.keys(compiler.resolverFactory.hooks).forEach(hookName => { |
|
const hook = compiler.resolverFactory.hooks[hookName]; |
|
if (hook) { |
|
hook.intercept(makeInterceptorFor("Resolver", tracer)(hookName)); |
|
} |
|
}); |
|
|
|
compiler.hooks.compilation.tap( |
|
pluginName, |
|
(compilation, { normalModuleFactory, contextModuleFactory }) => { |
|
interceptAllHooksFor(compilation, tracer, "Compilation"); |
|
interceptAllHooksFor( |
|
normalModuleFactory, |
|
tracer, |
|
"Normal Module Factory" |
|
); |
|
interceptAllHooksFor( |
|
contextModuleFactory, |
|
tracer, |
|
"Context Module Factory" |
|
); |
|
interceptAllParserHooks(normalModuleFactory, tracer); |
|
interceptAllJavascriptModulesPluginHooks(compilation, tracer); |
|
} |
|
); |
|
|
|
// We need to write out the CPU profile when we are all done. |
|
compiler.hooks.done.tapAsync( |
|
{ |
|
name: pluginName, |
|
stage: Infinity |
|
}, |
|
(stats, callback) => { |
|
if (compiler.watchMode) return callback(); |
|
tracer.profiler.stopProfiling().then(parsedResults => { |
|
if (parsedResults === undefined) { |
|
tracer.profiler.destroy(); |
|
tracer.end(callback); |
|
return; |
|
} |
|
|
|
const cpuStartTime = parsedResults.profile.startTime; |
|
const cpuEndTime = parsedResults.profile.endTime; |
|
|
|
tracer.trace.completeEvent({ |
|
name: "TaskQueueManager::ProcessTaskFromWorkQueue", |
|
id: ++tracer.counter, |
|
cat: ["toplevel"], |
|
ts: cpuStartTime, |
|
args: { |
|
src_file: "../../ipc/ipc_moji_bootstrap.cc", |
|
src_func: "Accept" |
|
} |
|
}); |
|
|
|
tracer.trace.completeEvent({ |
|
name: "EvaluateScript", |
|
id: ++tracer.counter, |
|
cat: ["devtools.timeline"], |
|
ts: cpuStartTime, |
|
dur: cpuEndTime - cpuStartTime, |
|
args: { |
|
data: { |
|
url: "webpack", |
|
lineNumber: 1, |
|
columnNumber: 1, |
|
frame: "0xFFF" |
|
} |
|
} |
|
}); |
|
|
|
tracer.trace.instantEvent({ |
|
name: "CpuProfile", |
|
id: ++tracer.counter, |
|
cat: ["disabled-by-default-devtools.timeline"], |
|
ts: cpuEndTime, |
|
args: { |
|
data: { |
|
cpuProfile: parsedResults.profile |
|
} |
|
} |
|
}); |
|
|
|
tracer.profiler.destroy(); |
|
tracer.end(callback); |
|
}); |
|
} |
|
); |
|
} |
|
} |
|
|
|
const interceptAllHooksFor = (instance, tracer, logLabel) => { |
|
if (Reflect.has(instance, "hooks")) { |
|
Object.keys(instance.hooks).forEach(hookName => { |
|
const hook = instance.hooks[hookName]; |
|
if (hook && !hook._fakeHook) { |
|
hook.intercept(makeInterceptorFor(logLabel, tracer)(hookName)); |
|
} |
|
}); |
|
} |
|
}; |
|
|
|
const interceptAllParserHooks = (moduleFactory, tracer) => { |
|
const moduleTypes = [ |
|
"javascript/auto", |
|
"javascript/dynamic", |
|
"javascript/esm", |
|
"json", |
|
"webassembly/async", |
|
"webassembly/sync" |
|
]; |
|
|
|
moduleTypes.forEach(moduleType => { |
|
moduleFactory.hooks.parser |
|
.for(moduleType) |
|
.tap("ProfilingPlugin", (parser, parserOpts) => { |
|
interceptAllHooksFor(parser, tracer, "Parser"); |
|
}); |
|
}); |
|
}; |
|
|
|
const interceptAllJavascriptModulesPluginHooks = (compilation, tracer) => { |
|
interceptAllHooksFor( |
|
{ |
|
hooks: |
|
require("../javascript/JavascriptModulesPlugin").getCompilationHooks( |
|
compilation |
|
) |
|
}, |
|
tracer, |
|
"JavascriptModulesPlugin" |
|
); |
|
}; |
|
|
|
const makeInterceptorFor = (instance, tracer) => hookName => ({ |
|
register: tapInfo => { |
|
const { name, type, fn } = tapInfo; |
|
const newFn = |
|
// Don't tap our own hooks to ensure stream can close cleanly |
|
name === pluginName |
|
? fn |
|
: makeNewProfiledTapFn(hookName, tracer, { |
|
name, |
|
type, |
|
fn |
|
}); |
|
return { |
|
...tapInfo, |
|
fn: newFn |
|
}; |
|
} |
|
}); |
|
|
|
// TODO improve typing |
|
/** @typedef {(...args: TODO[]) => void | Promise<TODO>} PluginFunction */ |
|
|
|
/** |
|
* @param {string} hookName Name of the hook to profile. |
|
* @param {Trace} tracer The trace object. |
|
* @param {object} options Options for the profiled fn. |
|
* @param {string} options.name Plugin name |
|
* @param {string} options.type Plugin type (sync | async | promise) |
|
* @param {PluginFunction} options.fn Plugin function |
|
* @returns {PluginFunction} Chainable hooked function. |
|
*/ |
|
const makeNewProfiledTapFn = (hookName, tracer, { name, type, fn }) => { |
|
const defaultCategory = ["blink.user_timing"]; |
|
|
|
switch (type) { |
|
case "promise": |
|
return (...args) => { |
|
const id = ++tracer.counter; |
|
tracer.trace.begin({ |
|
name, |
|
id, |
|
cat: defaultCategory |
|
}); |
|
const promise = /** @type {Promise<*>} */ (fn(...args)); |
|
return promise.then(r => { |
|
tracer.trace.end({ |
|
name, |
|
id, |
|
cat: defaultCategory |
|
}); |
|
return r; |
|
}); |
|
}; |
|
case "async": |
|
return (...args) => { |
|
const id = ++tracer.counter; |
|
tracer.trace.begin({ |
|
name, |
|
id, |
|
cat: defaultCategory |
|
}); |
|
const callback = args.pop(); |
|
fn(...args, (...r) => { |
|
tracer.trace.end({ |
|
name, |
|
id, |
|
cat: defaultCategory |
|
}); |
|
callback(...r); |
|
}); |
|
}; |
|
case "sync": |
|
return (...args) => { |
|
const id = ++tracer.counter; |
|
// Do not instrument ourself due to the CPU |
|
// profile needing to be the last event in the trace. |
|
if (name === pluginName) { |
|
return fn(...args); |
|
} |
|
|
|
tracer.trace.begin({ |
|
name, |
|
id, |
|
cat: defaultCategory |
|
}); |
|
let r; |
|
try { |
|
r = fn(...args); |
|
} catch (error) { |
|
tracer.trace.end({ |
|
name, |
|
id, |
|
cat: defaultCategory |
|
}); |
|
throw error; |
|
} |
|
tracer.trace.end({ |
|
name, |
|
id, |
|
cat: defaultCategory |
|
}); |
|
return r; |
|
}; |
|
default: |
|
break; |
|
} |
|
}; |
|
|
|
module.exports = ProfilingPlugin; |
|
module.exports.Profiler = Profiler;
|
|
|