[v3.0] Restructure timings (#4566)

src/Bundle.ts

@@ -45,43 +45,47 @@ export default class Bundle {
 		this.pluginDriver.setOutputBundle(outputBundle, this.outputOptions);
 
 		try {
+			timeStart('initialize render', 2);
+
 			await this.pluginDriver.hookParallel('renderStart', [this.outputOptions, this.inputOptions]);
 
+			timeEnd('initialize render', 2);
 			timeStart('generate chunks', 2);
+
 			const getHashPlaceholder = getHashPlaceholderGenerator();
 			const chunks = await this.generateChunks(outputBundle, getHashPlaceholder);
 			if (chunks.length > 1) {
 				validateOptionsForMultiChunkOutput(this.outputOptions, this.inputOptions.onwarn);
 			}
 			this.pluginDriver.setChunkInformation(this.facadeChunkByModule);
-
-			timeEnd('generate chunks', 2);
-
-			timeStart('render chunks', 2);
-
 			for (const chunk of chunks) {
 				chunk.generateExports();
 			}
+
+			timeEnd('generate chunks', 2);
+
 			await renderChunks(
 				chunks,
 				outputBundle,
 				this.pluginDriver,
 				this.outputOptions,
 				this.inputOptions.onwarn
 			);
-
-			timeEnd('render chunks', 2);
 		} catch (err: any) {
 			await this.pluginDriver.hookParallel('renderError', [err]);
 			throw err;
 		}
+
+		timeStart('generate bundle', 2);
+
 		await this.pluginDriver.hookSeq('generateBundle', [
 			this.outputOptions,
 			outputBundle as OutputBundle,
 			isWrite
 		]);
 		this.finaliseAssets(outputBundle);
 
+		timeEnd('generate bundle', 2);
 		timeEnd('GENERATE', 1);
 		return outputBundle as OutputBundle;
 	}

src/Chunk.ts

@@ -55,7 +55,6 @@ import { basename, extname, isAbsolute } from './utils/path';
 import relativeId, { getAliasName, getImportPath } from './utils/relativeId';
 import type { RenderOptions } from './utils/renderHelpers';
 import { makeUnique, renderNamePattern } from './utils/renderNamePattern';
-import { timeEnd, timeStart } from './utils/timers';
 import { MISSING_EXPORT_SHIM_VARIABLE } from './utils/variableNames';
 
 export interface ModuleDeclarations {
@@ -600,7 +599,6 @@ export default class Chunk {
 		const { accessedGlobals, indent, magicString, renderedSource, usedModules, usesTopLevelAwait } =
 			this.renderModules(preliminaryFileName.fileName);
 
-		timeStart('render format', 2);
 		const renderedDependencies = [...this.getRenderedDependencies().values()];
 		const renderedExports = exportMode === 'none' ? [] : this.getChunkExportDeclarations(format);
 		const hasExports =
@@ -634,7 +632,6 @@ export default class Chunk {
 		);
 		if (banner) magicString.prepend(banner);
 		if (footer) magicString.append(footer);
-		timeEnd('render format', 2);
 
 		return {
 			chunk: this,

src/Graph.ts

@@ -97,10 +97,10 @@ export default class Graph {
 		await this.generateModuleGraph();
 		timeEnd('generate module graph', 2);
 
-		timeStart('sort modules', 2);
+		timeStart('sort and bind modules', 2);
 		this.phase = BuildPhase.ANALYSE;
 		this.sortModules();
-		timeEnd('sort modules', 2);
+		timeEnd('sort and bind modules', 2);
 
 		timeStart('mark included statements', 2);
 		this.includeStatements();

src/Module.ts

@@ -712,6 +712,8 @@ export default class Module {
 		resolvedIds?: ResolvedIdMap;
 		transformFiles?: EmittedFile[] | undefined;
 	}): void {
+		timeStart('generate ast', 3);
+
 		this.info.code = code;
 		this.originalCode = originalCode;
 		this.originalSourcemap = originalSourcemap;
@@ -723,13 +725,12 @@ export default class Module {
 		this.customTransformCache = customTransformCache;
 		this.updateOptions(moduleOptions);
 
-		timeStart('generate ast', 3);
-
 		if (!ast) {
 			ast = this.tryParse();
 		}
 
 		timeEnd('generate ast', 3);
+		timeStart('analyze ast', 3);
 
 		this.resolvedIds = resolvedIds || Object.create(null);
 
@@ -742,8 +743,6 @@ export default class Module {
 			indentExclusionRanges: []
 		});
 
-		timeStart('analyse ast', 3);
-
 		this.astContext = {
 			addDynamicImport: this.addDynamicImport.bind(this),
 			addExport: this.addExport.bind(this),
@@ -778,7 +777,7 @@ export default class Module {
 		this.ast = new Program(ast, { context: this.astContext, type: 'Module' }, this.scope);
 		this.info.ast = ast;
 
-		timeEnd('analyse ast', 3);
+		timeEnd('analyze ast', 3);
 	}
 
 	toJSON(): ModuleJSON {

src/ModuleLoader.ts

@@ -33,7 +33,6 @@ import { promises as fs } from './utils/fs';
 import { isAbsolute, isRelative, resolve } from './utils/path';
 import relativeId from './utils/relativeId';
 import { resolveId } from './utils/resolveId';
-import { timeEnd, timeStart } from './utils/timers';
 import transform from './utils/transform';
 
 export interface UnresolvedModule {
@@ -245,22 +244,19 @@ export class ModuleLoader {
 		importer: string | undefined,
 		module: Module
 	): Promise<void> {
-		timeStart('load modules', 3);
 		let source: LoadResult;
 		try {
 			source = await this.graph.fileOperationQueue.run(
 				async () =>
 					(await this.pluginDriver.hookFirst('load', [id])) ?? (await fs.readFile(id, 'utf8'))
 			);
 		} catch (err: any) {
-			timeEnd('load modules', 3);
 			let msg = `Could not load ${id}`;
 			if (importer) msg += ` (imported by ${relativeId(importer)})`;
 			msg += `: ${err.message}`;
 			err.message = msg;
 			throw err;
 		}
-		timeEnd('load modules', 3);
 		const sourceDescription =
 			typeof source === 'string'
 				? { code: source }

src/rollup/rollup.ts

@@ -51,7 +51,9 @@ export async function rollupInternal(
 
 	await catchUnfinishedHookActions(graph.pluginDriver, async () => {
 		try {
+			timeStart('initialize', 2);
 			await graph.pluginDriver.hookParallel('buildStart', [inputOptions]);
+			timeEnd('initialize', 2);
 			await graph.build();
 		} catch (err: any) {
 			const watchFiles = Object.keys(graph.watchFiles);
@@ -167,6 +169,7 @@ function handleGenerateWrite(
 		const bundle = new Bundle(outputOptions, unsetOptions, inputOptions, outputPluginDriver, graph);
 		const generated = await bundle.generate(isWrite);
 		if (isWrite) {
+			timeStart('WRITE', 1);
 			if (!outputOptions.dir && !outputOptions.file) {
 				return error({
 					code: 'MISSING_OPTION',
@@ -179,6 +182,7 @@ function handleGenerateWrite(
 				)
 			);
 			await outputPluginDriver.hookParallel('writeBundle', [outputOptions, generated]);
+			timeEnd('WRITE', 1);
 		}
 		return createOutput(generated);
 	});

src/utils/renderChunks.ts

@@ -41,8 +41,14 @@ export async function renderChunks(
 	outputOptions: NormalizedOutputOptions,
 	onwarn: WarningHandler
 ) {
+	timeStart('render chunks', 2);
+
 	reserveEntryChunksInBundle(chunks);
 	const renderedChunks = await Promise.all(chunks.map(chunk => chunk.render()));
+
+	timeEnd('render chunks', 2);
+	timeStart('transform chunks', 2);
+
 	const chunkGraph = getChunkGraph(chunks);
 	const {
 		nonHashedChunksWithPlaceholders,
@@ -66,6 +72,8 @@ export async function renderChunks(
 		outputBundle,
 		nonHashedChunksWithPlaceholders
 	);
+
+	timeEnd('transform chunks', 2);
 }
 
 function reserveEntryChunksInBundle(chunks: Chunk[]) {
@@ -122,7 +130,7 @@ async function transformChunk(
 	if (!compact && code[code.length - 1] !== '\n') code += '\n';
 
 	if (sourcemap) {
-		timeStart('sourcemap', 2);
+		timeStart('sourcemaps', 3);
 
 		let file: string;
 		if (options.file) file = resolve(options.sourcemapFile || options.file);
@@ -154,7 +162,7 @@ async function transformChunk(
 			})
 			.map(normalize);
 
-		timeEnd('sourcemap', 2);
+		timeEnd('sourcemaps', 3);
 	}
 	return {
 		code,

src/utils/timers.ts

@@ -1,4 +1,4 @@
-import type { InputOptions, Plugin, SerializedTimings } from '../rollup/types';
+import type { InputOptions, Plugin, PluginHooks, SerializedTimings } from '../rollup/types';
 import performance from './performance';
 import process from './process';
 
@@ -74,7 +74,26 @@ export function getTimings(): SerializedTimings {
 export let timeStart: (label: string, level?: number) => void = NOOP;
 export let timeEnd: (label: string, level?: number) => void = NOOP;
 
-const TIMED_PLUGIN_HOOKS = ['load', 'resolveDynamicImport', 'resolveId', 'transform'] as const;
+const TIMED_PLUGIN_HOOKS: readonly (keyof PluginHooks)[] = [
+	'augmentChunkHash',
+	'buildEnd',
+	'buildStart',
+	'generateBundle',
+	'load',
+	'moduleParsed',
+	'options',
+	'outputOptions',
+	'renderChunk',
+	'renderDynamicImport',
+	'renderStart',
+	'resolveDynamicImport',
+	'resolveFileUrl',
+	'resolveId',
+	'resolveImportMeta',
+	'shouldTransformCachedModule',
+	'transform',
+	'writeBundle'
+];
 
 function getPluginWithTimers(plugin: any, index: number): Plugin {
 	for (const hook of TIMED_PLUGIN_HOOKS) {
@@ -91,13 +110,6 @@ function getPluginWithTimers(plugin: any, index: number): Plugin {
 				timeStart(timerLabel, 4);
 				const result = func.apply(this, args);
 				timeEnd(timerLabel, 4);
-				if (result && typeof result.then === 'function') {
-					timeStart(`${timerLabel} (async)`, 4);
-					return result.then((hookResult: unknown) => {
-						timeEnd(`${timerLabel} (async)`, 4);
-						return hookResult;
-					});
-				}
 				return result;
 			};
 		}