Improve benchmark, fix bugs, test stack trace correctness

Dockerfile

@@ -0,0 +1,7 @@
+FROM ubuntu
+
+WORKDIR /app
+COPY ./configure-image.sh /app/configure-image.sh
+RUN ./configure-image.sh
+COPY ./ /app
+CMD ["node", "/app/lib-tsc/run-tests.js"]

README.md

@@ -1,18 +1,20 @@
 # Source Map Performance Demo
 
-This project is a simple experiment to get a general sense of the performance penalty
-incurred for enabling source map support in a node runtime using various techniques.
+This project is a simple experiment to get a general sense of the correctness
+and performance penalty incurred for enabling source map support in a node
+runtime using various techniques.
 
 The approach taken is to generate builds of a simple application using 
 both `esbuild` and `tsc`. The application imports a few commonly used libraries
 to intentionally inflate the resulting source maps. We then generate N number of
-source maps, and record the elapsed time. 
+stack traces, and record the elapsed time. 
 
-- `index.ts` - simple test app to generate stacks and record elapsed time
+- `index.ts` - simple test app to generate stacks and test their correctness
 - `run-tests.ts` - run timing tests for combinations of node version, compiler, and sourcemap support options.
 
 Related Discussions:
 - https://github.com/nodejs/node/issues/41541
+- https://github.com/nodejs/node/issues/42417
 - https://github.com/evanw/node-source-map-support/issues/122
 
 ## Usage
@@ -36,29 +38,29 @@ yarn test
 ## Example Output
 
 ### Results for 10000 stack traces.
-| image | compiler | options | elapsed_ms |
-| ----- | -------- | ------- | ---------- |
-| node:14.19-alpine | esbuild | --enable-source-maps | 4754 |
-| node:14.19-alpine | esbuild | -r @cspotcode/source-map-support/register | 119 |
-| node:14.19-alpine | esbuild | -r source-map-support/register | 289 |
-| node:14.19-alpine | esbuild |  | 7 |
-| node:14.19-alpine | tsc | --enable-source-maps | 88 |
-| node:14.19-alpine | tsc | -r @cspotcode/source-map-support/register | 70 |
-| node:14.19-alpine | tsc | -r source-map-support/register | 48 |
-| node:14.19-alpine | tsc |  | 6 |
-| node:16.14-alpine | esbuild | --enable-source-maps | 4260 |
-| node:16.14-alpine | esbuild | -r @cspotcode/source-map-support/register | 115 |
-| node:16.14-alpine | esbuild | -r source-map-support/register | 285 |
-| node:16.14-alpine | esbuild |  | 8 |
-| node:16.14-alpine | tsc | --enable-source-maps | 94 |
-| node:16.14-alpine | tsc | -r @cspotcode/source-map-support/register | 71 |
-| node:16.14-alpine | tsc | -r source-map-support/register | 45 |
-| node:16.14-alpine | tsc |  | 6 |
-| node:17.8-alpine | esbuild | --enable-source-maps | 4298 |
-| node:17.8-alpine | esbuild | -r @cspotcode/source-map-support/register | 112 |
-| node:17.8-alpine | esbuild | -r source-map-support/register | 280 |
-| node:17.8-alpine | esbuild |  | 9 |
-| node:17.8-alpine | tsc | --enable-source-maps | 116 |
-| node:17.8-alpine | tsc | -r @cspotcode/source-map-support/register | 59 |
-| node:17.8-alpine | tsc | -r source-map-support/register | 41 |
-| node:17.8-alpine | tsc |  | 5 |
+| node | compiler | options | stack_traces_correct | elapsed_ms |
+| ---- | -------- | ------- | -------------------- | ---------- |
+| 14.19.1 | esbuild | --enable-source-maps | ❌ | 366404 |
+| 14.19.1 | esbuild | -r @cspotcode/source-map-support/register | ✅ | 652 |
+| 14.19.1 | esbuild | -r source-map-support/register | ❌ | 807 |
+| 14.19.1 | esbuild |  |  | 230 |
+| 14.19.1 | tsc | --enable-source-maps | ❌ | 1916 |
+| 14.19.1 | tsc | -r @cspotcode/source-map-support/register | ✅ | 673 |
+| 14.19.1 | tsc | -r source-map-support/register | ❌ | 642 |
+| 14.19.1 | tsc |  |  | 268 |
+| 16.14.2 | esbuild | --enable-source-maps | ❌ | 358514 |
+| 16.14.2 | esbuild | -r @cspotcode/source-map-support/register | ✅ | 542 |
+| 16.14.2 | esbuild | -r source-map-support/register | ❌ | 748 |
+| 16.14.2 | esbuild |  |  | 222 |
+| 16.14.2 | tsc | --enable-source-maps | ❌ | 1870 |
+| 16.14.2 | tsc | -r @cspotcode/source-map-support/register | ✅ | 547 |
+| 16.14.2 | tsc | -r source-map-support/register | ❌ | 576 |
+| 16.14.2 | tsc |  |  | 236 |
+| 17.8.0 | esbuild | --enable-source-maps | ❌ | 367329 |
+| 17.8.0 | esbuild | -r @cspotcode/source-map-support/register | ✅ | 598 |
+| 17.8.0 | esbuild | -r source-map-support/register | ❌ | 737 |
+| 17.8.0 | esbuild |  |  | 202 |
+| 17.8.0 | tsc | --enable-source-maps | ❌ | 1726 |
+| 17.8.0 | tsc | -r @cspotcode/source-map-support/register | ✅ | 539 |
+| 17.8.0 | tsc | -r source-map-support/register | ❌ | 535 |
+| 17.8.0 | tsc |  |  | 244 |

