Add timing functionality (#295)

bin/concurrently.js

@@ -62,6 +62,11 @@ const args = yargs
             default: defaults.hide,
             type: 'string'
         },
+        'timings': {
+            describe: 'Show timing information for all processes',
+            type: 'boolean',
+            default: defaults.timings
+        },
 
         // 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', '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,
+    timings: args.timings
 }).then(
     () => process.exit(0),
     () => process.exit(1)

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,47 @@ describe('--handle-input', () => {
         }, done);
     });
 });
+
+describe('--timings', () => {
+    const defaultTimestampFormatRegex = /\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d{3}/;
+    const processStartedMessageRegex = (index, command) => {
+        return new RegExp( `^\\[${ index }] ${ command } started at ${ defaultTimestampFormatRegex.source }$` );
+    };
+    const processStoppedMessageRegex = (index, command) => {
+        return new RegExp( `^\\[${ index }] ${ command } stopped at ${ defaultTimestampFormatRegex.source } 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)));
+    };
+
+    const expectLinesForTimingsTable = (lines) => {
+        const tableTopBorderRegex = /┌[─┬]+┐/g;
+        expect(lines).toContainEqual(expect.stringMatching(tableTopBorderRegex));
+        const tableHeaderRowRegex = /(\W+(name|duration|exit code|killed|command)\W+){5}/g;
+        expect(lines).toContainEqual(expect.stringMatching(tableHeaderRowRegex));
+        const tableBottomBorderRegex = /└[─┴]+┘/g;
+        expect(lines).toContainEqual(expect.stringMatching(tableBottomBorderRegex));
+    };
+
+    it('shows timings on success', done => {
+        const child = run('--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');
+            expectLinesForTimingsTable(lines);
+            done();
+        }, done);
+    });
+
+    it('shows timings on failure', done => {
+        const child = run('--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');
+            expectLinesForTimingsTable(lines);
+            done();
+        }, done);
+    });
+});

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,14 @@ module.exports = exports = (commands, options = {}) => {
             new KillOthers({
                 logger,
                 conditions: options.killOthers
+            }),
+            new LogTimings({
+                logger: options.timings ? logger: null,
+                timestampFormat: options.timestampFormat,
             })
         ],
-        prefixColors: options.prefixColors || []
+        prefixColors: options.prefixColors || [],
+        timings: options.timings
     });
 };
 
@@ -60,3 +66,4 @@ exports.LogError = LogError;
 exports.LogExit = LogExit;
 exports.LogOutput = LogOutput;
 exports.RestartProcess = RestartProcess;
+exports.LogTimings = LogTimings;

src/command-parser/expand-npm-wildcard.spec.js

@@ -1,4 +1,5 @@
 const ExpandNpmWildcard = require('./expand-npm-wildcard');
+const fs = require('fs');
 
 let parser, readPkg;
 
@@ -7,6 +8,34 @@ beforeEach(() => {
     parser = new ExpandNpmWildcard(readPkg);
 });
 
+describe('ExpandNpmWildcard#readPackage', () => {
+    it('can read package', () => {
+        const expectedPackage = {
+            'name': 'concurrently',
+            'version': '6.4.0',
+        };
+        jest.spyOn(fs, 'readFileSync').mockImplementation((path, options) => {
+            if (path === 'package.json') {
+                return JSON.stringify(expectedPackage);
+            }
+            return null;
+        });
+
+        const actualReadPackage = ExpandNpmWildcard.readPackage();
+        expect(actualReadPackage).toEqual(expectedPackage);
+    });
+
+    it('can handle errors reading package', () => {
+        jest.spyOn(fs, 'readFileSync').mockImplementation(() => {
+            throw new Error('Error reading package');
+        });
+
+        expect(() => ExpandNpmWildcard.readPackage()).not.toThrow();
+        expect(ExpandNpmWildcard.readPackage()).toEqual({});
+    });
+
+});
+
 it('returns same command if not an npm run command', () => {
     const commandInfo = {
         command: 'npm test'

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);

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);

src/completion-listener.js

@@ -32,7 +32,7 @@ module.exports = class CompletionListener {
                         ? Rx.of(exitInfos, this.scheduler)
                         : Rx.throwError(exitInfos, this.scheduler)
                 ),
-                take(1)
+                take(1),
             )
             .toPromise();
     }

src/completion-listener.spec.js

@@ -85,4 +85,5 @@ describe('with success condition set to last', () => {
 
         return expect(result).rejects.toEqual([{ exitCode: 0 }, { exitCode: 1 }]);
     });
+
 });

src/concurrently.js

@@ -18,6 +18,7 @@ const defaults = {
     raw: false,
     controllers: [],
     cwd: undefined,
+    timings: false
 };
 
 module.exports = (commands, options) => {
@@ -50,6 +51,7 @@ module.exports = (commands, options) => {
                     prefixColor: lastColor,
                     killProcess: options.kill,
                     spawn: options.spawn,
+                    timings: options.timings,
                 }, command)
             );
         })
@@ -73,7 +75,9 @@ module.exports = (commands, options) => {
         maybeRunMore(commandsLeft);
     }
 
-    return new CompletionListener({ successCondition: options.successCondition })
+    return new CompletionListener({
+        successCondition: options.successCondition,
+    })
         .listen(commands)
         .finally(() => {
             handleResult.onFinishCallbacks.forEach((onFinish) => onFinish());
@@ -86,6 +90,7 @@ function mapToCommandInfo(command) {
         name: command.name || '',
         env: command.env || {},
         cwd: command.cwd || '',
+
     }, command.prefixColor ? {
         prefixColor: command.prefixColor,
     } : {});

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
+    timings: false,
 };

src/flow-control/base-handler.spec.js

@@ -0,0 +1,22 @@
+const stream = require('stream');
+const { createMockInstance } = require('jest-create-mock-instance');
+
+const Logger = require('../logger');
+const createFakeCommand = require('./fixtures/fake-command');
+const BaseHandler = require('./base-handler');
+
+let commands, controller, inputStream, logger;
+
+beforeEach(() => {
+    commands = [
+        createFakeCommand('foo', 'echo foo', 0),
+        createFakeCommand('bar', 'echo bar', 1),
+    ];
+    inputStream = new stream.PassThrough();
+    logger = createMockInstance(Logger);
+    controller = new BaseHandler({ logger });
+});
+
+it('returns same commands and null onFinish callback by default', () => {
+    expect(controller.handle(commands)).toMatchObject({ commands, onFinish: null });
+});