Feat: improve production build logging (#2857)

* feat: log setup, vite, and route gen steps

* refactor: add back "build" + timestamp for consistency

* feat: improve ms increase logs to match old debug output

* feat: add log for server assets

* chore: remove redundant debug logs

* feat: add logs for ssr steps

* fix: hide  per-page log for ssr builds

* fix: hide "index.html" from debug log in SSR

* feat: add log for "collecting page data" step

* feat: add timeout logs for longer data imports

* chore: add changeset

* remove (includes setup + teardown)

* refactor: add newline to separate ssr from client build

* fix: move "gen static routes" heading to pages

* fix: only show client build ms when triggered

* fix: remove dup render loop

* chore: remove unused static-build imports

.changeset/rude-trainers-repeat.md

@@ -0,0 +1,9 @@
+---
+'astro': patch
+---
+
+Improve granularity of production build logs. This now lists:
+- the "data collection" build step, with timeout warnings for larger imports. This is useful for understanding large `import.meta.glob` calls.
+- the Vite client bundling step. This logs all Vite production build info to clarify what assets are built alongside your HTML.
+- the route generation step, complete with all output HTML files for a given input file. This is especially useful when debugging `getStaticPaths`.
+- fixes "0 pages in Infinityms" log when building to SSR

packages/astro/src/core/build/generate.ts

@@ -8,13 +8,15 @@ import type { RenderOptions } from '../../core/render/core';
 import fs from 'fs';
 import npath from 'path';
 import { fileURLToPath } from 'url';
-import { debug, error } from '../../core/logger.js';
+import { debug, error, info } from '../../core/logger.js';
 import { prependForwardSlash } from '../../core/path.js';
 import { resolveDependency } from '../../core/util.js';
 import { call as callEndpoint } from '../endpoint/index.js';
 import { render } from '../render/core.js';
 import { createLinkStylesheetElementSet, createModuleScriptElementWithSrcSet } from '../render/ssr-element.js';
 import { getOutRoot, getOutFolder, getOutFile } from './common.js';
+import { bgMagenta, black, cyan, dim, magenta } from 'kleur/colors';
+import { getTimeStat } from './util.js';
 
 // Render is usually compute, which Node.js can't parallelize well.
 // In real world testing, dropping from 10->1 showed a notiable perf
@@ -83,7 +85,7 @@ export function chunkIsPage(astroConfig: AstroConfig, output: OutputAsset | Outp
 }
 
 export async function generatePages(result: RollupOutput, opts: StaticBuildOptions, internals: BuildInternals, facadeIdToPageDataMap: Map<string, PageBuildData>) {
-	debug('build', 'Finish build. Begin generating.');
+	info(opts.logging, null, `\n${bgMagenta(black(' generating static routes '))}\n`);
 
 	// Get renderers to be shared for each page generation.
 	const renderers = await loadRenderers(opts.astroConfig);
@@ -102,6 +104,7 @@ async function generatePage(
 	facadeIdToPageDataMap: Map<string, PageBuildData>,
 	renderers: SSRLoadedRenderer[]
 ) {
+	let timeStart = performance.now();
 	const { astroConfig } = opts;
 
 	let url = new URL('./' + output.fileName, getOutRoot(astroConfig));
@@ -126,14 +129,29 @@ async function generatePage(
 		renderers,
 	};
 
-	const renderPromises = [];
+	const icon = pageData.route.type === 'page' ? cyan('</>') : magenta('{-}');
+	info(opts.logging, null, `${icon} ${pageData.route.component}`);
+
 	// Throttle the paths to avoid overloading the CPU with too many tasks.
+	const renderPromises = [];
 	for (const paths of throttle(MAX_CONCURRENT_RENDERS, pageData.paths)) {
 		for (const path of paths) {
 			renderPromises.push(generatePath(path, opts, generationOptions));
 		}
 		// This blocks generating more paths until these 10 complete.
 		await Promise.all(renderPromises);
+		const timeEnd = performance.now();
+		const timeChange = getTimeStat(timeStart, timeEnd);
+		let shouldLogTimeChange = !getTimeStat(timeStart, timeEnd).startsWith('0');
+		for (const path of paths) {
+			const timeIncrease = shouldLogTimeChange ? ` ${dim(`+${timeChange}`)}` : '';
+			info(opts.logging, null, `    ${dim('┃')} ${path}${timeIncrease}`);
+			// Should only log build time on the first generated path
+			// Logging for all generated paths adds extra noise
+			shouldLogTimeChange = false;
+		}
+		// Reset timeStart for the next batch of rendered paths
+		timeStart = performance.now();
 		// This empties the array without allocating a new one.
 		renderPromises.length = 0;
 	}

packages/astro/src/core/build/index.ts

@@ -15,6 +15,7 @@ import { build as scanBasedBuild } from './scan-based-build.js';
 import { staticBuild } from './static-build.js';
 import { RouteCache } from '../render/route-cache.js';
 import { runHookBuildDone, runHookBuildStart, runHookConfigDone, runHookConfigSetup } from '../../integrations/index.js';
+import { getTimeStat } from './util.js';
 
 export interface BuildOptions {
 	mode?: string;
@@ -54,6 +55,8 @@ class AstroBuilder {
 	}
 
 	async build() {
+		info(this.logging, 'build', 'Initial setup...');
+
 		const { logging, origin } = this;
 		const timer: Record<string, number> = {};
 		timer.init = performance.now();
@@ -77,6 +80,7 @@ class AstroBuilder {
 		const buildConfig: BuildConfig = { staticMode: undefined };
 		await runHookBuildStart({ config: this.config, buildConfig });
 
+		info(this.logging, 'build', 'Collecting page data...');
 		timer.loadStart = performance.now();
 		const { assets, allPages } = await collectPagesData({
 			astroConfig: this.config,
@@ -108,6 +112,7 @@ class AstroBuilder {
 		// Bundle the assets in your final build: This currently takes the HTML output
 		// of every page (stored in memory) and bundles the assets pointed to on those pages.
 		timer.buildStart = performance.now();
+		info(this.logging, 'build', colors.dim(`Completed in ${getTimeStat(timer.init, performance.now())}`));
 
 		// Use the new faster static based build.
 		if (!this.config.buildOptions.legacyBuild) {
@@ -134,7 +139,6 @@ class AstroBuilder {
 				viteServer: this.viteServer,
 			});
 		}
-		debug('build', timerMessage('Vite build finished', timer.buildStart));
 
 		// Write any additionally generated assets to disk.
 		timer.assetsStart = performance.now();
@@ -166,16 +170,26 @@ class AstroBuilder {
 		await runHookBuildDone({ config: this.config, pages: pageNames });
 
 		if (logging.level && levels[logging.level] <= levels['info']) {
-			await this.printStats({ logging, timeStart: timer.init, pageCount: pageNames.length });
+			const buildMode = this.config.buildOptions.experimentalSsr ? 'ssr' : 'static';
+			await this.printStats({ logging, timeStart: timer.init, pageCount: pageNames.length, buildMode });
 		}
 	}
 
 	/** Stats */
-	private async printStats({ logging, timeStart, pageCount }: { logging: LogOptions; timeStart: number; pageCount: number }) {
+	private async printStats({ logging, timeStart, pageCount, buildMode }: { logging: LogOptions; timeStart: number; pageCount: number; buildMode: 'static' | 'ssr' }) {
 		const buildTime = performance.now() - timeStart;
-		const total = buildTime < 750 ? `${Math.round(buildTime)}ms` : `${(buildTime / 1000).toFixed(2)}s`;
-		const perPage = `${Math.round(buildTime / pageCount)}ms`;
-		info(logging, 'build', `${pageCount} pages built in ${colors.bold(total)} ${colors.dim(`(${perPage}/page)`)}`);
+		const total = getTimeStat(timeStart, performance.now());
+
+		let messages: string[] = [];
+		if (buildMode === 'static') {
+			const timePerPage = Math.round(buildTime / pageCount);
+			const perPageMsg = colors.dim(`(${colors.bold(`${timePerPage}ms`)} avg per page + resources)`);
+			messages = [`${pageCount} pages built in`, colors.bold(total), perPageMsg];
+		} else {
+			messages = ['Server built in', colors.bold(total)];
+		}
+
+		info(logging, 'build', messages.join(' '));
 		info(logging, 'build', `🚀 ${colors.cyan(colors.bold('Done'))}`);
 	}
 }

packages/astro/src/core/build/page-data.ts

@@ -1,6 +1,7 @@
 import type { AstroConfig, ComponentInstance, ManifestData, RouteData } from '../../@types/astro';
 import type { AllPagesData } from './types';
 import type { LogOptions } from '../logger';
+import { info } from '../logger.js';
 import type { ViteDevServer } from 'vite';
 
 import { fileURLToPath } from 'url';
@@ -32,13 +33,30 @@ export async function collectPagesData(opts: CollectPagesDataOptions): Promise<C
 	const assets: Record<string, string> = {};
 	const allPages: AllPagesData = {};
 
+	const buildMode = astroConfig.buildOptions.experimentalSsr ? 'ssr' : 'static';
+
+	const dataCollectionLogTimeout = setInterval(() => {
+		info(opts.logging, 'build', 'The data collection step may take longer for larger projects...');
+		clearInterval(dataCollectionLogTimeout);
+	}, 30000);
+
 	// Collect all routes ahead-of-time, before we start the build.
 	// NOTE: This enforces that `getStaticPaths()` is only called once per route,
 	// and is then cached across all future SSR builds. In the past, we've had trouble
 	// with parallelized builds without guaranteeing that this is called first.
 	for (const route of manifest.routes) {
 		// static route:
 		if (route.pathname) {
+			const routeCollectionLogTimeout = setInterval(() => {
+				info(
+					opts.logging,
+					'build',
+					`${colors.bold(
+						route.component
+					)} is taking a bit longer to import. This is common for larger "Astro.glob(...)" or "import.meta.globEager(...)" calls, for instance. Hang tight!`
+				);
+				clearInterval(routeCollectionLogTimeout);
+			}, 10000);
 			allPages[route.component] = {
 				route,
 				paths: [route.pathname],
@@ -48,11 +66,17 @@ export async function collectPagesData(opts: CollectPagesDataOptions): Promise<C
 					viteServer,
 				})
 					.then((routes) => {
-						const html = `${route.pathname}`.replace(/\/?$/, '/index.html');
-						debug('build', `├── ${colors.bold(colors.green('✔'))} ${route.component} → ${colors.yellow(html)}`);
+						clearInterval(routeCollectionLogTimeout);
+						if (buildMode === 'static') {
+							const html = `${route.pathname}`.replace(/\/?$/, '/index.html');
+							debug('build', `├── ${colors.bold(colors.green('✔'))} ${route.component} → ${colors.yellow(html)}`);
+						} else {
+							debug('build', `├── ${colors.bold(colors.green('✔'))} ${route.component}`);
+						}
 						return routes;
 					})
 					.catch((err) => {
+						clearInterval(routeCollectionLogTimeout);
 						debug('build', `├── ${colors.bold(colors.red('✘'))} ${route.component}`);
 						throw err;
 					}),
@@ -106,6 +130,8 @@ export async function collectPagesData(opts: CollectPagesDataOptions): Promise<C
 		};
 	}
 
+	clearInterval(dataCollectionLogTimeout);
+
 	return { assets, allPages };
 }
 

packages/astro/src/core/build/static-build.ts

@@ -2,13 +2,14 @@ import type { RollupOutput } from 'rollup';
 import type { BuildInternals } from '../../core/build/internal.js';
 import type { ViteConfigWithSSR } from '../create-vite';
 import type { PageBuildData, StaticBuildOptions } from './types';
-
 import glob from 'fast-glob';
 import fs from 'fs';
+import { bgGreen, bgMagenta, black, dim } from 'kleur/colors';
 import npath from 'path';
 import { fileURLToPath } from 'url';
 import * as vite from 'vite';
 import { createBuildInternals } from '../../core/build/internal.js';
+import { info } from '../../core/logger.js';
 import { appendForwardSlash, prependForwardSlash } from '../../core/path.js';
 import { emptyDir, removeDir } from '../../core/util.js';
 import { rollupPluginAstroBuildCSS } from '../../vite-plugin-build-css/index.js';
@@ -17,6 +18,7 @@ import { vitePluginInternals } from './vite-plugin-internals.js';
 import { vitePluginSSR } from './vite-plugin-ssr.js';
 import { generatePages } from './generate.js';
 import { getClientRoot, getServerRoot, getOutRoot } from './common.js';
+import { getTimeStat } from './util.js';
 
 export async function staticBuild(opts: StaticBuildOptions) {
 	const { allPages, astroConfig } = opts;
@@ -33,6 +35,12 @@ export async function staticBuild(opts: StaticBuildOptions) {
 
 	// Build internals needed by the CSS plugin
 	const internals = createBuildInternals();
+
+	const timer: Record<string, number> = {};
+
+	timer.buildStart = performance.now();
+	info(opts.logging, 'build', 'Discovering entrypoints...');
+
 	for (const [component, pageData] of Object.entries(allPages)) {
 		const astroModuleURL = new URL('./' + component, astroConfig.projectRoot);
 		const astroModuleId = prependForwardSlash(component);
@@ -76,18 +84,26 @@ export async function staticBuild(opts: StaticBuildOptions) {
 	// condition, so we are doing it ourselves
 	emptyDir(astroConfig.dist, new Set('.git'));
 
+	timer.clientBuild = performance.now();
 	// Run client build first, so the assets can be fed into the SSR rendered version.
 	await clientBuild(opts, internals, jsInput);
 
 	// Build your project (SSR application code, assets, client JS, etc.)
+	timer.ssr = performance.now();
+	info(opts.logging, 'build', 'Building for SSR...');
 	const ssrResult = (await ssrBuild(opts, internals, pageInput)) as RollupOutput;
+	info(opts.logging, 'build', dim(`Completed in ${getTimeStat(timer.ssr, performance.now())}`));
 
+	timer.generate = performance.now();
 	if (opts.buildConfig.staticMode) {
+		console.log('huh?');
 		await generatePages(ssrResult, opts, internals, facadeIdToPageDataMap);
 		await cleanSsrOutput(opts);
 	} else {
+		info(opts.logging, null, `\n${bgMagenta(black(' finalizing server assets '))}\n`);
 		await ssrMoveAssets(opts);
 	}
+	info(opts.logging, null, dim(`Completed in ${getTimeStat(timer.generate, performance.now())}\n`));
 }
 
 async function ssrBuild(opts: StaticBuildOptions, internals: BuildInternals, input: Set<string>) {
@@ -141,6 +157,7 @@ async function ssrBuild(opts: StaticBuildOptions, internals: BuildInternals, inp
 
 async function clientBuild(opts: StaticBuildOptions, internals: BuildInternals, input: Set<string>) {
 	const { astroConfig, viteConfig } = opts;
+	const timer = performance.now();
 
 	// Nothing to do if there is no client-side JS.
 	if (!input.size) {
@@ -150,8 +167,11 @@ async function clientBuild(opts: StaticBuildOptions, internals: BuildInternals,
 	const out = astroConfig.buildOptions.experimentalSsr ? getClientRoot(astroConfig) : getOutRoot(astroConfig);
 
 	// TODO: use vite.mergeConfig() here?
-	return await vite.build({
-		logLevel: 'error',
+
+	info(opts.logging, null, `\n${bgGreen(black(' building resources '))}\n`);
+
+	const buildResult = await vite.build({
+		logLevel: 'info',
 		mode: 'production',
 		css: viteConfig.css,
 		build: {
@@ -184,6 +204,8 @@ async function clientBuild(opts: StaticBuildOptions, internals: BuildInternals,
 		server: viteConfig.server,
 		base: appendForwardSlash(astroConfig.buildOptions.site ? new URL(astroConfig.buildOptions.site).pathname : '/'),
 	});
+	info(opts.logging, null, dim(`Completed in ${getTimeStat(timer, performance.now())}\n`));
+	return buildResult;
 }
 
 async function cleanSsrOutput(opts: StaticBuildOptions) {
@@ -200,6 +222,7 @@ async function cleanSsrOutput(opts: StaticBuildOptions) {
 }
 
 async function ssrMoveAssets(opts: StaticBuildOptions) {
+	info(opts.logging, 'build', 'Rearranging server assets...');
 	const { astroConfig } = opts;
 	const serverRoot = getServerRoot(astroConfig);
 	const clientRoot = getClientRoot(astroConfig);

packages/astro/src/core/build/util.ts

@@ -0,0 +1,4 @@
+export function getTimeStat(timeStart: number, timeEnd: number) {
+	const buildTime = timeEnd - timeStart;
+	return buildTime < 750 ? `${Math.round(buildTime)}ms` : `${(buildTime / 1000).toFixed(2)}s`;
+}