From 49e33fb6e794eb440b7d5b46874ba58f26570047 Mon Sep 17 00:00:00 2001 From: Misha Nasledov Date: Tue, 6 Oct 2026 16:31:44 -0700 Subject: [PATCH] bench: engine load tools, a worklet over-budget counter, and an instruction gate The worklet times every process() call against the quantum it rendered (Date.now, the only clock in its scope: 1 ms steps, so `over budget' is a reading of 3 ms or more at 48 kHz) and posts the count over budget, the slowest call and a histogram by whole milliseconds with each tape, plus whether the clock is too coarse to trust. host.js's synth.quanta() keeps the totals and the last ~2.7 s apart; the jam numbers panel shows both. A tape from an older worklet without the fields is delivered uncounted. bench.mjs plays each piece the way the page does -- samples, default patches for empty channels, seed 1 for pieces with none -- so every shipped piece is timed, and says which channels were timed as silence. --json writes one document: per piece and chord p50/p99/p99.9/max per quantum against the budget, failures as entries, and the build timed (its path and wasm hash) beside the script's commit. --only and --seconds are checked; a run that times nothing fails. dspbench gains -j (JSON), -l and -r (window length and rate), the chord's every window timed (nearest-rank p99 over how many windows), and -s/-h in milliseconds, so play loads compare across window lengths. worklettime.mjs plays pieces on the solo page in a real AudioContext and reports over-budget calls per minute, the slowest call, p99 and the audio clock against the wall clock; a page error fails the piece. instrcount: dspbench on four instruments under cachegrind, against a baseline keyed by compiler, flags, LTO, glibc and Valgrind, failing over x1.10 or under x0.98 so a speedup is recorded with --update in the commit that made it. CI's toolchain is committed; a desktop's counts live in its build. CI pins the linux job to ubuntu-24.04 so an image change is a commit that records new counts, and prints the margin. --- .github/workflows/ci.yml | 24 +++- docs/JAM.md | 20 +++ scripts/CMakeLists.txt | 45 +++++++ scripts/dspbench.cpp | 151 ++++++++++++++++++----- scripts/instrcount.json | 8 ++ scripts/instrcount.py | 214 ++++++++++++++++++++++++++++++++ wasm/web/bench.mjs | 159 +++++++++++++++++++++--- wasm/web/browsertest.mjs | 19 ++- wasm/web/host.js | 64 ++++++++++ wasm/web/jam.js | 7 ++ wasm/web/main.js | 6 + wasm/web/render.mjs | 86 +++++++------ wasm/web/worklet.js | 72 +++++++++++ wasm/web/worklettime.mjs | 258 +++++++++++++++++++++++++++++++++++++++ 14 files changed, 1037 insertions(+), 96 deletions(-) create mode 100644 scripts/instrcount.json create mode 100755 scripts/instrcount.py create mode 100644 wasm/web/worklettime.mjs diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index be099ac8..a90e43fa 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -56,7 +56,10 @@ concurrency: jobs: linux: name: linux (gcc) - runs-on: ubuntu-latest + # Pinned, not ubuntu-latest: instrcount's baseline is this image's + # compiler and glibc, so a move to a new Ubuntu is a commit that records + # the new image's counts rather than a gate that fails every PR. + runs-on: ubuntu-24.04 env: CMAKE_C_COMPILER_LAUNCHER: ccache @@ -83,7 +86,7 @@ jobs: adwaita-icon-theme librsvg2-common \ libx11-dev libxcursor-dev libxext-dev libxrandr-dev \ libxtst-dev libdbus-1-dev \ - xvfb + valgrind xvfb # localecheck wants a locale whose decimal separator is a comma, and # the runner image has none; without one it skips. Checked here, so a @@ -126,9 +129,26 @@ jobs: # cores. The two that build widgets are RUN_SERIAL in # scripts/CMakeLists.txt, so they still run with the machine to # themselves. + # + # instrcount holds a few instruments' instruction counts to + # scripts/instrcount.json. Counted under Valgrind rather than timed, + # because a runner's times move by several percent between runs and a + # count does not move at all, and rather than with perf, because these + # runners expose no hardware counters. Strict here: a toolchain the + # file has no counts for is a failure rather than the skip it is on a + # desktop, so a new compiler on the image cannot turn the gate off + # without anybody noticing. About ten seconds, beside the others. - name: Test + env: + THINK_INSTRCOUNT_STRICT: 1 run: xvfb-run -a ctest --test-dir build --output-on-failure -j "$(nproc)" + # ctest shows a passing test's output to nobody, and the margin under + # instrcount's limits is the number worth seeing on every run. + - name: Instruction counts + if: ${{ !cancelled() }} + run: '[ ! -f build/instrcount.txt ] || cat build/instrcount.txt' + - name: Package run: cpack --config build/CPackConfig.cmake -B build/package diff --git a/docs/JAM.md b/docs/JAM.md index 661d61a5..b7fcd074 100644 --- a/docs/JAM.md +++ b/docs/JAM.md @@ -172,6 +172,26 @@ starts where that ends: is moving the worst of all of them is about 0.6 ms, a fifth of the quantum, and p99 stays under 0.4 ms. That is the measurement that could have sent the scheduler back out of the worklet, and it did not. + `--json FILE` writes the same runs, with the node version, CPU model, + the script's commit and the build's path and module hash, as one + document for comparing machines. It plays every piece the way the page + does -- the kit's samples loaded, the channels a piece leaves to the + page given their default patches, an unseeded piece a fixed seed -- + and `--only a.gen,b.gen` and `--seconds N` cut a run down. +- `wasm/web/worklettime.mjs` is the same question asked of a browser: the + solo page plays each piece in a real-time AudioContext, under + `scripts/headless.sh`, and the worklet's own counts of its `process()` + calls are read back through `window.solo.quanta`. It prints the calls + over the quantum's budget per minute, the slowest call and the p99, and + the audio clock against the wall clock, and `--json FILE` writes them: + + ``` + node wasm/web/worklettime.mjs --browser firefox --seconds 30 \ + --json ff.json build-web airports.gen fern.gen + ``` + + Not a gate: the counts belong to the machine and the browser, and the + worklet's clock is a whole millisecond. - What is left for done: the same bench and the same pieces on a slow machine and on real hardware, in Chrome and Firefox. A fast desktop and a headless browser are not the case that decides it. diff --git a/scripts/CMakeLists.txt b/scripts/CMakeLists.txt index 20dbc9a7..61c02c99 100644 --- a/scripts/CMakeLists.txt +++ b/scripts/CMakeLists.txt @@ -1005,6 +1005,51 @@ set_tests_properties(editorcheck PROPERTIES set_tests_properties(composercheck editorcheck windowcheck PROPERTIES RUN_SERIAL TRUE) +# What a few instruments cost, in instructions under Valgrind, against +# instrcount.json. The counts belong to the compiler as much as to the code, +# so the toolchain names the set it is held to; one with no counts skips, +# except in CI (instrcount.py says why). Not under a sanitizer, +# whose binaries Valgrind cannot run and whose counts would say nothing about +# a release build anyway. +find_package(Python3 COMPONENTS Interpreter) + +if(Python3_Interpreter_FOUND AND NOT THINK_SANITIZE) + # The flags and LTO too: an -O3 -march=native build is another toolchain, + # and compared with CI's counts it would pass or fail for nothing. + string(TOUPPER "${CMAKE_BUILD_TYPE}" _config) + separate_arguments(_flags UNIX_COMMAND + "${CMAKE_CXX_FLAGS} ${CMAKE_CXX_FLAGS_${_config}}") + list(JOIN _flags " " _flags) + string(CONCAT _toolchain + "${CMAKE_CXX_COMPILER_ID} ${CMAKE_CXX_COMPILER_VERSION} " + "${CMAKE_BUILD_TYPE} [${_flags}]") + + if(THINK_FAST_MATH) + string(APPEND _toolchain " fast-math") + endif() + + if(CMAKE_INTERPROCEDURAL_OPTIMIZATION OR + CMAKE_INTERPROCEDURAL_OPTIMIZATION_${_config}) + string(APPEND _toolchain " lto") + endif() + + set(_instrcount Python3::Interpreter + "${PROJECT_SOURCE_DIR}/scripts/instrcount.py" + --toolchain "${_toolchain}") + add_test(NAME instrcount COMMAND ${_instrcount} "${PROJECT_BINARY_DIR}") + + # Four Valgrinds at once, one a workload. + set_tests_properties(instrcount PROPERTIES SKIP_RETURN_CODE 77 + PROCESSORS 4) + + # A target and not a test, because it writes a baseline; this build's + # key is the one thing it needs and nobody should have to type. + add_custom_target(instrcount-update + COMMAND ${_instrcount} --update "${PROJECT_BINARY_DIR}" + USES_TERMINAL) + add_dependencies(instrcount-update dspbench plugins) +endif() + set_tests_properties(dspcheck.dsp dspcheck.guard dspcheck.patch dsplevel dspblock dspmidi ringcheck visualcheck dspprobe editorcheck argtype exprcheck statecheck voicecheck poolcheck fxcheck gencheck diff --git a/scripts/dspbench.cpp b/scripts/dspbench.cpp index 33b50e1d..f7ab3d04 100644 --- a/scripts/dspbench.cpp +++ b/scripts/dspbench.cpp @@ -26,26 +26,35 @@ * - chord: -n notes struck at once and held for -w windows. Prints * addNote's time per note, the first window's time -- every voice's * first window at once, which is where a note-on's cost lands on the - * audio thread -- and the mean over the rest. + * audio thread -- and the mean, p99 and worst over the rest. * - * - play: a note every -s windows up a scale across five octaves, each - * released -h windows later, so voices pile up in release the way a - * player's do. Prints the mean and worst window. -o writes its output, + * - play: a note every -s ms up a scale across five octaves, each + * released -h ms later, so voices pile up in release the way a player's + * do. In milliseconds, rounded to whole windows, so that the notes are the + * same at any -l; -w is in windows, so scale it with -l for the same + * length of play. Prints the mean and worst window. -o writes its output, * raw interleaved floats, for comparing two plugin sets sample by sample. * + * -l and -r set the window length and the sample rate, the default + * engine's otherwise; a browser runs 128 or 256 frames at 44.1 or 48 kHz. * Times are wall clock on the calling thread, against the window's own - * length at the default rate; on a loaded machine take the best of a few + * length at that rate; on a loaded machine take the best of a few * runs. -v prints the chord's mean every two seconds, for a graph whose - * cost changes as its voices decay. + * cost changes as its voices decay. -j writes the inputs and both loads' + * numbers to a file as one JSON object, for a script to compare runs. */ #include "config.h" +#include #include #include #include #include +#include +#include + #include "think.h" using namespace std; @@ -67,11 +76,30 @@ static int playNote (int k) return 33 + 12 * ((k / 7) % 5) + scale[k % 7]; } +static void jsonString (FILE *f, const char *s) +{ + fputc('"', f); + + for (; *s; s++) + { + if (*s == '"' || *s == '\\') + fprintf(f, "\\%c", *s); + else if ((unsigned char)*s < 0x20) + fprintf(f, "\\u%04x", *s); + else + fputc(*s, f); + } + + fputc('"', f); +} + int main (int argc, char **argv) { string plugins = "plugins/"; - const char *file = NULL, *dump = NULL; - int voices = 16, windows = 400, step = 4, hold = 20; + const char *file = NULL, *dump = NULL, *json = NULL; + int voices = 16, windows = 400; + double stepMs = 100, holdMs = 500; + int windowlen = TH_DEFAULT_WINDOW_LENGTH, rate = TH_DEFAULT_SAMPLES; bool verbose = false; for (int i = 1; i < argc; i++) @@ -83,11 +111,17 @@ int main (int argc, char **argv) else if (!strcmp(argv[i], "-w") && i + 1 < argc) windows = atoi(argv[++i]); else if (!strcmp(argv[i], "-s") && i + 1 < argc) - step = atoi(argv[++i]); + stepMs = atof(argv[++i]); else if (!strcmp(argv[i], "-h") && i + 1 < argc) - hold = atoi(argv[++i]); + holdMs = atof(argv[++i]); + else if (!strcmp(argv[i], "-l") && i + 1 < argc) + windowlen = atoi(argv[++i]); + else if (!strcmp(argv[i], "-r") && i + 1 < argc) + rate = atoi(argv[++i]); else if (!strcmp(argv[i], "-o") && i + 1 < argc) dump = argv[++i]; + else if (!strcmp(argv[i], "-j") && i + 1 < argc) + json = argv[++i]; else if (!strcmp(argv[i], "-v")) verbose = true; else if (argv[i][0] != '-' && file == NULL) @@ -96,21 +130,39 @@ int main (int argc, char **argv) file = NULL, i = argc; } - if (file == NULL || voices < 1 || windows < 1 || step < 1 || hold < 0) + if (file == NULL || voices < 1 || windows < 1 || !(stepMs > 0) || + !(holdMs >= 0) || + windowlen < 1 || rate < 1) { fprintf(stderr, "usage: dspbench [-p plugins/] [-n voices] [-w windows] " - "[-s step] [-h hold] [-o play.f32] [-v] file.dsp\n"); + "[-s step_ms] [-h hold_ms] [-l windowlen] [-r rate] [-o play.f32] " + "[-j out.json] [-v] file.dsp\n"); return 2; } - const double windowSec = - (double)TH_DEFAULT_WINDOW_LENGTH / TH_DEFAULT_SAMPLES; - const int block = (int)(2.0 / windowSec + 0.5); + /* Opened before the timing, so a path that cannot be written is + known before a run's worth of waiting rather than after. */ + FILE *jsonOut = NULL; + + if (json != NULL && (jsonOut = fopen(json, "w")) == NULL) + { + perror(json); + return 1; + } + + const double windowSec = (double)windowlen / rate; + const int block = max(1, (int)(2.0 / windowSec + 0.5)); + const int step = max(1, (int)(stepMs / 1e3 / windowSec + 0.5)); + const int hold = (int)(holdMs / 1e3 / windowSec + 0.5); + + /* Each load's numbers, in ms, for -j. */ + double chordAdd, chordFirst, chordMean, chordP99, chordWorst; + double playAdd, playMean, playWorst; /* chord */ { - thSynth synth(plugins, TH_DEFAULT_WINDOW_LENGTH, TH_DEFAULT_SAMPLES); + thSynth synth(plugins, windowlen, rate); if (synth.loadTree(file, 0, 100) == NULL) { @@ -118,14 +170,15 @@ int main (int argc, char **argv) return 1; } - double add = 0, t, first, since; + double add = 0, t, first, busy = 0, since = 0; + vector took(windows); - /* Fifths up from C2, so no two voices share a pitch, at three - velocities. */ + /* Fifths up from C1, wrapping round 73 semitones, so no two of up + to 73 voices share a pitch, at three velocities. */ for (int i = 0; i < voices; i++) { t = now(); - synth.addNote(0, 36 + (i * 7) % 60, 40 + 40 * (i % 3)); + synth.addNote(0, 24 + (i * 7) % 73, 40 + 40 * (i % 3)); add += now() - t; } @@ -133,30 +186,40 @@ int main (int argc, char **argv) synth.process(); first = now() - t; - t = since = now(); - for (int w = 0; w < windows; w++) { + t = now(); synth.process(); + took[w] = now() - t; + busy += took[w]; + since += took[w]; if (verbose && (w + 1) % block == 0) { printf(" %4.0f s: %.3f ms/window\n", (w + 1) * windowSec, - 1e3 * (now() - since) / block); - since = now(); + 1e3 * since / block); + since = 0; } } - t = now() - t; - printf("chord %d: %.3f ms/window, %.1f%% of real time; " - "addNote %.3f ms; first window %.3f ms\n", - voices, 1e3 * t / windows, 100 * t / windows / windowSec, - 1e3 * add / voices, 1e3 * first); + sort(took.begin(), took.end()); + chordAdd = 1e3 * add / voices; + chordFirst = 1e3 * first; + chordMean = 1e3 * busy / windows; + /* Nearest rank: below a hundred windows this is the worst + one, which is why the count is printed beside it. */ + chordP99 = 1e3 * took[(size_t)ceil(0.99 * windows) - 1]; + chordWorst = 1e3 * took.back(); + printf("chord %d: %.3f ms/window, %.1f%% of real time, p99 %.3f ms " + "of %d windows, worst %.3f ms; addNote %.3f ms; " + "first window %.3f ms\n", + voices, chordMean, 100 * busy / windows / windowSec, + chordP99, windows, chordWorst, chordAdd, chordFirst); } /* play */ { - thSynth synth(plugins, TH_DEFAULT_WINDOW_LENGTH, TH_DEFAULT_SAMPLES); + thSynth synth(plugins, windowlen, rate); synth.loadTree(file, 0, 100); @@ -202,10 +265,34 @@ int main (int argc, char **argv) if (out) fclose(out); + playAdd = 1e3 * add / notes; + playMean = 1e3 * busy / windows; + playWorst = 1e3 * worst; printf("play: %.3f ms/window, %.1f%% of real time, worst %.3f ms; " "addNote %.3f ms\n", - 1e3 * busy / windows, 100 * busy / windows / windowSec, - 1e3 * worst, 1e3 * add / notes); + playMean, 100 * busy / windows / windowSec, playWorst, + playAdd); + } + + if (jsonOut != NULL) + { + FILE *f = jsonOut; + const double windowMs = 1e3 * windowSec; + + fputs("{\"dsp\": ", f); + jsonString(f, file); + fprintf(f, ", \"voices\": %d, \"windows\": %d, \"stepMs\": %g, " + "\"holdMs\": %g, \"windowlen\": %d, \"rate\": %d,\n" + " \"chord\": {\"addNoteMs\": %.4f, \"firstWindowMs\": %.4f, " + "\"meanMs\": %.4f, \"p99Ms\": %.4f, \"worstMs\": %.4f, " + "\"realTimePct\": %.2f},\n" + " \"play\": {\"addNoteMs\": %.4f, \"meanMs\": %.4f, " + "\"worstMs\": %.4f, \"realTimePct\": %.2f}}\n", + voices, windows, stepMs, holdMs, windowlen, rate, chordAdd, + chordFirst, chordMean, chordP99, chordWorst, + 100 * chordMean / windowMs, playAdd, playMean, playWorst, + 100 * playMean / windowMs); + fclose(f); } return 0; diff --git a/scripts/instrcount.json b/scripts/instrcount.json new file mode 100644 index 00000000..0d49f384 --- /dev/null +++ b/scripts/instrcount.json @@ -0,0 +1,8 @@ +{ + "GNU 13.3.0 RelWithDebInfo [-O2 -g -DNDEBUG]; glibc 2.39; valgrind-3.22.0": { + "dx5 -n 8 -w 16": 880796003, + "fircomb -n 4 -w 10": 858879730, + "grand -n 8 -w 20": 751016530, + "kit_snare -n 8 -w 40": 292035157 + } +} diff --git a/scripts/instrcount.py b/scripts/instrcount.py new file mode 100755 index 00000000..22512948 --- /dev/null +++ b/scripts/instrcount.py @@ -0,0 +1,214 @@ +#!/usr/bin/env python3 +"""The engine's cost in instructions, held to a committed baseline. + + instrcount.py --toolchain KEY [--update] BUILD_DIR + +Runs scripts/dspbench on a few instruments under Valgrind's cachegrind and +counts the instructions each run executes. A count is the same to within +about a part in a million from one run to the next, and a few parts in ten +thousand from one machine to another, where a wall-clock time on the same +machine moves by several percent, so a count can fail a change that a time +could only hint at. +Valgrind and not `perf stat': a hosted CI runner exposes no hardware +counters at all, and a count from one would depend on which CPU the job +landed on, through the library routines glibc picks at load. + +A count is a property of the compiler, its flags and the C library as much +as of the code, so a set of counts is held to the toolchain it was measured +with, named by KEY -- which CMake passes as the compiler, its version, the +build type, the C++ flags and whether LTO is on -- with the glibc and +Valgrind versions added here. + +The baseline committed beside this, instrcount.json, holds CI's toolchain +alone. A desktop's is its owner's: it would go stale with every upgrade of +their system, and every change that moves a count would owe it numbers +from a machine its author does not have. A desktop's counts are held in +BUILD_DIR/instrcount.json instead, which no commit carries, for comparing +a change against the tree before it. A toolchain with counts in neither is +skipped (exit 77, which ctest reports as a skip), unless +THINK_INSTRCOUNT_STRICT is set, as CI sets it, so that the gate cannot +quietly stop running when the runner's compiler changes; it fails and +prints what it measured instead. + +--update measures this toolchain's counts and writes them where they are +held: over its own in instrcount.json, leaving any other there alone, and +otherwise as the whole of BUILD_DIR/instrcount.json, so that file never +collects stale toolchains. `cmake --build BUILD_DIR --target +instrcount-update' runs it with the build's KEY. Do that when a change is +meant to cost more, and when it costs less by more than FLOOR, which fails +too, in the same commit, so the reason is reviewed with the number. A +failure prints the counts it measured, for CI's toolchain from its log. +CI's counts come from the Ubuntu 24.04 image the linux job pins: the commit +that moves the pin replaces the key in instrcount.json with the new image's, +from a strict failure's log or a container of that image. +""" + +import argparse +import concurrent.futures +import json +import os +import platform +import re +import shutil +import subprocess +import sys + +HERE = os.path.dirname(os.path.abspath(__file__)) +TOP = os.path.dirname(HERE) +BASELINE = os.path.join(HERE, 'instrcount.json') + +# A count above the baseline by more than this fails. The noise is under a +# thousandth of a percent, so this is not a margin for it: it is how much a +# change may cost before it has to say so with --update. +LIMIT = 1.10 + +# A count below the baseline by more than this fails too, so that a change +# that makes the engine cheaper lowers the baseline with --update in its +# own commit. Without it the room a speedup made is spent unseen by later +# changes under LIMIT, the one that crosses LIMIT takes the blame for all of +# them, and a regression of up to LIMIT / FLOOR passes. Far from the noise: +# a count repeats to about a part in a million on one machine, and a +# runner's came within a few parts in ten thousand of a container's on a +# desktop with another CPU. +FLOOR = 0.98 + +# dspbench's arguments for each instrument: a delay-line comb, a piano's +# waveguides, an FM voice and a modeled drum, at a few voices and a few +# dozen windows each. Sized so that the whole set is seconds under Valgrind; +# a startup's fixed cost is in every count, and that is a cost too. +WORKLOADS = { + 'fircomb': ['-n', '4', '-w', '10'], + 'grand': ['-n', '8', '-w', '20'], + 'dx5': ['-n', '8', '-w', '16'], + 'kit_snare': ['-n', '8', '-w', '40'], +} + + +def toolchain(key): + valgrind = subprocess.run(['valgrind', '--version'], capture_output=True, + text=True, check=True).stdout.strip() + return f'{key}; glibc {platform.libc_ver()[1]}; {valgrind}' + + +def count(build, name, args): + run = subprocess.run( + ['valgrind', '--tool=cachegrind', '--cache-sim=no', + '--cachegrind-out-file=/dev/null', + os.path.join(build, 'scripts', 'dspbench'), + '-p', os.path.join(build, 'plugins', ''), *args, + os.path.join(TOP, 'dsp', name + '.dsp')], + capture_output=True, text=True, + env={**os.environ, 'THINK_DSP_PATH': os.path.join(TOP, 'dsp')}) + found = re.search(r'I\s+refs:\s+([\d,]+)', run.stderr) + + if run.returncode != 0 or found is None: + sys.exit(f'{name}: dspbench under valgrind failed\n{run.stderr}') + + return int(found.group(1).replace(',', '')) + + +def main(): + parser = argparse.ArgumentParser() + parser.add_argument('--toolchain', required=True) + parser.add_argument('--update', action='store_true') + parser.add_argument('build') + opts = parser.parse_args() + strict = os.environ.get('THINK_INSTRCOUNT_STRICT', '') != '' + + if shutil.which('valgrind') is None: + if strict or opts.update: + sys.exit('instrcount: no valgrind') + + print('instrcount: no valgrind; skipped') + return 77 + + key = toolchain(opts.toolchain) + + local = os.path.join(opts.build, 'instrcount.json') + held = BASELINE + + with open(BASELINE) as f: + baseline = json.load(f) + + if key not in baseline: + held, baseline = local, {} + + if os.path.exists(local): + with open(local) as f: + baseline = json.load(f) + + known = baseline.get(key) + + if known is None and not strict and not opts.update: + print(f'instrcount: no counts for "{key}" in {BASELINE} or {local};' + f' skipped. `cmake --build {opts.build} --target' + " instrcount-update' records them.") + return 77 + + # One workload a process, and they are independent, so at once. + with concurrent.futures.ThreadPoolExecutor() as pool: + jobs = {name: pool.submit(count, opts.build, name, args) + for name, args in WORKLOADS.items()} + measured = {f'{name} {" ".join(WORKLOADS[name])}': job.result() + for name, job in jobs.items()} + + if opts.update: + if held == local: + baseline = {} + + baseline[key] = measured + + with open(held, 'w') as f: + json.dump(baseline, f, indent=2, sort_keys=True) + f.write('\n') + + print(f'instrcount: wrote the counts for "{key}" to {held}') + return 0 + + if known is None: + print(f'instrcount: no counts for "{key}" in {BASELINE}. ' + 'Measured, for the file:\n' + + json.dumps({key: measured}, indent=2, sort_keys=True)) + return 1 + + failed = 0 + table = [f'toolchain: {key}', + f'{"workload":<26} {"baseline":>15} {"measured":>15} ratio'] + + for name, got in measured.items(): + want = known.get(name) + + if want is None: + table.append(f'{name:<26} {"none":>15} {got:>15,} -- FAIL, ' + 'not in the baseline') + failed += 1 + continue + + ratio = got / want + note = '' + + if ratio > LIMIT: + note = f' FAIL, over {LIMIT:.2f}' + failed += 1 + elif ratio < FLOOR: + note = f' FAIL, under {FLOOR:.2f}: --update lowers the baseline' + failed += 1 + + table.append(f'{name:<26} {want:>15,} {got:>15,} {ratio:.4f}{note}') + + if failed: + table.append('Measured, for the file:\n' + + json.dumps({key: measured}, indent=2, sort_keys=True)) + + # Beside the build as well, because ctest shows a passing test's output + # to nobody and CI prints this file to show the margin. + print('\n'.join(table)) + + with open(os.path.join(opts.build, 'instrcount.txt'), 'w') as f: + f.write('\n'.join(table) + '\n') + + return 1 if failed else 0 + + +if __name__ == '__main__': + sys.exit(main()) diff --git a/wasm/web/bench.mjs b/wasm/web/bench.mjs index 4b74c32d..058afcdf 100644 --- a/wasm/web/bench.mjs +++ b/wasm/web/bench.mjs @@ -20,7 +20,8 @@ /* * bench.mjs -- what one quantum costs with a piece running. * - * node wasm/web/bench.mjs [BUILD_DIR] + * node wasm/web/bench.mjs [--json out.json] [--only a.gen,b.gen] + * [--seconds 60] [BUILD_DIR] * * The one measurement that could send the scheduler back out of the * worklet. A quantum is 128 frames, 2.67 ms at 48 kHz, and it is a @@ -36,6 +37,12 @@ * distribution of the per-quantum time and the worst one, against the * budget. * + * Each piece is played the way the page plays it, or a piece that leans on + * the page measures as silence: the kit's samples handed over, and every + * channel the piece leaves to the page given its default patch. A piece + * that pins no seed is given SEED below, so that two runs time the same + * composition rather than two the host happened to draw. + * * Node rather than a browser on purpose: this is the engine's cost, and * the engine is the same wasm either way. What a browser adds on top is the * port and the de-interleave, and browsertest.mjs already holds a browser's @@ -44,18 +51,41 @@ * anything a background tab can throttle. * * The number that decides anything is this run on the slowest machine the - * thing is meant to play on, not on the one it was written on. + * thing is meant to play on, not on the one it was written on. --json + * writes every run's numbers and the machine they came from, so runs on + * two machines can be set side by side. */ +import { execFileSync } from 'node:child_process'; +import { createHash } from 'node:crypto'; +import fs from 'node:fs'; +import os from 'node:os'; import path from 'node:path'; import { fileURLToPath, pathToFileURL } from 'node:url'; +import { parseArgs } from 'node:util'; -import { instruments, pieces } from './piececheck.mjs'; -import { loadPiece } from './render.mjs'; +import { defaults, instruments, pieces, samples } from './piececheck.mjs'; +import { aim, loadPiece } from './render.mjs'; const here = path.dirname(fileURLToPath(import.meta.url)); -const build = path.resolve(process.argv[2] ?? +const { values: opts, positionals } = + parseArgs({ options: { json: { type: 'string' }, + only: { type: 'string' }, + seconds: { type: 'string', default: '60' } }, + allowPositionals: true }); +const build = path.resolve(positionals[0] ?? path.join(here, '..', '..', 'build-web')); +const SECONDS = Number(opts.seconds); + +if (!(Number.isFinite(SECONDS) && SECONDS > 0)) +{ + process.stderr.write(`bench: --seconds ${opts.seconds} is not a time\n`); + process.exit(2); +} + +/* Opened now, so a path that cannot be written is known before the + minutes of timing rather than after. */ +const jsonOut = opts.json !== undefined ? fs.openSync(opts.json, 'w') : null; const { default: createThinkWeb } = await import(pathToFileURL(path.join(build, 'thinkweb.js')).href); @@ -63,7 +93,9 @@ const { default: createThinkWeb } = const RATE = 48000; const WINDOW = 256; const QUANTUM = 128; -const SECONDS = 60; + +/* Any fixed seed would do; what matters is that it is fixed. */ +const SEED = 1; /* A chord, pressed and released twice a second: six voices is a hand. */ const CHORD = [48, 55, 60, 64, 67, 72]; @@ -77,16 +109,22 @@ function quantile (sorted, q) const ms = (x) => `${x.toFixed(3)} ms`; -async function run (gen, dsps, chord) +async function run (gen, dsps, kit, patchFor, chord) { const { M, ok, errors } = await loadPiece(createThinkWeb, { rate: RATE, windowlen: WINDOW, block: QUANTUM, gen, - instruments: dsps }); + instruments: dsps, samples: kit, + seed: SEED }); if (!ok) return { errors }; + /* Kept: a channel left unaimed is timed as silence, which is cheaper + than the page would play it. */ + const log = []; + const { unaimed } = aim(M, patchFor, log); + M._tw_transport(-1, 0, 0); /* Allocated once, and a typed array: a JavaScript array grown a @@ -141,11 +179,14 @@ async function run (gen, dsps, chord) } return { times: times.subarray(0, taken).sort(), notes, worst, worstAt, - moving }; + moving, unaimed, log }; } const budget = QUANTUM / RATE * 1000; const dsps = instruments(build); +const kit = samples(build); +const patchFor = defaults(build); +const only = opts.only?.split(','); process.stdout.write( `a quantum of ${QUANTUM} frames at ${RATE} Hz is ${budget.toFixed(2)} ms, ` + @@ -156,20 +197,34 @@ process.stdout.write( `of quantum worst at\n`); const rows = []; +const failed = []; +const all = pieces(build); + +/* Kept with the failures, so that a misspelled name fails the run and is + in --json's document, rather than timing nothing. */ +for (const name of only ?? []) +{ + if (!all.some((p) => p.name === name)) + { + process.stdout.write(`${name}: no such piece\n`); + failed.push({ name, chord: null, errors: ['no such piece'] }); + } +} -for (const piece of pieces(build)) +for (const piece of all) { - if (!piece.seeded) + if (only !== undefined && !only.includes(piece.name)) continue; for (const chord of [false, true]) { - const r = await run(piece.text, dsps, chord); + const r = await run(piece.text, dsps, kit, patchFor, chord); if (r.errors !== undefined) { process.stdout.write(`${piece.name}: did not load -- ` + `${r.errors.join('; ')}\n`); + failed.push({ name: piece.name, chord, errors: r.errors }); continue; } @@ -184,6 +239,14 @@ for (const piece of pieces(build)) `${ms(r.worst)} ` + `${(r.worst / budget * 100).toFixed(1).padStart(8)}% ` + `${r.worstAt.toFixed(2)} s\n`); + + if (!chord && r.unaimed.length > 0) + process.stdout.write( + ` timed as silence: channel ` + + `${r.unaimed.map((u) => `${u.channel + 1} ` + + `(${u.wanted || 'no default'})`) + .join(', ')}` + + `${r.log.map((l) => `\n ${l}`).join('')}\n`); } } @@ -199,12 +262,68 @@ const top = rows[0]; on a machine where every first quantum is the worst there would be no such run, and on any other a run's second-worst was being thrown away with its first. */ -const running = [...rows].sort((a, b) => b.moving - a.moving)[0]; +if (top !== undefined) +{ + const running = [...rows].sort((a, b) => b.moving - a.moving)[0]; + + process.stdout.write( + `\nworst of all: ${top.name} at ${top.worst.toFixed(3)} ms, ` + + `${(top.worst / budget * 100).toFixed(1)}% of the quantum, ` + + `${top.worstAt.toFixed(2)} s in\n` + + `worst once the transport is moving: ${running.name} at ` + + `${running.moving.toFixed(3)} ms, ` + + `${(running.moving / budget * 100).toFixed(1)}% of the quantum\n`); +} -process.stdout.write( - `\nworst of all: ${top.name} at ${top.worst.toFixed(3)} ms, ` + - `${(top.worst / budget * 100).toFixed(1)}% of the quantum, ` + - `${top.worstAt.toFixed(2)} s in\n` + - `worst once the transport is moving: ${running.name} at ` + - `${running.moving.toFixed(3)} ms, ` + - `${(running.moving / budget * 100).toFixed(1)}% of the quantum\n`); +if (jsonOut !== null) +{ + /* This script's checkout, which need not be what the build was made + from: the build is named by its path and the hash of the module + that was timed. */ + const git = (...args) => + { + try + { + return execFileSync('git', ['-C', here, ...args], + { encoding: 'utf8', + stdio: ['ignore', 'pipe', 'ignore'] }) + .trim(); + } + catch + { + /* Not a checkout, or no git: the run is still worth having. */ + return null; + } + }; + const status = git('status', '--porcelain', '--untracked-files=no'); + + /* By piece and then chord, not by time, so that two documents line + up run for run. */ + const runs = [ + ...rows.map((r) => ({ + piece: r.name, chord: r.chord, notes: r.notes, + p50Ms: quantile(r.times, 0.5), p99Ms: quantile(r.times, 0.99), + p999Ms: quantile(r.times, 0.999), maxMs: r.worst, + worstAtS: r.worstAt, movingMaxMs: r.moving, + unaimed: r.unaimed.map((u) => ({ channel: u.channel + 1, + wanted: u.wanted })), + aimLog: r.log })), + ...failed.map((f) => ({ piece: f.name, chord: f.chord, + error: f.errors.join('; ') })), + ].sort((a, b) => (a.piece > b.piece) - (a.piece < b.piece) || + a.chord - b.chord); + + fs.writeFileSync(jsonOut, JSON.stringify({ + rate: RATE, windowlen: WINDOW, quantum: QUANTUM, seconds: SECONDS, + seed: SEED, budgetMs: budget, + env: { node: process.version, cpu: os.cpus()[0]?.model ?? null, + benchCommit: git('rev-parse', 'HEAD'), + benchDirty: status === null ? null : status !== '', + build, + wasmSha256: createHash('sha256') + .update(fs.readFileSync(path.join(build, 'thinkweb.wasm'))) + .digest('hex') }, + runs }, null, 2) + '\n'); +} + +process.exit(failed.length > 0 || rows.length === 0 ? 1 : 0); diff --git a/wasm/web/browsertest.mjs b/wasm/web/browsertest.mjs index b8a16a7b..63f4d829 100644 --- a/wasm/web/browsertest.mjs +++ b/wasm/web/browsertest.mjs @@ -193,7 +193,9 @@ async function pieceInBrowser (page, gen, dsps, windowlen) await synth.flush(); return { ok: true, logs, errors: [], events, - knobs: piece.knobs.length, windowlen: synth.windowlen }; + knobs: piece.knobs.length, windowlen: synth.windowlen, + load: synth.quanta(), + rendered: Math.ceil(ctx.length / 128) }; }, { gen, dsps, windowlen, seconds: SECONDS, rate: RATE }); } @@ -358,9 +360,18 @@ async function runBrowser (label, type) const tape = tapeBefore(got.events.map(tapeLine).join(''), SECONDS); - cells.push(tape === want ? `${windowlen} ok` - : `${windowlen} DIFFERS -- ` + - firstDifference(want, tape)); + /* Every quantum timed once: one lost or counted twice where a + batch is posted is a load figure that means nothing. */ + const load = got.load; + + cells.push(tape !== want + ? `${windowlen} DIFFERS -- ` + + firstDifference(want, tape) + : load.calls !== got.rendered + ? `${windowlen} timed ${load.calls} of ${got.rendered} ` + + `quanta, ${load.overBudget} over, p99 ` + + `${load.p99Ms} ms, slowest ${load.slowestMs} ms` + : `${windowlen} ok`); } const bad = cells.some((c) => !c.endsWith('ok')); diff --git a/wasm/web/host.js b/wasm/web/host.js index b58c9ad0..d824b497 100644 --- a/wasm/web/host.js +++ b/wasm/web/host.js @@ -74,6 +74,38 @@ function wasmBytes () return fetched; } +/* The tape batches the load's recent figures are summed over: 64 is + 2.7 s at 48 kHz. */ +const RECENT_BATCHES = 64; + +/* A batch's process() costs (worklet.js, postTape) added into a sum. */ +function addLoad (into, m) +{ + into.overBudget += m.overBudget; + into.slowestMs = Math.max(into.slowestMs, m.slowestMs); + + for (let ms = 0; ms < m.took.length; ms++) + { + into.took[ms] = (into.took[ms] ?? 0) + m.took[ms]; + into.calls += m.took[ms]; + } +} + +/* A sum, and the whole millisecond 99% of its calls took no longer than; + the last bin is that many or more. */ +function withP99 (q) +{ + let ms = 0; + + for (let seen = q.took[0] ?? 0; seen < 0.99 * q.calls; + seen += q.took[ms]) + ms++; + + return { ...q, took: [...q.took], p99Ms: ms }; +} + +const noLoad = () => ({ calls: 0, overBudget: 0, slowestMs: 0, took: [] }); + export async function createSynth (ctx, { windowlen = 256, onLog = () => {}, onTape = () => {}, @@ -130,6 +162,15 @@ export async function createSynth (ctx, { windowlen = 256, if (mirror !== null) mirror.onmessage = (e) => onMirror(e.data); + /* What the worklet's process() calls have cost, summed since the + start: a batch is 16 calls, too few to have a p99 of its own. And + the last RECENT_BATCHES batches, kept apart, because the first + quantum of a run builds the graphs and is the slowest by far, and + a figure since the start goes on showing it for good. */ + const quanta = noLoad(); + const recent = []; + let batches = 0; + /* One message, both ports. See the top of this file. */ /* Collecting, inside batch() below. */ let batching = null; @@ -222,6 +263,18 @@ export async function createSynth (ctx, { windowlen = 256, mirror?.postMessage({ type: 'step', frame: m.frame, epoch: m.epoch, keys: m.keys }); onTape(m); + + /* After the tape, and only when the batch carries them: a + worklet.js from another build may post none, and a load + figure is not worth losing the tape over. */ + if (m.took === undefined) + break; + + addLoad(quanta, m); + quanta.coarseClock = m.coarseClock; + recent[batches++ % RECENT_BATCHES] = + { overBudget: m.overBudget, slowestMs: m.slowestMs, + took: m.took }; break; } }; @@ -261,6 +314,17 @@ export async function createSynth (ctx, { windowlen = 256, windowlen: info.windowlen, sampleRate: info.sampleRate, + /* The sums above, the recent one as `recent'. */ + quanta: () => + { + const last = noLoad(); + + for (const b of recent) + addLoad(last, b); + + return { ...withP99(quanta), recent: withP99(last) }; + }, + /* Resolves true if the .dsp parsed. The channel is the caller's: a piece that routes `input midi' to a channel it declares no instrument for needs something put there to sound. */ diff --git a/wasm/web/jam.js b/wasm/web/jam.js index a672f3b0..672c7f33 100644 --- a/wasm/web/jam.js +++ b/wasm/web/jam.js @@ -1522,6 +1522,7 @@ function showNumbers () `relay offset spread ${ms(room.clock.spread)} ` + `(${room.clock.count} samples)`, ]; + const load = synth?.quanta(); if (audioClock !== null) lines.push( @@ -1531,6 +1532,12 @@ function showNumbers () `base latency ${ms(ctx.baseLatency * 1000)}`, `output latency ${ms((ctx.outputLatency ?? NaN) * 1000)}`, `synth window ${synth.windowlen} frames`, + `quanta over budget ${load.recent.overBudget} of the last ` + + `${load.recent.calls}; slowest ${load.recent.slowestMs} ms, ` + + `p99 ${load.recent.p99Ms} ms` + + (load.coarseClock ? '; the clock is too coarse to trust' : ''), + ` since the start ${load.overBudget} of ${load.calls}; ` + + `slowest ${load.slowestMs} ms, p99 ${load.p99Ms} ms`, `transport ` + (transport.running ? `${transportNow().toFixed(3)} s` : 'stopped')); diff --git a/wasm/web/main.js b/wasm/web/main.js index b3757ff0..f22997bd 100644 --- a/wasm/web/main.js +++ b/wasm/web/main.js @@ -3069,6 +3069,12 @@ window.solo = { were ever compiled for this page. */ pane: (what, ...args) => panes[what](...args), + /* What the worklet's process() calls have cost (host.js, quanta), + and the audio clock to hold the wall clock against, for + worklettime.mjs. */ + quanta: () => synth?.quanta() ?? null, + audioTime: () => ctx?.currentTime ?? null, + /* Which of the drawing panes is asking for frames. A pane in a background tab, folded away or in the mode that is not up costs nothing, and this is the only way to see from outside that it diff --git a/wasm/web/render.mjs b/wasm/web/render.mjs index b0e8a09d..af49162a 100644 --- a/wasm/web/render.mjs +++ b/wasm/web/render.mjs @@ -232,6 +232,53 @@ export function schedule (M, c) throw new Error(`no scheduler command '${c.op}'`); } +/* A loaded piece's channels aimed the page's way, which playAimed below + describes. Apart from it so that the bench plays a piece the way the + page does as well. */ +export function aim (M, patchFor, log) +{ + const aimed = []; + + /* Channels the piece asked for that `patchFor' had nothing for. Kept + and returned rather than skipped quietly: a caller that cannot tell + "this piece names no channel" from "this build ships no patch for + its channels" sends somebody hunting in the wrong place. */ + const unaimed = []; + + for (let i = 0; i < M._tw_sink_count(); i++) + { + const channel = M._tw_sink_channel(i); + const want = M.ccall('tw_patch_default', 'string', ['number'], + [channel]); + const text = want === '' ? null : patchFor(want); + + if (text === null || text === undefined) + { + unaimed.push({ channel, wanted: want }); + continue; + } + + /* The whole .patch, read by the module: the graph it names, its + side, its effect and its overrides, in the order the format + requires. This used to be a tw_load and a loop of tw_chanarg + done here in the right order by hand -- a third copy of that + order, beside patch.js's and the application's. */ + if (M.ccall('tw_patch_apply', 'number', + ['number', 'string', 'string'], + [channel, text, want]) === 0) + { + log.push(`channel ${channel + 1}: ${want}: ` + + M.ccall('tw_patch_why', 'string', [], [])); + unaimed.push({ channel, wanted: want }); + continue; + } + + aimed.push({ channel, patch: want }); + } + + return { aimed, unaimed }; +} + /* A piece played the way the page plays it: loaded, then aimed, then * listened to. * @@ -280,44 +327,7 @@ export async function playAimed (createThinkWeb, return { ok, log, errors, aimed: [], unaimed: [], listens: [], peak: 0, at: 0 }; - const aimed = []; - - /* Channels the piece asked for that `patchFor' had nothing for. Kept - and returned rather than skipped quietly: a caller that cannot tell - "this piece names no channel" from "this build ships no patch for - its channels" sends somebody hunting in the wrong place. */ - const unaimed = []; - - for (let i = 0; i < M._tw_sink_count(); i++) - { - const channel = M._tw_sink_channel(i); - const want = M.ccall('tw_patch_default', 'string', ['number'], - [channel]); - const text = want === '' ? null : patchFor(want); - - if (text === null || text === undefined) - { - unaimed.push({ channel, wanted: want }); - continue; - } - - /* The whole .patch, read by the module: the graph it names, its - side, its effect and its overrides, in the order the format - requires. This used to be a tw_load and a loop of tw_chanarg - done here in the right order by hand -- a third copy of that - order, beside patch.js's and the application's. */ - if (M.ccall('tw_patch_apply', 'number', - ['number', 'string', 'string'], - [channel, text, want]) === 0) - { - log.push(`channel ${channel + 1}: ${want}: ` + - M.ccall('tw_patch_why', 'string', [], [])); - unaimed.push({ channel, wanted: want }); - continue; - } - - aimed.push({ channel, patch: want }); - } + const { aimed, unaimed } = aim(M, patchFor, log); const listens = []; diff --git a/wasm/web/worklet.js b/wasm/web/worklet.js index f83bce8c..89d39fdf 100644 --- a/wasm/web/worklet.js +++ b/wasm/web/worklet.js @@ -51,6 +51,10 @@ import { drain, loadErrors } from './tape.js'; /* How many 128-frame quanta between posts to the page: 43 ms at 48 kHz. */ const TAPE_EVERY = 16; +/* process() calls counted by whole milliseconds taken, the last bin + holding everything slower. */ +const TOOK_BINS = 8; + /* The glue asks for the time now and then; a worklet has no performance object to ask. Not currentTime: it stands still through a process() call, and a late joiner's catch-up budget (thinkweb.cpp, catchUp) is @@ -116,6 +120,21 @@ class ThinkProcessor extends AudioWorkletProcessor * the samples already are, rather than through a wasm call the page * has no thread to make. */ this.micPeak = 0; + + /* What process() has cost since the last batch, against the + length of the quantum each call renders. The browser keeps no + xrun count a page can read, so this is the nearest thing to + one. */ + this.budgetMs = 0; + this.overBudget = 0; + this.slowestMs = 0; + this.took = new Uint16Array(TOOK_BINS); + + /* The smallest step the clock has taken between two calls' starts, + and the last start. */ + this.clockStepMs = Infinity; + this.lastStart = Infinity; + this.epoch = 0; /* the epoch this.events belong to */ this.port.onmessage = (e) => this.receive(e.data); @@ -645,6 +664,26 @@ class ThinkProcessor extends AudioWorkletProcessor if (this.M === null || out.length === 0) return true; + /* Date.now, because it is the only clock here: neither Chromium nor + Firefox gives this scope a performance object (the one above + reads currentTime, which stands still inside a call). Its + resolution is a whole millisecond, so one call reads as the + floor or the ceiling of what it took -- right on average, off by + under a millisecond each time. Against a 2.67 ms budget that + makes `overBudget' a call that read 3 ms or more: one that took + between 2 and 3 can land either side. A wall clock, too, so a + clock step shows as one odd reading. Firefox under + resistFingerprinting rounds it to tens of milliseconds, where + every count is noise, which is what `coarseClock' says. */ + const start = Date.now(); + + const step = start - this.lastStart; + + if (step > 0 && step < this.clockStepMs) + this.clockStepMs = step; + + this.lastStart = start; + /* The module's frame counter starts at zero when tw_create ran; this context's is already well past zero by then, and every frame the page hands in -- a Play's origin above all -- is in @@ -663,6 +702,8 @@ class ThinkProcessor extends AudioWorkletProcessor const frames = out[0].length; + this.budgetMs = frames * 1000 / sampleRate; + this.feedInput(inputs[0], frames); const p = this.M._tw_render(frames) >> 2; @@ -741,6 +782,18 @@ class ThinkProcessor extends AudioWorkletProcessor if (++this.quanta >= TAPE_EVERY) this.postTape(); + /* After the post, so the call that posted counts in the next + batch and not in none. */ + const took = Math.max(0, Date.now() - start); + + if (took > this.slowestMs) + this.slowestMs = took; + + if (took > this.budgetMs) + this.overBudget++; + + this.took[Math.min(took, TOOK_BINS - 1)]++; + return true; } @@ -964,6 +1017,22 @@ class ThinkProcessor extends AudioWorkletProcessor speed: this.M._tw_speed_now(), late: this.M._tw_late(), + /* process() since the last batch: how many calls ran past the + quantum's budget, the slowest, and how many took each whole + millisecond (TOOK_BINS), which is what a p99 over any span + the page likes is summed from. */ + overBudget: this.overBudget, + slowestMs: this.slowestMs, + took: this.took, + + /* Calls come a quantum apart or, rendering offline, closer: + on a millisecond clock two of them read three apart at + most. One that has stepped, but never by less than two + quanta, is too coarse to time a call by; one not yet seen to + step is not called coarse on no evidence. */ + coarseClock: this.clockStepMs !== Infinity && + this.clockStepMs > 2 * this.budgetMs, + /* A late joiner's transport, still being stepped up to the output: silent until it is (thinkweb.cpp, catchUp). */ catching: this.M._tw_catching() !== 0, @@ -997,6 +1066,9 @@ class ThinkProcessor extends AudioWorkletProcessor this.keys = []; this.taps.clear(); this.micPeak = 0; + this.overBudget = 0; + this.slowestMs = 0; + this.took.fill(0); } } diff --git a/wasm/web/worklettime.mjs b/wasm/web/worklettime.mjs new file mode 100644 index 00000000..8447d64f --- /dev/null +++ b/wasm/web/worklettime.mjs @@ -0,0 +1,258 @@ +/* + * Copyright (C) 2004-2026 The thinksynth authors + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by the + * Free Software Foundation; either version 2 of the License, or (at your + * option) any later version. + * + * This program is distributed in the hope that it will be useful, but + * WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General + * Public License for more details. + * + * You should have received a copy of the GNU General + * Public License along with this program; if not, write to the + * Free Software Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. + */ + +/* + * worklettime.mjs -- what the worklet's process() calls cost on the solo + * page, playing a piece in a real-time AudioContext. + * + * node wasm/web/worklettime.mjs [--browser chromium|firefox] + * [--seconds 30] [--json out.json] [BUILD_DIR] [piece.gen...] + * + * bench.mjs times the engine in Node, which is the cost and nothing else. + * This is the same pieces as a listener gets them: the page loads one, + * presses Play, and the worklet counts its own calls (worklet.js, the + * calls over the quantum's budget and a histogram by millisecond), which + * host.js sums and window.solo.quanta hands out. For each piece it prints + * the calls over budget per minute of play, the slowest call and the p99, + * and the audio clock against the wall clock, which is what says the + * context really ran in real time and did not fall behind or stop. + * + * Every piece by default. Not a gate: a count of calls over budget is a + * property of the machine, its load and its browser as much as of the + * code, and the clock the worklet times itself by is Date.now, a whole + * millisecond (worklet.js says what that means for the count). Under + * scripts/headless.sh, as the browser tests are, so the context plays + * into a null sink that is still clocked like a device. + */ + +/* Under scripts/headless.sh unless THINK_TEST_HEADLESS=0: see headless.mjs. */ +import './headless.mjs'; + +import fs from 'node:fs'; +import path from 'node:path'; +import { fileURLToPath } from 'node:url'; +import { parseArgs } from 'node:util'; + +import { chromium, firefox } from 'playwright'; + +import { serve } from './serve.mjs'; + +/* What host.js's recent load figures span, RECENT_BATCHES at 44.1 kHz and + then some. */ +const RECENT_S = 3; + +const here = path.dirname(fileURLToPath(import.meta.url)); +const { values: opts, positionals } = + parseArgs({ options: { browser: { type: 'string', default: 'chromium' }, + seconds: { type: 'string', default: '30' }, + json: { type: 'string' } }, + allowPositionals: true }); +const build = path.resolve(positionals[0] ?? + path.join(here, '..', '..', 'build-web')); +const SECONDS = Number(opts.seconds); +const engine = { chromium, firefox }[opts.browser]; + +/* Whole seconds: play() takes a reading a second. */ +if (!(Number.isInteger(SECONDS) && SECONDS > 0)) +{ + process.stderr.write( + `worklettime: --seconds ${opts.seconds} is not a positive whole number\n`); + process.exit(2); +} + +if (engine === undefined) +{ + process.stderr.write(`worklettime: no browser '${opts.browser}'\n`); + process.exit(2); +} + +/* Opened now, so a path that cannot be written is known before the + minutes of playing rather than after. */ +const jsonOut = opts.json !== undefined ? fs.openSync(opts.json, 'w') : null; + +const names = positionals.length > 1 ? positionals.slice(1) + : JSON.parse(fs.readFileSync(path.join(build, 'gen', 'index.json'), + 'utf8')); + +/* The whole millisecond 99% of the calls took no longer than, from the + worklet's histogram; the last bin is that many or more. */ +function p99 (took, calls) +{ + let ms = 0; + + for (let seen = took[0] ?? 0; seen < 0.99 * calls; seen += took[ms] ?? 0) + ms++; + + return ms; +} + +/* The calls and the histogram between two readings of + window.solo.quanta. */ +function since (a, b) +{ + return { calls: b.calls - a.calls, overBudget: b.overBudget - a.overBudget, + took: b.took.map((n, ms) => n - (a.took[ms] ?? 0)) }; +} + +/* Once a second for `seconds': the wall clock, the audio clock and the + load figures. The slowest call since the start is the one that built + the piece's graphs at load, for good, so the slowest of the recent + calls is kept instead: they span RECENT_S, longer than a reading + apart. */ +async function play (page, seconds) +{ + return page.evaluate(async (S) => + { + const s = window.solo; + const read = () => ({ wallS: performance.now() / 1000, + audioS: s.audioTime(), + quanta: s.quanta() }); + const out = [read()]; + let slowestMs = 0; + + for (let i = 0; i < S; i++) + { + await new Promise((go) => setTimeout(go, 1000)); + out.push(read()); + slowestMs = Math.max(slowestMs, out.at(-1).quanta.recent.slowestMs); + } + + return { readings: out, slowestMs }; + }, seconds); +} + +const site = await serve(build, 0, '127.0.0.1', null); +const url = `http://127.0.0.1:${site.address().port}/index.html?panes=0`; +const browser = await engine.launch(opts.browser === 'chromium' + ? { args: ['--autoplay-policy=no-user-gesture-required'] } : {}); +const version = browser.version(); +const results = []; +let failures = 0; + +process.stdout.write( + `${opts.browser} ${version}, ${SECONDS} s a piece\n\n` + + 'piece over/min slowest p99 audio/wall worst 1 s\n'); + +try +{ + for (const name of names) + { + const page = await browser.newPage(); + const errors = []; + + /* The console's too: an exception in the worklet's own scope is + no pageerror, and it is the one that silences the piece. */ + page.on('pageerror', (e) => errors.push(e.message)); + page.on('console', (m) => + { + if (m.type() === 'error') + errors.push(m.text()); + }); + + try + { + await page.goto(url); + await page.waitForFunction( + () => document.getElementById('range').textContent !== ''); + await page.selectOption('#mode', 'piece'); + await page.selectOption('#piece', name); + await page.click('#start'); + await page.waitForFunction( + () => !document.getElementById('loadpiece').disabled, + null, { timeout: 60000 }); + await page.evaluate(() => window.solo.settled()); + + /* For the load's quanta to leave the recent figures before + Play, since nothing could be heard to break in them. */ + await page.waitForTimeout(RECENT_S * 1000); + await page.waitForFunction( + () => !document.getElementById('play').disabled, + null, { timeout: 60000 }); + await page.click('#play'); + await page.waitForFunction( + () => window.solo.quanta()?.calls > 0, + null, { timeout: 60000 }); + + const { readings, slowestMs } = await play(page, SECONDS); + const first = readings[0], last = readings.at(-1); + const q = since(first.quanta, last.quanta); + const wallS = last.wallS - first.wallS; + const audioS = last.audioS - first.audioS; + + /* The worst second's audio against its wall second: a context + that stalled and caught up shows here and not in the ratio + over the whole run. */ + let worstSecondS = 0; + + for (let i = 1; i < readings.length; i++) + { + const a = readings[i - 1], b = readings[i]; + + worstSecondS = Math.max(worstSecondS, + Math.abs((b.audioS - a.audioS) - (b.wallS - a.wallS))); + } + + const r = { + piece: name, calls: q.calls, overBudget: q.overBudget, + overBudgetPerMin: q.overBudget / (wallS / 60), + slowestMs, p99Ms: p99(q.took, q.calls), took: q.took, + coarseClock: last.quanta.coarseClock, + wallS, audioS, audioOverWall: audioS / wallS, worstSecondS, + errors }; + + results.push(r); + process.stdout.write( + `${name.padEnd(15)} ${r.overBudgetPerMin.toFixed(1).padStart(9)} ` + + `${`${slowestMs} ms`.padStart(9)} ${`${r.p99Ms} ms`.padStart(5)} ` + + `${r.audioOverWall.toFixed(4).padStart(12)} ` + + `${(worstSecondS * 1000).toFixed(0).padStart(7)} ms` + + (r.coarseClock ? ' the clock is too coarse to trust' : '') + + '\n'); + + /* Timed, and the numbers kept, but not a run to trust. */ + if (errors.length > 0) + { + failures++; + r.error = 'the page reported errors'; + process.stdout.write(`${name}: ${r.error}: ` + + `${errors.join('; ')}\n`); + } + } + catch (e) + { + failures++; + results.push({ piece: name, error: e.message.split('\n')[0], + errors }); + process.stdout.write(`${name}: ${e.message.split('\n')[0]}\n`); + } + + await page.close(); + } +} +finally +{ + await browser.close(); + site.close(); +} + +if (jsonOut !== null) + fs.writeFileSync(jsonOut, JSON.stringify({ + browser: opts.browser, version, seconds: SECONDS, + build, results }, null, 2) + '\n'); + +process.exit(failures);