Revive and improve the JS compiler brenchmarker profiler. NFC

src/jsifier.mjs

@@ -39,6 +39,7 @@ import {
   warnOnce,
   warningOccured,
   localFile,
+  timer,
 } from './utility.mjs';
 import {LibraryManager, librarySymbols, nativeAliases} from './modules.mjs';
 
@@ -918,7 +919,9 @@ var proxiedFunctionTable = [
       }),
     );
   } else {
+    timer.start('finalCombiner')
     finalCombiner();
+    timer.stop('finalCombiner')
   }
 
   if (errorOccured()) {

src/modules.mjs

@@ -22,6 +22,7 @@ import {
   runInMacroContext,
   mergeInto,
   localFile,
+  timer,
 } from './utility.mjs';
 import {preprocess, processMacros} from './parseTools.mjs';
 
@@ -224,6 +225,7 @@ function getTempDir() {
 }
 
 function preprocessFiles(filenames) {
+  timer.start('preprocessFiles')
   const results = {};
   for (const filename of filenames) {
     debugLog(`pre-processing JS library: ${filename}`);
@@ -237,6 +239,7 @@ function preprocessFiles(filenames) {
       popCurrentFile();
     }
   }
+  timer.stop('preprocessFiles')
   return results;
 }
 
@@ -262,15 +265,22 @@ export const LibraryManager = {
   },
 
   load() {
+    timer.start('load')
+
     assert(!this.loaded);
     this.loaded = true;
     // Save the list for has() queries later.
     this.libraries = calculateLibraries();
 
     const preprocessed = preprocessFiles(this.libraries);
+
+    timer.start('executeJS')
     for (const [filename, contents] of Object.entries(preprocessed)) {
       this.executeJSLibraryFile(filename, contents);
     }
+    timer.stop('executeJS')
+
+    timer.stop('load')
   },
 
   executeJSLibraryFile(filename, contents) {

src/utility.mjs

@@ -251,40 +251,61 @@ export function debugLog(...args) {
   if (VERBOSE) printErr(...args);
 }
 
-export class Benchmarker {
-  totals = {};
+class Profiler {
   ids = [];
   lastTime = 0;
 
+  constructor() {
+    this.start('overall')
+    this.startTime = performance.now();
+  }
+
+  log(msg) {
+    const depth = this.ids.length;
+    const indent = ' '.repeat(depth)
+    printErr('[prof] ' + indent + msg);
+  }
+
   start(id) {
-    const now = Date.now();
-    if (this.ids.length > 0) {
-      this.totals[this.ids[this.ids.length - 1]] += now - this.lastTime;
-    }
-    this.lastTime = now;
-    this.ids.push(id);
-    this.totals[id] ||= 0;
+    this.log(`-> ${id}`)
+    const now = performance.now();
+    this.ids.push([id, now]);
   }
 
   stop(id) {
-    const now = Date.now();
-    assert(id === this.ids[this.ids.length - 1]);
-    this.totals[id] += now - this.lastTime;
-    this.lastTime = now;
-    this.ids.pop();
+    const [poppedId, startTime] = this.ids.pop();
+    assert(id === poppedId);
+    const now = performance.now();
+    const duration = now - startTime;
+    this.log(`<- ${id} [${duration.toFixed(1)} ms]`)
   }
 
-  print(text) {
-    const ids = Object.keys(this.totals);
-    if (ids.length > 0) {
-      ids.sort((a, b) => this.totals[b] - this.totals[a]);
-      printErr(
-        text + ' times: \n' + ids.map((id) => id + ' : ' + this.totals[id] + ' ms').join('\n'),
-      );
+  terminate() {
+    while (this.ids.length) {
+      const lastID = this.ids[this.ids.length - 1][0];
+      this.stop(lastID);
     }
+    // const overall = performance.now() - this.startTime
+    // printErr(`overall total: ${overall.toFixed(1)} ms`);
   }
 }
 
+class NullProfiler {
+  start(_id) {}
+  stop(_id) {}
+  terminate() {}
+}
+
+// Enable JS compiler profiling if EMPROFILE is "2".  This mode reports profile
+// data to stderr.
+const EMPROFILE = process.env.EMPROFILE == '2';
+
+export const timer = EMPROFILE ? new Profiler() : new NullProfiler();
+
+if (EMPROFILE) {
+  process.on('exit', () => timer.terminate());
+}
+
 /**
  * Context in which JS library code is evaluated.  This is distinct from the
  * global scope of the compiler itself which avoids exposing all of the compiler
@@ -311,9 +332,11 @@ export function applySettings(obj) {
 }
 
 export function loadSettingsFile(f) {
+  timer.start('loadSettingsFile')
   const settings = {};
   vm.runInNewContext(readFile(f), settings, {filename: f});
   applySettings(settings);
+  timer.stop('loadSettingsFile')
   return settings;
 }
 

tools/compiler.mjs

@@ -10,13 +10,15 @@
 import assert from 'node:assert';
 import {parseArgs} from 'node:util';
 import {
-  Benchmarker,
   applySettings,
   loadDefaultSettings,
   printErr,
   readFile,
+  timer,
 } from '../src/utility.mjs';
 
+timer.start('startup')
+
 loadDefaultSettings();
 
 const options = {
@@ -36,6 +38,8 @@ Usage: compiler.mjs <settings.json> [-o out.js] [--symbols-only]`);
   process.exit(0);
 }
 
+timer.start('read settings')
+
 // Load settings from JSON passed on the command line
 let settingsFile = positionals[0];
 assert(settingsFile, 'settings file not specified');
@@ -46,6 +50,8 @@ if (settingsFile == '-') {
 const userSettings = JSON.parse(readFile(settingsFile));
 applySettings(userSettings);
 
+timer.stop('read settings')
+
 export const symbolsOnly = values['symbols-only'];
 
 // TODO(sbc): Remove EMCC_BUILD_DIR at some point.  It used to be required
@@ -77,6 +83,8 @@ assert(
 
 // Load compiler code
 
+timer.start('dynamic imports')
+
 // We can't use static import statements here because several of these
 // file depend on having the settings defined in the global scope (which
 // we do dynamically above.
@@ -87,16 +95,18 @@ if (!STRICT) {
 }
 const jsifier = await import('../src/jsifier.mjs');
 
+timer.stop('dynamic imports')
+
+timer.stop('startup')
+
 // ===============================
 // Main
 // ===============================
 
-const B = new Benchmarker();
-
 try {
+  timer.start('runJSify')
   await jsifier.runJSify(values.output, symbolsOnly);
-
-  B.print('glue');
+  timer.stop('runJSify')
 } catch (err) {
   if (err.toString().includes('Aborting compilation due to previous errors')) {
     // Compiler failed on user error, don't print the stacktrace in this case.