Update dev logs to include request timings

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