diff --git a/bin/concurrently.js b/bin/concurrently.js index 9dc31fc6..ed4750db 100755 --- a/bin/concurrently.js +++ b/bin/concurrently.js @@ -62,6 +62,11 @@ const args = yargs default: defaults.hide, type: 'string' }, + 'show-timings': { + describe: 'Show timing information for all processes', + type: 'boolean', + default: defaults.showTimings + }, // Kill others 'k': { @@ -142,7 +147,7 @@ const args = yargs 'Can be either the index or the name of the process.' } }) - .group(['m', 'n', 'name-separator', 'raw', 's', 'no-color', 'hide'], 'General') + .group(['m', 'n', 'name-separator', 'raw', 's', 'no-color', 'hide', 'show-timings'], 'General') .group(['p', 'c', 'l', 't'], 'Prefix styling') .group(['i', 'default-input-target'], 'Input handling') .group(['k', 'kill-others-on-fail'], 'Killing other processes') @@ -172,6 +177,7 @@ concurrently(args._.map((command, index) => ({ restartTries: args.restartTries, successCondition: args.success, timestampFormat: args.timestampFormat, + showTimings: args.showTimings }).then( () => process.exit(0), () => process.exit(1) diff --git a/bin/concurrently.spec.js b/bin/concurrently.spec.js index aa1b84af..8172435d 100644 --- a/bin/concurrently.spec.js +++ b/bin/concurrently.spec.js @@ -346,7 +346,6 @@ describe('--handle-input', () => { }, done); }); - it('forwards input to process --default-input-target', done => { const lines = []; const child = run('-ki --default-input-target 1 "node fixtures/read-echo.js" "node fixtures/read-echo.js"'); @@ -383,3 +382,37 @@ describe('--handle-input', () => { }, done); }); }); + +describe('--show-timings', () => { + const dateRegex = '\\d+\/\\d+\/\\d+'; + const timeRegex = '\\d+:\\d+:\\d+(AM|PM|\\s)*'; + const processStartedMessageRegex = (index, command) => { + return new RegExp( `^\\[${ index }] ${ command } started at ${ dateRegex }, ${ timeRegex }$` ); + }; + const processStoppedMessageRegex = (index, command) => { + return new RegExp( `^\\[${ index }] ${ command } stopped at ${ dateRegex }, ${ timeRegex } after (\\d|,)+ms$` ); + }; + const expectLinesForProcessStartAndStop = (lines, index, command) => { + const escapedCommand = _.escapeRegExp(command); + expect(lines).toContainEqual(expect.stringMatching(processStartedMessageRegex(index, escapedCommand))); + expect(lines).toContainEqual(expect.stringMatching(processStoppedMessageRegex(index, escapedCommand))); + }; + + it('shows timings on success', done => { + const child = run('--show-timings "sleep 0.5" "exit 0"'); + child.log.pipe(buffer(child.close)).subscribe(lines => { + expectLinesForProcessStartAndStop(lines, 0, 'sleep 0.5'); + expectLinesForProcessStartAndStop(lines, 1, 'exit 0'); + done(); + }, done); + }); + + it('shows timings on failure', done => { + const child = run('--show-timings "sleep 0.75" "exit 1"'); + child.log.pipe(buffer(child.close)).subscribe(lines => { + expectLinesForProcessStartAndStop(lines, 0, 'sleep 0.75'); + expectLinesForProcessStartAndStop(lines, 1, 'exit 1'); + done(); + }, done); + }); +}); diff --git a/index.js b/index.js index 5abc24f0..9ad94634 100644 --- a/index.js +++ b/index.js @@ -8,6 +8,7 @@ const RestartProcess = require('./src/flow-control/restart-process'); const concurrently = require('./src/concurrently'); const Logger = require('./src/logger'); +const LogTimings = require( './src/flow-control/log-timings' ); module.exports = exports = (commands, options = {}) => { const logger = new Logger({ @@ -43,9 +44,13 @@ module.exports = exports = (commands, options = {}) => { new KillOthers({ logger, conditions: options.killOthers + }), + new LogTimings({ + logger: options.showTimings ? logger: null }) ], - prefixColors: options.prefixColors || [] + prefixColors: options.prefixColors || [], + showTimings: options.showTimings }); }; @@ -60,3 +65,4 @@ exports.LogError = LogError; exports.LogExit = LogExit; exports.LogOutput = LogOutput; exports.RestartProcess = RestartProcess; +exports.LogTimings = LogTimings; diff --git a/src/command.js b/src/command.js index f39c3b2f..9f2a60f7 100644 --- a/src/command.js +++ b/src/command.js @@ -17,6 +17,7 @@ module.exports = class Command { this.killed = false; this.error = new Rx.Subject(); + this.timer = new Rx.Subject(); this.close = new Rx.Subject(); this.stdout = new Rx.Subject(); this.stderr = new Rx.Subject(); @@ -26,13 +27,21 @@ module.exports = class Command { const child = this.spawn(this.command, this.spawnOpts); this.process = child; this.pid = child.pid; + const startDate = new Date(Date.now()); + const highResStartTime = process.hrtime(); + this.timer.next({startDate}); Rx.fromEvent(child, 'error').subscribe(event => { this.process = undefined; + const endDate = new Date(Date.now()); + this.timer.next({startDate, endDate}); this.error.next(event); }); Rx.fromEvent(child, 'close').subscribe(([exitCode, signal]) => { this.process = undefined; + const endDate = new Date(Date.now()); + this.timer.next({startDate, endDate}); + const [durationSeconds, durationNanoSeconds] = process.hrtime(highResStartTime); this.close.next({ command: { command: this.command, @@ -43,6 +52,11 @@ module.exports = class Command { index: this.index, exitCode: exitCode === null ? signal : exitCode, killed: this.killed, + timings: { + startDate, + endDate, + durationSeconds: durationSeconds + (durationNanoSeconds / 1e9), + } }); }); child.stdout && pipeTo(Rx.fromEvent(child.stdout, 'data'), this.stdout); diff --git a/src/command.spec.js b/src/command.spec.js index 9d64cc19..f111ad95 100644 --- a/src/command.spec.js +++ b/src/command.spec.js @@ -1,4 +1,5 @@ const EventEmitter = require('events'); +const process = require('process'); const Command = require('./command'); const createProcess = () => { @@ -54,6 +55,72 @@ describe('#start()', () => { process.emit('error', 'foo'); }); + it('shares start and close timing events to the timing stream', done => { + const process = createProcess(); + const command = new Command({ spawn: () => process }); + + const startDate = new Date(); + const endDate = new Date(startDate.getTime() + 1000); + jest.spyOn(Date, 'now') + .mockReturnValueOnce(startDate.getTime()) + .mockReturnValueOnce(endDate.getTime()); + + let callCount = 0; + command.timer.subscribe(({startDate: actualStartDate, endDate: actualEndDate}) => { + switch (callCount) { + case 0: + expect(actualStartDate).toStrictEqual(startDate); + expect(actualEndDate).toBeUndefined(); + break; + case 1: + expect(actualStartDate).toStrictEqual(startDate); + expect(actualEndDate).toStrictEqual(endDate); + done(); + break; + default: + throw new Error('Unexpected call count'); + } + callCount++; + }); + + command.start(); + process.emit('close', 0, null); + + }); + + it('shares start and error timing events to the timing stream', done => { + const process = createProcess(); + const command = new Command({ spawn: () => process }); + + const startDate = new Date(); + const endDate = new Date(startDate.getTime() + 1000); + jest.spyOn(Date, 'now') + .mockReturnValueOnce(startDate.getTime()) + .mockReturnValueOnce(endDate.getTime()); + + let callCount = 0; + command.timer.subscribe(({startDate: actualStartDate, endDate: actualEndDate}) => { + switch (callCount) { + case 0: + expect(actualStartDate).toStrictEqual(startDate); + expect(actualEndDate).toBeUndefined(); + break; + case 1: + expect(actualStartDate).toStrictEqual(startDate); + expect(actualEndDate).toStrictEqual(endDate); + done(); + break; + default: + throw new Error('Unexpected call count'); + } + callCount++; + }); + + command.start(); + process.emit('error', 0, null); + + }); + it('shares closes to the close stream with exit code', done => { const process = createProcess(); const command = new Command({ spawn: () => process }); @@ -83,6 +150,31 @@ describe('#start()', () => { process.emit('close', null, 'SIGKILL'); }); + it('shares closes to the close stream with timing information', done => { + const process1 = createProcess(); + const command = new Command({ spawn: () => process1 }); + + const startDate = new Date(); + const endDate = new Date(startDate.getTime() + 1000); + jest.spyOn(Date, 'now') + .mockReturnValueOnce(startDate.getTime()) + .mockReturnValueOnce(endDate.getTime()); + + jest.spyOn(process, 'hrtime') + .mockReturnValueOnce([0, 0]) + .mockReturnValueOnce([1, 1e8]); + + command.close.subscribe(data => { + expect(data.timings.startDate).toStrictEqual(startDate); + expect(data.timings.endDate).toStrictEqual(endDate); + expect(data.timings.durationSeconds).toBe(1.1); + done(); + }); + + command.start(); + process1.emit('close', null, 'SIGKILL'); + }); + it('shares closes to the close stream with command info and index', done => { const process = createProcess(); const commandInfo = { @@ -170,7 +262,7 @@ describe('#kill()', () => { it('marks the command as killed', done => { command.start(); - + command.close.subscribe(data => { expect(data.exitCode).toBe(1); expect(data.killed).toBe(true); diff --git a/src/completion-listener.js b/src/completion-listener.js index 791a49aa..c789c497 100644 --- a/src/completion-listener.js +++ b/src/completion-listener.js @@ -1,10 +1,12 @@ const Rx = require('rxjs'); -const { bufferCount, switchMap, take } = require('rxjs/operators'); +const { bufferCount, switchMap, take, tap } = require('rxjs/operators'); +const _ = require('lodash'); module.exports = class CompletionListener { - constructor({ successCondition, scheduler }) { + constructor({ successCondition, scheduler, showTimings}) { this.successCondition = successCondition; this.scheduler = scheduler; + this.showTimings = showTimings; } isSuccess(exitCodes) { @@ -22,6 +24,29 @@ module.exports = class CompletionListener { } } + printExitInfoTimingTableIfValid(exitInfos) { + if (!Array.isArray(exitInfos)) { return exitInfos; } + + const exitInfoTable = _(exitInfos) + .map(({ command, timings, index, killed, exitCode }) => { + const readableDurationMs = (timings.endDate - timings.startDate).toLocaleString(); + return { + 'call-index': index, + name: command.name, + duration: `~${readableDurationMs}ms`, + 'exit-code': exitCode, + killed, + command: command.command, + }; + }) + .sortBy('duration') + .value(); + + console.log('\nTimings:'); + console.table(exitInfoTable); + return exitInfos; + }; + listen(commands) { const closeStreams = commands.map(command => command.close); return Rx.merge(...closeStreams) @@ -32,7 +57,10 @@ module.exports = class CompletionListener { ? Rx.of(exitInfos, this.scheduler) : Rx.throwError(exitInfos, this.scheduler) ), - take(1) + take(1), + tap((exitInfos) => { + if (this.showTimings) { this.printExitInfoTimingTableIfValid(exitInfos); } + }) ) .toPromise(); } diff --git a/src/concurrently.js b/src/concurrently.js index 06b3574e..54d4bfd3 100644 --- a/src/concurrently.js +++ b/src/concurrently.js @@ -18,6 +18,7 @@ const defaults = { raw: false, controllers: [], cwd: undefined, + showTimings: false }; module.exports = (commands, options) => { @@ -50,6 +51,7 @@ module.exports = (commands, options) => { prefixColor: lastColor, killProcess: options.kill, spawn: options.spawn, + showTimings: options.showTimings, }, command) ); }) @@ -73,9 +75,12 @@ module.exports = (commands, options) => { maybeRunMore(commandsLeft); } - return new CompletionListener({ successCondition: options.successCondition }) + return new CompletionListener({ + successCondition: options.successCondition, + showTimings: options.showTimings + }) .listen(commands) - .finally(() => { + .finally((...args) => { handleResult.onFinishCallbacks.forEach((onFinish) => onFinish()); }); }; @@ -86,6 +91,7 @@ function mapToCommandInfo(command) { name: command.name || '', env: command.env || {}, cwd: command.cwd || '', + }, command.prefixColor ? { prefixColor: command.prefixColor, } : {}); diff --git a/src/defaults.js b/src/defaults.js index 695c0dd1..97e99a9f 100644 --- a/src/defaults.js +++ b/src/defaults.js @@ -29,5 +29,7 @@ module.exports = { // Refer to https://date-fns.org/v2.0.1/docs/format timestampFormat: 'yyyy-MM-dd HH:mm:ss.SSS', // Current working dir passed as option to spawn command. Default: process.cwd() - cwd: undefined + cwd: undefined, + // Whether to show timing information for processes in console output + showTimings: false, }; diff --git a/src/flow-control/fixtures/fake-command.js b/src/flow-control/fixtures/fake-command.js index 7c057ab1..a5fbb53c 100644 --- a/src/flow-control/fixtures/fake-command.js +++ b/src/flow-control/fixtures/fake-command.js @@ -10,6 +10,7 @@ module.exports = (name = 'foo', command = 'echo foo', index = 0) => ({ error: new Subject(), stderr: new Subject(), stdout: new Subject(), + timer: new Subject(), stdin: createMockInstance(Writable), start: jest.fn(), kill: jest.fn() diff --git a/src/flow-control/log-timings.js b/src/flow-control/log-timings.js new file mode 100644 index 00000000..c7b853ac --- /dev/null +++ b/src/flow-control/log-timings.js @@ -0,0 +1,21 @@ +const BaseHandler = require('./base-handler'); + +module.exports = class LogTimings extends BaseHandler { + handle(commands) { + commands.forEach(command => { + this.logger && command.timer.subscribe( { + next: ({startDate, endDate}) => { + if (!endDate) { + this.logger.logCommandEvent( `${ command.command } started at ${ startDate.toLocaleString() }`, command ); + } else { + const durationMs = (endDate.getTime() - startDate.getTime()); + + this.logger.logCommandEvent( `${ command.command } stopped at ${ endDate.toLocaleString() } after ${durationMs.toLocaleString()}ms`, command ); + } + }, + } ); + }); + + return { commands }; + } +}; diff --git a/src/flow-control/log-timings.spec.js b/src/flow-control/log-timings.spec.js new file mode 100644 index 00000000..8486b884 --- /dev/null +++ b/src/flow-control/log-timings.spec.js @@ -0,0 +1,69 @@ +const { createMockInstance } = require('jest-create-mock-instance'); +const Logger = require('../logger'); +const LogTimings = require( './log-timings' ); +const createFakeCommand = require('./fixtures/fake-command'); + +let controller, logger, commands; + +// shown in timing order +const startDate0 = new Date(); +const startDate1 = new Date(startDate0.getTime() + 1000); +const endDate1 = new Date(startDate0.getTime() + 3000); +const endDate0 = new Date(startDate0.getTime() + 5000); + +const getDurationText = (startDate, endDate) => (endDate.getTime() - startDate.getTime()).toLocaleString(); +const command0DurationTextMs = getDurationText(startDate0, endDate0); +const command1DurationTextMs = getDurationText(startDate1, endDate1); + +beforeEach(() => { + commands = [ + createFakeCommand(), + createFakeCommand(), + ]; + + logger = createMockInstance(Logger); + controller = new LogTimings({ logger }); +}); + +it('returns same commands', () => { + expect(controller.handle(commands)).toMatchObject({ commands }); +}); + +it('does not log timings and doesn\'t throw if no logger is provided', () => { + controller = new LogTimings({ }); + controller.handle(commands); + + commands[0].timer.next({ startDate: startDate0 }); + commands[1].timer.next({ startDate: startDate1 }); + commands[1].timer.next({startDate: startDate1, endDate: endDate1 }); + commands[0].timer.next({startDate: startDate0, endDate: endDate0 }); + + expect(logger.logCommandEvent).toHaveBeenCalledTimes(0); +}); + +it('logs the timings at the start and end (ie complete or error) event of each command', () => { + controller.handle(commands); + + commands[0].timer.next({ startDate: startDate0 }); + commands[1].timer.next({ startDate: startDate1 }); + commands[1].timer.next({startDate: startDate1, endDate: endDate1 }); + commands[0].timer.next({startDate: startDate0, endDate: endDate0 }); + + expect(logger.logCommandEvent).toHaveBeenCalledTimes(4); + expect(logger.logCommandEvent).toHaveBeenCalledWith( + `${commands[0].command} started at ${startDate0.toLocaleString()}`, + commands[0] + ); + expect(logger.logCommandEvent).toHaveBeenCalledWith( + `${commands[1].command} started at ${startDate1.toLocaleString()}`, + commands[1] + ); + expect(logger.logCommandEvent).toHaveBeenCalledWith( + `${commands[1].command} stopped at ${endDate1.toLocaleString()} after ${command1DurationTextMs}ms`, + commands[1] + ); + expect(logger.logCommandEvent).toHaveBeenCalledWith( + `${commands[0].command} stopped at ${endDate0.toLocaleString()} after ${command0DurationTextMs}ms`, + commands[0] + ); +});