Granular loader data (#17)

Add in an experimental mode of granular loader timing data

Author: stephencookdev

README.md

@@ -53,6 +53,8 @@ const webpackConfig = smp.wrap({
 });
 ```
 
+and you're done! SMP will now be printing timing output to the console by default
+
 ## Options
 
 Options are (optionally) passed in to the constructor
@@ -87,3 +89,17 @@ Type: `Boolean`<br>
 Default: `false`
 
 If truthy, this plugin does nothing at all. It is recommended to set this with something similar to `{ disable: !process.env.MEASURE }` to allow opt-in measurements with a `MEASURE=true npm run build`
+
+### `options.granularLoaderData` _(experimental)_
+
+Type: `Boolean`<br>
+Default: `false`
+
+If truthy, this plugin will attempt to break down the loader timing data to give per-loader timing information.
+
+Points of note that the following loaders will have inaccurate results in this mode:
+
+ * loaders using separate processes (e.g. `thread-loader`) - these make it difficult to get timing information on the subsequent loaders, as they're not attached to the main thread
+ * loaders emitting file output (e.g. `file-loader`) - the time taken in outputting the actual file is not included in the running time of the loader
+
+These are restrictions from technical limitations - ideally we would find solutions to these problems before removing the _(experimental)_ flag on this options

WrappedPlugin/index.js

@@ -2,9 +2,9 @@ let idInc = 0;
 
 const genPluginMethod = (orig, pluginName, smp, type) =>
   function(method, func) {
+    const timeEventName = pluginName + "/" + type + "/" + method;
     const wrappedFunc = (...args) => {
       const id = idInc++;
-      const timeEventName = pluginName + "/" + type + "/" + method;
       // we don't know if there's going to be a callback applied to a particular
       // call, so we just set it multiple times, letting each one override the last
       let endCallCount = 0;

index.js

@@ -1,6 +1,7 @@
+const path = require("path");
 const fs = require("fs");
 const { WrappedPlugin } = require("./WrappedPlugin");
-const { getModuleName, getLoaderNames } = require("./utils");
+const { getModuleName, getLoaderNames, prependLoader } = require("./utils");
 const {
   getHumanOutput,
   getMiscOutput,
@@ -9,6 +10,8 @@ const {
 } = require("./output");
 const { stripColours } = require("./colours");
 
+const NS = path.dirname(fs.realpathSync(__filename));
+
 module.exports = class SpeedMeasurePlugin {
   constructor(options) {
     this.options = options || {};
@@ -20,18 +23,24 @@ module.exports = class SpeedMeasurePlugin {
     this.getOutput = this.getOutput.bind(this);
     this.addTimeEvent = this.addTimeEvent.bind(this);
     this.apply = this.apply.bind(this);
+    this.provideLoaderTiming = this.provideLoaderTiming.bind(this);
   }
 
   wrap(config) {
     if (this.options.disable) return config;
 
     config.plugins = (config.plugins || []).map(plugin => {
-      const pluginName = (plugin.constructor && plugin.constructor.name) ||
+      const pluginName =
+        (plugin.constructor && plugin.constructor.name) ||
         "(unable to deduce plugin name)";
       return new WrappedPlugin(plugin, pluginName, this);
     });
 
-    if(!this.smpPluginAdded) {
+    if (config.module && this.options.granularLoaderData) {
+      config.module = prependLoader(config.module);
+    }
+
+    if (!this.smpPluginAdded) {
       config.plugins = config.plugins.concat(this);
       this.smpPluginAdded = true;
     }
@@ -78,7 +87,7 @@ module.exports = class SpeedMeasurePlugin {
       const eventToModify =
         matchingEvent || (data.fillLast && eventList.find(e => !e.end));
       if (!eventToModify) {
-        console.log(
+        console.error(
           "Could not find a matching event to end",
           category,
           event,
@@ -119,6 +128,10 @@ module.exports = class SpeedMeasurePlugin {
     });
 
     compiler.plugin("compilation", compilation => {
+      compilation.plugin("normal-module-loader", loaderContext => {
+        loaderContext[NS] = this.provideLoaderTiming;
+      });
+
       compilation.plugin("build-module", module => {
         const name = getModuleName(module);
         if (name) {
@@ -141,4 +154,14 @@ module.exports = class SpeedMeasurePlugin {
       });
     });
   }
+
+  provideLoaderTiming(info) {
+    const infoData = { id: info.id };
+    if(info.type !== "end") {
+      infoData.loader = info.loaderName;
+      infoData.name = info.module;
+    }
+
+    this.addTimeEvent("loaders", "build-specific", info.type, infoData);
+  }
 };

loader.js

@@ -0,0 +1,62 @@
+const path = require("path");
+const fs = require("fs");
+const { hackWrapLoaders } = require("./utils");
+
+let id = 0;
+
+const NS = path.dirname(fs.realpathSync(__filename));
+
+const getLoaderName = path => {
+  const nodeModuleName = /\/node_modules\/([^\/]+)/.exec(path);
+  return (nodeModuleName && nodeModuleName[1]) || "";
+};
+
+module.exports.pitch = function() {
+  const callback = this[NS];
+  const module = this.resourcePath;
+  const loaderPaths = this.loaders
+    .map(l => l.path)
+    .filter(l => !l.includes("speed-measure-webpack-plugin"));
+
+  // Hack ourselves to overwrite the `require` method so we can override the
+  // loadLoaders
+  hackWrapLoaders(loaderPaths, (loader, path) => {
+    const loaderName = getLoaderName(path);
+    const wrapFunc = func =>
+      function() {
+        const loaderId = id++;
+        const almostThis = Object.assign({}, this, {
+          async: function() {
+            const asyncCallback = this.async.apply(this, arguments);
+
+            return function() {
+              callback({
+                id: loaderId,
+                type: "end",
+              });
+              return asyncCallback.apply(this, arguments);
+            };
+          }.bind(this)
+        });
+
+        callback({
+          module,
+          loaderName,
+          id: loaderId,
+          type: "start",
+        });
+        const ret = func.apply(almostThis, arguments);
+        callback({
+          id: loaderId,
+          type: "end",
+        });
+        return ret;
+      };
+
+    if (loader.normal) loader.normal = wrapFunc(loader.normal);
+    if (loader.default) loader.default = wrapFunc(loader.default);
+    if (loader.pitch) loader.pitch = wrapFunc(loader.pitch);
+    if (typeof loader === "function") return wrapFunc(loader);
+    return loader;
+  });
+};

output.js

@@ -67,24 +67,38 @@ module.exports.getHumanOutput = (outputObj, options = {}) => {
           fg(hT(loaderObj.activeTime), loaderObj.activeTime) +
           "\n";
 
+        let xEqualsY = [];
         if (options.verbose) {
-          output +=
-            "    median       = " + hT(loaderObj.averages.median) + ",\n";
-          output += "    mean         = " + hT(loaderObj.averages.mean) + ",\n";
+          xEqualsY.push(["median", hT(loaderObj.averages.median)]);
+          xEqualsY.push(["mean", hT(loaderObj.averages.mean)]);
           if (typeof loaderObj.averages.variance === "number")
-            output +=
-              "    s.d          = " +
-              hT(Math.sqrt(loaderObj.averages.variance)) +
-              ", \n";
-          output +=
-            "    range        = (" +
-            hT(loaderObj.averages.range.start) +
-            " --> " +
-            hT(loaderObj.averages.range.end) +
-            "), \n";
+            xEqualsY.push(["s.d.", hT(Math.sqrt(loaderObj.averages.variance))]);
+          xEqualsY.push([
+            "range",
+            "(" +
+              hT(loaderObj.averages.range.start) +
+              " --> " +
+              hT(loaderObj.averages.range.end) +
+              ")",
+          ]);
         }
 
-        output += "    module count = " + loaderObj.averages.dataPoints + "\n";
+        if (loaderObj.loaders.length > 1) {
+          Object.keys(loaderObj.subLoadersTime).forEach(subLoader => {
+            xEqualsY.push([subLoader, hT(loaderObj.subLoadersTime[subLoader])]);
+          });
+        }
+
+        xEqualsY.push(["module count", loaderObj.averages.dataPoints]);
+
+        const maxXLength = xEqualsY.reduce(
+          (acc, cur) => Math.max(acc, cur[0].length),
+          0
+        );
+        xEqualsY.forEach(xY => {
+          const padEnd = maxXLength - xY[0].length;
+          output += "  " + xY[0] + " ".repeat(padEnd) + " = " + xY[1] + "\n";
+        });
       });
   }
 
@@ -100,6 +114,7 @@ module.exports.getMiscOutput = data => ({
 module.exports.getPluginsOutput = data =>
   Object.keys(data).reduce((acc, key) => {
     const inData = data[key];
+
     const startEndsByName = groupBy("name", inData);
 
     return startEndsByName.reduce((innerAcc, startEnds) => {
@@ -109,20 +124,29 @@ module.exports.getPluginsOutput = data =>
     }, acc);
   }, {});
 
-module.exports.getLoadersOutput = data =>
-  Object.keys(data).reduce((acc, key) => {
-    const startEndsByLoader = groupBy("loaders", data[key]);
-
-    acc[key] = startEndsByLoader.map(startEnds => {
-      const averages = getAverages(startEnds);
-      const activeTime = getTotalActiveTime(startEnds);
-
-      return {
-        averages,
-        activeTime,
-        loaders: startEnds[0].loaders,
-      };
-    });
-
-    return acc;
-  }, {});
+module.exports.getLoadersOutput = data => {
+  const startEndsByLoader = groupBy("loaders", data.build);
+  const allSubLoaders = data["build-specific"] || [];
+
+  const buildData = startEndsByLoader.map(startEnds => {
+    const averages = getAverages(startEnds);
+    const activeTime = getTotalActiveTime(startEnds);
+    const subLoaders = groupBy(
+      "loader",
+      allSubLoaders.filter(l => startEnds.find(x => x.name === l.name))
+    );
+    const subLoadersActiveTime = subLoaders.reduce((acc, loaders) => {
+      acc[loaders[0].loader] = getTotalActiveTime(loaders);
+      return acc;
+    }, {});
+
+    return {
+      averages,
+      activeTime,
+      loaders: startEnds[0].loaders,
+      subLoadersTime: subLoadersActiveTime,
+    };
+  });
+
+  return { build: buildData };
+};

package.json

@@ -3,6 +3,9 @@
   "version": "1.0.0",
   "description": "Measure + analyse the speed of your webpack loaders and plugins",
   "main": "index.js",
+  "scripts": {
+    "test": "jest"
+  },
   "repository": {
     "type": "git",
     "url": "git+https://github.com/stephencookdev/speed-measure-webpack-plugin.git"
@@ -24,6 +27,7 @@
     "webpack": "^3"
   },
   "devDependencies": {
+    "jest": "^22.3.0",
     "prettier": "1.10.2"
   }
 }

utils.js

@@ -51,11 +51,12 @@ module.exports.getLoaderNames = loaders =>
     ? loaders
         .map(l => l.loader)
         .map(l => l.replace(/^.*\/node_modules\/([^\/]+).*$/, (_, m) => m))
+        .filter(l => !l.includes("speed-measure-webpack-plugin"))
     : ["modules with no loaders"];
 
 module.exports.groupBy = (key, arr) => {
   const groups = [];
-  arr.forEach(arrItem => {
+  (arr || []).forEach(arrItem => {
     const groupItem = groups.find(poss => isEqual(poss[0][key], arrItem[key]));
     if (groupItem) groupItem.push(arrItem);
     else groups.push([arrItem]);
@@ -82,3 +83,56 @@ module.exports.getTotalActiveTime = group => {
   const mergedRanges = mergeRanges(group);
   return mergedRanges.reduce((acc, range) => acc + range.end - range.start, 0);
 };
+
+const prependLoader = rules => {
+  if (!rules) return rules;
+  if (Array.isArray(rules)) return rules.map(prependLoader);
+
+  if (rules.loader) {
+    rules.use = [rules.loader];
+    delete rules.loader;
+  }
+
+  if (rules.use) {
+    rules.use.unshift("speed-measure-webpack-plugin/loader");
+  }
+
+  if (rules.oneOf) {
+    rules.oneOf = prependLoader(rules.oneOf);
+  }
+  if (rules.rules) {
+    rules.rules = prependLoader(rules.rules);
+  }
+  if (Array.isArray(rules.resource)) {
+    rules.resource = prependLoader(rules.resource);
+  }
+  if (rules.resource && rules.resource.and) {
+    rules.resource.and = prependLoader(rules.resource.and);
+  }
+  if (rules.resource && rules.resource.or) {
+    rules.resource.or = prependLoader(rules.resource.or);
+  }
+
+  return rules;
+};
+module.exports.prependLoader = prependLoader;
+
+module.exports.hackWrapLoaders = (loaderPaths, callback) => {
+  const wrapReq = reqMethod => {
+    return function() {
+      const ret = reqMethod.apply(this, arguments);
+      if (loaderPaths.includes(arguments[0])) {
+        if(ret.__smpHacked) return ret;
+        ret.__smpHacked = true;
+        return callback(ret, arguments[0]);
+      }
+      return ret;
+    };
+  };
+
+  if (typeof System === "object" && typeof System.import === "function") {
+    System.import = wrapReq(System.import);
+  }
+  const Module = require("module");
+  Module.prototype.require = wrapReq(Module.prototype.require);
+};