ProfilingPlugin.js 14 KB

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