123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454 |
- /*
- 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;
|