From 04e5a4f0aee46907c02fc74a237ea1e77c589d79 Mon Sep 17 00:00:00 2001 From: Daniel Roe Date: Mon, 28 Sep 2026 13:14:21 +0000 Subject: [PATCH] feat(dev): trace requests on a timeline in the network view --- docs/dev.md | 10 +- .../nuxt-cli/runtime/dev-request-context.mjs | 190 +++++++++++++++++- packages/nuxt-cli/src/commands/dev.ts | 6 +- packages/nuxt-cli/src/dev/compile-timing.ts | 189 +++++++++++++++++ packages/nuxt-cli/src/dev/index.ts | 32 +++ packages/nuxt-cli/src/dev/span-channel.ts | 38 ++++ packages/nuxt-cli/src/dev/tui/controller.ts | 4 + packages/nuxt-cli/src/dev/tui/index.ts | 1 + .../nuxt-cli/src/dev/tui/request-overlay.ts | 167 +++++++++++++++ packages/nuxt-cli/src/dev/tui/requests.ts | 43 +++- packages/nuxt-cli/src/dev/utils.ts | 33 ++- .../test/unit/commands/dev-run.spec.ts | 1 + .../nuxt-cli/test/unit/compile-timing.spec.ts | 108 ++++++++++ .../test/unit/dev-request-context.spec.ts | 59 ++++++ packages/nuxt-cli/test/unit/dev-tui.spec.ts | 42 ++++ playground-nightly/app/app.vue | 2 +- playground-nightly/app/middleware/traced.ts | 1 + playground-nightly/app/pages/index.vue | 3 + playground-nightly/app/pages/trace.vue | 9 + playground-nightly/test/e2e/dev-tui.spec.ts | 38 ++++ 20 files changed, 968 insertions(+), 8 deletions(-) create mode 100644 packages/nuxt-cli/src/dev/compile-timing.ts create mode 100644 packages/nuxt-cli/src/dev/span-channel.ts create mode 100644 packages/nuxt-cli/test/unit/compile-timing.spec.ts create mode 100644 playground-nightly/app/middleware/traced.ts create mode 100644 playground-nightly/app/pages/index.vue create mode 100644 playground-nightly/app/pages/trace.vue diff --git a/docs/dev.md b/docs/dev.md index aca9b3637..3a08f0397 100644 --- a/docs/dev.md +++ b/docs/dev.md @@ -90,7 +90,15 @@ In an interactive terminal, `nuxt dev` renders a pinned panel: the server URLs, Inside a view, `y` copies the selected row and `shift-y` copies every row the filters and search leave, keeping the newest when there is too much to paste. In the info view, `shift-y` copies the [`nuxt info`](/docs/api/commands/info) table instead. -Pass `--no-tui` to stream logs instead, which is also what `NUXT_TUI=plain` does for good. `NUXT_TUI=1` forces the UI on where the environment checks would otherwise turn it off, but never where the output is piped or redirected. +### Tracing a request + +In the network view (`n`), select a request and press `enter` to see where its time went. The trace draws everything the server did for that request on one timeline: route middleware, server route handlers, Nuxt plugins, hooks, data fetching, rendering, and requests your app made to other servers. Below the timeline, it lists how long Vite spent compiling modules for the request, broken down by Vite plugin and slowest module, followed by the logs the request produced. + +The trace is built from the [tracing channels](https://nodejs.org/api/diagnostics_channel.html#class-tracingchannel) that Nuxt and Nitro publish, so how much it shows depends on your versions. `nuxt dev` turns on the `tracingChannel` option for you; set `tracingChannel: false` in your `nuxt.config` to opt out. + +### Disabling the UI + +Pass `--no-tui` or set `NUXT_TUI=plain` to stream logs instead. You can also force the UI _on_ by passing `NUXT_TUI=1` (though this doesn't do anything if the output is piped or redirected). ![nuxt dev with plain output](/capture/output/nuxt-dev-plain-static.svg) diff --git a/packages/nuxt-cli/runtime/dev-request-context.mjs b/packages/nuxt-cli/runtime/dev-request-context.mjs index 76fb61610..ba0a0a360 100644 --- a/packages/nuxt-cli/runtime/dev-request-context.mjs +++ b/packages/nuxt-cli/runtime/dev-request-context.mjs @@ -1,36 +1,222 @@ import { AsyncLocalStorage } from 'node:async_hooks' +import dc from 'node:diagnostics_channel' +import process from 'node:process' import { formatWithOptions } from 'node:util' import { consola } from 'consola' /** - * Attribute the app's logs to the request that caused them. + * Attribute the app's logs, and the spans it publishes on `diagnostics_channel`, + * to the request that caused them. * * Nitro runs the app in a worker thread, so the CLI's own request context cannot * reach it: `AsyncLocalStorage` does not cross threads, and neither `globalThis` * nor `process` is the same object either side. This runs on the app's side of * that boundary, opening its own context around the handler and reporting from * inside it. Only the request identity crosses, as a header, and only the - * finished log comes back, on a `BroadcastChannel`. + * finished log or span comes back, on a `BroadcastChannel`. * * Everything here is best-effort: a dev server must never fail because a log * could not be attributed. */ const CHANNEL = 'nuxt:dev:log' +const SPAN_CHANNEL = 'nuxt:dev:span' /** Left on the request: Nuxt reads it to attribute the error reports it publishes. */ const HEADER = 'x-nuxt-dev-request-id' const LABEL_HEADER = 'x-nuxt-dev-request-label' const storage = new AsyncLocalStorage() +let spanChannel + export default function (nitroApp) { try { trackRequests(nitroApp) reportLogs() + trackHooks(nitroApp) + subscribeSpans() + } + catch {} +} + +function now() { + return performance.timeOrigin + performance.now() +} + +function postSpan(request, kind, name, start, extra) { + try { + if (!spanChannel) { + spanChannel = new BroadcastChannel(SPAN_CHANNEL) + spanChannel.unref?.() + } + spanChannel.postMessage({ requestId: request.id, kind, name, start, duration: now() - start, ...extra }) } catch {} } +/** A module path as a reader would name it: from its package, or from the project. */ +function shortenPath(path) { + if (!path) { + return undefined + } + const file = String(path).replace(/^@(?=\/)/, '') + const packaged = file.lastIndexOf('/node_modules/') + if (packaged !== -1) { + return file.slice(packaged + '/node_modules/'.length) + } + const root = `${process.cwd()}/` + return file.startsWith(root) ? file.slice(root.length) : file +} + +function pathOf(url) { + try { + const { pathname, search } = new URL(url, 'http://localhost') + return `${pathname}${search}` + } + catch { + return String(url ?? '/') + } +} + +/** + * `TracingChannel`s published by Nuxt, h3 and Nitro, and how each span is shown. + * All of them are published with `tracePromise`, so a span ends on `asyncEnd` + * or `error`. + */ +const TRACING_CHANNELS = { + 'nuxt.plugin': context => ['plugin', context.plugin?.name || 'anonymous'], + 'nuxt.data': context => ['data', context.functionName ? `${context.functionName}(${context.key})` : String(context.key)], + 'nuxt.render': context => ['render', context.streaming ? 'stream' : 'renderToString'], + 'nuxt.island': context => ['island', context.islandContext?.name || 'island'], + 'nuxt.hook': context => ['hook', String(context.name ?? context.hook?.name)], + 'nuxt.middleware': context => ['middleware', context.middleware?.name || shortenPath(context.middleware?.path) || 'anonymous'], + 'h3.request': (context) => { + const request = context.event?.req ?? context.event?.node?.req + const label = `${request?.method || 'GET'} ${pathOf(request?.url)}` + return [context.type === 'middleware' ? 'middleware' : 'route', label] + }, +} + +/** Undici's fetch lifecycle, published as plain channels rather than a `TracingChannel`. */ +const UNDICI_CHANNELS = ['undici:request:create', 'undici:request:headers', 'undici:request:trailers', 'undici:request:error'] + +const SUBSCRIPTION = Symbol.for('nuxt:dev:span:subscription') +const STARTED = Symbol('nuxt:dev:span:started') + +/** + * Report spans published while serving a request, against that request. + * + * Subscriptions are process-wide, so any left by an earlier copy of this module + * are dropped first. + */ +function subscribeSpans() { + globalThis[SUBSCRIPTION]?.() + const unsubscribers = [] + + for (const [name, describe] of Object.entries(TRACING_CHANNELS)) { + const handlers = { + start(context) { + const request = storage.getStore() + if (request) { + context[STARTED] = { request, start: now() } + } + }, + asyncEnd: context => finishTraced(context, describe), + error: context => finishTraced(context, describe, true), + } + const channel = dc.tracingChannel(name) + channel.subscribe(handlers) + unsubscribers.push(() => channel.unsubscribe(handlers)) + } + + const fetches = new WeakMap() + const onFetch = { + 'undici:request:create': ({ request }) => { + const inflight = storage.getStore() + if (inflight) { + fetches.set(request, { request: inflight, start: now() }) + } + }, + 'undici:request:headers': ({ request, response }) => { + const started = fetches.get(request) + if (started) { + started.status = response?.statusCode + } + }, + 'undici:request:trailers': ({ request }) => finishFetch(fetches, request), + 'undici:request:error': ({ request }) => finishFetch(fetches, request, true), + } + for (const name of UNDICI_CHANNELS) { + const listener = (message) => { + try { + onFetch[name](message) + } + catch {} + } + dc.subscribe(name, listener) + unsubscribers.push(() => dc.unsubscribe(name, listener)) + } + + globalThis[SUBSCRIPTION] = () => { + for (const unsubscribe of unsubscribers) { + unsubscribe() + } + } +} + +function finishTraced(context, describe, error) { + const started = context[STARTED] + if (!started) { + return + } + context[STARTED] = undefined + try { + const [kind, name] = describe(context) + const status = context.event?.res?.status ?? context.event?.node?.res?.statusCode + postSpan(started.request, kind, name, started.start, { + ...kind === 'route' && typeof status === 'number' ? { status } : {}, + ...error ? { error: true } : {}, + }) + } + catch {} +} + +function finishFetch(fetches, request, error) { + const started = fetches.get(request) + if (!started) { + return + } + fetches.delete(request) + const url = `${request.origin ?? ''}${request.path ?? ''}` + postSpan(started.request, 'fetch', `${request.method || 'GET'} ${url}`, started.start, { + ...typeof started.status === 'number' ? { status: started.status } : {}, + ...error ? { error: true } : {}, + }) +} + +/** + * Time the Nitro hooks the app has listeners for. Nitro publishes no channel for + * its hooks, so these are timed through hookable directly. + */ +function trackHooks(nitroApp) { + const hooks = nitroApp?.hooks + if (typeof hooks?.beforeEach !== 'function' || typeof hooks?.afterEach !== 'function') { + return + } + hooks.beforeEach((event) => { + const request = storage.getStore() + if (request && event.context && hooks._hooks?.[event.name]?.length) { + event.context[STARTED] = { request, start: now() } + } + }) + hooks.afterEach((event) => { + const started = event.context?.[STARTED] + if (started) { + postSpan(started.request, 'hook', event.name, started.start) + } + }) +} + function parseRequest(id, label) { if (!id) { return undefined diff --git a/packages/nuxt-cli/src/commands/dev.ts b/packages/nuxt-cli/src/commands/dev.ts index bdeb7bf28..ba266f74a 100644 --- a/packages/nuxt-cli/src/commands/dev.ts +++ b/packages/nuxt-cli/src/commands/dev.ts @@ -257,7 +257,7 @@ const command = defineCommand({ throw error }) - const { listener, close, reload, onRestart, onReady, onLoading, onEachReady, onLog, onRequests, onRoutes, onBuilding, onReport, onReportClear, onFileChange } = started + const { listener, close, reload, onRestart, onReady, onLoading, onEachReady, onLog, onRequests, onSpans, onRoutes, onBuilding, onReport, onReportClear, onFileChange } = started /** Feed the dev UI from the server running in this process. */ function attachDevUI(devUI: DevUIController): DevUIController { @@ -266,6 +266,7 @@ const command = defineCommand({ onBuilding(building => devUI.setStatus(building ? 'building' : 'ready')) onLog(log => devUI.pushServerLog(log)) onRequests(requests => devUI.pushRequests(requests)) + onSpans(spans => devUI.pushSpans(spans)) onReport(report => devUI.pushReport(report)) onReportClear(id => devUI.clearReport(id)) onRoutes(payload => devUI.setRoutes(payload)) @@ -371,6 +372,9 @@ const command = defineCommand({ else if (message.type === 'nuxt:internal:dev:requests') { devUI.pushRequests(message.requests) } + else if (message.type === 'nuxt:internal:dev:spans') { + devUI.pushSpans(message.spans) + } else if (message.type === 'nuxt:internal:dev:report') { devUI.pushReport(message.report) } diff --git a/packages/nuxt-cli/src/dev/compile-timing.ts b/packages/nuxt-cli/src/dev/compile-timing.ts new file mode 100644 index 000000000..739727090 --- /dev/null +++ b/packages/nuxt-cli/src/dev/compile-timing.ts @@ -0,0 +1,189 @@ +import type { DevRequestSpan } from './span-channel' + +import { AsyncLocalStorage } from 'node:async_hooks' +import { tracingChannel } from 'node:diagnostics_channel' +import { existsSync } from 'node:fs' + +const STARTED = Symbol('nuxt:cli:compile:started') +const NESTED = Symbol('nuxt:cli:compile:nested') + +/** A request the compile time can be charged to. */ +export interface InflightAppRequest { + id: string + internal: boolean +} + +interface ModuleContext { + /** Published on `vite.module`. */ + url?: string + /** Published on `nuxt.bundler.module`. */ + id?: string + environment?: string + [NESTED]?: boolean +} + +interface PluginContext { + plugin?: string +} + +interface Frame { + /** Self time per plugin for the module being compiled, in milliseconds. */ + plugins: Map + /** Time spent in plugin calls nested inside this one. */ + nested: number + parent?: Frame +} + +/** Where Vite publishes, and where Nuxt publishes for a Vite that does not. */ +const MODULE_CHANNELS = ['vite.module', 'nuxt.bundler.module'] +const PLUGIN_CHANNELS = ['vite.plugin', 'nuxt.bundler.plugin'] + +function ignore(): void {} + +const UNUSED = { end: ignore, asyncStart: ignore, error: ignore } + +interface Started { + frame: Frame + start: number + requests?: InflightAppRequest[] +} + +type Traced = T & { [STARTED]?: Started } + +/** + * Report the modules Vite compiles for requests, and each Vite plugin's share of + * them, from the `vite.module` and `vite.plugin` tracing channels, or their + * `nuxt.bundler.*` counterparts. A module traced on both is reported once. + * + * A module compiled while serving a request, such as one the browser asked + * for, is charged to that request. A server module is requested by the app's + * runner over a message channel instead, so no request context reaches Vite; + * every app request in flight is charged, and a module compiled for several is + * marked `shared`. + * + * Returns a function that unsubscribes. + */ +export function subscribeCompileTiming(options: { + rootDir: () => string + /** The request being served on this call stack, if any. */ + current: () => { id: string } | undefined + inflight: () => InflightAppRequest[] + report: (span: DevRequestSpan) => void +}): () => void { + const storage = new AsyncLocalStorage() + const modules = MODULE_CHANNELS.map(name => tracingChannel>(name)) + const plugins = PLUGIN_CHANNELS.map(name => tracingChannel>(name)) + + const openModule = (context: Traced): Frame => { + const outer = storage.getStore() + if (outer) { + context[NESTED] = true + return outer + } + return { plugins: new Map(), nested: 0 } + } + const openPlugin = (): Frame | undefined => { + const parent = storage.getStore() + return parent && { plugins: parent.plugins, nested: 0, parent } + } + + const moduleHandlers = { + ...UNUSED, + start(context: Traced) { + const frame = storage.getStore() + if (context[NESTED]) { + return + } + const current = options.current() + const requests = current + ? [{ id: current.id, internal: false }] + : options.inflight().filter(request => !request.internal) + if (frame && requests.length) { + context[STARTED] = { frame, start: performance.now(), requests } + } + }, + asyncEnd(context: Traced) { + const started = context[STARTED] + if (!started?.requests) { + return + } + context[STARTED] = undefined + const duration = performance.now() - started.start + const timings = Object.fromEntries([...started.frame.plugins].map(([plugin, time]) => [plugin, Math.round(time * 100) / 100])) + for (const request of started.requests) { + options.report({ + requestId: request.id, + kind: 'compile', + name: shortenModuleId(String(context.url ?? context.id ?? ''), options.rootDir()), + start: performance.timeOrigin + started.start, + duration, + ...context.environment ? { environment: context.environment } : {}, + plugins: timings, + ...started.requests.length > 1 ? { shared: true } : {}, + }) + } + }, + } + + const pluginHandlers = { + ...UNUSED, + start(context: Traced) { + const frame = storage.getStore() + if (frame?.parent) { + context[STARTED] = { frame, start: performance.now() } + } + }, + asyncEnd(context: Traced) { + const started = context[STARTED] + if (!started) { + return + } + context[STARTED] = undefined + const { frame } = started + const duration = performance.now() - started.start + const name = context.plugin || 'anonymous' + frame.plugins.set(name, (frame.plugins.get(name) ?? 0) + Math.max(0, duration - frame.nested)) + frame.parent!.nested += duration + }, + } + + for (const channel of modules) { + channel.start.bindStore(storage, openModule) + channel.subscribe(moduleHandlers) + } + for (const channel of plugins) { + channel.start.bindStore(storage, openPlugin) + channel.subscribe(pluginHandlers) + } + return () => { + for (const channel of modules) { + channel.unsubscribe(moduleHandlers) + channel.start.unbindStore(storage) + } + for (const channel of plugins) { + channel.unsubscribe(pluginHandlers) + channel.start.unbindStore(storage) + } + } +} + +/** + * A module URL as a reader would name it: from its package, or from the + * project. Vite URLs are relative to the project root unless they name a file + * outside it. + */ +export function shortenModuleId(url: string, rootDir: string): string { + if (/^\/?@id\//.test(url)) { + return url.replace(/^\/?@id\/(?:__x00__)?/, '') + } + const file = url.replace(/^\/@fs(?=\/)/, '').replace(/\?.*$/, '') + const packaged = file.lastIndexOf('/node_modules/') + if (packaged !== -1) { + return file.slice(packaged + '/node_modules/'.length) + } + const root = `${rootDir.replace(/\/$/, '')}/` + if (file.startsWith(root)) { + return file.slice(root.length) + } + return file.startsWith('/') && !url.startsWith('/@fs/') && !existsSync(file) ? file.slice(1) : file +} diff --git a/packages/nuxt-cli/src/dev/index.ts b/packages/nuxt-cli/src/dev/index.ts index 229bb06fe..872d15db4 100644 --- a/packages/nuxt-cli/src/dev/index.ts +++ b/packages/nuxt-cli/src/dev/index.ts @@ -5,6 +5,7 @@ import type { ProgressSnapshot } from '../utils/progress-snapshot' import type { DevRestartReason } from './reason' import type { DevReportSummary } from './error-channel' import type { ServerLogEvent } from './log-channel' +import type { DevRequestSpan } from './span-channel' import type { DevRequestEvent, DevRoutes, NuxtDevContext, NuxtDevIPCMessage, NuxtParentIPCMessage } from './utils' import process from 'node:process' @@ -31,6 +32,8 @@ const start = Date.now() const REQUEST_FLUSH_MS = 100 const REQUEST_BATCH_LIMIT = 200 +/** A cold page load compiles hundreds of modules, each reported as a span. */ +const SPAN_BATCH_LIMIT = 5000 const PENDING_REQUEST_BATCHES = 20 const PENDING_LOG_LIMIT = 500 const PENDING_REPORTS = 20 @@ -228,6 +231,8 @@ interface InitializeReturn { onLog: (callback: (log: ServerLogEvent) => void) => void /** Called with batches of served requests. */ onRequests: (callback: (requests: DevRequestEvent[]) => void) => void + /** Called with batches of spans the app timed while serving requests. */ + onSpans: (callback: (spans: DevRequestSpan[]) => void) => void /** Called with reports the app forwarded, rendered for a terminal. */ onReport: (callback: (report: DevReportSummary) => void) => void /** Called when the app reports that its error has gone. */ @@ -309,6 +314,7 @@ export async function initialize(devContext: NuxtDevContext, ctx: InitializeOpti const logs = createFeed(PENDING_LOG_LIMIT) const requests = createFeed(PENDING_REQUEST_BATCHES) + const spans = createFeed(PENDING_REQUEST_BATCHES) const routes = createFeed(1) const building = createFeed(0) const reports = createFeed(PENDING_REPORTS) @@ -338,6 +344,7 @@ export async function initialize(devContext: NuxtDevContext, ctx: InitializeOpti }) let closeLogChannel: (() => void) | undefined + let closeSpanChannel: (() => void) | undefined if (captureUIEvents) { const { openDevLogChannel } = await import('./log-channel') closeLogChannel = openDevLogChannel((log) => { @@ -348,6 +355,29 @@ export async function initialize(devContext: NuxtDevContext, ctx: InitializeOpti logs.emit(log) }) + const { openDevSpanChannel } = await import('./span-channel') + let spanBatch: DevRequestSpan[] = [] + let spanTimer: NodeJS.Timeout | undefined + const pushSpan = (span: DevRequestSpan) => { + spanBatch.push(span) + if (spanBatch.length > SPAN_BATCH_LIMIT) { + spanBatch.shift() + } + spanTimer ??= setTimeout(() => { + spanTimer = undefined + const flushed = spanBatch + spanBatch = [] + if (ipc.enabled) { + ipc.send({ type: 'nuxt:internal:dev:spans', spans: flushed }) + return + } + spans.emit(flushed) + }, REQUEST_FLUSH_MS) + spanTimer.unref?.() + } + closeSpanChannel = openDevSpanChannel(pushSpan) + devServer.on('span', pushSpan) + devServer.on('building', (value) => { if (ipc.enabled) { ipc.send({ type: 'nuxt:internal:dev:building', building: value }) @@ -473,6 +503,7 @@ export async function initialize(devContext: NuxtDevContext, ctx: InitializeOpti const close = () => { closePromise ??= (async () => { closeLogChannel?.() + closeSpanChannel?.() devServer.closeWatchers() try { await Promise.all([ @@ -512,6 +543,7 @@ export async function initialize(devContext: NuxtDevContext, ctx: InitializeOpti }, onLog: logs.subscribe, onRequests: requests.subscribe, + onSpans: spans.subscribe, onBuilding: building.subscribe, onReport: reports.subscribe, onReportClear: reportsCleared.subscribe, diff --git a/packages/nuxt-cli/src/dev/span-channel.ts b/packages/nuxt-cli/src/dev/span-channel.ts new file mode 100644 index 000000000..0f0ae7721 --- /dev/null +++ b/packages/nuxt-cli/src/dev/span-channel.ts @@ -0,0 +1,38 @@ +import { BroadcastChannel } from 'node:worker_threads' + +/** A timed piece of work the app did while serving a request. */ +export interface DevRequestSpan { + requestId: string + /** + * `route` and `middleware` for h3 handlers, `fetch` for an outgoing request, + * `compile` for a module Vite compiled, and the rest for the Nuxt + * channel of the same name. + */ + kind: 'route' | 'middleware' | 'fetch' | 'hook' | 'plugin' | 'data' | 'render' | 'island' | 'compile' + /** What ran: a hook, plugin or data key, or `METHOD url` for a request. */ + name: string + /** Epoch milliseconds, fractional. */ + start: number + duration: number + status?: number + error?: boolean + /** For `compile`: the Vite environment the module was compiled for. */ + environment?: string + /** For `compile`: milliseconds each Vite plugin spent on the module, excluding nested calls. */ + plugins?: Record + /** For `compile`: fetched while other app requests were also in flight. */ + shared?: boolean +} + +/** Where `runtime/dev-request-context.mjs` sends the spans it times. */ +const DEV_SPAN_CHANNEL = 'nuxt:dev:span' + +/** Receive the app's spans until the returned function is called. */ +export function openDevSpanChannel(sink: (span: DevRequestSpan) => void): () => void { + const channel = new BroadcastChannel(DEV_SPAN_CHANNEL) + channel.unref() + channel.onmessage = (event: { data: DevRequestSpan }) => { + sink(event.data) + } + return () => channel.close() +} diff --git a/packages/nuxt-cli/src/dev/tui/controller.ts b/packages/nuxt-cli/src/dev/tui/controller.ts index 75ac2eac7..4239789f2 100644 --- a/packages/nuxt-cli/src/dev/tui/controller.ts +++ b/packages/nuxt-cli/src/dev/tui/controller.ts @@ -2,6 +2,7 @@ import type { PendingRender } from '../../utils/progress-snapshot' import type { DevReportSummary } from '../error-channel' import type { ServerLogEvent } from '../log-channel' import type { ShortcutContext } from '../shortcuts' +import type { DevRequestSpan } from '../span-channel' import type { DevRequestEvent, DevRoutes } from '../utils' import type { DevUIOptions } from './index' import type { DevStatus } from './panel' @@ -24,6 +25,8 @@ export interface DevUIController { pushServerLog: (log: ForwardedLog) => void /** Record a batch of served requests for the traffic ticker. */ pushRequests: (requests: DevRequestEvent[]) => void + /** Record spans the app timed while serving requests, for the trace view. */ + pushSpans: (spans: DevRequestSpan[]) => void /** Record a report the app raised, for the log view and the status line. */ pushReport: (report: DevReportSummary) => void /** Drop a report the status line is still naming. */ @@ -45,6 +48,7 @@ export const NOOP_CONTROLLER: DevUIController = { settleRestart: () => {}, pushServerLog: () => {}, pushRequests: () => {}, + pushSpans: () => {}, pushReport: () => {}, clearReport: () => {}, setRoutes: () => {}, diff --git a/packages/nuxt-cli/src/dev/tui/index.ts b/packages/nuxt-cli/src/dev/tui/index.ts index a26276aa7..28601069f 100644 --- a/packages/nuxt-cli/src/dev/tui/index.ts +++ b/packages/nuxt-cli/src/dev/tui/index.ts @@ -672,6 +672,7 @@ export function setupDevUI(context: ShortcutContext, options: DevUIOptions = {}) activityTimer = setTimeout(clearActivity, ACTIVITY_MS) activityTimer.unref?.() }, + pushSpans: spans => requests.pushSpans(spans), pushReport: (report) => { // Set before the event, which would otherwise paint the badge's standing // description in between. diff --git a/packages/nuxt-cli/src/dev/tui/request-overlay.ts b/packages/nuxt-cli/src/dev/tui/request-overlay.ts index 1516e5685..82d8e02c1 100644 --- a/packages/nuxt-cli/src/dev/tui/request-overlay.ts +++ b/packages/nuxt-cli/src/dev/tui/request-overlay.ts @@ -1,3 +1,4 @@ +import type { DevRequestSpan } from '../span-channel' import type { DevEventLog, DevLogEvent } from './events' import type { Key } from './keys' import type { DevRequest, RequestLog } from './requests' @@ -15,6 +16,7 @@ import { MUTED, paint } from '../../utils/terminal-theme' import { formatEvent, formatTime } from './overlay' import { paintStatus } from './panel' import { formatHints, ScreenOverlay } from './screen' +import { truncate } from './width' type TrafficFilter = 'all' | 'errors' | 'slow' @@ -162,6 +164,7 @@ export class RequestOverlay extends ScreenOverlay { }, ...file ? [{ lines: [`${' '.repeat(12)}${styleText(MUTED, 'served by ')}${link(file, { cwd: this.#cwd })}`], copy: file }] : [], { lines: [''] }, + ...renderTimeline(request, this.#requests.spansFor(request), columns), ] const events = this.#traceEvents(request) if (!events.length) { @@ -221,6 +224,170 @@ export class RequestOverlay extends ScreenOverlay { } } +type SpanColor = 'white' | 'red' | 'cyan' | 'green' | 'magenta' | 'blue' | 'yellow' | 'gray' + +const SPAN_COLORS: Record = { + route: 'green', + middleware: 'green', + fetch: 'magenta', + hook: 'cyan', + plugin: 'blue', + data: 'yellow', + render: 'white', + island: 'white', + compile: 'gray', +} + +/** Columns taken by the kind, the duration and the gaps between them and the label and bar. */ +const TIMELINE_CHROME = 22 +const LABEL_MIN_WIDTH = 16 +const TIMELINE_MIN_WIDTH = 10 +/** How many Vite plugins and modules the compile breakdown lists. */ +const TOP_PLUGINS = 8 +const TOP_MODULES = 5 + +interface TimelineRow { + kind: string + label: string + /** Disjoint intervals drawn on the row, as `[start, end]` in epoch milliseconds. */ + segments: Array<[number, number]> + duration: number + color: SpanColor +} + +/** + * The request and every span timed for it, as bars on one time axis spanning + * the request. Each span is indented beneath the spans it ran inside, and the + * server modules compiled for it are drawn as one row wherever any was + * compiling. + */ +function renderTimeline(request: DevRequest, spans: DevRequestSpan[], columns: number): OverlayEntry[] { + if (!spans.length) { + return [] + } + const origin = Math.min(request.start ?? Number.POSITIVE_INFINITY, ...spans.map(span => span.start)) + const end = Math.max(origin + request.duration, ...spans.map(span => span.start + span.duration)) + const total = Math.max(end - origin, 1) + const requestStart = request.start ?? origin + + const compiled = spans.filter(span => span.kind === 'compile') + const rows: TimelineRow[] = [ + { kind: 'request', label: `${request.method} ${request.url}`, segments: [[requestStart, requestStart + request.duration]], duration: request.duration, color: 'white' }, + ] + if (compiled.length) { + const segments = mergeIntervals(compiled.map(span => [span.start, span.start + span.duration])) + const shared = compiled.some(span => span.shared) ? ', shared' : '' + rows.push({ + kind: 'compile', + label: ` ${compiled.length} ${compiled.length === 1 ? 'module' : 'modules'}${shared}`, + segments, + duration: segments.reduce((sum, [from, to]) => sum + to - from, 0), + color: SPAN_COLORS.compile, + }) + } + const open: DevRequestSpan[] = [] + for (const span of spans) { + if (span.kind === 'compile') { + continue + } + const spanEnd = span.start + span.duration + while (open.length && open.at(-1)!.start + open.at(-1)!.duration < spanEnd) { + open.pop() + } + rows.push({ + kind: span.kind, + label: `${' '.repeat(open.length + 1)}${span.name}${span.status ? ` ${span.status}` : ''}`, + segments: [[span.start, spanEnd]], + duration: span.duration, + color: span.error || (span.status ?? 0) >= 400 ? 'red' : SPAN_COLORS[span.kind] ?? 'white', + }) + open.push(span) + } + + const longest = Math.max(...rows.map(row => row.label.length)) + const labelWidth = Math.max(LABEL_MIN_WIDTH, Math.min(longest, Math.floor(columns * 0.4))) + const width = Math.max(TIMELINE_MIN_WIDTH, columns - labelWidth - TIMELINE_CHROME) + const totalLabel = formatSpanDuration(total) + const axis = styleText(MUTED, `${'0ms'.padEnd(width - totalLabel.length)}${totalLabel}`) + + return [ + { lines: [`${styleText('bold', 'timeline'.padEnd(labelWidth + 11))} ${axis}`] }, + ...rows.map((row) => { + const label = truncate(row.label, labelWidth).padEnd(labelWidth) + const time = formatSpanDuration(row.duration).padStart(9) + return { + lines: [`${styleText(MUTED, row.kind.padEnd(10))} ${label} ${drawBar(row, origin, total, width)} ${styleText(MUTED, time)}`], + copy: `+${formatSpanDuration(row.segments[0]![0] - origin)} ${row.kind} ${row.label.trim()} ${formatSpanDuration(row.duration)}`, + } + }), + { lines: [''] }, + ...renderCompileBreakdown(compiled, columns), + ] +} + +function drawBar(row: TimelineRow, origin: number, total: number, width: number): string { + const cells = Array.from({ length: width }).fill(false) + for (const [from, to] of row.segments) { + const offset = Math.min(width - 1, Math.floor((from - origin) / total * width)) + const length = Math.max(1, Math.min(width - offset, Math.round((to - from) / total * width))) + cells.fill(true, offset, offset + length) + } + return cells + .map(filled => filled ? '█' : ' ') + .join('') + .replace(/█+/g, run => styleText(row.color, run)) +} + +function mergeIntervals(intervals: Array<[number, number]>): Array<[number, number]> { + const merged: Array<[number, number]> = [] + for (const [from, to] of intervals.sort((a, b) => a[0] - b[0])) { + const last = merged.at(-1) + if (last && from <= last[1]) { + last[1] = Math.max(last[1], to) + } + else { + merged.push([from, to]) + } + } + return merged +} + +/** Where the compile time went: the busiest Vite plugins, then the slowest modules. */ +function renderCompileBreakdown(compiled: DevRequestSpan[], columns: number): OverlayEntry[] { + if (!compiled.length) { + return [] + } + const byPlugin = new Map() + for (const span of compiled) { + for (const [plugin, time] of Object.entries(span.plugins ?? {})) { + byPlugin.set(plugin, (byPlugin.get(plugin) ?? 0) + time) + } + } + const plugins = [...byPlugin].sort((a, b) => b[1] - a[1]).slice(0, TOP_PLUGINS) + const modules = [...compiled].sort((a, b) => b.duration - a.duration).slice(0, TOP_MODULES) + const nameWidth = Math.max(0, columns - 12) + const row = (name: string, duration: number): OverlayEntry => ({ + lines: [` ${formatSpanDuration(duration).padStart(8)} ${truncate(name, nameWidth)}`], + copy: `${formatSpanDuration(duration)} ${name}`, + }) + return [ + ...plugins.length + ? [ + { lines: [styleText('bold', 'vite plugins') + styleText(MUTED, ' · time spent compiling for this request')] }, + ...plugins.map(([plugin, time]) => row(plugin, time)), + { lines: [''] }, + ] + : [], + { lines: [styleText('bold', 'slowest modules')] }, + ...modules.map(span => row(span.environment ? `${span.name} ${styleText(MUTED, `(${span.environment})`)}` : span.name, span.duration)), + { lines: [''] }, + ] +} + +function formatSpanDuration(duration: number): string { + return duration < 10 ? `${Math.max(0, duration).toFixed(1)}ms` : `${Math.round(duration)}ms` +} + function formatDuration(duration: number): string { const text = `${duration}ms`.padStart(7) if (duration >= VERY_SLOW_MS) { diff --git a/packages/nuxt-cli/src/dev/tui/requests.ts b/packages/nuxt-cli/src/dev/tui/requests.ts index a5fc57f77..fbe9f5b70 100644 --- a/packages/nuxt-cli/src/dev/tui/requests.ts +++ b/packages/nuxt-cli/src/dev/tui/requests.ts @@ -1,7 +1,11 @@ +import type { DevRequestSpan } from '../span-channel' + export interface DevRequest { /** Identity shared with attributed log events, when the server reported one. */ id?: string time: number + /** Epoch milliseconds at which the server received it, fractional. */ + start?: number method: string url: string status: number @@ -16,6 +20,7 @@ export class RequestLog { #listeners = new Set<() => void>() #capacity: number #total = 0 + #spans = new Map() constructor(capacity = 1000) { this.#capacity = capacity @@ -33,13 +38,48 @@ export class RequestLog { this.#total += requests.length this.#requests.push(...requests) if (this.#requests.length > this.#capacity) { - this.#requests.splice(0, this.#requests.length - this.#capacity) + for (const dropped of this.#requests.splice(0, this.#requests.length - this.#capacity)) { + if (dropped.id !== undefined) { + this.#spans.delete(dropped.id) + } + } } for (const listener of this.#listeners) { listener() } } + /** Record spans the app timed, against the requests they were timed for. */ + pushSpans(spans: DevRequestSpan[]): void { + if (!spans.length) { + return + } + for (const span of spans) { + const list = this.#spans.get(span.requestId) + if (list) { + list.push(span) + } + else { + this.#spans.set(span.requestId, [span]) + } + } + // Spans can arrive for a request whose own event never does; bound them too. + while (this.#spans.size > this.#capacity) { + this.#spans.delete(this.#spans.keys().next().value!) + } + for (const listener of this.#listeners) { + listener() + } + } + + /** The spans timed for a request, in the order they started, outermost first. */ + spansFor(request: DevRequest): DevRequestSpan[] { + if (request.id === undefined) { + return [] + } + return [...this.#spans.get(request.id) ?? []].sort((a, b) => a.start - b.start || b.duration - a.duration) + } + recent(count: number, filter?: (request: DevRequest) => boolean): DevRequest[] { const source = filter ? this.#requests.filter(filter) : this.#requests return source.slice(-count) @@ -67,6 +107,7 @@ export class RequestLog { /** Drop the history and the running total, telling anyone displaying them. */ clear(): void { this.#requests.length = 0 + this.#spans.clear() this.#total = 0 for (const listener of this.#listeners) { listener() diff --git a/packages/nuxt-cli/src/dev/utils.ts b/packages/nuxt-cli/src/dev/utils.ts index 64bd56982..5871488b6 100644 --- a/packages/nuxt-cli/src/dev/utils.ts +++ b/packages/nuxt-cli/src/dev/utils.ts @@ -7,11 +7,13 @@ import type { Server as HttpServer, IncomingMessage, RequestListener, ServerResp import type { PendingRender } from '../utils/progress-snapshot' import type { ResolvedCertificate } from './cert' +import type { InflightAppRequest } from './compile-timing' import type { DevReportSummary } from './error-channel' import type { InspectOptions } from './inspect' import type { BoundServer, DevListenOverrides, Listener, ListenOptions, ListenURL } from './listen' import type { ServerLogEvent } from './log-channel' import type { DevRestartReason } from './reason' +import type { DevRequestSpan } from './span-channel' import { Buffer } from 'node:buffer' import { hash } from 'node:crypto' import EventEmitter from 'node:events' @@ -48,7 +50,7 @@ import { resolveDefaultLoadingTemplate } from './loading-template' import { resolvePortlessURLs } from './portless' import { DEV_INTERNAL_PREFIX, DevProgress } from './progress' import { formatChangedKeys, formatRestartReason, formatSkippedReload, mergeRestartReasons, withConfigKeys } from './reason' -import { createRequest, encodeRequestLabel, REQUEST_HEADER, REQUEST_LABEL_HEADER, runWithRequest } from './serving-state' +import { createRequest, currentRequest, encodeRequestLabel, REQUEST_HEADER, REQUEST_LABEL_HEADER, runWithRequest } from './serving-state' import { WarmupGate } from './warmup-gate' /** @@ -110,6 +112,7 @@ export type NuxtDevIPCMessage | { type: 'nuxt:internal:dev:loading:error', error: Error } | ({ type: 'nuxt:internal:dev:log' } & ServerLogEvent) | { type: 'nuxt:internal:dev:requests', requests: DevRequestEvent[] } + | { type: 'nuxt:internal:dev:spans', spans: DevRequestSpan[] } | { type: 'nuxt:internal:dev:routes', payload: DevRoutes } | { type: 'nuxt:internal:dev:building', building: boolean } | { type: 'nuxt:internal:dev:rendering', pending?: PendingRender, awaiting?: boolean } @@ -356,6 +359,8 @@ export interface DevRequestEvent { method: string url: string status: number + /** Epoch milliseconds at which the request was received, fractional. */ + start?: number /** Milliseconds from receiving the request to the response closing. */ duration: number /** Served by the bundler (module graph, HMR plumbing) rather than the app. */ @@ -398,6 +403,8 @@ interface DevServerEventMap { 'restart': [reason?: DevRestartReason] 'change': [] 'request': [event: DevRequestEvent] + /** Time spent serving a request that the app did not publish itself. */ + 'span': [span: DevRequestSpan] 'routes': [payload: DevRoutes] 'building': [building: boolean] /** A report the app forwarded, rendered for a terminal. */ @@ -423,6 +430,9 @@ export class NuxtDevServer extends EventEmitter { #inflightResponses = new Set() /** Responses the CLI answered itself, kept out of the dev UI's request feed. */ #internalResponses = new Set() + /** Requests being served, which the compile time Vite reports is charged to. */ + #inflight = new Map() + #unsubscribeCompileTiming?: () => void #lockCleanup?: () => void #lockedBuildDir?: string #pendingReason?: DevRestartReason @@ -517,8 +527,10 @@ export class NuxtDevServer extends EventEmitter { } const start = performance.now() const fetchDest = String(req.headers['sec-fetch-dest'] || '') || undefined + this.#inflight.set(request.id, { id: request.id, internal: isBundlerRequest(url, fetchDest) }) return runWithRequest(request, () => { res.once('close', () => { + this.#inflight.delete(request.id) if (this.#internalResponses.delete(res)) { return } @@ -527,6 +539,7 @@ export class NuxtDevServer extends EventEmitter { method, url, status: res.statusCode, + start: performance.timeOrigin + start, duration: Math.round(performance.now() - start), internal: isBundlerRequest(url, fetchDest) || undefined, }) @@ -795,6 +808,15 @@ export class NuxtDevServer extends EventEmitter { this.emit('loading', this.#loadingMessage) this.#openErrorBridge() + if (this.options.captureUIEvents && !this.#unsubscribeCompileTiming) { + const { subscribeCompileTiming } = await import('./compile-timing') + this.#unsubscribeCompileTiming = subscribeCompileTiming({ + rootDir: () => this.#rootDir(), + current: currentRequest, + inflight: () => [...this.#inflight.values()], + report: span => this.emit('span', span), + }) + } await this.#bindEagerListener() try { @@ -831,10 +853,12 @@ export class NuxtDevServer extends EventEmitter { this.#configWatcher?.() } - /** Stop listening for forwarded reports. Call only on final shutdown, not during reloads. */ + /** Stop listening for forwarded reports and bundler timings. Call only on final shutdown, not during reloads. */ closeErrorBridge(): void { this.#closeErrorBridge?.() this.#closeErrorBridge = undefined + this.#unsubscribeCompileTiming?.() + this.#unsubscribeCompileTiming = undefined } /** @@ -922,6 +946,11 @@ export class NuxtDevServer extends EventEmitter { loadOptions.defaults = resolveDevServerDefaults({ hostname, https: !!this.listener?.https }, urls) } + // A default rather than an override, so a project can still opt out. + if (captureUIEvents) { + loadOptions.defaults = { ...loadOptions.defaults, tracingChannel: true } as NuxtConfig + } + return loadOptions } diff --git a/packages/nuxt-cli/test/unit/commands/dev-run.spec.ts b/packages/nuxt-cli/test/unit/commands/dev-run.spec.ts index a2c94a73c..f4106770e 100644 --- a/packages/nuxt-cli/test/unit/commands/dev-run.spec.ts +++ b/packages/nuxt-cli/test/unit/commands/dev-run.spec.ts @@ -107,6 +107,7 @@ beforeEach(() => { onEachReady: vi.fn(), onLog: vi.fn(), onRequests: vi.fn(), + onSpans: vi.fn(), onRoutes: vi.fn(), onBuilding: vi.fn(), onReport: vi.fn(), diff --git a/packages/nuxt-cli/test/unit/compile-timing.spec.ts b/packages/nuxt-cli/test/unit/compile-timing.spec.ts new file mode 100644 index 000000000..2d2b0111b --- /dev/null +++ b/packages/nuxt-cli/test/unit/compile-timing.spec.ts @@ -0,0 +1,108 @@ +import type { DevRequestSpan } from '../../src/dev/span-channel' + +import { tracingChannel } from 'node:diagnostics_channel' +import { afterEach, describe, expect, it } from 'vitest' + +import { shortenModuleId, subscribeCompileTiming } from '../../src/dev/compile-timing' + +const sleep = (ms: number) => new Promise(resolve => setTimeout(resolve, ms)) + +function selfTotal(span: DevRequestSpan): number { + return Object.values(span.plugins ?? {}).reduce((sum, time) => sum + time, 0) +} + +const modules = tracingChannel('vite.module') +const plugins = tracingChannel('vite.plugin') +const nuxtModules = tracingChannel('nuxt.bundler.module') +const nuxtPlugins = tracingChannel('nuxt.bundler.plugin') + +function plugin(name: string, fn: () => Promise): Promise { + return plugins.tracePromise(fn, { plugin: name, hook: 'transform' }) +} + +/** Compile a module the way the bundler would: a transform that resolves a dependency. */ +function compile(id: string) { + return modules.tracePromise(async () => { + await plugin('transformer', async () => { + await plugin('resolver', () => sleep(20)) + await sleep(20) + }) + return { id } + }, { url: id, environment: 'ssr' }) +} + +let unsubscribe: (() => void) | undefined +afterEach(() => unsubscribe?.()) + +function subscribe(inflight: Array<{ id: string, internal: boolean }>, current?: { id: string }) { + const spans: DevRequestSpan[] = [] + unsubscribe = subscribeCompileTiming({ rootDir: () => '/project', current: () => current, inflight: () => inflight, report: span => spans.push(span) }) + return spans +} + +describe('compile timing', () => { + it('charges a module to the app request in flight, with each plugin\'s own time', async () => { + const spans = subscribe([{ id: 'r1', internal: false }, { id: 'bundler', internal: true }]) + await compile('/project/app/pages/index.vue?macro=true') + + expect(spans).toHaveLength(1) + const [span] = spans + expect(span).toMatchObject({ requestId: 'r1', kind: 'compile', name: 'app/pages/index.vue', environment: 'ssr' }) + expect(span!.shared).toBeUndefined() + expect(span!.plugins!.resolver).toBeGreaterThanOrEqual(15) + expect(span!.plugins!.transformer).toBeGreaterThanOrEqual(15) + expect(selfTotal(span!)).toBeLessThanOrEqual(span!.duration + 1) + }) + + it('keeps concurrent modules apart', async () => { + const spans = subscribe([{ id: 'r1', internal: false }]) + await Promise.all([compile('/project/a.ts'), compile('/project/b.ts')]) + expect(spans.map(span => span.name).sort()).toEqual(['a.ts', 'b.ts']) + for (const span of spans) { + expect(Object.keys(span.plugins!).sort()).toEqual(['resolver', 'transformer']) + expect(selfTotal(span)).toBeLessThanOrEqual(span.duration + 1) + } + }) + + it('charges a module compiled while serving a request to that request alone', async () => { + const spans = subscribe([{ id: 'r1', internal: false }, { id: 'r2', internal: false }], { id: 'asset' }) + await compile('/project/app/app.vue') + expect(spans.map(span => [span.requestId, span.shared])).toEqual([['asset', undefined]]) + }) + + it('reads the channels Nuxt publishes, and reports a module traced on both once', async () => { + const spans = subscribe([{ id: 'r1', internal: false }]) + await nuxtModules.tracePromise(async () => { + await nuxtPlugins.tracePromise(() => sleep(20), { plugin: 'nuxt:only', hook: 'transform' }) + }, { id: '/project/app/app.vue', environment: 'ssr' }) + await nuxtModules.tracePromise(() => compile('/project/server/api/hello.ts'), { id: '/project/server/api/hello.ts', environment: 'ssr' }) + + expect(spans.map(span => span.name)).toEqual(['app/app.vue', 'server/api/hello.ts']) + expect(spans[0]!.plugins!['nuxt:only']).toBeGreaterThanOrEqual(15) + expect(Object.keys(spans[1]!.plugins!).sort()).toEqual(['resolver', 'transformer']) + }) + + it('marks a module compiled while several app requests are in flight as shared', async () => { + const spans = subscribe([{ id: 'r1', internal: false }, { id: 'r2', internal: false }]) + await compile('/project/server/api/hello.ts') + expect(spans.map(span => [span.requestId, span.shared])).toEqual([['r1', true], ['r2', true]]) + }) + + it('reports nothing when no app request is in flight, or once unsubscribed', async () => { + const spans = subscribe([]) + await compile('/project/app/app.vue') + expect(spans).toHaveLength(0) + unsubscribe!() + await compile('/project/app/app.vue') + expect(spans).toHaveLength(0) + }) + + it('names modules from their package or the project', () => { + expect(shortenModuleId('/@fs/project/node_modules/.pnpm/vue@3/node_modules/vue/index.mjs?v=1', '/project')).toBe('vue/index.mjs') + expect(shortenModuleId('/project/app/app.vue', '/project/')).toBe('app/app.vue') + expect(shortenModuleId('virtual:nuxt:app.config', '/project')).toBe('virtual:nuxt:app.config') + expect(shortenModuleId('/pages/index.vue?macro=true', '/project')).toBe('pages/index.vue') + expect(shortenModuleId('/@fs/elsewhere/lib.mjs', '/project')).toBe('/elsewhere/lib.mjs') + expect(shortenModuleId('@id/__x00__nuxt-nitro-virtual:#internal/nuxt/error-channel', '/project')).toBe('nuxt-nitro-virtual:#internal/nuxt/error-channel') + }) +}) diff --git a/packages/nuxt-cli/test/unit/dev-request-context.spec.ts b/packages/nuxt-cli/test/unit/dev-request-context.spec.ts index 97b9c3531..f7a8ebc3a 100644 --- a/packages/nuxt-cli/test/unit/dev-request-context.spec.ts +++ b/packages/nuxt-cli/test/unit/dev-request-context.spec.ts @@ -1,8 +1,12 @@ +import type { DevRequestSpan } from '../../src/dev/span-channel' + +import { channel, tracingChannel } from 'node:diagnostics_channel' import { BroadcastChannel } from 'node:worker_threads' import { describe, expect, it, vi } from 'vitest' import { DEV_LOG_CHANNEL, openDevLogChannel } from '../../src/dev/log-channel' +import { openDevSpanChannel } from '../../src/dev/span-channel' const reporters: Array<{ log: (logObj: unknown) => void }> = [] vi.mock('consola', () => ({ @@ -146,4 +150,59 @@ describe('dev request context plugin', () => { close() } }) + + it('reports spans published while serving a request, against that request', async () => { + const before: Array<(event: { name: string, context: Record }) => void> = [] + const after: typeof before = [] + const hooks = { + _hooks: { 'render:html': [() => {}] } as Record, + beforeEach: (fn: (typeof before)[number]) => before.push(fn), + afterEach: (fn: (typeof before)[number]) => after.push(fn), + callHook(name: string) { + const event = { name, context: {} } + before.forEach(fn => fn(event)) + after.forEach(fn => fn(event)) + }, + } + const fetchRequest = { method: 'GET', origin: 'https://api.example.com', path: '/data' } + const { app, nitroApp: instance } = nitroApp(async () => { + await tracingChannel('nuxt.plugin').tracePromise(async () => {}, { plugin: { name: 'nuxt:head' } }) + await tracingChannel('nuxt.hook').tracePromise(async () => {}, { name: 'app:rendered', args: [] }) + await tracingChannel('nuxt.hook').tracePromise(async () => {}, { hook: { name: 'app:created' } }) + await tracingChannel('nuxt.middleware').tracePromise(async () => {}, { middleware: { name: 'auth', global: false } }) + await tracingChannel('nuxt.middleware').tracePromise(async () => {}, { middleware: { path: '@/project/node_modules/nuxt/dist/app/middleware/guard.js', global: true } }) + await tracingChannel('nuxt.data').tracePromise(async () => {}, { key: 'posts', functionName: 'useFetch' }) + await tracingChannel('h3.request').tracePromise(async () => {}, { type: 'route', event: { req: { method: 'GET', url: 'http://localhost/api/posts?page=2' }, res: { status: 201 } } }) + hooks.callHook('render:html') + hooks.callHook('request') + channel('undici:request:create').publish({ request: fetchRequest }) + channel('undici:request:headers').publish({ request: fetchRequest, response: { statusCode: 200 } }) + channel('undici:request:trailers').publish({ request: fetchRequest }) + return 'served' + }) + plugin({ ...instance, hooks }) + + const received: DevRequestSpan[] = [] + const close = openDevSpanChannel(span => received.push(span)) + try { + await tracingChannel('nuxt.plugin').tracePromise(async () => {}, { plugin: { name: 'outside a request' } }) + await app.handler(eventFor({ [HEADER]: 'req-9', [LABEL_HEADER]: 'GET%20%2F' })) + await vi.waitFor(() => expect(received).toHaveLength(9)) + expect(received.every(span => span.requestId === 'req-9')).toBe(true) + expect(received.map(({ kind, name, status }) => ({ kind, name, status }))).toEqual(expect.arrayContaining([ + { kind: 'plugin', name: 'nuxt:head', status: undefined }, + { kind: 'hook', name: 'app:rendered', status: undefined }, + { kind: 'hook', name: 'app:created', status: undefined }, + { kind: 'middleware', name: 'auth', status: undefined }, + { kind: 'middleware', name: 'nuxt/dist/app/middleware/guard.js', status: undefined }, + { kind: 'data', name: 'useFetch(posts)', status: undefined }, + { kind: 'route', name: 'GET /api/posts?page=2', status: 201 }, + { kind: 'hook', name: 'render:html', status: undefined }, + { kind: 'fetch', name: 'GET https://api.example.com/data', status: 200 }, + ])) + } + finally { + close() + } + }) }) diff --git a/packages/nuxt-cli/test/unit/dev-tui.spec.ts b/packages/nuxt-cli/test/unit/dev-tui.spec.ts index c7efb8c81..2eb16926d 100644 --- a/packages/nuxt-cli/test/unit/dev-tui.spec.ts +++ b/packages/nuxt-cli/test/unit/dev-tui.spec.ts @@ -1718,6 +1718,48 @@ describe('request overlay', () => { expect(lastFrame()).toContain('traffic') }) + it('draws the spans timed for a request on a timeline', () => { + const { log, overlay, lastFrame } = create({ events: new DevEventLog() }) + log.push([{ id: 'r1', time: 0, start: 1000, method: 'GET', url: '/', status: 200, duration: 100 }]) + log.pushSpans([ + { requestId: 'r1', kind: 'route', name: 'GET /api/data', start: 1010, duration: 50, status: 200 }, + { requestId: 'r1', kind: 'hook', name: 'render:html', start: 1080, duration: 0.4 }, + { requestId: 'r1', kind: 'fetch', name: 'GET https://a.dev', start: 1020, duration: 30, status: 200 }, + { requestId: 'r1', kind: 'middleware', name: 'GET /api/data', start: 1010, duration: 5 }, + { requestId: 'r2', kind: 'hook', name: 'unrelated', start: 1000, duration: 1 }, + ]) + overlay.open() + overlay.handleKey({ name: 'down' }) + overlay.handleKey({ name: 'return' }) + const frame = lastFrame() + expect(frame).toContain('timeline') + expect(frame).toMatch(/route\s+ {2}GET \/api\/data 200\s+█+\s+50ms/) + expect(frame).toMatch(/middleware\s+ {4}GET \/api\/data\s+█+\s+5\.0ms/) + expect(frame).toMatch(/fetch\s+ {4}GET https:\/\/a\.dev 200/) + expect(frame).toMatch(/hook\s+ {2}render:html\s+█\s+0\.4ms/) + expect(frame).not.toContain('unrelated') + expect(frame.indexOf('GET /api/data')).toBeLessThan(frame.indexOf('a.dev')) + }) + + it('draws compiled modules as one row and breaks their time down by plugin', () => { + const { log, overlay, lastFrame } = create({ events: new DevEventLog() }) + log.push([{ id: 'r1', time: 0, start: 1000, method: 'GET', url: '/', status: 200, duration: 100 }]) + log.pushSpans([ + { requestId: 'r1', kind: 'compile', name: 'app/app.vue', start: 1000, duration: 30, environment: 'nitro', plugins: { 'vite:vue': 20, 'nuxt:components': 4 } }, + { requestId: 'r1', kind: 'compile', name: 'vue/index.mjs', start: 1010, duration: 10, environment: 'nitro', plugins: { 'vite:vue': 1 } }, + { requestId: 'r1', kind: 'compile', name: 'app/pages/index.vue', start: 1060, duration: 20, environment: 'nitro', plugins: { 'nuxt:components': 9 } }, + { requestId: 'r1', kind: 'route', name: 'GET /', start: 1030, duration: 60, status: 200 }, + ]) + overlay.open() + overlay.handleKey({ name: 'down' }) + overlay.handleKey({ name: 'return' }) + const frame = lastFrame() + expect(frame).toMatch(/compile\s+3 modules\s+█+ +█+ +50ms/) + expect(frame).toMatch(/vite plugins[\s\S]*21ms\s+vite:vue[\s\S]*13ms\s+nuxt:components/) + expect(frame).toMatch(/slowest modules[\s\S]*30ms\s+app\/app\.vue \(nitro\)/) + expect(frame).not.toMatch(/compile\s+ {2}app\/app\.vue/) + }) + it('says so when a request has no attributed logs', () => { const events = new DevEventLog() const { log, overlay, lastFrame } = create({ events }) diff --git a/playground-nightly/app/app.vue b/playground-nightly/app/app.vue index fa164a2e6..8f62b8bf9 100644 --- a/playground-nightly/app/app.vue +++ b/playground-nightly/app/app.vue @@ -1,3 +1,3 @@ diff --git a/playground-nightly/app/middleware/traced.ts b/playground-nightly/app/middleware/traced.ts new file mode 100644 index 000000000..3d59968d2 --- /dev/null +++ b/playground-nightly/app/middleware/traced.ts @@ -0,0 +1 @@ +export default defineNuxtRouteMiddleware(() => {}) diff --git a/playground-nightly/app/pages/index.vue b/playground-nightly/app/pages/index.vue new file mode 100644 index 000000000..fa164a2e6 --- /dev/null +++ b/playground-nightly/app/pages/index.vue @@ -0,0 +1,3 @@ + diff --git a/playground-nightly/app/pages/trace.vue b/playground-nightly/app/pages/trace.vue new file mode 100644 index 000000000..316f02b87 --- /dev/null +++ b/playground-nightly/app/pages/trace.vue @@ -0,0 +1,9 @@ + + + diff --git a/playground-nightly/test/e2e/dev-tui.spec.ts b/playground-nightly/test/e2e/dev-tui.spec.ts index 55c200a01..4fe3032b1 100644 --- a/playground-nightly/test/e2e/dev-tui.spec.ts +++ b/playground-nightly/test/e2e/dev-tui.spec.ts @@ -87,4 +87,42 @@ describe('dev ui on nuxt nightly', () => { expect(output.split('log from the server route')).toHaveLength(2) }, 240_000) + + it('should trace a page through its middleware, data fetching and render', async () => { + const session = record(`NUXT_IGNORE_LOCK=1 NUXT_TUI=1 node ${bin} dev --port 3214 --no-takeover`, { + cwd, + rows: 80, + columns: 140, + env: {}, + }) + try { + await session.waitFor(/ready in/, 180_000) + await fetch('http://localhost:3214/trace').then(response => response.text()) + await session.wait(2000) + session.send('n') + await session.wait(500) + session.send('/') + session.send('trace') + session.send('\r') + session.send('\u001B[B') + await session.wait(500) + session.send('\r') + await session.wait(1500) + const trace = plain(session.output()).split('trace · GET /trace').at(-1)! + + expect(trace).toContain('timeline') + expect(trace).toMatch(/middleware\s+traced/) + expect(trace).toMatch(/data\s+useFetch\(/) + expect(trace).toMatch(/route\s+GET \/api\/pid/) + expect(trace).toMatch(/render\s+renderToString/) + expect(trace).toMatch(/plugin\s+nuxt:router/) + expect(trace).toMatch(/hook\s+app:rendered/) + expect(trace).not.toContain('@/') + expect(trace).toMatch(/compile\s+\d+ modules/) + expect(trace).toMatch(/vite plugins[\s\S]*slowest modules/) + } + finally { + await session.stop() + } + }, 240_000) })