diff --git a/commands/exec/README.md b/commands/exec/README.md index a6184b52d1..529210d807 100644 --- a/commands/exec/README.md +++ b/commands/exec/README.md @@ -79,3 +79,27 @@ Pass `--no-bail` to disable this behavior, executing in _all_ packages regardles Disable package name prefixing when output is streaming (`--stream` _or_ `--parallel`). This option can be useful when piping results to other processes, such as editor plugins. + +### `--profile` + +Profiles the command executions and produces a performance profile which can be analyzed using DevTools in a +Chromium-based browser (direct url: `devtools://devtools/bundled/devtools_app.html`). The profile shows a timeline of +the command executions where each execution is assigned to an open slot. The number of slots is determined by the +`--concurrency` option and the number of open slots is determined by `--concurrency` minus the number of ongoing +operations. The end result is a visualization of the parallel execution of your commands. + +The default location of the performance profile output is at the root of your project. + +```sh +$ lerna exec --profile -- +``` + +> **Note:** Lerna will only profile when topological sorting is enabled (i.e. without `--parallel` and `--no-sort`). + +### `--profile-location ` + +You can provide a custom location for the performance profile output. The path provided will be resolved relative to the current working directory. + +```sh +$ lerna exec --profile --profile-location=logs/profile/ -- +``` diff --git a/commands/exec/__tests__/exec-command.test.js b/commands/exec/__tests__/exec-command.test.js index a82d9ce075..4cc4b59be0 100644 --- a/commands/exec/__tests__/exec-command.test.js +++ b/commands/exec/__tests__/exec-command.test.js @@ -1,6 +1,8 @@ "use strict"; const path = require("path"); +const fs = require("fs-extra"); +const globby = require("globby"); // mocked modules const ChildProcessUtilities = require("@lerna/child-process"); @@ -191,6 +193,42 @@ describe("ExecCommand", () => { }); }); + describe("with --profile", () => { + it("executes a profiled command in all packages", async () => { + const cwd = await initFixture("basic"); + + await lernaExec(cwd)("--profile", "--", "ls"); + + const [profileLocation] = await globby("Lerna-Profile-*.json", { cwd, absolute: true }); + const json = await fs.readJson(profileLocation); + + expect(json).toMatchObject([ + { + name: "package-1", + ph: "X", + ts: expect.any(Number), + pid: 1, + tid: expect.any(Number), + dur: expect.any(Number), + }, + { + name: "package-2", + }, + ]); + }); + + it("accepts --profile-location", async () => { + const cwd = await initFixture("basic"); + + await lernaExec(cwd)("--profile", "--profile-location", "foo/bar", "--", "ls"); + + const [profileLocation] = await globby("foo/bar/Lerna-Profile-*.json", { cwd, absolute: true }); + const exists = await fs.exists(profileLocation); + + expect(exists).toBe(true); + }); + }); + describe("with --no-sort", () => { it("runs commands in lexical (not topological) order", async () => { const testDir = await initFixture("toposort"); diff --git a/commands/exec/command.js b/commands/exec/command.js index 4d64622fd2..dc1eb40077 100644 --- a/commands/exec/command.js +++ b/commands/exec/command.js @@ -57,6 +57,16 @@ exports.builder = yargs => { hidden: true, type: "boolean", }, + profile: { + group: "Command Options:", + describe: "Profile command executions and output performance profile to default location.", + type: "boolean", + }, + "profile-location": { + group: "Command Options:", + describe: "Output performance profile to custom location instead of default project root.", + type: "string", + }, }); return filterable(yargs); diff --git a/commands/exec/index.js b/commands/exec/index.js index bc104cb625..7e2d935853 100644 --- a/commands/exec/index.js +++ b/commands/exec/index.js @@ -4,6 +4,7 @@ const pMap = require("p-map"); const ChildProcessUtilities = require("@lerna/child-process"); const Command = require("@lerna/command"); +const Profiler = require("@lerna/profiler"); const runTopologically = require("@lerna/run-topologically"); const ValidationError = require("@lerna/validation-error"); const { getFilteredPackages } = require("@lerna/filter-options"); @@ -119,15 +120,39 @@ class ExecCommand extends Command { }; } - runCommandInPackagesTopological() { - const runner = this.options.stream + getRunner() { + return this.options.stream ? pkg => this.runCommandInPackageStreaming(pkg) : pkg => this.runCommandInPackageCapturing(pkg); + } + + runCommandInPackagesTopological() { + let profiler; + let runner; + + if (this.options.profile) { + profiler = new Profiler({ + concurrency: this.concurrency, + log: this.logger, + outputDirectory: this.options.profileLocation || this.project.rootPath, + }); + + const callback = this.getRunner(); + runner = pkg => profiler.run(() => callback(pkg), pkg.name); + } else { + runner = this.getRunner(); + } - return runTopologically(this.filteredPackages, runner, { + let chain = runTopologically(this.filteredPackages, runner, { concurrency: this.concurrency, rejectCycles: this.options.rejectCycles, }); + + if (profiler) { + chain = chain.then(results => profiler.output().then(() => results)); + } + + return chain; } runCommandInPackagesParallel() { @@ -135,11 +160,7 @@ class ExecCommand extends Command { } runCommandInPackagesLexical() { - const runner = this.options.stream - ? pkg => this.runCommandInPackageStreaming(pkg) - : pkg => this.runCommandInPackageCapturing(pkg); - - return pMap(this.filteredPackages, runner, { concurrency: this.concurrency }); + return pMap(this.filteredPackages, this.getRunner(), { concurrency: this.concurrency }); } runCommandInPackageStreaming(pkg) { diff --git a/commands/exec/package.json b/commands/exec/package.json index 367c1c3e6b..8008cb617d 100644 --- a/commands/exec/package.json +++ b/commands/exec/package.json @@ -35,6 +35,7 @@ "@lerna/child-process": "file:../../core/child-process", "@lerna/command": "file:../../core/command", "@lerna/filter-options": "file:../../core/filter-options", + "@lerna/profiler": "file:../../utils/profiler", "@lerna/run-topologically": "file:../../utils/run-topologically", "@lerna/validation-error": "file:../../core/validation-error", "p-map": "^2.1.0" diff --git a/commands/run/README.md b/commands/run/README.md index a7048c577d..55bffd6446 100644 --- a/commands/run/README.md +++ b/commands/run/README.md @@ -82,3 +82,27 @@ Pass `--no-bail` to disable this behavior, running the script in _all_ packages Disable package name prefixing when output is streaming (`--stream` _or_ `--parallel`). This option can be useful when piping results to other processes, such as editor plugins. + +### `--profile` + +Profiles the script executions and produces a performance profile which can be analyzed using DevTools in a +Chromium-based browser (direct url: `devtools://devtools/bundled/devtools_app.html`). The profile shows a timeline of +the script executions where each execution is assigned to an open slot. The number of slots is determined by the +`--concurrency` option and the number of open slots is determined by `--concurrency` minus the number of ongoing +operations. The end result is a visualization of the parallel execution of your scripts. + +The default location of the performance profile output is at the root of your project. + +```sh +$ lerna run build --profile +``` + +> **Note:** Lerna will only profile when topological sorting is enabled (i.e. without `--parallel` and `--no-sort`). + +### `--profile-location ` + +You can provide a custom location for the performance profile output. The path provided will be resolved relative to the current working directory. + +```sh +$ lerna run build --profile --profile-location=logs/profile/ +``` diff --git a/commands/run/__tests__/run-command.test.js b/commands/run/__tests__/run-command.test.js index b5f2de723f..8a143e84e4 100644 --- a/commands/run/__tests__/run-command.test.js +++ b/commands/run/__tests__/run-command.test.js @@ -2,6 +2,9 @@ jest.mock("@lerna/npm-run-script"); +const fs = require("fs-extra"); +const globby = require("globby"); + // mocked modules const npmRunScript = require("@lerna/npm-run-script"); const output = require("@lerna/output"); @@ -161,6 +164,42 @@ describe("RunCommand", () => { }); }); + describe("with --profile", () => { + it("executes a profiled command in all packages", async () => { + const cwd = await initFixture("basic"); + + await lernaRun(cwd)("--profile", "my-script"); + + const [profileLocation] = await globby("Lerna-Profile-*.json", { cwd, absolute: true }); + const json = await fs.readJson(profileLocation); + + expect(json).toMatchObject([ + { + name: "package-1", + ph: "X", + ts: expect.any(Number), + pid: 1, + tid: expect.any(Number), + dur: expect.any(Number), + }, + { + name: "package-3", + }, + ]); + }); + + it("accepts --profile-location", async () => { + const cwd = await initFixture("basic"); + + await lernaRun(cwd)("--profile", "--profile-location", "foo/bar", "my-script"); + + const [profileLocation] = await globby("foo/bar/Lerna-Profile-*.json", { cwd, absolute: true }); + const exists = await fs.exists(profileLocation); + + expect(exists).toBe(true); + }); + }); + describe("with --no-sort", () => { it("runs scripts in lexical (not topological) order", async () => { const testDir = await initFixture("toposort"); diff --git a/commands/run/command.js b/commands/run/command.js index 4564b5f57f..6cfbebaa5c 100644 --- a/commands/run/command.js +++ b/commands/run/command.js @@ -59,6 +59,16 @@ exports.builder = yargs => { hidden: true, type: "boolean", }, + profile: { + group: "Command Options:", + describe: "Profile script executions and output performance profile to default location.", + type: "boolean", + }, + "profile-location": { + group: "Command Options:", + describe: "Output performance profile to custom location instead of default project root.", + type: "string", + }, }); return filterable(yargs); diff --git a/commands/run/index.js b/commands/run/index.js index c9e920fde9..c6eb9ee965 100644 --- a/commands/run/index.js +++ b/commands/run/index.js @@ -5,6 +5,7 @@ const pMap = require("p-map"); const Command = require("@lerna/command"); const npmRunScript = require("@lerna/npm-run-script"); const output = require("@lerna/output"); +const Profiler = require("@lerna/profiler"); const timer = require("@lerna/timer"); const runTopologically = require("@lerna/run-topologically"); const ValidationError = require("@lerna/validation-error"); @@ -127,15 +128,39 @@ class RunCommand extends Command { }; } - runScriptInPackagesTopological() { - const runner = this.options.stream + getRunner() { + return this.options.stream ? pkg => this.runScriptInPackageStreaming(pkg) : pkg => this.runScriptInPackageCapturing(pkg); + } + + runScriptInPackagesTopological() { + let profiler; + let runner; + + if (this.options.profile) { + profiler = new Profiler({ + concurrency: this.concurrency, + log: this.logger, + outputDirectory: this.options.profileLocation, + }); + + const callback = this.getRunner(); + runner = pkg => profiler.run(() => callback(pkg), pkg.name); + } else { + runner = this.getRunner(); + } - return runTopologically(this.packagesWithScript, runner, { + let chain = runTopologically(this.packagesWithScript, runner, { concurrency: this.concurrency, rejectCycles: this.options.rejectCycles, }); + + if (profiler) { + chain = chain.then(results => profiler.output().then(() => results)); + } + + return chain; } runScriptInPackagesParallel() { @@ -143,11 +168,7 @@ class RunCommand extends Command { } runScriptInPackagesLexical() { - const runner = this.options.stream - ? pkg => this.runScriptInPackageStreaming(pkg) - : pkg => this.runScriptInPackageCapturing(pkg); - - return pMap(this.packagesWithScript, runner, { concurrency: this.concurrency }); + return pMap(this.packagesWithScript, this.getRunner(), { concurrency: this.concurrency }); } runScriptInPackageStreaming(pkg) { diff --git a/commands/run/package.json b/commands/run/package.json index 937465fb53..87601b95eb 100644 --- a/commands/run/package.json +++ b/commands/run/package.json @@ -36,6 +36,7 @@ "@lerna/filter-options": "file:../../core/filter-options", "@lerna/npm-run-script": "file:../../utils/npm-run-script", "@lerna/output": "file:../../utils/output", + "@lerna/profiler": "file:../../utils/profiler", "@lerna/run-topologically": "file:../../utils/run-topologically", "@lerna/timer": "file:../../utils/timer", "@lerna/validation-error": "file:../../core/validation-error", diff --git a/package-lock.json b/package-lock.json index 634dd30f36..10747393f5 100644 --- a/package-lock.json +++ b/package-lock.json @@ -958,6 +958,7 @@ "@lerna/child-process": "file:core/child-process", "@lerna/command": "file:core/command", "@lerna/filter-options": "file:core/filter-options", + "@lerna/profiler": "file:utils/profiler", "@lerna/run-topologically": "file:utils/run-topologically", "@lerna/validation-error": "file:core/validation-error", "p-map": "^2.1.0" @@ -1191,6 +1192,15 @@ "semver": "^6.2.0" } }, + "@lerna/profiler": { + "version": "file:utils/profiler", + "requires": { + "figgy-pudding": "^3.5.1", + "fs-extra": "^8.1.0", + "npmlog": "^4.1.2", + "upath": "^1.2.0" + } + }, "@lerna/project": { "version": "file:core/project", "requires": { @@ -1287,6 +1297,7 @@ "@lerna/filter-options": "file:core/filter-options", "@lerna/npm-run-script": "file:utils/npm-run-script", "@lerna/output": "file:utils/output", + "@lerna/profiler": "file:utils/profiler", "@lerna/run-topologically": "file:utils/run-topologically", "@lerna/timer": "file:utils/timer", "@lerna/validation-error": "file:core/validation-error", @@ -9312,6 +9323,11 @@ } } }, + "upath": { + "version": "1.2.0", + "resolved": "https://registry.npmjs.org/upath/-/upath-1.2.0.tgz", + "integrity": "sha512-aZwGpamFO61g3OlfT7OQCHqhGnW43ieH9WZeP7QxN/G/jS4jfqUkZxoryvJgVPEcrl5NL/ggHsSmLMHuH64Lhg==" + }, "uri-js": { "version": "4.2.2", "resolved": "https://registry.npmjs.org/uri-js/-/uri-js-4.2.2.tgz", diff --git a/utils/profiler/README.md b/utils/profiler/README.md new file mode 100644 index 0000000000..e6da87f11a --- /dev/null +++ b/utils/profiler/README.md @@ -0,0 +1,9 @@ +# `@lerna/profiler` + +> An internal Lerna tool + +## Usage + +You probably shouldn't, at least directly. + +Install [lerna](https://www.npmjs.com/package/lerna) for access to the `lerna` CLI. diff --git a/utils/profiler/package.json b/utils/profiler/package.json new file mode 100644 index 0000000000..80bf940ba1 --- /dev/null +++ b/utils/profiler/package.json @@ -0,0 +1,39 @@ +{ + "name": "@lerna/profiler", + "version": "3.18.5", + "description": "An internal Lerna tool", + "keywords": [ + "lerna", + "utils" + ], + "homepage": "https://github.com/lerna/lerna/tree/master/utils/profiler#readme", + "license": "MIT", + "author": { + "name": "Benjamin Weggersen", + "url": "https://github.com/bweggersen" + }, + "files": [ + "profiler.js" + ], + "main": "profiler.js", + "engines": { + "node": ">= 6.9.0" + }, + "publishConfig": { + "access": "public" + }, + "repository": { + "type": "git", + "url": "git+https://github.com/lerna/lerna.git", + "directory": "utils/profiler" + }, + "scripts": { + "test": "echo \"Run tests from root\" && exit 1" + }, + "dependencies": { + "figgy-pudding": "^3.5.1", + "fs-extra": "^8.1.0", + "npmlog": "^4.1.2", + "upath": "^1.2.0" + } +} diff --git a/utils/profiler/profiler.js b/utils/profiler/profiler.js new file mode 100644 index 0000000000..32823ba6ac --- /dev/null +++ b/utils/profiler/profiler.js @@ -0,0 +1,81 @@ +"use strict"; + +const figgyPudding = require("figgy-pudding"); +const fs = require("fs-extra"); +const npmlog = require("npmlog"); +const upath = require("upath"); + +const hrtimeToMicroseconds = hrtime => { + return (hrtime[0] * 1e9 + hrtime[1]) / 1000; +}; + +const range = len => { + return Array(len) + .fill() + .map((_, idx) => idx); +}; + +const getTimeBasedFilename = () => { + const now = new Date(); // 2011-10-05T14:48:00.000Z + const datetime = now.toISOString().split(".")[0]; // 2011-10-05T14:48:00 + const datetimeNormalized = datetime.replace(/-|:/g, ""); // 20111005T144800 + return `Lerna-Profile-${datetimeNormalized}.json`; +}; + +const ProfilerConfig = figgyPudding({ + concurrency: {}, + log: { default: npmlog }, + outputDirectory: {}, +}); + +class Profiler { + constructor(opts) { + const { concurrency, log, outputDirectory } = ProfilerConfig(opts); + + this.events = []; + this.logger = log; + this.outputPath = upath.join(upath.resolve(outputDirectory || "."), getTimeBasedFilename()); + this.threads = range(concurrency); + } + + run(fn, name) { + let startTime; + let threadId; + + return Promise.resolve() + .then(() => { + startTime = process.hrtime(); + threadId = this.threads.shift(); + }) + .then(() => fn()) + .then(value => { + const duration = process.hrtime(startTime); + + // Trace Event Format documentation: + // https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview + const event = { + name, + ph: "X", + ts: hrtimeToMicroseconds(startTime), + pid: 1, + tid: threadId, + dur: hrtimeToMicroseconds(duration), + }; + + this.events.push(event); + + this.threads.unshift(threadId); + this.threads.sort(); + + return value; + }); + } + + output() { + return fs + .outputJson(this.outputPath, this.events) + .then(() => this.logger.info("profiler", `Performance profile saved to ${this.outputPath}`)); + } +} + +module.exports = Profiler;