From 1061d6477af328e93c9a727e70900ae20c0116c8 Mon Sep 17 00:00:00 2001 From: Ben Holmes Date: Thu, 24 Mar 2022 15:23:37 -0400 Subject: [PATCH] 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 | 9 ++++++ packages/astro/src/core/build/generate.ts | 24 +++++++++++++-- packages/astro/src/core/build/index.ts | 26 ++++++++++++---- packages/astro/src/core/build/page-data.ts | 30 +++++++++++++++++-- packages/astro/src/core/build/static-build.ts | 29 ++++++++++++++++-- packages/astro/src/core/build/util.ts | 4 +++ 6 files changed, 108 insertions(+), 14 deletions(-) create mode 100644 .changeset/rude-trainers-repeat.md create mode 100644 packages/astro/src/core/build/util.ts diff --git a/.changeset/rude-trainers-repeat.md b/.changeset/rude-trainers-repeat.md new file mode 100644 index 000000000..4202f395a --- /dev/null +++ b/.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 \ No newline at end of file diff --git a/packages/astro/src/core/build/generate.ts b/packages/astro/src/core/build/generate.ts index dedba1e4f..306187ffd 100644 --- a/packages/astro/src/core/build/generate.ts +++ b/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) { - 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, 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; } diff --git a/packages/astro/src/core/build/index.ts b/packages/astro/src/core/build/index.ts index 5b3bd3a36..d830eb88d 100644 --- a/packages/astro/src/core/build/index.ts +++ b/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 = {}; 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'))}`); } } diff --git a/packages/astro/src/core/build/page-data.ts b/packages/astro/src/core/build/page-data.ts index 4cf96d388..946ebbefc 100644 --- a/packages/astro/src/core/build/page-data.ts +++ b/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,6 +33,13 @@ export async function collectPagesData(opts: CollectPagesDataOptions): Promise = {}; 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 @@ -39,6 +47,16 @@ export async function collectPagesData(opts: CollectPagesDataOptions): Promise { + 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 { - 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 = {}; + + 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) { @@ -141,6 +157,7 @@ async function ssrBuild(opts: StaticBuildOptions, internals: BuildInternals, inp async function clientBuild(opts: StaticBuildOptions, internals: BuildInternals, input: Set) { 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); diff --git a/packages/astro/src/core/build/util.ts b/packages/astro/src/core/build/util.ts new file mode 100644 index 000000000..8e558f9bb --- /dev/null +++ b/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`; +}