ProfilingPlugin.js 15 KB

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