bench: engine load tools, a worklet over-budget counter, and an instruction gate

.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
 

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.

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

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 <math.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
 #include <time.h>
 
+#include <algorithm>
+#include <vector>
+
 #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,67 +130,96 @@ 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)
         {
             fprintf(stderr, "%s: did not load\n", file);
             return 1;
         }
 
-        double add = 0, t, first, since;
+        double add = 0, t, first, busy = 0, since = 0;
+        vector<double> 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;
         }
 
         t = now();
         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;

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
+  }
+}