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