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`;
+}