| 1 | /*
|
|---|
| 2 | MIT License http://www.opensource.org/licenses/mit-license.php
|
|---|
| 3 | */
|
|---|
| 4 |
|
|---|
| 5 | "use strict";
|
|---|
| 6 |
|
|---|
| 7 | const { Tracer } = require("chrome-trace-event");
|
|---|
| 8 | const createSchemaValidation = require("../util/create-schema-validation");
|
|---|
| 9 | const { dirname, mkdirpSync } = require("../util/fs");
|
|---|
| 10 |
|
|---|
| 11 | /** @typedef {import("../../declarations/plugins/debug/ProfilingPlugin").ProfilingPluginOptions} ProfilingPluginOptions */
|
|---|
| 12 | /** @typedef {import("../util/fs").IntermediateFileSystem} IntermediateFileSystem */
|
|---|
| 13 |
|
|---|
| 14 | const validate = createSchemaValidation(
|
|---|
| 15 | require("../../schemas/plugins/debug/ProfilingPlugin.check.js"),
|
|---|
| 16 | () => require("../../schemas/plugins/debug/ProfilingPlugin.json"),
|
|---|
| 17 | {
|
|---|
| 18 | name: "Profiling Plugin",
|
|---|
| 19 | baseDataPath: "options"
|
|---|
| 20 | }
|
|---|
| 21 | );
|
|---|
| 22 | let inspector = undefined;
|
|---|
| 23 |
|
|---|
| 24 | try {
|
|---|
| 25 | // eslint-disable-next-line node/no-unsupported-features/node-builtins
|
|---|
| 26 | inspector = require("inspector");
|
|---|
| 27 | } catch (e) {
|
|---|
| 28 | console.log("Unable to CPU profile in < node 8.0");
|
|---|
| 29 | }
|
|---|
| 30 |
|
|---|
| 31 | class Profiler {
|
|---|
| 32 | constructor(inspector) {
|
|---|
| 33 | this.session = undefined;
|
|---|
| 34 | this.inspector = inspector;
|
|---|
| 35 | this._startTime = 0;
|
|---|
| 36 | }
|
|---|
| 37 |
|
|---|
| 38 | hasSession() {
|
|---|
| 39 | return this.session !== undefined;
|
|---|
| 40 | }
|
|---|
| 41 |
|
|---|
| 42 | startProfiling() {
|
|---|
| 43 | if (this.inspector === undefined) {
|
|---|
| 44 | return Promise.resolve();
|
|---|
| 45 | }
|
|---|
| 46 |
|
|---|
| 47 | try {
|
|---|
| 48 | this.session = new inspector.Session();
|
|---|
| 49 | this.session.connect();
|
|---|
| 50 | } catch (_) {
|
|---|
| 51 | this.session = undefined;
|
|---|
| 52 | return Promise.resolve();
|
|---|
| 53 | }
|
|---|
| 54 |
|
|---|
| 55 | const hrtime = process.hrtime();
|
|---|
| 56 | this._startTime = hrtime[0] * 1000000 + Math.round(hrtime[1] / 1000);
|
|---|
| 57 |
|
|---|
| 58 | return Promise.all([
|
|---|
| 59 | this.sendCommand("Profiler.setSamplingInterval", {
|
|---|
| 60 | interval: 100
|
|---|
| 61 | }),
|
|---|
| 62 | this.sendCommand("Profiler.enable"),
|
|---|
| 63 | this.sendCommand("Profiler.start")
|
|---|
| 64 | ]);
|
|---|
| 65 | }
|
|---|
| 66 |
|
|---|
| 67 | sendCommand(method, params) {
|
|---|
| 68 | if (this.hasSession()) {
|
|---|
| 69 | return new Promise((res, rej) => {
|
|---|
| 70 | return this.session.post(method, params, (err, params) => {
|
|---|
| 71 | if (err !== null) {
|
|---|
| 72 | rej(err);
|
|---|
| 73 | } else {
|
|---|
| 74 | res(params);
|
|---|
| 75 | }
|
|---|
| 76 | });
|
|---|
| 77 | });
|
|---|
| 78 | } else {
|
|---|
| 79 | return Promise.resolve();
|
|---|
| 80 | }
|
|---|
| 81 | }
|
|---|
| 82 |
|
|---|
| 83 | destroy() {
|
|---|
| 84 | if (this.hasSession()) {
|
|---|
| 85 | this.session.disconnect();
|
|---|
| 86 | }
|
|---|
| 87 |
|
|---|
| 88 | return Promise.resolve();
|
|---|
| 89 | }
|
|---|
| 90 |
|
|---|
| 91 | stopProfiling() {
|
|---|
| 92 | return this.sendCommand("Profiler.stop").then(({ profile }) => {
|
|---|
| 93 | const hrtime = process.hrtime();
|
|---|
| 94 | const endTime = hrtime[0] * 1000000 + Math.round(hrtime[1] / 1000);
|
|---|
| 95 | if (profile.startTime < this._startTime || profile.endTime > endTime) {
|
|---|
| 96 | // In some cases timestamps mismatch and we need to adjust them
|
|---|
| 97 | // Both process.hrtime and the inspector timestamps claim to be relative
|
|---|
| 98 | // to a unknown point in time. But they do not guarantee that this is the
|
|---|
| 99 | // same point in time.
|
|---|
| 100 | const duration = profile.endTime - profile.startTime;
|
|---|
| 101 | const ownDuration = endTime - this._startTime;
|
|---|
| 102 | const untracked = Math.max(0, ownDuration - duration);
|
|---|
| 103 | profile.startTime = this._startTime + untracked / 2;
|
|---|
| 104 | profile.endTime = endTime - untracked / 2;
|
|---|
| 105 | }
|
|---|
| 106 | return { profile };
|
|---|
| 107 | });
|
|---|
| 108 | }
|
|---|
| 109 | }
|
|---|
| 110 |
|
|---|
| 111 | /**
|
|---|
| 112 | * an object that wraps Tracer and Profiler with a counter
|
|---|
| 113 | * @typedef {Object} Trace
|
|---|
| 114 | * @property {Tracer} trace instance of Tracer
|
|---|
| 115 | * @property {number} counter Counter
|
|---|
| 116 | * @property {Profiler} profiler instance of Profiler
|
|---|
| 117 | * @property {Function} end the end function
|
|---|
| 118 | */
|
|---|
| 119 |
|
|---|
| 120 | /**
|
|---|
| 121 | * @param {IntermediateFileSystem} fs filesystem used for output
|
|---|
| 122 | * @param {string} outputPath The location where to write the log.
|
|---|
| 123 | * @returns {Trace} The trace object
|
|---|
| 124 | */
|
|---|
| 125 | const createTrace = (fs, outputPath) => {
|
|---|
| 126 | const trace = new Tracer({
|
|---|
| 127 | noStream: true
|
|---|
| 128 | });
|
|---|
| 129 | const profiler = new Profiler(inspector);
|
|---|
| 130 | if (/\/|\\/.test(outputPath)) {
|
|---|
| 131 | const dirPath = dirname(fs, outputPath);
|
|---|
| 132 | mkdirpSync(fs, dirPath);
|
|---|
| 133 | }
|
|---|
| 134 | const fsStream = fs.createWriteStream(outputPath);
|
|---|
| 135 |
|
|---|
| 136 | let counter = 0;
|
|---|
| 137 |
|
|---|
| 138 | trace.pipe(fsStream);
|
|---|
| 139 | // These are critical events that need to be inserted so that tools like
|
|---|
| 140 | // chrome dev tools can load the profile.
|
|---|
| 141 | trace.instantEvent({
|
|---|
| 142 | name: "TracingStartedInPage",
|
|---|
| 143 | id: ++counter,
|
|---|
| 144 | cat: ["disabled-by-default-devtools.timeline"],
|
|---|
| 145 | args: {
|
|---|
| 146 | data: {
|
|---|
| 147 | sessionId: "-1",
|
|---|
| 148 | page: "0xfff",
|
|---|
| 149 | frames: [
|
|---|
| 150 | {
|
|---|
| 151 | frame: "0xfff",
|
|---|
| 152 | url: "webpack",
|
|---|
| 153 | name: ""
|
|---|
| 154 | }
|
|---|
| 155 | ]
|
|---|
| 156 | }
|
|---|
| 157 | }
|
|---|
| 158 | });
|
|---|
| 159 |
|
|---|
| 160 | trace.instantEvent({
|
|---|
| 161 | name: "TracingStartedInBrowser",
|
|---|
| 162 | id: ++counter,
|
|---|
| 163 | cat: ["disabled-by-default-devtools.timeline"],
|
|---|
| 164 | args: {
|
|---|
| 165 | data: {
|
|---|
| 166 | sessionId: "-1"
|
|---|
| 167 | }
|
|---|
| 168 | }
|
|---|
| 169 | });
|
|---|
| 170 |
|
|---|
| 171 | return {
|
|---|
| 172 | trace,
|
|---|
| 173 | counter,
|
|---|
| 174 | profiler,
|
|---|
| 175 | end: callback => {
|
|---|
| 176 | // Wait until the write stream finishes.
|
|---|
| 177 | fsStream.on("close", () => {
|
|---|
| 178 | callback();
|
|---|
| 179 | });
|
|---|
| 180 | // Tear down the readable trace stream.
|
|---|
| 181 | trace.push(null);
|
|---|
| 182 | }
|
|---|
| 183 | };
|
|---|
| 184 | };
|
|---|
| 185 |
|
|---|
| 186 | const pluginName = "ProfilingPlugin";
|
|---|
| 187 |
|
|---|
| 188 | class ProfilingPlugin {
|
|---|
| 189 | /**
|
|---|
| 190 | * @param {ProfilingPluginOptions=} options options object
|
|---|
| 191 | */
|
|---|
| 192 | constructor(options = {}) {
|
|---|
| 193 | validate(options);
|
|---|
| 194 | this.outputPath = options.outputPath || "events.json";
|
|---|
| 195 | }
|
|---|
| 196 |
|
|---|
| 197 | apply(compiler) {
|
|---|
| 198 | const tracer = createTrace(
|
|---|
| 199 | compiler.intermediateFileSystem,
|
|---|
| 200 | this.outputPath
|
|---|
| 201 | );
|
|---|
| 202 | tracer.profiler.startProfiling();
|
|---|
| 203 |
|
|---|
| 204 | // Compiler Hooks
|
|---|
| 205 | Object.keys(compiler.hooks).forEach(hookName => {
|
|---|
| 206 | compiler.hooks[hookName].intercept(
|
|---|
| 207 | makeInterceptorFor("Compiler", tracer)(hookName)
|
|---|
| 208 | );
|
|---|
| 209 | });
|
|---|
| 210 |
|
|---|
| 211 | Object.keys(compiler.resolverFactory.hooks).forEach(hookName => {
|
|---|
| 212 | compiler.resolverFactory.hooks[hookName].intercept(
|
|---|
| 213 | makeInterceptorFor("Resolver", tracer)(hookName)
|
|---|
| 214 | );
|
|---|
| 215 | });
|
|---|
| 216 |
|
|---|
| 217 | compiler.hooks.compilation.tap(
|
|---|
| 218 | pluginName,
|
|---|
| 219 | (compilation, { normalModuleFactory, contextModuleFactory }) => {
|
|---|
| 220 | interceptAllHooksFor(compilation, tracer, "Compilation");
|
|---|
| 221 | interceptAllHooksFor(
|
|---|
| 222 | normalModuleFactory,
|
|---|
| 223 | tracer,
|
|---|
| 224 | "Normal Module Factory"
|
|---|
| 225 | );
|
|---|
| 226 | interceptAllHooksFor(
|
|---|
| 227 | contextModuleFactory,
|
|---|
| 228 | tracer,
|
|---|
| 229 | "Context Module Factory"
|
|---|
| 230 | );
|
|---|
| 231 | interceptAllParserHooks(normalModuleFactory, tracer);
|
|---|
| 232 | interceptAllJavascriptModulesPluginHooks(compilation, tracer);
|
|---|
| 233 | }
|
|---|
| 234 | );
|
|---|
| 235 |
|
|---|
| 236 | // We need to write out the CPU profile when we are all done.
|
|---|
| 237 | compiler.hooks.done.tapAsync(
|
|---|
| 238 | {
|
|---|
| 239 | name: pluginName,
|
|---|
| 240 | stage: Infinity
|
|---|
| 241 | },
|
|---|
| 242 | (stats, callback) => {
|
|---|
| 243 | tracer.profiler.stopProfiling().then(parsedResults => {
|
|---|
| 244 | if (parsedResults === undefined) {
|
|---|
| 245 | tracer.profiler.destroy();
|
|---|
| 246 | tracer.trace.flush();
|
|---|
| 247 | tracer.end(callback);
|
|---|
| 248 | return;
|
|---|
| 249 | }
|
|---|
| 250 |
|
|---|
| 251 | const cpuStartTime = parsedResults.profile.startTime;
|
|---|
| 252 | const cpuEndTime = parsedResults.profile.endTime;
|
|---|
| 253 |
|
|---|
| 254 | tracer.trace.completeEvent({
|
|---|
| 255 | name: "TaskQueueManager::ProcessTaskFromWorkQueue",
|
|---|
| 256 | id: ++tracer.counter,
|
|---|
| 257 | cat: ["toplevel"],
|
|---|
| 258 | ts: cpuStartTime,
|
|---|
| 259 | args: {
|
|---|
| 260 | src_file: "../../ipc/ipc_moji_bootstrap.cc",
|
|---|
| 261 | src_func: "Accept"
|
|---|
| 262 | }
|
|---|
| 263 | });
|
|---|
| 264 |
|
|---|
| 265 | tracer.trace.completeEvent({
|
|---|
| 266 | name: "EvaluateScript",
|
|---|
| 267 | id: ++tracer.counter,
|
|---|
| 268 | cat: ["devtools.timeline"],
|
|---|
| 269 | ts: cpuStartTime,
|
|---|
| 270 | dur: cpuEndTime - cpuStartTime,
|
|---|
| 271 | args: {
|
|---|
| 272 | data: {
|
|---|
| 273 | url: "webpack",
|
|---|
| 274 | lineNumber: 1,
|
|---|
| 275 | columnNumber: 1,
|
|---|
| 276 | frame: "0xFFF"
|
|---|
| 277 | }
|
|---|
| 278 | }
|
|---|
| 279 | });
|
|---|
| 280 |
|
|---|
| 281 | tracer.trace.instantEvent({
|
|---|
| 282 | name: "CpuProfile",
|
|---|
| 283 | id: ++tracer.counter,
|
|---|
| 284 | cat: ["disabled-by-default-devtools.timeline"],
|
|---|
| 285 | ts: cpuEndTime,
|
|---|
| 286 | args: {
|
|---|
| 287 | data: {
|
|---|
| 288 | cpuProfile: parsedResults.profile
|
|---|
| 289 | }
|
|---|
| 290 | }
|
|---|
| 291 | });
|
|---|
| 292 |
|
|---|
| 293 | tracer.profiler.destroy();
|
|---|
| 294 | tracer.trace.flush();
|
|---|
| 295 | tracer.end(callback);
|
|---|
| 296 | });
|
|---|
| 297 | }
|
|---|
| 298 | );
|
|---|
| 299 | }
|
|---|
| 300 | }
|
|---|
| 301 |
|
|---|
| 302 | const interceptAllHooksFor = (instance, tracer, logLabel) => {
|
|---|
| 303 | if (Reflect.has(instance, "hooks")) {
|
|---|
| 304 | Object.keys(instance.hooks).forEach(hookName => {
|
|---|
| 305 | const hook = instance.hooks[hookName];
|
|---|
| 306 | if (!hook._fakeHook) {
|
|---|
| 307 | hook.intercept(makeInterceptorFor(logLabel, tracer)(hookName));
|
|---|
| 308 | }
|
|---|
| 309 | });
|
|---|
| 310 | }
|
|---|
| 311 | };
|
|---|
| 312 |
|
|---|
| 313 | const interceptAllParserHooks = (moduleFactory, tracer) => {
|
|---|
| 314 | const moduleTypes = [
|
|---|
| 315 | "javascript/auto",
|
|---|
| 316 | "javascript/dynamic",
|
|---|
| 317 | "javascript/esm",
|
|---|
| 318 | "json",
|
|---|
| 319 | "webassembly/async",
|
|---|
| 320 | "webassembly/sync"
|
|---|
| 321 | ];
|
|---|
| 322 |
|
|---|
| 323 | moduleTypes.forEach(moduleType => {
|
|---|
| 324 | moduleFactory.hooks.parser
|
|---|
| 325 | .for(moduleType)
|
|---|
| 326 | .tap("ProfilingPlugin", (parser, parserOpts) => {
|
|---|
| 327 | interceptAllHooksFor(parser, tracer, "Parser");
|
|---|
| 328 | });
|
|---|
| 329 | });
|
|---|
| 330 | };
|
|---|
| 331 |
|
|---|
| 332 | const interceptAllJavascriptModulesPluginHooks = (compilation, tracer) => {
|
|---|
| 333 | interceptAllHooksFor(
|
|---|
| 334 | {
|
|---|
| 335 | hooks:
|
|---|
| 336 | require("../javascript/JavascriptModulesPlugin").getCompilationHooks(
|
|---|
| 337 | compilation
|
|---|
| 338 | )
|
|---|
| 339 | },
|
|---|
| 340 | tracer,
|
|---|
| 341 | "JavascriptModulesPlugin"
|
|---|
| 342 | );
|
|---|
| 343 | };
|
|---|
| 344 |
|
|---|
| 345 | const makeInterceptorFor = (instance, tracer) => hookName => ({
|
|---|
| 346 | register: ({ name, type, context, fn }) => {
|
|---|
| 347 | const newFn = makeNewProfiledTapFn(hookName, tracer, {
|
|---|
| 348 | name,
|
|---|
| 349 | type,
|
|---|
| 350 | fn
|
|---|
| 351 | });
|
|---|
| 352 | return {
|
|---|
| 353 | name,
|
|---|
| 354 | type,
|
|---|
| 355 | context,
|
|---|
| 356 | fn: newFn
|
|---|
| 357 | };
|
|---|
| 358 | }
|
|---|
| 359 | });
|
|---|
| 360 |
|
|---|
| 361 | // TODO improve typing
|
|---|
| 362 | /** @typedef {(...args: TODO[]) => void | Promise<TODO>} PluginFunction */
|
|---|
| 363 |
|
|---|
| 364 | /**
|
|---|
| 365 | * @param {string} hookName Name of the hook to profile.
|
|---|
| 366 | * @param {Trace} tracer The trace object.
|
|---|
| 367 | * @param {object} options Options for the profiled fn.
|
|---|
| 368 | * @param {string} options.name Plugin name
|
|---|
| 369 | * @param {string} options.type Plugin type (sync | async | promise)
|
|---|
| 370 | * @param {PluginFunction} options.fn Plugin function
|
|---|
| 371 | * @returns {PluginFunction} Chainable hooked function.
|
|---|
| 372 | */
|
|---|
| 373 | const makeNewProfiledTapFn = (hookName, tracer, { name, type, fn }) => {
|
|---|
| 374 | const defaultCategory = ["blink.user_timing"];
|
|---|
| 375 |
|
|---|
| 376 | switch (type) {
|
|---|
| 377 | case "promise":
|
|---|
| 378 | return (...args) => {
|
|---|
| 379 | const id = ++tracer.counter;
|
|---|
| 380 | tracer.trace.begin({
|
|---|
| 381 | name,
|
|---|
| 382 | id,
|
|---|
| 383 | cat: defaultCategory
|
|---|
| 384 | });
|
|---|
| 385 | const promise = /** @type {Promise<*>} */ (fn(...args));
|
|---|
| 386 | return promise.then(r => {
|
|---|
| 387 | tracer.trace.end({
|
|---|
| 388 | name,
|
|---|
| 389 | id,
|
|---|
| 390 | cat: defaultCategory
|
|---|
| 391 | });
|
|---|
| 392 | return r;
|
|---|
| 393 | });
|
|---|
| 394 | };
|
|---|
| 395 | case "async":
|
|---|
| 396 | return (...args) => {
|
|---|
| 397 | const id = ++tracer.counter;
|
|---|
| 398 | tracer.trace.begin({
|
|---|
| 399 | name,
|
|---|
| 400 | id,
|
|---|
| 401 | cat: defaultCategory
|
|---|
| 402 | });
|
|---|
| 403 | const callback = args.pop();
|
|---|
| 404 | fn(...args, (...r) => {
|
|---|
| 405 | tracer.trace.end({
|
|---|
| 406 | name,
|
|---|
| 407 | id,
|
|---|
| 408 | cat: defaultCategory
|
|---|
| 409 | });
|
|---|
| 410 | callback(...r);
|
|---|
| 411 | });
|
|---|
| 412 | };
|
|---|
| 413 | case "sync":
|
|---|
| 414 | return (...args) => {
|
|---|
| 415 | const id = ++tracer.counter;
|
|---|
| 416 | // Do not instrument ourself due to the CPU
|
|---|
| 417 | // profile needing to be the last event in the trace.
|
|---|
| 418 | if (name === pluginName) {
|
|---|
| 419 | return fn(...args);
|
|---|
| 420 | }
|
|---|
| 421 |
|
|---|
| 422 | tracer.trace.begin({
|
|---|
| 423 | name,
|
|---|
| 424 | id,
|
|---|
| 425 | cat: defaultCategory
|
|---|
| 426 | });
|
|---|
| 427 | let r;
|
|---|
| 428 | try {
|
|---|
| 429 | r = fn(...args);
|
|---|
| 430 | } catch (error) {
|
|---|
| 431 | tracer.trace.end({
|
|---|
| 432 | name,
|
|---|
| 433 | id,
|
|---|
| 434 | cat: defaultCategory
|
|---|
| 435 | });
|
|---|
| 436 | throw error;
|
|---|
| 437 | }
|
|---|
| 438 | tracer.trace.end({
|
|---|
| 439 | name,
|
|---|
| 440 | id,
|
|---|
| 441 | cat: defaultCategory
|
|---|
| 442 | });
|
|---|
| 443 | return r;
|
|---|
| 444 | };
|
|---|
| 445 | default:
|
|---|
| 446 | break;
|
|---|
| 447 | }
|
|---|
| 448 | };
|
|---|
| 449 |
|
|---|
| 450 | module.exports = ProfilingPlugin;
|
|---|
| 451 | module.exports.Profiler = Profiler;
|
|---|
