Debug tracing: Include navigation through hydration timing (#54078)

This:
- Adds a simple, generic tracer in the client that can be subscribed to in order to report spans
- Reports client spans through the HMR socket in the dev server
- Receives these spans and includes them in `.next/trace`


Closes WEB-1387

packages/next/src/client/dev/error-overlay/websocket.ts

@@ -17,7 +17,7 @@ export function addMessageListener(cb: (event: any) => void) {
   eventCallbacks.push(cb)
 }
 
-export function sendMessage(data: any) {
+export function sendMessage(data: string) {
   if (!source || source.readyState !== source.OPEN) return
   return source.send(data)
 }

packages/next/src/client/index.tsx

@@ -46,6 +46,8 @@ import {
 } from '../shared/lib/router/adapters'
 import { SearchParamsContext } from '../shared/lib/hooks-client-context'
 import onRecoverableError from './on-recoverable-error'
+import tracer from './tracing/tracer'
+import reportToSocket from './tracing/report-to-socket'
 
 /// <reference types="react-dom/experimental" />
 
@@ -186,6 +188,8 @@ class Container extends React.Component<{
 export async function initialize(opts: { webpackHMR?: any } = {}): Promise<{
   assetPrefix: string
 }> {
+  tracer.onSpanEnd(reportToSocket)
+
   // This makes sure this specific lines are removed in production
   if (process.env.NODE_ENV === 'development') {
     webpackHMR = opts.webpackHMR
@@ -450,12 +454,31 @@ function markHydrateComplete(): void {
 
   performance.mark('afterHydrate') // mark end of hydration
 
-  performance.measure(
+  const beforeHydrationMeasure = performance.measure(
     'Next.js-before-hydration',
     'navigationStart',
     'beforeRender'
   )
-  performance.measure('Next.js-hydration', 'beforeRender', 'afterHydrate')
+
+  const hydrationMeasure = performance.measure(
+    'Next.js-hydration',
+    'beforeRender',
+    'afterHydrate'
+  )
+
+  tracer
+    .startSpan('navigation-to-hydration', {
+      startTime: performance.timeOrigin + beforeHydrationMeasure.startTime,
+      attributes: {
+        pathname: location.pathname,
+        query: location.search,
+      },
+    })
+    .end(
+      performance.timeOrigin +
+        hydrationMeasure.startTime +
+        hydrationMeasure.duration
+    )
 
   if (onPerfEntry) {
     performance.getEntriesByName('Next.js-hydration').forEach(onPerfEntry)

packages/next/src/client/tracing/report-to-socket.ts

@@ -0,0 +1,18 @@
+import { sendMessage } from '../dev/error-overlay/websocket'
+import { Span } from './tracer'
+
+export default function reportToSocket(span: Span) {
+  if (span.state.state !== 'ended') {
+    throw new Error('Expected span to be ended')
+  }
+
+  sendMessage(
+    JSON.stringify({
+      event: 'span-end',
+      startTime: span.startTime,
+      endTime: span.state.endTime,
+      spanName: span.name,
+      attributes: span.attributes,
+    })
+  )
+}

packages/next/src/client/tracing/tracer.ts

@@ -0,0 +1,77 @@
+import mitt, { MittEmitter } from '../../shared/lib/mitt'
+
+export type SpanOptions = {
+  startTime?: number
+  attributes?: Record<string, unknown>
+}
+
+export type SpanState =
+  | {
+      state: 'inprogress'
+    }
+  | {
+      state: 'ended'
+      endTime: number
+    }
+
+interface ISpan {
+  name: string
+  startTime: number
+  attributes: Record<string, unknown>
+  state: SpanState
+  end(endTime?: number): void
+}
+
+class Span implements ISpan {
+  name: string
+  startTime: number
+  onSpanEnd: (span: Span) => void
+  state: SpanState
+  attributes: Record<string, unknown>
+
+  constructor(
+    name: string,
+    options: SpanOptions,
+    onSpanEnd: (span: Span) => void
+  ) {
+    this.name = name
+    this.attributes = options.attributes ?? {}
+    this.startTime = options.startTime ?? Date.now()
+    this.onSpanEnd = onSpanEnd
+    this.state = { state: 'inprogress' }
+  }
+
+  end(endTime?: number) {
+    if (this.state.state === 'ended') {
+      throw new Error('Span has already ended')
+    }
+
+    this.state = {
+      state: 'ended',
+      endTime: endTime ?? Date.now(),
+    }
+    this.onSpanEnd(this)
+  }
+}
+
+class Tracer {
+  _emitter: MittEmitter<string> = mitt()
+
+  private handleSpanEnd = (span: Span) => {
+    this._emitter.emit('spanend', span)
+  }
+
+  startSpan(name: string, options: SpanOptions) {
+    return new Span(name, options, this.handleSpanEnd)
+  }
+
+  onSpanEnd(cb: (span: ISpan) => void): () => void {
+    this._emitter.on('spanend', cb)
+    return () => {
+      this._emitter.off('spanend', cb)
+    }
+  }
+}
+
+export { ISpan as Span }
+export default new Tracer()

packages/next/src/server/dev/hot-reloader.ts

@@ -64,6 +64,8 @@ import { getRouteLoaderEntry } from '../../build/webpack/loaders/next-route-load
 import { isInternalComponent } from '../../lib/is-internal-component'
 import { RouteKind } from '../future/route-kind'
 
+const MILLISECONDS_IN_NANOSECOND = 1_000_000
+
 function diff(a: Set<any>, b: Set<any>) {
   return new Set([...a].filter((v) => !b.has(v)))
 }
@@ -369,11 +371,27 @@ export default class HotReloader {
             | undefined
 
           switch (payload.event) {
+            case 'span-end': {
+              new Span({
+                name: payload.spanName,
+                startTime:
+                  BigInt(Math.floor(payload.startTime)) *
+                  BigInt(MILLISECONDS_IN_NANOSECOND),
+                attrs: payload.attributes,
+              }).stop(
+                BigInt(Math.floor(payload.endTime)) *
+                  BigInt(MILLISECONDS_IN_NANOSECOND)
+              )
+              break
+            }
             case 'client-hmr-latency': {
               traceChild = {
                 name: payload.event,
-                startTime: BigInt(payload.startTime) * BigInt(1000 * 1000),
-                endTime: BigInt(payload.endTime) * BigInt(1000 * 1000),
+                startTime:
+                  BigInt(payload.startTime) *
+                  BigInt(MILLISECONDS_IN_NANOSECOND),
+                endTime:
+                  BigInt(payload.endTime) * BigInt(MILLISECONDS_IN_NANOSECOND),
                 attrs: {
                   updatedModules: payload.updatedModules,
                   page: payload.page,