291 add timing functionality

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)

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,48 @@ 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)));
+    };
+
+    const expectLinesForTimingsTable = (lines) => {
+        const tableTopBorderRegex = /┌[─┬]+┐/g;
+        expect(lines).toContainEqual(expect.stringMatching(tableTopBorderRegex));
+        const tableHeaderRowRegex = /(\W+(\(index\)|call-index|name|duration|exit-code|killed|command)\W+){7}/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('--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');
+            expectLinesForTimingsTable(lines);
+            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');
+            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,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;

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

@@ -2,9 +2,10 @@ const Rx = require('rxjs');
 const { bufferCount, switchMap, take } = require('rxjs/operators');
 
 module.exports = class CompletionListener {
-    constructor({ successCondition, scheduler }) {
+    constructor({ successCondition, scheduler, showTimings}) {
         this.successCondition = successCondition;
         this.scheduler = scheduler;
+        this.showTimings = showTimings;
     }
 
     isSuccess(exitCodes) {
@@ -32,7 +33,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,
+    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,
     } : {});

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,
 };

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