webpack/lib/debug/ProfilingPlugin.js

/*
	MIT License http://www.opensource.org/licenses/mit-license.php
*/

"use strict";

const { Tracer } = require("chrome-trace-event");
const {
	JAVASCRIPT_MODULE_TYPE_AUTO,
	JAVASCRIPT_MODULE_TYPE_DYNAMIC,
	JAVASCRIPT_MODULE_TYPE_ESM,
	WEBASSEMBLY_MODULE_TYPE_ASYNC,
	WEBASSEMBLY_MODULE_TYPE_SYNC,
	JSON_MODULE_TYPE
} = require("../ModuleTypeConstants");
const createSchemaValidation = require("../util/create-schema-validation");
const { dirname, mkdirpSync } = require("../util/fs");

/** @typedef {import("../../declarations/plugins/debug/ProfilingPlugin").ProfilingPluginOptions} ProfilingPluginOptions */
/** @typedef {import("../Compilation")} Compilation */
/** @typedef {import("../Compiler")} Compiler */
/** @typedef {import("../ContextModuleFactory")} ContextModuleFactory */
/** @typedef {import("../ModuleFactory")} ModuleFactory */
/** @typedef {import("../NormalModuleFactory")} NormalModuleFactory */
/** @typedef {import("../util/fs").IntermediateFileSystem} IntermediateFileSystem */

/** @typedef {TODO} Inspector */

const validate = createSchemaValidation(
	require("../../schemas/plugins/debug/ProfilingPlugin.check.js"),
	() => require("../../schemas/plugins/debug/ProfilingPlugin.json"),
	{
		name: "Profiling Plugin",
		baseDataPath: "options"
	}
);

/** @type {Inspector | undefined} */
let inspector = undefined;

try {
	// eslint-disable-next-line n/no-unsupported-features/node-builtins
	inspector = require("inspector");
} catch (e) {
	console.log("Unable to CPU profile in < node 8.0");
}

class Profiler {
	/**
	 * @param {Inspector} inspector inspector
	 */
	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")
		]);
	}

	/**
	 * @param {string} method method name
	 * @param {object} [params] params
	 * @returns {Promise<TODO>} Promise for the result
	 */
	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);
					}
				});
			});
		}
		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);
			// Avoid coverage problems due indirect changes
			/* istanbul ignore next */
			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(/** @type {Inspector} */ (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 PLUGIN_NAME = "ProfilingPlugin";

class ProfilingPlugin {
	/**
	 * @param {ProfilingPluginOptions=} options options object
	 */
	constructor(options = {}) {
		validate(options);
		this.outputPath = options.outputPath || "events.json";
	}

	/**
	 * Apply the plugin
	 * @param {Compiler} compiler the compiler instance
	 * @returns {void}
	 */
	apply(compiler) {
		const tracer = createTrace(
			/** @type {IntermediateFileSystem} */
			(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(
			PLUGIN_NAME,
			(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: PLUGIN_NAME,
				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);
				});
			}
		);
	}
}

/**
 * @param {any} instance instance
 * @param {Trace} tracer tracer
 * @param {string} logLabel log label
 */
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));
			}
		});
	}
};

/**
 * @param {NormalModuleFactory} moduleFactory normal module factory
 * @param {Trace} tracer tracer
 */
const interceptAllParserHooks = (moduleFactory, tracer) => {
	const moduleTypes = [
		JAVASCRIPT_MODULE_TYPE_AUTO,
		JAVASCRIPT_MODULE_TYPE_DYNAMIC,
		JAVASCRIPT_MODULE_TYPE_ESM,
		JSON_MODULE_TYPE,
		WEBASSEMBLY_MODULE_TYPE_ASYNC,
		WEBASSEMBLY_MODULE_TYPE_SYNC
	];

	moduleTypes.forEach(moduleType => {
		moduleFactory.hooks.parser
			.for(moduleType)
			.tap(PLUGIN_NAME, (parser, parserOpts) => {
				interceptAllHooksFor(parser, tracer, "Parser");
			});
	});
};

/**
 * @param {Compilation} compilation compilation
 * @param {Trace} tracer tracer
 */
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 === PLUGIN_NAME
				? 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 === PLUGIN_NAME) {
					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;