cli: Add timing to build output

.github/files/build-all-projects.sh

@@ -79,7 +79,7 @@ for SLUG in "${SLUGS[@]}"; do
 			OLDLOCK=
 		fi
 	fi
-	if (cd $BASE && pnpx jetpack build "${SLUG}" -v --production --no-pnpm-install); then
+	if (cd $BASE && pnpx jetpack build "${SLUG}" -v --production --timing --no-pnpm-install); then
 		FAIL=false
 	else
 		FAIL=true

tools/cli/commands/build.js

@@ -12,10 +12,12 @@ import UpdateRenderer from 'listr-update-renderer';
  * Internal dependencies
  */
 import { chalkJetpackGreen } from '../helpers/styling.js';
+import formatDuration from '../helpers/format-duration.js';
 import promptForProject from '../helpers/promptForProject.js';
 import { readComposerJson } from '../helpers/json.js';
 import { getInstallArgs, projectDir } from '../helpers/install.js';
 import { allProjects, allProjectsByType } from '../helpers/projectHelpers.js';
+import PrefixTransformStream from '../helpers/prefix-stream.js';
 
 export const command = 'build [project...]';
 export const describe = 'Builds one or more monorepo projects';
@@ -44,6 +46,10 @@ export function builder( yargs ) {
 		.option( 'no-pnpm-install', {
 			type: 'boolean',
 			description: 'Skip execution of `pnpm install` before the build.',
+		} )
+		.option( 'timing', {
+			type: 'boolean',
+			description: 'Output timing information.',
 		} );
 }
 
@@ -153,16 +159,23 @@ function createBuildTask( argv, title, build ) {
 		task: async ( ctx, task ) => {
 			const t = {};
 			if ( argv.v ) {
+				const stdout = new PrefixTransformStream( { time: !! argv.timing } );
+				const stderr = new PrefixTransformStream( { time: !! argv.timing } );
+				stdout.pipe( process.stdout );
+				stderr.pipe( process.stderr );
+
 				t.execa = ( file, args, options ) => {
 					const p = execa( file, args, {
-						stdio: [ 'ignore', 'inherit', 'inherit' ],
+						stdio: [ 'ignore', 'pipe', 'pipe' ],
 						...options,
 					} );
+					p.stdout.pipe( stdout, { end: false } );
+					p.stderr.pipe( stderr, { end: false } );
 					return p;
 				};
 				t.output = m =>
 					new Promise( resolve => {
-						process.stdout.write( m, 'utf8', resolve );
+						stdout.write( m, 'utf8', resolve );
 					} );
 				t.setStatus = s => t.output( '\n' + chalk.bold( `== ${ title } [${ s }] ==` ) + '\n\n' );
 			} else {
@@ -173,10 +186,11 @@ function createBuildTask( argv, title, build ) {
 				};
 			}
 
+			const t0 = Date.now();
 			try {
 				await build( t );
 			} finally {
-				await t.setStatus( 'complete' );
+				await t.setStatus( argv.timing ? formatDuration( Date.now() - t0 ) + 's' : 'complete' );
 			}
 		},
 	};

tools/cli/helpers/format-duration.js

@@ -0,0 +1,31 @@
+/**
+ * External dependencies
+ */
+import { sprintf } from 'sprintf-js';
+
+/**
+ * A function to format a duration as h:m:s.
+ *
+ * @param {number} duration - Duration in milliseconds.
+ * @returns {string} Formatted duration.
+ */
+export default function formatDuration( duration ) {
+	let n = '';
+	if ( duration < 0 ) {
+		n = '-';
+		duration = -duration;
+	}
+	duration = Math.floor( duration );
+
+	return (
+		n +
+		// eslint-disable-next-line @wordpress/valid-sprintf -- This isn't WordPress's i18n sprintf.
+		sprintf(
+			'%d:%02d:%02d.%03d',
+			Math.floor( duration / 3600000 ), // https://github.com/alexei/sprintf.js/issues/103
+			Math.floor( duration / 60000 ) % 60,
+			Math.floor( duration / 1000 ) % 60,
+			duration % 1000
+		).replace( /^[0:]+(?!\.)/, '' )
+	);
+}

tools/cli/helpers/prefix-stream.js

