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;
|
---|