Merge pull request #916 from rollup/debug

Add performance labels

src/Bundle.js

@@ -1,3 +1,4 @@
+import { timeStart, timeEnd } from './utils/flushTime.js';
 import { decode } from 'sourcemap-codec';
 import { Bundle as MagicStringBundle } from 'magic-string';
 import first from './utils/first.js';
@@ -102,12 +103,19 @@ export default class Bundle {
 
 				// Phase 2 – binding. We link references to their declarations
 				// to generate a complete picture of the bundle
+
+				timeStart( 'phase 2' );
+
 				this.modules.forEach( module => module.bindImportSpecifiers() );
 				this.modules.forEach( module => module.bindReferences() );
 
+				timeEnd( 'phase 2' );
+
 				// Phase 3 – marking. We 'run' each statement to see which ones
 				// need to be included in the generated bundle
 
+				timeStart( 'phase 3' );
+
 				// mark all export statements
 				entryModule.getExports().forEach( name => {
 					const declaration = entryModule.traceExport( name );
@@ -146,11 +154,18 @@ export default class Bundle {
 					}
 				}
 
+				timeEnd( 'phase 3' );
+
 				// Phase 4 – final preparation. We order the modules with an
 				// enhanced topological sort that accounts for cycles, then
 				// ensure that names are deconflicted throughout the bundle
+
+				timeStart( 'phase 4' );
+
 				this.orderedModules = this.sort();
 				this.deconflict();
+
+				timeEnd( 'phase 4' );
 			});
 	}
 
@@ -332,6 +347,8 @@ export default class Bundle {
 		let magicString = new MagicStringBundle({ separator: '\n\n' });
 		const usedModules = [];
 
+		timeStart( 'render modules' );
+
 		this.orderedModules.forEach( module => {
 			const source = module.render( format === 'es' );
 
@@ -341,6 +358,8 @@ export default class Bundle {
 			}
 		});
 
+		timeEnd( 'render modules' );
+
 		let intro = [ options.intro ]
 			.concat(
 				this.plugins.map( plugin => plugin.intro && plugin.intro() )
@@ -355,8 +374,12 @@ export default class Bundle {
 		const finalise = finalisers[ format ];
 		if ( !finalise ) throw new Error( `You must specify an output type - valid options are ${keys( finalisers ).join( ', ' )}` );
 
+		timeStart( 'render format' );
+
 		magicString = finalise( this, magicString.trim(), { exportMode, indentString, intro }, options );
 
+		timeEnd( 'render format' );
+
 		const banner = [ options.banner ]
 			.concat( this.plugins.map( plugin => plugin.banner ) )
 			.map( callIfFunction )
@@ -380,6 +403,8 @@ export default class Bundle {
 			.replace( new RegExp( `\\/\\/#\\s+${SOURCEMAPPING_URL}=.+\\n?`, 'g' ), '' );
 
 		if ( options.sourceMap ) {
+			timeStart( 'sourceMap' );
+
 			let file = options.sourceMapFile || options.dest;
 			if ( file ) file = resolve( typeof process !== 'undefined' ? process.cwd() : '', file );
 
@@ -394,6 +419,8 @@ export default class Bundle {
 			}
 
 			map.sources = map.sources.map( normalize );
+
+			timeEnd( 'sourceMap' );
 		}
 
 		return { code, map };

src/Module.js

@@ -1,3 +1,4 @@
+import { timeStart, timeEnd } from './utils/flushTime.js';
 import { parse } from 'acorn/src/index.js';
 import MagicString from 'magic-string';
 import { assign, blank, deepClone, keys } from './utils/object.js';
@@ -34,9 +35,14 @@ export default class Module {
 		this.sourceMapChain = sourceMapChain;
 
 		this.comments = [];
+
+		timeStart( 'ast' );
+
 		this.ast = ast || tryParse( code, this.comments, bundle.acornOptions, id ); // TODO what happens to comments if AST is provided?
 		this.astClone = deepClone( this.ast );
 
+		timeEnd( 'ast' );
+
 		this.bundle = bundle;
 		this.id = id;
 		this.excludeFromSourcemap = /\0/.test( id );
@@ -72,8 +78,13 @@ export default class Module {
 		this.declarations = blank();
 		this.type = 'Module'; // TODO only necessary so that Scope knows this should be treated as a function scope... messy
 		this.scope = new ModuleScope( this );
+
+		timeStart( 'analyse' );
+
 		this.analyse();
 
+		timeEnd( 'analyse' );
+
 		this.strongDependencies = [];
 	}
 

src/rollup.js

@@ -1,3 +1,4 @@
+import { timeStart, timeEnd, flushTime } from './utils/flushTime.js';
 import { basename } from './utils/path.js';
 import { writeFile } from './utils/fs.js';
 import { assign, keys } from './utils/object.js';
@@ -54,10 +55,18 @@ export function rollup ( options ) {
 
 	const bundle = new Bundle( options );
 
+	timeStart( '--BUILD--' );
+
 	return bundle.build().then( () => {
+		timeEnd( '--BUILD--' );
+
 		function generate ( options ) {
+			timeStart( '--GENERATE--' );
+
 			const rendered = bundle.render( options );
 
+			timeEnd( '--GENERATE--' );
+
 			bundle.plugins.forEach( plugin => {
 				if ( plugin.ongenerate ) {
 					plugin.ongenerate( assign({
@@ -66,6 +75,8 @@ export function rollup ( options ) {
 				}
 			});
 
+			flushTime();
+
 			return rendered;
 		}
 

src/utils/flushTime.js

@@ -0,0 +1,37 @@
+const DEBUG = false;
+const map = new Map;
+
+export function timeStart ( label ) {
+	if ( !map.has( label ) ) {
+		map.set( label, {
+			time: 0
+		});
+	}
+	map.get( label ).start = process.hrtime();
+}
+
+export function timeEnd ( label ) {
+	if ( map.has( label ) ) {
+		const item = map.get( label );
+		item.time += toMilliseconds( process.hrtime( item.start ) );
+	}
+}
+
+export function flushTime ( log = defaultLog ) {
+	for ( const item of map.entries() ) {
+		log( item[0], item[1].time );
+	}
+	map.clear();
+}
+
+function toMilliseconds ( time ) {
+	return time[0] * 1e+3 + Math.floor( time[1] * 1e-6 );
+}
+
+function defaultLog ( label, time ) {
+	if ( DEBUG ) {
+		/* eslint-disable no-console */
+		console.info( '%dms: %s', time, label );
+		/* eslint-enable no-console */
+	}
+}