From 954a91bc8795f0a8be18a6efc53b7f8b72abfb33 Mon Sep 17 00:00:00 2001 From: Sam Clegg Date: Fri, 31 Oct 2025 11:04:20 -0700 Subject: [PATCH] Revive and improve the JS compiler brenchmarker profiler. NFC There is a sample output: ``` $ EMPROFILE=2 ./emcc ~/test/hello.cprofiler:INFO: start block "read_ports" profiler:INFO: block "read_ports" took 0.004 seconds profiler:INFO: start block "main" profiler:INFO: start block "parse_arguments" profiler:INFO: block "parse_arguments" took 0.000 seconds profiler:INFO: start block "check_sanity" profiler:INFO: block "check_sanity" took 0.000 seconds profiler:INFO: start block "setup" profiler:INFO: block "setup" took 0.000 seconds profiler:INFO: start block "compile inputs" profiler:INFO: start block "ensure_sysroot" profiler:INFO: block "ensure_sysroot" took 0.000 seconds profiler:INFO: block "compile inputs" took 0.067 seconds profiler:INFO: start block "linker_setup" profiler:INFO: block "linker_setup" took 0.048 seconds profiler:INFO: start block "calculate linker inputs" profiler:INFO: block "calculate linker inputs" took 0.000 seconds profiler:INFO: start block "calculate system libraries" profiler:INFO: block "calculate system libraries" took 0.001 seconds profiler:INFO: start block "JS symbol generation" profiler:INFO: block "JS symbol generation" took 0.013 seconds profiler:INFO: start block "link" profiler:INFO: block "link" took 0.079 seconds profiler:INFO: start block "post link" profiler:INFO: start block "emscript" profiler:INFO: start block "get_metadata" profiler:INFO: block "get_metadata" took 0.001 seconds profiler:INFO: start block "compile_javascript" [prof] -> overall [prof] -> startup [prof] -> loadSettingsFile [prof] <- loadSettingsFile [1.8 ms] [prof] -> loadSettingsFile [prof] <- loadSettingsFile [1.6 ms] [prof] -> read settings [prof] <- read settings [0.2 ms] [prof] -> dynamic imports [prof] <- dynamic imports [8.1 ms] [prof] <- startup [13.2 ms] [prof] -> runJSify [prof] -> load [prof] -> preprocessFiles [prof] <- preprocessFiles [65.9 ms] [prof] -> executeJS [prof] <- executeJS [31.0 ms] [prof] <- load [97.9 ms] [prof] -> finalCombiner [prof] <- finalCombiner [12.4 ms] [prof] <- runJSify [114.0 ms] [prof] <- overall [135.6 ms] profiler:INFO: block "compile_javascript" took 0.177 seconds profiler:INFO: block "emscript" took 0.188 seconds profiler:INFO: start block "binaryen" profiler:INFO: block "binaryen" took 0.000 seconds profiler:INFO: start block "final emitting" profiler:INFO: block "final emitting" took 0.001 seconds profiler:INFO: block "post link" took 0.189 seconds profiler:INFO: block "main" took 0.403 seconds ``` --- src/jsifier.mjs | 3 +++ src/modules.mjs | 10 +++++++ src/utility.mjs | 65 +++++++++++++++++++++++++++++++--------------- tools/compiler.mjs | 20 ++++++++++---- 4 files changed, 72 insertions(+), 26 deletions(-) diff --git a/src/jsifier.mjs b/src/jsifier.mjs index a3e21ab3f922e..aaec445ca2ad3 100644 --- a/src/jsifier.mjs +++ b/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()) { diff --git a/src/modules.mjs b/src/modules.mjs index a13236f846beb..94371134cafbe 100644 --- a/src/modules.mjs +++ b/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) { diff --git a/src/utility.mjs b/src/utility.mjs index 65459a401dec9..f3ffa770118ba 100644 --- a/src/utility.mjs +++ b/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; } diff --git a/tools/compiler.mjs b/tools/compiler.mjs index 8a0556f24c94c..e155ef20e02c3 100755 --- a/tools/compiler.mjs +++ b/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 [-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.