ProfilingPlugin.js 10 KB

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