feat(dev): trace requests on a timeline in the network view

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)
 

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

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)
             }