Update dev logs to include request timings (#49191)

This updates our dev logs to include request timings and also includes
fetch timings in app directory to including info on whether the cache
was leveraged or not allowing easier debugging of contributing factors
to render times. In the future we can expand to include middleware
timings separate as well to single that out along with timings for
`getStaticProps` potentially as well.


<details>

<summary>Screenshot</summary>

![CleanShot 2023-05-04 at 00 13
19@2x](https://user-images.githubusercontent.com/22380829/236135624-da1d873b-5abf-42d0-9708-8e20d1c56cef.png)

</details>

<details>

<summary>Screenshot</summary>

![CleanShot 2023-05-04 at 00 13
32@2x](https://user-images.githubusercontent.com/22380829/236135642-bc974b82-13e0-47f0-8be5-581d92077fc1.png)

</details>

<details>

<summary>Screenshot</summary>

![CleanShot 2023-05-04 at 00 13
47@2x](https://user-images.githubusercontent.com/22380829/236135664-5b2975ce-fa78-40d5-b320-d42d35b17541.png)

</details>

x-ref: [slack
thread](https://vercel.slack.com/archives/C042LHPJ1NX/p1681418590738249)

packages/next/src/build/output/log.ts

@@ -1,13 +1,13 @@
 import chalk from '../../lib/chalk'
 
 export const prefixes = {
-  wait: chalk.cyan('wait') + '  -',
-  error: chalk.red('error') + ' -',
-  warn: chalk.yellow('warn') + '  -',
-  ready: chalk.green('ready') + ' -',
-  info: chalk.cyan('info') + '  -',
-  event: chalk.magenta('event') + ' -',
-  trace: chalk.magenta('trace') + ' -',
+  wait: '- ' + chalk.cyan('wait'),
+  error: '- ' + chalk.red('error'),
+  warn: '- ' + chalk.yellow('warn'),
+  ready: '- ' + chalk.green('ready'),
+  info: '- ' + chalk.cyan('info'),
+  event: '- ' + chalk.magenta('event'),
+  trace: '- ' + chalk.magenta('trace'),
 }
 
 export function wait(...message: any[]) {

packages/next/src/client/components/static-generation-async-storage.ts

@@ -31,6 +31,15 @@ export interface StaticGenerationStore {
   pathWasRevalidated?: boolean
 
   tags?: string[]
+  fetchMetrics?: Array<{
+    url: string
+    idx: number
+    end: number
+    start: number
+    method: string
+    status: number
+    cacheStatus: 'hit' | 'miss'
+  }>
 }
 
 export type StaticGenerationAsyncStorage =

packages/next/src/server/app-render/app-render.tsx

@@ -217,6 +217,8 @@ export async function renderToHTMLOrFlight(
         `Invariant: Render expects to have staticGenerationAsyncStorage, none found`
       )
     }
+    staticGenerationStore.fetchMetrics = []
+    ;(renderOpts as any).fetchMetrics = staticGenerationStore.fetchMetrics
 
     // don't modify original query object
     query = { ...query }

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

@@ -1613,6 +1613,10 @@ export default abstract class Server<ServerOptions extends Options = Options> {
           // Handle the match and collect the response if it's a static response.
           const response = await this.handlers.handle(match, req, context)
           if (response) {
+            ;(req as any).fetchMetrics = (
+              context.staticGenerationContext as any
+            ).fetchMetrics
+
             const cacheTags = (context.staticGenerationContext as any).fetchTags
 
             // If the request is for a static response, we can cache it so long
@@ -1753,6 +1757,7 @@ export default abstract class Server<ServerOptions extends Options = Options> {
           'x-next-cache-tags': cacheTags,
         }
       }
+      ;(req as any).fetchMetrics = (renderOpts as any).fetchMetrics
 
       // we don't throw static to dynamic errors in dev as isSSG
       // is a best guess in dev since we don't have the prerender pass

packages/next/src/server/future/route-modules/app-route/module.ts

@@ -345,6 +345,8 @@ export class AppRouteRouteModule extends RouteModule<
                     const res = await handler(wrappedRequest, {
                       params: context.params,
                     })
+                    ;(context.staticGenerationContext as any).fetchMetrics =
+                      staticGenerationStore.fetchMetrics
 
                     await Promise.all(
                       staticGenerationStore.pendingRevalidates || []

packages/next/src/server/lib/patch-fetch.ts

@@ -26,6 +26,43 @@ export function addImplicitTags(
   return newTags
 }
 
+function trackFetchMetric(
+  staticGenerationStore: ReturnType<StaticGenerationAsyncStorage['getStore']>,
+  ctx: {
+    url: string
+    status: number
+    method: string
+    cacheStatus: 'hit' | 'miss'
+    start: number
+  }
+) {
+  if (!staticGenerationStore) return
+  if (!staticGenerationStore.fetchMetrics) {
+    staticGenerationStore.fetchMetrics = []
+  }
+  const dedupeFields = ['url', 'status', 'method']
+
+  // don't add metric if one already exists for the fetch
+  if (
+    staticGenerationStore.fetchMetrics.some((metric) => {
+      return dedupeFields.every(
+        (field) => (metric as any)[field] === (ctx as any)[field]
+      )
+    })
+  ) {
+    return
+  }
+  staticGenerationStore.fetchMetrics.push({
+    url: ctx.url,
+    cacheStatus: ctx.cacheStatus,
+    status: ctx.status,
+    method: ctx.method,
+    start: ctx.start,
+    end: Date.now(),
+    idx: staticGenerationStore.nextFetchId || 0,
+  })
+}
+
 // we patch fetch to collect cache information used for
 // determining if a page is static or not
 export function patchFetch({
@@ -53,7 +90,7 @@ export function patchFetch({
       // Error caused by malformed URL should be handled by native fetch
       url = undefined
     }
-
+    const fetchStart = Date.now()
     const method = init?.method?.toUpperCase() || 'GET'
 
     return await getTracer().trace(
@@ -267,14 +304,23 @@ export function patchFetch({
         const fetchIdx = staticGenerationStore.nextFetchId ?? 1
         staticGenerationStore.nextFetchId = fetchIdx + 1
 
-        const doOriginalFetch = async () => {
+        const doOriginalFetch = async (isStale?: boolean) => {
           // add metadata to init without editing the original
           const clonedInit = {
             ...init,
             next: { ...init?.next, fetchType: 'origin', fetchIdx },
           }
 
           return originFetch(input, clonedInit).then(async (res) => {
+            if (!isStale) {
+              trackFetchMetric(staticGenerationStore, {
+                start: fetchStart,
+                url: fetchUrl,
+                cacheStatus: 'miss',
+                status: res.status,
+                method: clonedInit.method || 'GET',
+              })
+            }
             if (
               res.status === 200 &&
               staticGenerationStore.incrementalCache &&
@@ -336,7 +382,7 @@ export function patchFetch({
                   staticGenerationStore.pendingRevalidates = []
                 }
                 staticGenerationStore.pendingRevalidates.push(
-                  doOriginalFetch().catch(console.error)
+                  doOriginalFetch(true).catch(console.error)
                 )
               } else if (
                 tags &&
@@ -374,6 +420,14 @@ export function patchFetch({
                 decodedBody = Buffer.from(resData.body, 'base64').subarray()
               }
 
+              trackFetchMetric(staticGenerationStore, {
+                start: fetchStart,
+                url: fetchUrl,
+                cacheStatus: 'hit',
+                status: resData.status || 200,
+                method: init?.method || 'GET',
+              })
+
               return new Response(decodedBody, {
                 headers: resData.headers,
                 status: resData.status,

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

@@ -18,7 +18,7 @@ import type RenderResult from './render-result'
 import type { FetchEventResult } from './web/types'
 import type { PrerenderManifest } from '../build'
 import type { CustomRoutes, Rewrite } from '../lib/load-custom-routes'
-import type { BaseNextRequest, BaseNextResponse } from './base-http'
+import { BaseNextRequest, BaseNextResponse } from './base-http'
 import type { PagesManifest } from '../build/webpack/plugins/pages-manifest-plugin'
 import type { PayloadOptions } from './send-payload'
 import type { NextParsedUrlQuery, NextUrlWithParsedQuery } from './request-meta'
@@ -109,6 +109,7 @@ import { pathHasPrefix } from '../shared/lib/router/utils/path-has-prefix'
 import { invokeRequest } from './lib/server-ipc/invoke-request'
 import { filterReqHeaders } from './lib/server-ipc/utils'
 import { createRequestResponseMocks } from './lib/mock-request'
+import chalk from 'next/dist/compiled/chalk'
 
 export * from './base-server'
 
@@ -1461,7 +1462,7 @@ export default class NextNodeServer extends BaseServer {
               'x-invoke-path': invokePathname,
               'x-invoke-query': encodeURIComponent(invokeQuery),
             }
-
+            ;(req as any).didInvokePath = true
             const invokeRes = await invokeRequest(
               renderUrl.toString(),
               {
@@ -1668,7 +1669,138 @@ export default class NextNodeServer extends BaseServer {
     void this.prepare()
     const handler = super.getRequestHandler()
     return async (req, res, parsedUrl) => {
-      return handler(this.normalizeReq(req), this.normalizeRes(res), parsedUrl)
+      const normalizedReq = this.normalizeReq(req)
+      const normalizedRes = this.normalizeRes(res)
+
+      if (this.renderOpts.dev) {
+        const _req = req as NodeNextRequest | IncomingMessage
+        const _res = res as NodeNextResponse | ServerResponse
+        const origReq = 'originalRequest' in _req ? _req.originalRequest : _req
+        const origRes =
+          'originalResponse' in _res ? _res.originalResponse : _res
+
+        const reqStart = Date.now()
+
+        const reqCallback = () => {
+          // if we already logged in a render worker
+          // don't log again in the router worker.
+          // we also don't log for middleware alone
+          if (
+            (normalizedReq as any).didInvokePath ||
+            origReq.headers['x-middleware-invoke']
+          ) {
+            return
+          }
+          const reqEnd = Date.now()
+          const fetchMetrics = (normalizedReq as any).fetchMetrics || []
+          const reqDuration = reqEnd - reqStart
+
+          const getDurationStr = (duration: number) => {
+            let durationStr = duration.toString()
+
+            if (duration < 500) {
+              durationStr = chalk.green(duration + 'ms')
+            } else if (duration < 2000) {
+              durationStr = chalk.yellow(duration + 'ms')
+            } else {
+              durationStr = chalk.red(duration + 'ms')
+            }
+            return durationStr
+          }
+
+          if (Array.isArray(fetchMetrics) && fetchMetrics.length) {
+            process.stdout.write('\n')
+            process.stdout.write(
+              `-  ${chalk.grey('┌')} ${chalk.cyan(req.method || 'GET')} ${
+                req.url
+              } ${res.statusCode} in ${getDurationStr(reqDuration)}\n`
+            )
+
+            const calcNestedLevel = (
+              prevMetrics: any[],
+              start: number
+            ): string => {
+              let nestedLevel = 0
+
+              for (let i = 0; i < prevMetrics.length; i++) {
+                const metric = prevMetrics[i]
+                const prevMetric = prevMetrics[i - 1]
+
+                if (
+                  metric.end <= start &&
+                  !(prevMetric && prevMetric.start < metric.end)
+                ) {
+                  nestedLevel += 1
+                }
+              }
+
+              if (nestedLevel === 0) return ''
+              return ` ${nestedLevel} level${nestedLevel === 1 ? '' : 's'} `
+            }
+
+            for (let i = 0; i < fetchMetrics.length; i++) {
+              const metric = fetchMetrics[i]
+              const lastItem = i === fetchMetrics.length - 1
+              let cacheStatus = metric.cacheStatus
+              const duration = metric.end - metric.start
+
+              if (cacheStatus === 'hit') {
+                cacheStatus = chalk.green('HIT')
+              } else {
+                cacheStatus = chalk.yellow('MISS')
+              }
+              let url = metric.url
+
+              if (url.length > 48) {
+                const parsed = new URL(url)
+                const truncatedHost =
+                  parsed.host.length > 16
+                    ? parsed.host.substring(0, 16) + '..'
+                    : parsed.host
+
+                const truncatedPath =
+                  parsed.pathname.length > 24
+                    ? parsed.pathname.substring(0, 24) + '..'
+                    : parsed.pathname
+
+                const truncatedSearch =
+                  parsed.search.length > 16
+                    ? parsed.search.substring(0, 16) + '..'
+                    : parsed.search
+
+                url =
+                  parsed.protocol +
+                  '//' +
+                  truncatedHost +
+                  truncatedPath +
+                  truncatedSearch
+              }
+
+              process.stdout.write(`   ${chalk.grey('│')}\n`)
+              process.stdout.write(
+                `   ${chalk.grey(
+                  `${lastItem ? '└' : '├'}──${calcNestedLevel(
+                    fetchMetrics.slice(0, i),
+                    metric.start
+                  )}──`
+                )} ${chalk.cyan(metric.method)} ${url} ${
+                  metric.status
+                } in ${getDurationStr(duration)} (cache: ${cacheStatus})\n`
+              )
+            }
+            process.stdout.write('\n')
+          } else {
+            process.stdout.write(
+              `- ${chalk.cyan(req.method || 'GET')} ${req.url} ${
+                res.statusCode
+              } in ${getDurationStr(reqDuration)}\n`
+            )
+          }
+          origRes.off('close', reqCallback)
+        }
+        origRes.on('close', reqCallback)
+      }
+      return handler(normalizedReq, normalizedRes, parsedUrl)
     }
   }
 

packages/next/src/server/web/spec-extension/unstable-cache.ts

@@ -2,6 +2,7 @@ import {
   StaticGenerationAsyncStorage,
   StaticGenerationStore,
 } from '../../../client/components/static-generation-async-storage'
+import { addImplicitTags } from '../../lib/patch-fetch'
 
 type Callback = (...args: any[]) => Promise<any>
 
@@ -54,6 +55,15 @@ export function unstable_cache<T extends Callback>(
             options.revalidate as number
           ))
 
+        const tags = options.tags || []
+        const implicitTags = addImplicitTags(store)
+
+        for (const tag of implicitTags) {
+          if (!tags.includes(tag)) {
+            tags.push(tag)
+          }
+        }
+
         const invokeCallback = async () => {
           const result = await cb(...args)
 
@@ -67,7 +77,7 @@ export function unstable_cache<T extends Callback>(
                   // TODO: handle non-JSON values?
                   body: JSON.stringify(result),
                   status: 200,
-                  tags: options.tags,
+                  tags,
                 },
                 revalidate: options.revalidate as number,
               },
@@ -106,15 +116,12 @@ export function unstable_cache<T extends Callback>(
               console.error(`revalidating cache with key: ${joinedKey}`, err)
             )
           )
-        } else if (
-          options.tags &&
-          !options.tags.every((tag) => currentTags?.includes(tag))
-        ) {
+        } else if (tags && !tags.every((tag) => currentTags?.includes(tag))) {
           if (!cacheEntry.value.data.tags) {
             cacheEntry.value.data.tags = []
           }
 
-          for (const tag of options.tags) {
+          for (const tag of tags) {
             if (!cacheEntry.value.data.tags.includes(tag)) {
               cacheEntry.value.data.tags.push(tag)
             }