misc: improve profiling script (#55732)

This PR improves the minimal server script by adding a slightly better look require profiler + some misc utility changes. This is eventually gonna be the basis for a `next profile` command. This is what the output look like + its usage. https://app.warp.dev/block/4AtutJ2PpVcM5BFDqlk7zk ``` next-cold-start: 56.024ms next-request: 58.462ms next-wall-time: 128.757ms └─ ../../../packages/next/dist/compiled/next-server/server.runtime.prod.js 39.31ms / 49.27ms ├─ ../../../server/lib/trace/tracer.js 9.92ms / 20.97ms │ ├─ ../constants.js 0.19ms / 0.19ms │ └─ ../../../../../../../node_modules/.pnpm/@opentelemetry+api@1.4.1/node_modules/@opentelemetry/api/build/src/index.js 10.86ms / 18.94ms │ ├─ ../baggage/utils.js 4.35ms / 7.41ms │ │ ├─ ../../api/diag.js 2.98ms / 5.70ms │ │ │ ├─ ../../diag/ComponentLogger.js 2.02ms / 3.66ms │ │ │ │ └─ ../../internal/global-utils.js 1.65ms / 2.71ms │ │ │ │ ├─ ../../platform/index.js 0.90ms / 1.22ms │ │ │ │ │ └─ ../node/index.js 0.32ms / 0.35ms │ │ │ │ │ └─ ../globalThis.js 0.03ms / 0.03ms │ │ │ │ ├─ ../../version.js 0.02ms / 0.02ms │ │ │ │ └─ ../semver.js 0.14ms / 0.14ms │ │ │ └─ ../../diag/internal/logLevelLogger.js 0.70ms / 0.76ms │ │ │ └─ ../../types.js 0.06ms / 0.06ms │ │ ├─ ../internal/baggage-impl.js 0.06ms / 0.06ms │ │ └─ ../internal/symbol.js 0.03ms / 0.03ms │ ├─ ../context/context.js 0.06ms / 0.06ms │ ├─ ../diag/consoleLogger.js 0.04ms / 0.04ms │ ├─ ../metrics/NoopMeter.js 0.12ms / 0.12ms │ ├─ ../metrics/Metric.js 0.03ms / 0.03ms │ ├─ ../propagation/TextMapPropagator.js 0.03ms / 0.03ms │ ├─ ../trace/ProxyTracer.js 1.69ms / 3.11ms │ │ └─ ../NoopTracer.js 1.42ms / 2.82ms │ │ ├─ ../../api/context.js 0.66ms / 0.73ms │ │ │ └─ ../../context/NoopContextManager.js 0.07ms / 0.07ms │ │ ├─ ../context-utils.js 0.70ms / 0.90ms │ │ │ └─ ../NonRecordingSpan.js 0.21ms / 0.55ms │ │ │ └─ ../invalid-span-constants.js 0.34ms / 0.37ms │ │ │ └─ ../trace_flags.js 0.03ms / 0.03ms │ │ └─ ../spancontext-utils.js 0.04ms / 0.04ms │ ├─ ../trace/ProxyTracerProvider.js 0.30ms / 0.33ms │ │ └─ ../NoopTracerProvider.js 0.03ms / 0.03ms │ ├─ ../trace/SamplingResult.js 0.03ms / 0.03ms │ ├─ ../trace/span_kind.js 0.03ms / 0.03ms │ ├─ ../trace/status.js 0.03ms / 0.03ms │ ├─ ../trace/internal/utils.js 0.44ms / 0.64ms │ │ └─ ../tracestate-impl.js 0.20ms / 0.25ms │ │ └─ ../tracestate-validators.js 0.04ms / 0.04ms │ ├─ ../context-api.js 0.06ms / 0.06ms │ ├─ ../diag-api.js 0.04ms / 0.04ms │ ├─ ../metrics-api.js 0.22ms / 0.48ms │ │ └─ ../api/metrics.js 0.26ms / 0.32ms │ │ └─ ../../metrics/NoopMeterProvider.js 0.06ms / 0.06ms │ ├─ ../propagation-api.js 0.30ms / 0.92ms │ │ └─ ../api/propagation.js 0.62ms / 0.74ms │ │ ├─ ../../propagation/NoopTextMapPropagator.js 0.03ms / 0.03ms │ │ └─ ../../baggage/context-helpers.js 0.09ms / 0.09ms │ └─ ../trace-api.js 0.31ms / 0.45ms │ └─ ../api/trace.js 0.15ms / 0.15ms ├─ ../../../shared/lib/runtime-config.external.js 0.05ms / 0.05ms ├─ ../../../../../../bench/basic-app/.next/server/app/page.js 4.07ms / 18.76ms │ ├─ ../../webpack-runtime.js 0.10ms / 0.10ms │ ├─ ../../chunks/388.js 0.06ms / 0.06ms │ ├─ ../../chunks/269.js 1.10ms / 1.10ms │ ├─ ../../../../../../packages/next/dist/compiled/next-server/app-page.runtime.prod.js 13.22ms / 13.63ms │ │ └─ ../../../client/components/request-async-storage.external.js 0.41ms / 0.47ms │ │ └─ ../async-local-storage.js 0.06ms / 0.06ms │ ├─ ../../../../../../packages/next/dist/client/components/static-generation-async-storage.external.js 0.16ms / 0.16ms │ └─ ../../../../../../packages/next/dist/client/components/action-async-storage.external.js 0.05ms / 0.05ms └─ ../../../../../../bench/basic-app/.next/server/app/page_client-reference-manifest.js 0.11ms / 0.11ms ```
2023-09-21 18:13:03 +02:00 · 2023-09-21 18:13:03 +02:00 · 76c9b2c469
commit 76c9b2c469
parent 9d089e3a0c
1 changed files with 88 additions and 11 deletions
--- a/scripts/minimal-server.js
+++ b/scripts/minimal-server.js
@ -1,5 +1,5 @@
 console.time('next-wall-time')
-// Usage: node scripts/minimal-server.js <path-to-app-dir>
+// Usage: node scripts/minimal-server.js <path-to-app-dir-build> <path-to-page>
 // This script is used to run a minimal Next.js server in production mode.

 process.env.NODE_ENV = 'production'
@ -7,19 +7,79 @@ process.env.NODE_ENV = 'production'
 // Change this to 'experimental' to opt into the React experimental channel (needed for server actions, ppr)
 process.env.__NEXT_PRIVATE_PREBUNDLED_REACT = 'next'

+let currentNode = null
+
+let outliers = []
+
+const chalk = {
+  yellow: (str) => `\x1b[33m${str}\x1b[0m`,
+  green: (str) => `\x1b[32m${str}\x1b[0m`,
+}
+
 if (process.env.LOG_REQUIRE) {
-  const originalRequire = require('module').prototype.require
+  const originalCompile = require('module').prototype._compile
+
+  require('module').prototype._compile = function (_content, filename) {
+    let parent = currentNode
+
+    currentNode = {
+      id: filename,
+      selfDuration: 0,
+      totalDuration: 0,
+      children: [],
+    }

-  require('module').prototype.require = function (path) {
    const start = performance.now()
-    const result = originalRequire.apply(this, arguments)
+    const result = originalCompile.apply(this, arguments)
    const end = performance.now()
-    console.log(`${path}, ${end - start}`)

+    currentNode.totalDuration = end - start
+    currentNode.selfDuration = currentNode.children.reduce(
+      (acc, child) => acc - child.selfDuration,
+      currentNode.totalDuration
+    )
+
+    parent?.children.push(currentNode)
+    currentNode = parent || currentNode
    return result
  }
 }

+function prettyPrint(
+  node,
+  distDir,
+  prefix = '',
+  isLast = false,
+  isRoot = true
+) {
+  let duration = `${node.selfDuration.toFixed(
+    2
+  )}ms / ${node.totalDuration.toFixed(2)}ms`
+
+  if (node.selfDuration > 70) {
+    duration = chalk.yellow(duration)
+    outliers.push(node)
+  }
+
+  let output = `${prefix}${isLast || isRoot ? '└─ ' : '├─ '}${chalk.green(
+    path.relative(distDir, node.id)
+  )} ${chalk.yellow(duration)}\n`
+
+  const childPrefix = `${prefix}${isRoot ? '  ' : isLast ? '   ' : '│  '}`
+
+  node.children.forEach((child, i) => {
+    output += prettyPrint(
+      child,
+      node.id,
+      childPrefix,
+      i === node.children.length - 1,
+      false
+    )
+  })
+
+  return output
+}
+
 if (process.env.LOG_COMPILE) {
  const originalCompile = require('module').prototype._compile
  const currentDir = process.cwd()
@ -45,13 +105,15 @@ if (process.env.LOG_READFILE) {

  require('fs').readFile = function (path, options, callback) {
    readFileCount++
-    console.log(`readFile: ${path}`)
+    console.log(`readFile: ${require('path').relative(absoluteAppDir, path)}`)
    return originalReadFile.apply(this, arguments)
  }

  require('fs').readFileSync = function (path, options) {
    readFileSyncCount++
-    console.log(`readFileSync: ${path}`)
+    console.log(
+      `readFileSync: ${require('path').relative(absoluteAppDir, path)}`
+    )
    return originalReadFileSync.apply(this, arguments)
  }
 }
@ -107,16 +169,31 @@ require('http')
  })
  .listen(3000, () => {
    console.timeEnd('next-cold-start')
-    fetch('http://localhost:3000/')
+    fetch('http://localhost:3000/' + (process.argv[3] || ''))
      .then((res) => res.text())
-      .then((text) => {
-        console.log(text)
-      })
      .catch((err) => {
        console.error(err)
      })
      .finally(() => {
        console.timeEnd('next-wall-time')
+        if (process.env.LOG_REQUIRE) {
+          console.log(
+            prettyPrint(currentNode, path.join(absoluteAppDir, distDir))
+          )
+          if (outliers.length > 0) {
+            console.log('Outliers:')
+            outliers.forEach((node) => {
+              console.log(
+                `  ${path.relative(
+                  path.join(absoluteAppDir, distDir),
+                  node.id
+                )} ${node.selfDuration.toFixed(
+                  2
+                )}ms / ${node.totalDuration.toFixed(2)}ms`
+              )
+            })
+          }
+        }
        require('process').exit(0)
      })
  })