feat(build): report build phases and where the time went (#1490)

Co-authored-by: autofix-ci[bot] <114827586+autofix-ci[bot]@users.noreply.github.com>

Author: danielroe

capture/output/nuxt-dev-plain-restart.svg

@@ -6,18 +6,23 @@ import { defineCommand } from 'citty'
 import { relative } from 'pathe'
 import { resolveDotenvFileNames } from '../utils/args'
 import { showBanner } from '../utils/banner'
-
+import { BuildProgress } from '../utils/build-progress'
 import { overrideEnv } from '../utils/env'
+
 import { ActionableError } from '../utils/errors'
 import { formatDuration } from '../utils/formatting'
 import { clearBuildDir } from '../utils/fs'
 import { loadKit } from '../utils/kit'
 import { acquireLock, acquireOutputLock, formatLockError } from '../utils/lockfile'
 import { intro, logger, outro } from '../utils/logger'
 import { resolveRootDir } from '../utils/paths'
+import { createPhaseReporter, formatPhaseBreakdown } from '../utils/phase-reporter'
 import { startCpuProfile, stopCpuProfile } from '../utils/profile'
 import { dotEnvArgs, envNameArgs, extendsArgs, logLevelArgs, profileArgs, rootDirArgs } from './_shared'
 
+/** How often a phase repeats itself where there is no animated line. */
+const HEARTBEAT_INTERVAL = 5000
+
 export default defineCommand({
   meta: {
     name: 'build',
@@ -55,9 +60,27 @@ export default defineCommand({
     }
 
     const releaseLocks: Array<() => void> = []
+    const progress = new BuildProgress()
+    let stopReporting = () => {}
     try {
       intro(styleText('cyan', 'Building Nuxt for production...'))
 
+      // The phase line owns a row of the terminal, which a silent build has no
+      // business drawing on. Subscribed after the intro so the first phase is
+      // reported below it rather than above.
+      if (ctx.args.logLevel !== 'silent') {
+        const reporter = createPhaseReporter({ heartbeat: HEARTBEAT_INTERVAL })
+        let unsubscribe: (() => void) | undefined
+        // Assigned before subscribing, because subscribing reports the phase in
+        // flight straight away: a first write that fails, on a pipe that has
+        // already been closed, must still leave the terminal recoverable.
+        stopReporting = () => {
+          unsubscribe?.()
+          reporter.stop()
+        }
+        unsubscribe = progress.onUpdate(reporter.update)
+      }
+
       const kit = await loadKit(cwd)
       const nuxt = await kit.loadNuxt({
         cwd,
@@ -85,6 +108,8 @@ export default defineCommand({
         },
       })
 
+      progress.attachNuxt(nuxt)
+
       showBanner(nuxt)
       await nuxt.ready()
 
@@ -115,6 +140,14 @@ export default defineCommand({
 
       await kit.buildNuxt(nuxt)
 
+      stopReporting()
+      progress.finish()
+
+      const breakdown = formatPhaseBreakdown(progress.timings)
+      if (breakdown) {
+        logger.message(styleText('dim', breakdown))
+      }
+
       if (ctx.args.prerender) {
         if (!nuxt.options.ssr) {
           logger.warn(`HTML content not prerendered because ${styleText('cyan', 'ssr: false')} was set.`)
@@ -129,6 +162,7 @@ export default defineCommand({
       }
     }
     finally {
+      stopReporting()
       for (const release of releaseLocks.reverse()) {
         release()
       }

capture/output/nuxt-init.svg

@@ -1,7 +1,7 @@
 /* eslint-disable perfectionist/sort-imports -- `./force-tty` must be evaluated before anything that loads `std-env` or `consola` */
 import type { NuxtConfig } from '@nuxt/schema'
 import type { DevListenOverrides, Listener, ListenURL } from './listen'
-import type { DevProgressSnapshot } from './progress'
+import type { ProgressSnapshot } from '../utils/progress-snapshot'
 import type { DevRestartReason } from './reason'
 import type { ServerLogEvent } from './log-channel'
 import type { DevRequestEvent, DevRoutes, NuxtDevContext, NuxtDevIPCMessage, NuxtParentIPCMessage } from './utils'
@@ -21,7 +21,7 @@ import { debug } from '../utils/logger'
 import { startCpuProfile, stopCpuProfile } from '../utils/profile.ts'
 import { openInspector } from './inspect'
 import { currentRequest, isServingRequest } from './serving-state'
-import { createStartupReporter } from './startup-log'
+import { createPhaseReporter } from '../utils/phase-reporter'
 import { NuxtDevServer } from './utils'
 
 const start = Date.now()
@@ -93,7 +93,7 @@ interface InitializeOptions {
    * Called with every startup progress snapshot, from before the first load
    * begins, so a UI can narrate startup as it happens rather than after.
    */
-  onProgress?: (snapshot: DevProgressSnapshot) => void
+  onProgress?: (snapshot: ProgressSnapshot) => void
   /**
    * Called as soon as a socket is bound, milliseconds into startup, and again
    * with `confirmed` once the resolved config has agreed with the address.
@@ -357,7 +357,7 @@ export async function initialize(devContext: NuxtDevContext, ctx: InitializeOpti
   // itself, so the transient reporter line would only fight it for the screen.
   const reporter = devContext.args.logLevel === 'silent' || ipc.enabled || ctx.captureUIEvents
     ? undefined
-    : createStartupReporter()
+    : createPhaseReporter()
   const unsubscribeProgress = reporter && devServer.progress.onUpdate(reporter.update)
   const stopReporting = () => {
     unsubscribeProgress?.()

packages/nuxt-cli/src/commands/build.ts

@@ -1,4 +1,4 @@
-import type { DevProgressSnapshot } from './progress'
+import type { ProgressSnapshot } from '../utils/progress-snapshot'
 
 /**
  * The scripts inlined into the dev server's loading and error pages.
@@ -36,7 +36,7 @@ export function progressClient(options: ProgressClientOptions): void {
     caption.textContent = label ? `${label} \u00B7 ${seconds}` : seconds
   }
 
-  function apply(snapshot: DevProgressSnapshot): void {
+  function apply(snapshot: ProgressSnapshot): void {
     start = Date.now() - snapshot.elapsed
     // The message, not the phase id: it carries whatever detail the server has,
     // such as the module currently being set up, and this page is what the user
@@ -53,7 +53,7 @@ export function progressClient(options: ProgressClientOptions): void {
     paint()
   }
 
-  function read(event: Event): DevProgressSnapshot | undefined {
+  function read(event: Event): ProgressSnapshot | undefined {
     try {
       return JSON.parse((event as MessageEvent).data)
     }

packages/nuxt-cli/src/dev/index.ts

@@ -1,4 +1,4 @@
-import type { DevProgressSnapshot } from './progress'
+import type { ProgressSnapshot } from '../utils/progress-snapshot'
 
 import { inlineScript, progressClient, recoveryClient } from './loading-client'
 import { PROGRESS_PATH } from './progress'
@@ -16,7 +16,7 @@ const MAX_POLL_INTERVAL_MS = 1000
 const STYLES = `.nuxt-loader-bar{right:auto!important;width:var(${PROGRESS_PROPERTY},4%);transition:width .3s ease}
 #${CAPTION_ID}{position:fixed;left:0;right:0;bottom:14px;text-align:center;font:12px/1.5 ui-sans-serif,system-ui,-apple-system,sans-serif;opacity:.55;font-variant-numeric:tabular-nums}`
 
-function progressTags(snapshot: DevProgressSnapshot): string {
+function progressTags(snapshot: ProgressSnapshot): string {
   return `<style>${STYLES}</style>${inlineScript(progressClient, {
     progressPath: PROGRESS_PATH,
     captionId: CAPTION_ID,
@@ -35,7 +35,7 @@ function progressTags(snapshot: DevProgressSnapshot): string {
  * adds is a determinate bar, a phase caption, the build error inline, and a
  * reload driven by the server rather than by a poll interval.
  */
-export function withProgress(html: string, snapshot: DevProgressSnapshot): string {
+export function withProgress(html: string, snapshot: ProgressSnapshot): string {
   const tags = progressTags(snapshot)
   const index = html.lastIndexOf('</body>')
   return index === -1 ? html + tags : html.slice(0, index) + tags + html.slice(index)

packages/nuxt-cli/src/dev/loading-client.ts

@@ -1,4 +1,5 @@
 import type { IncomingMessage, ServerResponse } from 'node:http'
+import type { PhaseTiming, ProgressSnapshot, ProgressStatus } from '../utils/progress-snapshot'
 
 /** Path prefix reserved for the CLI's own dev-time endpoints. */
 export const DEV_INTERNAL_PREFIX: string = '/__nuxt_dev__/'
@@ -107,33 +108,6 @@ function moduleName(module: unknown): string | undefined {
   return typeof name === 'string' && name ? name : undefined
 }
 
-export type DevProgressStatus = 'loading' | 'ready' | 'error'
-
-interface DevPhaseTiming {
-  phase: string
-  message: string
-  duration: number
-}
-
-export interface DevProgressSnapshot {
-  status: DevProgressStatus
-  phase: string
-  message: string
-  index: number
-  total: number
-  progress: number
-  elapsed: number
-  reload: boolean
-  /**
-   * Whether a request has actually been answered. `status` is `ready` from the
-   * moment the server is listening, so this is what tells a UI whether the app
-   * can be used yet.
-   */
-  serving: boolean
-  timings: DevPhaseTiming[]
-  error?: { name: string, message: string }
-}
-
 interface HookableLike {
   beforeEach?: (fn: (event: { name: string, args?: unknown[] }) => void) => void
   afterEach?: (fn: (event: { name: string }) => void) => void
@@ -150,16 +124,16 @@ interface ActiveHook {
  */
 export class DevProgress {
   #clients = new Set<ServerResponse>()
-  #listeners = new Set<(snapshot: DevProgressSnapshot) => void>()
+  #listeners = new Set<(snapshot: ProgressSnapshot) => void>()
   #heartbeat?: NodeJS.Timeout
 
   #index = 0
   #message = DEV_PHASES[0]!.message
-  #status: DevProgressStatus = 'loading'
+  #status: ProgressStatus = 'loading'
   #error?: Error
   #startedAt = Date.now()
   #phaseStartedAt = Date.now()
-  #timings: DevPhaseTiming[] = []
+  #timings: PhaseTiming[] = []
   #reload = false
   #baseMessage = DEV_PHASES[0]!.message
   #module?: ActiveHook
@@ -170,7 +144,7 @@ export class DevProgress {
   #observed = new WeakSet<HookableLike>()
   #ticker?: NodeJS.Timeout
 
-  get snapshot(): DevProgressSnapshot {
+  get snapshot(): ProgressSnapshot {
     const phase = DEV_PHASES[this.#index]!
     return {
       status: this.#status,
@@ -189,11 +163,11 @@ export class DevProgress {
     }
   }
 
-  get timings(): DevPhaseTiming[] {
+  get timings(): PhaseTiming[] {
     return this.#timings
   }
 
-  onUpdate(listener: (snapshot: DevProgressSnapshot) => void): () => void {
+  onUpdate(listener: (snapshot: ProgressSnapshot) => void): () => void {
     this.#listeners.add(listener)
     return () => this.#listeners.delete(listener)
   }
@@ -512,7 +486,7 @@ export class DevProgress {
     }
   }
 
-  #send(res: ServerResponse, snapshot: DevProgressSnapshot): void {
+  #send(res: ServerResponse, snapshot: ProgressSnapshot): void {
     if (res.writableEnded) {
       return
     }

packages/nuxt-cli/src/dev/loading-page.ts

@@ -1,5 +1,5 @@
+import type { ProgressSnapshot } from '../../utils/progress-snapshot'
 import type { ListenURL } from '../listen'
-import type { DevProgressSnapshot } from '../progress'
 import type { DevLogEvent } from './events'
 import type { PanelState } from './panel'
 import type { DevUISupportOptions } from './support'
@@ -85,7 +85,7 @@ export interface DevUISession {
   /** Stop the session's own startup animation, once the controller drives it. */
   stopStartupTicker: () => void
   /** Narrate the current startup phase while the server is loading. */
-  reportProgress: (snapshot: DevProgressSnapshot) => void
+  reportProgress: (snapshot: ProgressSnapshot) => void
   /**
    * Show the bound address the moment the socket answers, spinning until the
    * resolved config confirms it. The full URL block replaces it on ready.
@@ -175,7 +175,7 @@ export function beginDevUI(options: DevUISupportOptions & { version?: string, cw
     surface.render(renderPanel(state, process.stdout.columns || 80, process.stdout.rows || 24))
   }
 
-  function reportProgress(snapshot: DevProgressSnapshot): void {
+  function reportProgress(snapshot: ProgressSnapshot): void {
     if (snapshot.status === 'ready') {
       // Between the server accepting requests and answering one there is
       // nothing to watch but a badge, so it says which of the two has happened.