configure-image.sh

@@ -0,0 +1,13 @@
+#!/usr/bin/env bash
+set -euo pipefail
+shopt -s inherit_errexit
+
+apt-get update
+apt-get install -y curl
+
+curl -L https://github.com/sharkdp/hyperfine/releases/download/v1.13.0/hyperfine_1.13.0_amd64.deb -o hyperfine.deb
+dpkg -i ./hyperfine.deb
+
+curl -L https://github.com/raw/tj/n/master/bin/n -o n
+bash n lts
+npm install -g n

index.ts

@@ -25,18 +25,41 @@ const args = process.argv.slice(2);
 const max = args[0]
     ? parseInt(args[0])
     : 10_000;
+const isUsingSourcemaps = args[1] === 'true';
 
-const start = Date.now();
+let stackTracesAreCorrect: boolean | null = null;
 
-for (let i = 0; i < max; i++) {
-    if (i % 100 === 0) {
+async function main() {
+    const start = Date.now();
+
+    await loop();
+
+    const end = Date.now();
+    console.log(JSON.stringify({duration: end - start, stackTracesAreCorrect}));
+}
+
+async function loop() {
+    // Take one lap around the event loop
+    await void 0;
+
+    for (let i = 0; i < max; i++) {
         // console.log(`generating stack trace ${i+1}...`);
         const err = new Error();
         const { stack } = err;
+        if(i === 0) {
+            console.dir(stack);
+            const sourceMapRe = /at loop \(.*\/index\.ts:47:21\)\n    at async main \(.*\/index\.ts:35:5\)/
+            const nonSourceMapRe = /at loop \(.*\.js:.*?\)\n    at async main \(.*\.js:.*?\)/
+            if((isUsingSourcemaps ? sourceMapRe : nonSourceMapRe).test(stack!)) {
+                if(isUsingSourcemaps) stackTracesAreCorrect = true;
+            } else {
+                stackTracesAreCorrect = false;
+                if(!isUsingSourcemaps) throw new Error('invariant violated');
+                // throw new Error(`Stack trace looks wrong.\nStack is:\n${require('util').inspect(stack)}`);
+            }
+        }
         // schema.validate(err);
     }
 }
 
-const end = Date.now();
-console.log(end - start);
-
+main();

package.json

@@ -6,7 +6,8 @@
   "scripts": {
     "build:esbuild": "yarn esbuild --bundle --outfile=lib-esbuild/index.js --platform=node --sourcemap index.ts",
     "build:tsc": "yarn tsc",
-    "build": "yarn build:esbuild && yarn build:tsc",
+    "build:image": "docker build -t source-map-performance-demo .",
+    "build": "yarn build:esbuild && yarn build:tsc && yarn build:image",
     "clean:esbuild": "yarn rimraf lib-esbuild",
     "clean:tsc": "yarn rimraf lib-tsc",
     "clean": "yarn clean:esbuild && yarn clean:tsc",
@@ -18,7 +19,9 @@
     "start:tsc:evanw": "node -r source-map-support/register lib-tsc/index.js",
     "start:tsc:native": "node --enable-source-maps lib-tsc/index.js",
     "start:tsc:none": "node lib-tsc/index.js",
-    "start": "yarn clean && yarn build && yarn start:tsc:none && yarn start:tsc:native && yarn start:tsc:evanw && yarn start:tsc:cspotcode && yarn start:esbuild:none && yarn start:esbuild:native && yarn start:esbuild:evanw && yarn start:esbuild:cspotcode"
+    "run-tests-locally": "yarn start:tsc:none && yarn start:tsc:native && yarn start:tsc:evanw && yarn start:tsc:cspotcode && yarn start:esbuild:none && yarn start:esbuild:native && yarn start:esbuild:evanw && yarn start:esbuild:cspotcode",
+    "test": "docker run --rm source-map-performance-demo",
+    "start": "yarn clean && yarn build && yarn test"
   },
   "author": "",
   "license": "ISC",

run-tests.ts

@@ -0,0 +1,124 @@
+#!/usr/bin/env node
+import process from 'process';
+import { exec } from "child_process"
+import util from 'util';
+import fs from 'fs';
+const execAsync = util.promisify(exec);
+
+const generatedStackCount = 10_000;
+// const generatedStackCount = 1000;
+// const generatedStackCount = 1;
+
+const nodeVersions = [
+    '14.19.1',
+    '16.14.2',
+    '17.8.0'
+]
+
+const compilers = [
+    'esbuild',
+    'tsc',
+];
+
+const optionSets = [
+    '--enable-source-maps',
+    '-r @cspotcode/source-map-support/register',
+    '-r source-map-support/register',
+    '', // no sourcemap support
+];
+
+
+async function main() {
+
+    const args = `${generatedStackCount}`;
+
+    const results = [];
+    for (const nodeVersion of nodeVersions) {
+        for (const compiler of compilers) {
+            for (const options of optionSets) {
+                const {elapsed_ms, stackTracesAreCorrect} = await runTest(nodeVersion, compiler, options, args);
+                results.push({
+                    node: nodeVersion,
+                    compiler,
+                    options,
+                    generated_stack_count: generatedStackCount,
+                    elapsed_ms,
+                    stack_traces_correct: stackTracesAreCorrect
+                });
+            }
+        }
+    }
+
+    console.table(results);
+
+    // generate markdown table
+    const headers: Array<keyof typeof results[0]> = ['node', 'compiler', 'options', 'stack_traces_correct', 'elapsed_ms'];
+    const markdownTable = [
+        '| ' + headers.join(' | ') + ' |',
+        '| ' + headers.map((it) => '-'.repeat(`${it}`.length)).join(' | ') + ' |',
+        ...results.map((result) => '| ' + headers.map((it) => {
+            if(it === 'stack_traces_correct') return result[it] === true ? '✅' : result[it] === false ? '❌' : '';
+            return result[it];
+        }).join(' | ') + ' |')
+    ].join(`\n`)
+
+    console.log(`### Results for ${generatedStackCount} stack traces.`)
+    console.log(markdownTable);
+}
+
+async function runTest(nodeVersion: string, compiler: string, options: string, args: string) {
+
+    const description = `node-${nodeVersion}:${compiler}:${options}`
+    console.info(`running test for ${description}...`);
+
+    // Switch node versions
+    await execAsync(`n install ${nodeVersion}`);
+    const {stdout: nodeVersionCheck} = await execAsync(`node --version`);
+    if(nodeVersionCheck !== `v${nodeVersion}\n`) throw new Error('Failed to switch node versions');
+
+    // Run benchmark with hyperfine
+    const hyperfineExportPath = `${description.replace(/[ :@/]/g, '_')}.hyperfine.json`;
+    let hyperfineOptions = '';
+    if(options === '--enable-source-maps' && compiler.includes('esbuild')) {
+        // node's built-in sourcemap support is *extremely* slow for some reason.  Tell hyperfine to run it only once.
+        hyperfineOptions = '-w 0 -r 1'
+    }
+    // When sourcemaps are not enabled, skip asserting that the stacktrace looks correct
+    const isUsingSourcemaps = options !== '';
+    const cmd = `hyperfine ${hyperfineOptions} --show-output --time-unit millisecond --export-json ${hyperfineExportPath} "node ./lib-${compiler}/index.js ${args} ${isUsingSourcemaps}"`;
+    const { stdout, stderr } = await execAsync(cmd, {
+        env: {
+            ...process.env,
+            NODE_OPTIONS: options
+        }
+    });
+    console.log(stdout);
+    const jsReport = JSON.parse(stdout.match(/\n\{[^\n]+?\}\n/)![0]) as {duration: number, stackTracesAreCorrect: boolean};
+    const {stackTracesAreCorrect} = jsReport;
+
+    // Read benchmark results
+    const hyperfineReport = JSON.parse(fs.readFileSync(hyperfineExportPath, 'utf8')) as HyperfineReport;
+    interface HyperfineReport {
+        results: Array<{
+            command: string;
+            mean: number;
+            stddev: number;
+            median: number;
+            user: number;
+            system: number;
+            min: number;
+            max: number;
+            times: Array<number>;
+        }>;
+    }
+
+    const elapsed_ms = Math.round(hyperfineReport.results[0].mean * 1e3);
+    return {elapsed_ms, stackTracesAreCorrect};
+}
+
+
+
+main().catch((e) => {
+    console.error(e);
+    process.exit(1);
+})