@@ -0,0 +1,111 @@
+/**
+ * External dependencies
+ */
+import { Buffer } from 'buffer';
+import * as stream from 'stream';
+
+/**
+ * Internal dependencies
+ */
+import formatDuration from './format-duration.js';
+
+/**
+ * A Transform stream to prefix each line with a string.
+ *
+ * The data is line buffered to try to avoid interleaved output.
+ */
+export default class PrefixTransformStream extends stream.Transform {
+	static #openBracket = Buffer.from( '[' );
+	static #sep = Buffer.from( ' ' );
+	static #closeBracket = Buffer.from( '] ' );
+
+	#prefix;
+	#startTime;
+	#rest;
+	#onDrain;
+
+	/**
+	 * Constructor.
+	 *
+	 * @param {object} options - Options for stream constructors. In addition, the following options are recognized.
+	 * @param {string|Buffer|number[]|ArrayBuffer|Uint8Array|object} options.prefix - Prefix. Anything accepted by `Buffer.from()` is ok.
+	 * @param {boolean|number} options.time - Include time-since-start on each line. Value is the start timestamp (e.g. `Date.now()`), or boolean true to use `Date.now()`.
+	 */
+	constructor( options = {} ) {
+		const { prefix, time } = options;
+		delete options.prefix, options.time;
+		super( options );
+
+		this.#prefix = Buffer.from( prefix || '' );
+		this.#rest = Buffer.alloc( 0 );
+		if ( time === true ) {
+			this.#startTime = Date.now();
+		} else if ( time ) {
+			this.#startTime = options.time;
+		}
+	}
+
+	/**
+	 * Push a line to the stream.
+	 *
+	 * @param {Buffer} line - Line to push.
+	 * @returns {boolean} Whether the push succeeded.
+	 */
+	#doPush( line ) {
+		if ( ! this.#prefix.length && ! this.#startTime ) {
+			return this.push( line );
+		}
+
+		// Push to the stream as a single buffer to try to avoid split writes.
+		const bufs = [ PrefixTransformStream.#openBracket ];
+		if ( this.#prefix.length > 0 ) {
+			bufs.push( this.#prefix );
+		}
+		if ( this.#startTime ) {
+			if ( bufs.length > 1 ) {
+				bufs.push( PrefixTransformStream.#sep );
+			}
+			bufs.push( Buffer.from( formatDuration( Date.now() - this.#startTime ) ) );
+		}
+		bufs.push( PrefixTransformStream.#closeBracket, line );
+
+		return this.push( Buffer.concat( bufs ) );
+	}
+
+	_transform( chunk, encoding, callback ) {
+		this.#rest = Buffer.concat( [ this.#rest, chunk ] );
+		const func = () => {
+			let i;
+			while ( ( i = this.#rest.indexOf( '\n' ) ) >= 0 ) {
+				const line = this.#rest.slice( 0, ++i );
+				this.#rest = this.#rest.slice( i );
+				if ( ! this.#doPush( line ) ) {
+					this.#onDrain = func;
+					return false;
+				}
+			}
+			callback();
+			return true;
+		};
+		func();
+	}
+
+	_flush( callback ) {
+		if ( this.#rest.length ) {
+			this.#doPush( this.#rest );
+		}
+		callback();
+	}
+
+	_read( size ) {
+		if ( this.#onDrain ) {
+			const onDrain = this.#onDrain;
+			this.#onDrain = null;
+			if ( onDrain() ) {
+				super._read( size );
+			}
+		} else {
+			super._read( size );
+		}
+	}
+}

tools/cli/package.json

@@ -40,6 +40,7 @@
 		"process": "0.11.10",
 		"semver": "7.3.5",
 		"simple-git": "2.37.0",
+		"sprintf-js": "1.1.2",
 		"yargs": "16.2.0"
 	},
 	"devDependencies": {

tools/cli/tests/unit/helpers/format-duration.test.js

@@ -0,0 +1,32 @@
+/**
+ * External dependencies
+ */
+import chai from 'chai';
+
+/**
+ * Internal dependencies
+ */
+import formatDuration from '../../../helpers/format-duration.js';
+
+const tests = {
+	0: '0.000',
+	1: '0.001',
+	999: '0.999',
+	1000: '1.000',
+	59999: '59.999',
+	60000: '1:00.000',
+	3599999: '59:59.999',
+	3600000: '1:00:00.000',
+	86399999: '23:59:59.999',
+	86400000: '24:00:00.000',
+	'-1': '-0.001',
+	'-1000': '-1.000',
+	'-60000': '-1:00.000',
+	'0.0000000005': '0.000',
+};
+
+for ( const [ k, v ] of Object.entries( tests ) ) {
+	it( `formats ${ k }`, () => {
+		chai.expect( formatDuration( Number( k ) ) ).to.equal( v );
+	} );
+}

tools/cli/tests/unit/helpers/prefix-stream.test.js

@@ -0,0 +1,115 @@
+/**
+ * External dependencies
+ */
+import chai from 'chai';
+
+/**
+ * Internal dependencies
+ */
+import PrefixTransformStream from '../../../helpers/prefix-stream.js';
+
+it( 'prefixes', async () => {
+	const ts = new PrefixTransformStream( { prefix: 'foobar', encoding: 'utf8' } );
+
+	ts.write( 'line 1\n' );
+	chai.expect( ts.read() ).to.equal( '[foobar] line 1\n' );
+	ts.write( 'line 2...' );
+	chai.expect( ts.read() ).to.equal( null );
+	ts.write( ' ... done\n' );
+	chai.expect( ts.read() ).to.equal( '[foobar] line 2... ... done\n' );
+	ts.write( 'line 3\nline 4\nline 5\n' );
+	chai.expect( ts.read() ).to.equal( '[foobar] line 3\n[foobar] line 4\n[foobar] line 5\n' );
+	ts.write( 'line 6\nline 7' );
+	chai.expect( ts.read() ).to.equal( '[foobar] line 6\n' );
+	ts.write( '...\nline 8' );
+	chai.expect( ts.read() ).to.equal( '[foobar] line 7...\n' );
+	ts.end();
+	chai.expect( ts.read() ).to.equal( '[foobar] line 8' );
+} );
+
+it( "doesn't produce a stray prefix if EOF is a newline", async () => {
+	const ts = new PrefixTransformStream( { prefix: 'foobar', encoding: 'utf8' } );
+
+	ts.write( 'line 1\n' );
+	ts.end();
+	chai.expect( ts.read() ).to.equal( '[foobar] line 1\n' );
+} );
+
+it( "doesn't produce a stray prefix if nothing was written", async () => {
+	const ts = new PrefixTransformStream( { prefix: 'foobar', encoding: 'utf8' } );
+
+	ts.end();
+	chai.expect( ts.read() ).to.equal( null );
+} );
+
+it( 'prefixes with timing info', async () => {
+	const ts = new PrefixTransformStream( { prefix: 'foobar', encoding: 'utf8', time: true } );
+
+	ts.write( 'line 1\nline 2' );
+	chai.expect( ts.read() ).to.match( /^\[foobar 0\.0\d\d\] line 1\n$/ );
+	await new Promise( r => {
+		setTimeout( r, 100 );
+	} );
+	ts.end();
+	chai.expect( ts.read() ).to.match( /^\[foobar 0\.1\d\d\] line 2$/ );
+} );
+
+it( 'prefixes with timing info but no prefix', async () => {
+	const ts = new PrefixTransformStream( { encoding: 'utf8', time: Date.now() - 3723000 } );
+
+	ts.write( 'line 1\n' );
+	chai.expect( ts.read() ).to.match( /^\[1:02:03\.0\d\d\] line 1\n$/ );
+} );
+
+it( "doesn't prefix with no timing info and no prefix", async () => {
+	const ts = new PrefixTransformStream( { encoding: 'utf8' } );
+
+	ts.write( 'line 1\n' );
+	chai.expect( ts.read() ).to.equal( 'line 1\n' );
+} );
+
+it( "doesn't die from backpressure", async () => {
+	const ts = new PrefixTransformStream( {
+		prefix: 'foobar',
+		encoding: 'utf8',
+		highWaterMark: 100,
+	} );
+
+	let drains = 0;
+	let n = 0;
+	let expect = '';
+	let actual = '';
+	while ( drains < 2 ) {
+		expect += `[foobar] line ${ ++n }...\n`;
+		if ( ts.write( `line ${ n }...\n` ) === false ) {
+			drains++;
+			actual += ts.read();
+		}
+	}
+	ts.end();
+	actual += ts.read();
+	chai.expect( actual ).to.equal( expect );
+} );
+
+it( "doesn't die from backpressure (2)", async () => {
+	const ts = new PrefixTransformStream( {
+		prefix: 'foobar',
+		encoding: 'utf8',
+		highWaterMark: 100,
+	} );
+
+	let n = 0;
+	let expect = '';
+	do {
+		expect += `[foobar] line ${ ++n }...\n`;
+	} while ( ts.write( `line ${ n }...\n` ) !== false );
+	ts.end( 'end' );
+	expect += `[foobar] end`;
+
+	let actual = '';
+	let chunk;
+	while ( ( chunk = ts.read() ) !== null ) {
+		actual += chunk;
+	}
+	chai.expect( actual ).to.equal( expect );
+} );