Development: Implement request log time details

packages/next/src/build/duration-to-string.ts

@@ -1,32 +1,54 @@
+// Time thresholds in seconds
+const SECONDS_IN_MINUTE = 60
+const MINUTES_THRESHOLD_SECONDS = 120 // 2 minutes
+const SECONDS_THRESHOLD_HIGH = 40
+const SECONDS_THRESHOLD_LOW = 2
+const MILLISECONDS_PER_SECOND = 1000
+
+// Time thresholds and conversion factors for nanoseconds
+const NANOSECONDS_PER_SECOND = 1_000_000_000
+const NANOSECONDS_PER_MILLISECOND = 1_000_000
+const NANOSECONDS_PER_MICROSECOND = 1_000
+const NANOSECONDS_IN_MINUTE = 60_000_000_000 // 60 * 1_000_000_000
+const MINUTES_THRESHOLD_NANOSECONDS = 120_000_000_000 // 2 minutes in nanoseconds
+const SECONDS_THRESHOLD_HIGH_NANOSECONDS = 40_000_000_000 // 40 seconds in nanoseconds
+const SECONDS_THRESHOLD_LOW_NANOSECONDS = 2_000_000_000 // 2 seconds in nanoseconds
+const MILLISECONDS_THRESHOLD_NANOSECONDS = 1_000_000 // 1 millisecond in nanoseconds
+
 export function durationToString(compilerDuration: number) {
-  let durationString
-  if (compilerDuration > 120) {
-    durationString = `${(compilerDuration / 60).toFixed(1)}min`
-  } else if (compilerDuration > 40) {
-    durationString = `${compilerDuration.toFixed(0)}s`
-  } else if (compilerDuration > 2) {
-    durationString = `${compilerDuration.toFixed(1)}s`
+  if (compilerDuration > MINUTES_THRESHOLD_SECONDS) {
+    return `${(compilerDuration / SECONDS_IN_MINUTE).toFixed(1)}min`
+  } else if (compilerDuration > SECONDS_THRESHOLD_HIGH) {
+    return `${compilerDuration.toFixed(0)}s`
+  } else if (compilerDuration > SECONDS_THRESHOLD_LOW) {
+    return `${compilerDuration.toFixed(1)}s`
   } else {
-    durationString = `${(compilerDuration * 1000).toFixed(0)}ms`
+    return `${(compilerDuration * MILLISECONDS_PER_SECOND).toFixed(1)}ms`
   }
-  return durationString
-}
-
-export function hrtimeToSeconds(hrtime: [number, number]): number {
-  // hrtime is a tuple of [seconds, nanoseconds]
-  return hrtime[0] + hrtime[1] / 1e9
 }
 
-function nanosecondsBigIntToSeconds(nanoseconds: bigint): number {
-  return Number(nanoseconds) / 1000000000
+function durationToStringWithNanoseconds(durationBigInt: bigint): string {
+  const duration = Number(durationBigInt)
+  if (duration > MINUTES_THRESHOLD_NANOSECONDS) {
+    return `${(duration / NANOSECONDS_IN_MINUTE).toFixed(1)}min`
+  } else if (duration > SECONDS_THRESHOLD_HIGH_NANOSECONDS) {
+    return `${(duration / NANOSECONDS_PER_SECOND).toFixed(0)}s`
+  } else if (duration > SECONDS_THRESHOLD_LOW_NANOSECONDS) {
+    return `${(duration / NANOSECONDS_PER_SECOND).toFixed(1)}s`
+  } else if (duration > MILLISECONDS_THRESHOLD_NANOSECONDS) {
+    return `${(duration / NANOSECONDS_PER_MILLISECOND).toFixed(0)}ms`
+  } else {
+    return `${(duration / NANOSECONDS_PER_MICROSECOND).toFixed(0)}µs`
+  }
 }
 
-function hrtimeBigIntToSeconds(hrtime: bigint): number {
-  return nanosecondsBigIntToSeconds(hrtime)
+export function hrtimeToSeconds(hrtime: [number, number]): number {
+  // hrtime is a tuple of [seconds, nanoseconds]
+  return hrtime[0] + hrtime[1] / NANOSECONDS_PER_SECOND
 }
 
 export function hrtimeBigIntDurationToString(hrtime: bigint) {
-  return durationToString(hrtimeBigIntToSeconds(hrtime))
+  return durationToStringWithNanoseconds(hrtime)
 }
 
 export function hrtimeDurationToString(hrtime: [number, number]): string {

packages/next/src/build/templates/app-page.ts

@@ -10,7 +10,7 @@ import { RouteKind } from '../../server/route-kind' with { 'turbopack-transition
 
 import { getRevalidateReason } from '../../server/instrumentation/utils'
 import { getTracer, SpanKind, type Span } from '../../server/lib/trace/tracer'
-import { getRequestMeta } from '../../server/request-meta'
+import { addRequestMeta, getRequestMeta } from '../../server/request-meta'
 import { BaseServerSpan } from '../../server/lib/trace/constants'
 import { interopDefault } from '../../server/app-render/interop-default'
 import { stripFlightHeaders } from '../../server/app-render/strip-flight-headers'
@@ -118,6 +118,9 @@ export async function handler(
     waitUntil: (prom: Promise<void>) => void
   }
 ) {
+  if (routeModule.isDev) {
+    addRequestMeta(req, 'devRequestTimingInternalsEnd', process.hrtime.bigint())
+  }
   let srcPage = 'VAR_DEFINITION_PAGE'
 
   // turbopack doesn't normalize `/index` in the page name

packages/next/src/build/templates/app-route.ts

@@ -6,7 +6,7 @@ import {
 import { RouteKind } from '../../server/route-kind'
 import { patchFetch as _patchFetch } from '../../server/lib/patch-fetch'
 import type { IncomingMessage, ServerResponse } from 'node:http'
-import { getRequestMeta } from '../../server/request-meta'
+import { addRequestMeta, getRequestMeta } from '../../server/request-meta'
 import { getTracer, type Span, SpanKind } from '../../server/lib/trace/tracer'
 import { setReferenceManifestsSingleton } from '../../server/app-render/encryption-utils'
 import { createServerModuleMap } from '../../server/app-render/action-utils'
@@ -85,6 +85,9 @@ export async function handler(
     waitUntil: (prom: Promise<void>) => void
   }
 ) {
+  if (routeModule.isDev) {
+    addRequestMeta(req, 'devRequestTimingInternalsEnd', process.hrtime.bigint())
+  }
   let srcPage = 'VAR_DEFINITION_PAGE'
 
   // turbopack doesn't normalize `/index` in the page name

packages/next/src/server/dev/log-requests.ts

@@ -7,6 +7,7 @@ import {
   red,
   white,
   yellow,
+  dim,
 } from '../../lib/picocolors'
 import { stripNextRscUnionQuery } from '../../lib/url'
 import type { FetchMetric } from '../base-http'
@@ -43,14 +44,18 @@ export function logRequests(
   response: NodeNextResponse,
   loggingConfig: LoggingConfig,
   requestStartTime: bigint,
-  requestEndTime: bigint
+  requestEndTime: bigint,
+  devRequestTimingMiddlewareStart: bigint | undefined,
+  devRequestTimingMiddlewareEnd: bigint | undefined
 ): void {
   if (!ignoreLoggingIncomingRequests(request, loggingConfig)) {
     logIncomingRequests(
       request,
       requestStartTime,
       requestEndTime,
-      response.statusCode
+      response.statusCode,
+      devRequestTimingMiddlewareStart,
+      devRequestTimingMiddlewareEnd
     )
   }
 
@@ -65,9 +70,15 @@ function logIncomingRequests(
   request: NodeNextRequest,
   requestStartTime: bigint,
   requestEndTime: bigint,
-  statusCode: number
+  statusCode: number,
+  devRequestTimingMiddlewareStart: bigint | undefined,
+  devRequestTimingMiddlewareEnd: bigint | undefined
 ): void {
   const isRSC = getRequestMeta(request, 'isRSCRequest')
+  const devRequestTimingInternalsEnd = getRequestMeta(
+    request,
+    'devRequestTimingInternalsEnd'
+  )
   const url = isRSC ? stripNextRscUnionQuery(request.url) : request.url
 
   const statusCodeColor =
@@ -83,8 +94,31 @@ function logIncomingRequests(
 
   const coloredStatus = statusCodeColor(statusCode.toString())
 
+  const totalRequestTime = requestEndTime - requestStartTime
+
+  const times: Array<[label: string, time: bigint]> = []
+
+  let middlewareTime: bigint | undefined
+  if (devRequestTimingMiddlewareStart && devRequestTimingMiddlewareEnd) {
+    middlewareTime =
+      devRequestTimingMiddlewareEnd - devRequestTimingMiddlewareStart
+    times.push(['proxy.ts', middlewareTime])
+  }
+
+  if (devRequestTimingInternalsEnd) {
+    let frameworkTime = devRequestTimingInternalsEnd - requestStartTime
+
+    /* Middleware runs during the internals so we have to subtract it from the framework time */
+    if (middlewareTime) {
+      frameworkTime -= middlewareTime
+    }
+    // Insert as the first item to be rendered in the list
+    times.unshift(['compile', frameworkTime])
+    times.push(['render', requestEndTime - devRequestTimingInternalsEnd])
+  }
+
   return writeLine(
-    `${request.method} ${url} ${coloredStatus} in ${hrtimeBigIntDurationToString(requestEndTime - requestStartTime)}`
+    `${request.method} ${url} ${coloredStatus} in ${hrtimeBigIntDurationToString(totalRequestTime)}${times.length > 0 ? dim(` (${times.map(([label, time]) => `${label}: ${hrtimeBigIntDurationToString(time)}`).join(', ')})`) : ''}`
   )
 }
 

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

@@ -466,8 +466,14 @@ export default class DevServer extends Server {
       const loggingConfig = this.nextConfig.logging
 
       if (loggingConfig !== false) {
-        const requestStart = process.hrtime.bigint()
-        const isMiddlewareRequest = getRequestMeta(req, 'middlewareInvoke')
+        // The closure variable is not used here because the request handler may be invoked twice for one request when middleware is added in the application.
+        // By setting the start time we can ensure that the middleware timing is correctly included.
+        if (!getRequestMeta(req, 'devRequestTimingStart')) {
+          const requestStart = process.hrtime.bigint()
+          addRequestMeta(req, 'devRequestTimingStart', requestStart)
+        }
+        const isMiddlewareRequest =
+          getRequestMeta(req, 'middlewareInvoke') ?? false
 
         if (!isMiddlewareRequest) {
           response.originalResponse.once('close', () => {
@@ -480,13 +486,21 @@ export default class DevServer extends Server {
               return
             }
 
+            // The closure variable is not used here because the request handler may be invoked twice for one request when middleware is added in the application.
+            // By setting the start time we can ensure that the middleware timing is correctly included.
+            const requestStart = getRequestMeta(req, 'devRequestTimingStart')
+            if (!requestStart) {
+              return
+            }
             const requestEnd = process.hrtime.bigint()
             logRequests(
               request,
               response,
               loggingConfig,
               requestStart,
-              requestEnd
+              requestEnd,
+              getRequestMeta(req, 'devRequestTimingMiddlewareStart'),
+              getRequestMeta(req, 'devRequestTimingMiddlewareEnd')
             )
           })
         }

packages/next/src/server/lib/router-utils/resolve-routes.ts

@@ -519,6 +519,13 @@ export function getResolveRoutes(
             addRequestMeta(req, 'invokeOutput', '')
             addRequestMeta(req, 'invokeQuery', {})
             addRequestMeta(req, 'middlewareInvoke', true)
+            if (opts.dev) {
+              addRequestMeta(
+                req,
+                'devRequestTimingMiddlewareStart',
+                process.hrtime.bigint()
+              )
+            }
             debug('invoking middleware', req.url, req.headers)
 
             let middlewareRes: Response | undefined = undefined
@@ -543,6 +550,14 @@ export function getResolveRoutes(
                     },
                   })
                 }
+              } finally {
+                if (opts.dev) {
+                  addRequestMeta(
+                    req,
+                    'devRequestTimingMiddlewareEnd',
+                    process.hrtime.bigint()
+                  )
+                }
               }
             } catch (e) {
               // If the client aborts before we can receive a response object

packages/next/src/server/request-meta.ts

@@ -262,6 +262,14 @@ export interface RequestMeta {
    * DEV only: The fallback params that should be used when validating prerenders during dev
    */
   devValidatingFallbackParams?: OpaqueFallbackRouteParams
+
+  /**
+   * DEV only: Request timings in process.hrtime.bigint()
+   */
+  devRequestTimingStart?: bigint
+  devRequestTimingMiddlewareStart?: bigint
+  devRequestTimingMiddlewareEnd?: bigint
+  devRequestTimingInternalsEnd?: bigint
 }
 
 /**