Skip to content

Commit fbda2f7

Browse files
eliasm307eliasm307
committed
291 add timing functionality
1 parent 0da5d93 commit fbda2f7

File tree

12 files changed

+361
-9
lines changed

12 files changed

+361
-9
lines changed

‎bin/concurrently.js‎

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -62,6 +62,11 @@ const args = yargs
6262
default: defaults.hide,
6363
type: 'string'
6464
},
65+
'show-timings': {
66+
describe: 'Show timing information for all processes',
67+
type: 'boolean',
68+
default: defaults.showTimings
69+
},
6570

6671
// Kill others
6772
'k': {
@@ -142,7 +147,7 @@ const args = yargs
142147
'Can be either the index or the name of the process.'
143148
}
144149
})
145-
.group(['m', 'n', 'name-separator', 'raw', 's', 'no-color', 'hide'], 'General')
150+
.group(['m', 'n', 'name-separator', 'raw', 's', 'no-color', 'hide', 'show-timings'], 'General')
146151
.group(['p', 'c', 'l', 't'], 'Prefix styling')
147152
.group(['i', 'default-input-target'], 'Input handling')
148153
.group(['k', 'kill-others-on-fail'], 'Killing other processes')
@@ -172,6 +177,7 @@ concurrently(args._.map((command, index) => ({
172177
restartTries: args.restartTries,
173178
successCondition: args.success,
174179
timestampFormat: args.timestampFormat,
180+
showTimings: args.showTimings
175181
}).then(
176182
() => process.exit(0),
177183
() => process.exit(1)

‎bin/concurrently.spec.js‎

Lines changed: 34 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -346,7 +346,6 @@ describe('--handle-input', () => {
346346
}, done);
347347
});
348348

349-
350349
it('forwards input to process --default-input-target', done => {
351350
const lines = [];
352351
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', () => {
383382
}, done);
384383
});
385384
});
385+
386+
describe('--show-timings', () => {
387+
const dateRegex = '\\d+\/\\d+\/\\d+';
388+
const timeRegex = '\\d+:\\d+:\\d+(AM|PM|\\s)*';
389+
const processStartedMessageRegex = (index, command) => {
390+
return new RegExp( `^\\[${ index }] ${ command } started at ${ dateRegex }, ${ timeRegex }$` );
391+
};
392+
const processStoppedMessageRegex = (index, command) => {
393+
return new RegExp( `^\\[${ index }] ${ command } stopped at ${ dateRegex }, ${ timeRegex } after (\\d|,)+ms$` );
394+
};
395+
const expectLinesForProcessStartAndStop = (lines, index, command) => {
396+
const escapedCommand = _.escapeRegExp(command);
397+
expect(lines).toContainEqual(expect.stringMatching(processStartedMessageRegex(index, escapedCommand)));
398+
expect(lines).toContainEqual(expect.stringMatching(processStoppedMessageRegex(index, escapedCommand)));
399+
};
400+
401+
it('shows timings on success', done => {
402+
const child = run('--show-timings "sleep 0.5" "exit 0"');
403+
child.log.pipe(buffer(child.close)).subscribe(lines => {
404+
expectLinesForProcessStartAndStop(lines, 0, 'sleep 0.5');
405+
expectLinesForProcessStartAndStop(lines, 1, 'exit 0');
406+
done();
407+
}, done);
408+
});
409+
410+
it('shows timings on failure', done => {
411+
const child = run('--show-timings "sleep 0.75" "exit 1"');
412+
child.log.pipe(buffer(child.close)).subscribe(lines => {
413+
expectLinesForProcessStartAndStop(lines, 0, 'sleep 0.75');
414+
expectLinesForProcessStartAndStop(lines, 1, 'exit 1');
415+
done();
416+
}, done);
417+
});
418+
});

‎index.js‎

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@ const RestartProcess = require('./src/flow-control/restart-process');
88

99
const concurrently = require('./src/concurrently');
1010
const Logger = require('./src/logger');
11+
const LogTimings = require( './src/flow-control/log-timings' );
1112

1213
module.exports = exports = (commands, options = {}) => {
1314
const logger = new Logger({
@@ -43,9 +44,13 @@ module.exports = exports = (commands, options = {}) => {
4344
new KillOthers({
4445
logger,
4546
conditions: options.killOthers
47+
}),
48+
new LogTimings({
49+
logger: options.showTimings ? logger: null
4650
})
4751
],
48-
prefixColors: options.prefixColors || []
52+
prefixColors: options.prefixColors || [],
53+
showTimings: options.showTimings
4954
});
5055
};
5156

