ProfilingPlugin.js 15 KB

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