@@ -60,3 +65,4 @@ exports.LogError = LogError;
6065
exports.LogExit = LogExit;
6166
exports.LogOutput = LogOutput;
6267
exports.RestartProcess = RestartProcess;
68+
exports.LogTimings = LogTimings;

‎src/command.js‎

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ module.exports = class Command {
1717
this.killed = false;
1818

1919
this.error = new Rx.Subject();
20+
this.timer = new Rx.Subject();
2021
this.close = new Rx.Subject();
2122
this.stdout = new Rx.Subject();
2223
this.stderr = new Rx.Subject();
@@ -26,13 +27,21 @@ module.exports = class Command {
2627
const child = this.spawn(this.command, this.spawnOpts);
2728
this.process = child;
2829
this.pid = child.pid;
30+
const startDate = new Date(Date.now());
31+
const highResStartTime = process.hrtime();
32+
this.timer.next({startDate});
2933

3034
Rx.fromEvent(child, 'error').subscribe(event => {
3135
this.process = undefined;
36+
const endDate = new Date(Date.now());
37+
this.timer.next({startDate, endDate});
3238
this.error.next(event);
3339
});
3440
Rx.fromEvent(child, 'close').subscribe(([exitCode, signal]) => {
3541
this.process = undefined;
42+
const endDate = new Date(Date.now());
43+
this.timer.next({startDate, endDate});
44+
const [durationSeconds, durationNanoSeconds] = process.hrtime(highResStartTime);
3645
this.close.next({
3746
command: {
3847
command: this.command,
@@ -43,6 +52,11 @@ module.exports = class Command {
4352
index: this.index,
4453
exitCode: exitCode === null ? signal : exitCode,
4554
killed: this.killed,
55+
timings: {
56+
startDate,
57+
endDate,
58+
durationSeconds: durationSeconds + (durationNanoSeconds / 1e9),
59+
}
4660
});
4761
});
4862
child.stdout && pipeTo(Rx.fromEvent(child.stdout, 'data'), this.stdout);

‎src/command.spec.js‎

Lines changed: 93 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
const EventEmitter = require('events');
2+
const process = require('process');
23
const Command = require('./command');
34

45
const createProcess = () => {
@@ -54,6 +55,72 @@ describe('#start()', () => {
5455
process.emit('error', 'foo');
5556
});
5657

58+
it('shares start and close timing events to the timing stream', done => {
59+
const process = createProcess();
60+
const command = new Command({ spawn: () => process });
61+
62+
const startDate = new Date();
63+
const endDate = new Date(startDate.getTime() + 1000);
64+
jest.spyOn(Date, 'now')
65+
.mockReturnValueOnce(startDate.getTime())
66+
.mockReturnValueOnce(endDate.getTime());
67+
68+
let callCount = 0;
69+
command.timer.subscribe(({startDate: actualStartDate, endDate: actualEndDate}) => {
70+
switch (callCount) {
71+
case 0:
72+
expect(actualStartDate).toStrictEqual(startDate);
73+
expect(actualEndDate).toBeUndefined();
74+
break;
75+
case 1:
76+
expect(actualStartDate).toStrictEqual(startDate);
77+
expect(actualEndDate).toStrictEqual(endDate);
78+
done();
79+
break;
80+
default:
81+
throw new Error('Unexpected call count');
82+
}
83+
callCount++;
84+
});
85+
86+
command.start();
87+
process.emit('close', 0, null);
88+
89+
});
90+
91+
it('shares start and error timing events to the timing stream', done => {
92+
const process = createProcess();
93+
const command = new Command({ spawn: () => process });
94+
95+
const startDate = new Date();
96+
const endDate = new Date(startDate.getTime() + 1000);
97+
jest.spyOn(Date, 'now')
98+
.mockReturnValueOnce(startDate.getTime())
99+
.mockReturnValueOnce(endDate.getTime());
100+
101+
let callCount = 0;
102+
command.timer.subscribe(({startDate: actualStartDate, endDate: actualEndDate}) => {
103+
switch (callCount) {
104+
case 0:
105+
expect(actualStartDate).toStrictEqual(startDate);
106+
expect(actualEndDate).toBeUndefined();
107+
break;
108+
case 1:
109+
expect(actualStartDate).toStrictEqual(startDate);
110+
expect(actualEndDate).toStrictEqual(endDate);
111+
done();
112+
break;
113+
default:
114+
throw new Error('Unexpected call count');
115+
}
116+
callCount++;
117+
});
118+
119+
command.start();
120+
process.emit('error', 0, null);
121+
122+
});
123+
57124
it('shares closes to the close stream with exit code', done => {
58125
const process = createProcess();
59126
const command = new Command({ spawn: () => process });
@@ -83,6 +150,31 @@ describe('#start()', () => {
83150
process.emit('close', null, 'SIGKILL');
84151
});
85152

153+
it('shares closes to the close stream with timing information', done => {
154+
const process1 = createProcess();
155+
const command = new Command({ spawn: () => process1 });
156+
157+
const startDate = new Date();
158+
const endDate = new Date(startDate.getTime() + 1000);
159+
jest.spyOn(Date, 'now')
160+
.mockReturnValueOnce(startDate.getTime())
161+
.mockReturnValueOnce(endDate.getTime());
162+
163+
jest.spyOn(process, 'hrtime')
164+
.mockReturnValueOnce([0, 0])
165+
.mockReturnValueOnce([1, 1e8]);
166+
167+
command.close.subscribe(data => {
168+
expect(data.timings.startDate).toStrictEqual(startDate);
169+
expect(data.timings.endDate).toStrictEqual(endDate);
170+
expect(data.timings.durationSeconds).toBe(1.1);
171+
done();
172+
});
173+
174+
command.start();
175+
process1.emit('close', null, 'SIGKILL');
176+
});
177+
86178
it('shares closes to the close stream with command info and index', done => {
87179
const process = createProcess();
88180
const commandInfo = {
@@ -170,7 +262,7 @@ describe('#kill()', () => {
170262

171263
it('marks the command as killed', done => {
172264
command.start();
173-
265+
174266
command.close.subscribe(data => {
175267
expect(data.exitCode).toBe(1);
176268
expect(data.killed).toBe(true);

‎src/completion-listener.js‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -2,9 +2,10 @@ const Rx = require('rxjs');
22
const { bufferCount, switchMap, take } = require('rxjs/operators');
33

44
module.exports = class CompletionListener {
5-
constructor({ successCondition, scheduler }) {
5+
constructor({ successCondition, scheduler, showTimings}) {
66
this.successCondition = successCondition;
77
this.scheduler = scheduler;
8+
this.showTimings = showTimings;
89
}
910

1011
isSuccess(exitCodes) {
@@ -32,7 +33,7 @@ module.exports = class CompletionListener {
3233
? Rx.of(exitInfos, this.scheduler)
3334
: Rx.throwError(exitInfos, this.scheduler)
3435
),
35-
take(1)
36+
take(1),
3637
)
3738
.toPromise();
3839
}

‎src/completion-listener.spec.js‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -85,4 +85,5 @@ describe('with success condition set to last', () => {
8585

8686
return expect(result).rejects.toEqual([{ exitCode: 0 }, { exitCode: 1 }]);
8787
});
88+
8889
});

‎src/concurrently.js‎

Lines changed: 8 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@ const defaults = {
1818
raw: false,
1919
controllers: [],
2020
cwd: undefined,
21+
showTimings: false
2122
};
2223

2324
module.exports = (commands, options) => {
@@ -50,6 +51,7 @@ module.exports = (commands, options) => {
5051
prefixColor: lastColor,
5152
killProcess: options.kill,
5253
spawn: options.spawn,
54+
showTimings: options.showTimings,
5355
}, command)
5456
);
5557
})
@@ -73,9 +75,12 @@ module.exports = (commands, options) => {
7375
maybeRunMore(commandsLeft);
7476
}
7577

76-
return new CompletionListener({ successCondition: options.successCondition })
78+
return new CompletionListener({
79+
successCondition: options.successCondition,
80+
showTimings: options.showTimings
81+
})
7782
.listen(commands)
78-
.finally(() => {
83+
.finally((...args) => {
7984
handleResult.onFinishCallbacks.forEach((onFinish) => onFinish());
8085
});
8186
};
@@ -86,6 +91,7 @@ function mapToCommandInfo(command) {
8691
name: command.name || '',
8792
env: command.env || {},
8893
cwd: command.cwd || '',
94+
8995
}, command.prefixColor ? {
9096
prefixColor: command.prefixColor,
9197
} : {});

‎src/defaults.js‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -29,5 +29,7 @@ module.exports = {
2929
// Refer to https://date-fns.org/v2.0.1/docs/format
3030
timestampFormat: 'yyyy-MM-dd HH:mm:ss.SSS',
3131
// Current working dir passed as option to spawn command. Default: process.cwd()
32-
cwd: undefined
32+
cwd: undefined,
33+
// Whether to show timing information for processes in console output
34+
showTimings: false,
3335
};

‎src/flow-control/fixtures/fake-command.js‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@ module.exports = (name = 'foo', command = 'echo foo', index = 0) => ({
1010
error: new Subject(),
1111
stderr: new Subject(),
1212
stdout: new Subject(),
13+
timer: new Subject(),
1314
stdin: createMockInstance(Writable),
1415
start: jest.fn(),
1516
kill: jest.fn()

0 commit comments

Comments
 (0)