perf: speed up per-read validation hot loops, with profiling report and benchmark rig

benchmarks/README.md

@@ -0,0 +1,111 @@
+# readtools validation benchmarks
+
+The rig used to profile readtools' FASTQ validation path and to verify that the
+hot-loop changes in this branch are behaviour-preserving. Results and analysis are in
+[RESULTS.md](RESULTS.md).
+
+Nothing here is wired into the Gradle build — `benchmarks/` is outside the configured
+source sets, so it is neither compiled by `./gradlew build` nor scanned by spotless.
+The harnesses are compiled on demand by the scripts.
+
+## Why this exists
+
+Loculus invokes readtools once per submitted entry, as a fresh process:
+
+```
+java -jar readtools.jar <mate1> <mate2> --format FASTQ
+```
+
+That step was one of the larger per-entry costs in its raw-reads pipeline, and it was
+assumed to be dominated by JVM startup. It isn't — see RESULTS.md. Answering that
+required separating four things that a plain `time java -jar ...` conflates:
+
+1. JVM boot,
+2. classloading and JIT warmup,
+3. steady-state validation work,
+4. gzip inflate.
+
+The harnesses exist to pull those apart.
+
+## Setup
+
+**Build the jar to test.** readtools needs one dependency that is not on Maven Central:
+
+```bash
+git clone https://github.com/enasequence/webin-cli-validator.git
+cd webin-cli-validator
+APP_VERSION=2.15.1 ./gradlew publishToMavenLocal -Pgitlab_private_token=x
+```
+
+Then build readtools itself **with JDK 17** (the bundled Gradle 7.x cannot run on 21+):
+
+```bash
+JAVA_HOME=/path/to/jdk17 ./gradlew shadowJar   # -> build/libs/readtools-*-all.jar
+```
+
+> If the build fails resolving `webin-cli-validator:2.+`, pin it to `2.15.1` in
+> `build.gradle`. The floating range is resolved against `maven.imagej.net`, which
+> currently returns 503. That pin is a local build workaround and is deliberately not
+> part of this branch.
+
+**Get a reference jar** to compare against — the released artifact is the honest
+baseline, since it is what actually runs in production:
+
+```bash
+curl -L -o readtools-reference.jar \
+  https://github.com/loculus-project/readtools/releases/download/v1.0.0/readtools-2.15.1-all.jar
+```
+
+**Generate inputs** from any real paired library (a few hundred MB of source is plenty):
+
+```bash
+benchmarks/scripts/gen-testdata.sh SRRxxxxxxx_1.fastq.gz SRRxxxxxxx_2.fastq.gz /tmp/rtdata
+benchmarks/scripts/gen-edgecases.sh /tmp/rtedge
+```
+
+## Running
+
+```bash
+# correctness first - byte-identical stdout+stderr AND exit status
+benchmarks/scripts/check-equivalence.sh readtools-reference.jar build/libs/readtools-*-all.jar \
+    /tmp/rtdata /tmp/rtedge
+
+# then speed
+benchmarks/scripts/run-benchmark.sh readtools-reference.jar build/libs/readtools-*-all.jar \
+    /tmp/rtdata 4 0
+```
+
+## The harnesses
+
+Each calls `ValidatorWrapper` directly, so it measures the validation call itself
+rather than the CLI wrapper.
+
+| harness | question it answers |
+|---|---|
+| `WarmLoop` | How much of a cold run is boot vs classload+JIT vs work? Revalidates one input N times and prints JVM uptime at `main` plus each iteration. |
+| `WarmVaried` | Does the warm-up win survive *different* inputs, or is it just page cache? Rotates through distinct pairs. |
+| `WarmCpu` | The A/B workhorse. Same as `WarmVaried` but reports per-iteration **CPU** time, and discards the first 6 iterations as warmup. |
+| `WarmConcurrent` | Can one warm JVM serve concurrent validations, and are the results still correct? N threads, distinct inputs, prints per-validation cost and each result. |
+
+## Methodology notes
+
+These are the things that went wrong first and are worth not repeating.
+
+- **Do not benchmark this with wall clock on a shared machine.** During development,
+  two runs of the *same* jar differed by 2.3x because other JVMs were running. Use
+  `WarmCpu`'s CPU-time numbers, and pin with `taskset`.
+- **Discard the first iterations.** The cold iteration is ~2x the steady state; that
+  gap *is* the JIT warmup result, but it will wreck an average.
+- **Rotate distinct inputs when measuring warm-up**, otherwise page cache and branch
+  prediction flatter the result. (In practice rotating made the measured win *larger*,
+  not smaller — but that has to be shown, not assumed.)
+- **Compare exit status as well as output.** Half of what this code does is reject
+  files; a candidate that silently stops rejecting would otherwise look fine.
+- **Profile with JFR**, not perf/async-profiler, if you are in a container without the
+  required capabilities:
+  `-XX:StartFlightRecording=settings=profile,filename=x.jfr,dumponexit=true`, then
+  `jfr print --stack-depth 40 --events jdk.ExecutionSample x.jfr`. The default stack
+  depth of 5 leaves ~45% of samples unattributable to a readtools frame.
+- **JFR under-attributes native work.** `java.util.zip.Inflater` barely appears in
+  execution samples, so the gzip cost has to be measured by differencing `.gz` against
+  plain input rather than read off the profile.

benchmarks/RESULTS.md

@@ -0,0 +1,199 @@
+# Where readtools' FASTQ validation time goes
+
+Profiling report behind the hot-loop changes in this branch. Measured 2026-08-26 with
+the rig in this directory, against the released `v1.0.0` jar
+(`readtools-2.15.1-all.jar`).
+
+Environment: 16-vCPU aarch64 container, JDK 21 (conda-forge) unless stated, page cache
+warm, timing runs pinned to one core. **Absolute numbers will not transfer to other
+hardware; the ratios are the transferable part.**
+
+## Summary
+
+- JVM *boot* is negligible: **0.036 s**, under 2% of a cold call.
+- What a fresh process actually throws away is **JIT warmup**: a cold validation costs
+  **~0.7-0.85 s more** than a warm one, i.e. **38-51%** of the call.
+- Steady-state cost is dominated by the **per-base IUPAC check (28%)**, **htsjdk line
+  reading (16.5%)**, **quality scoring (15.9%)** and the **pairing check (~35% combined)**.
+- The changes in this branch target the first and part of the last: **~25-31% less CPU
+  in steady state, ~21-28% on a cold JVM** (two runs, different JDKs — see section 5).
+- Validation cost is **flat above 100k reads**, because quick mode stops there.
+
+## 1. Cold vs warm: it is JIT, not startup
+
+`WarmLoop`, same 50 MB gzipped pair validated 10x in one JVM, one core:
+
+```
+jvm-boot-to-main: 0.036 s
+iter  0: 1.909 s   <- cold: classload + JIT warmup + work
+iter  1: 1.272 s
+iter  2: 1.357 s
+iter  3: 1.255 s
+iter  4..9: ~1.20 s  <- steady
+```
+
+| component | time | share of a cold ~1.95 s call |
+|---|---|---|
+| JVM boot (VM init to `main`) | 0.036 s | 1.8% |
+| classloading + JIT warmup | ~0.71 s | 36% |
+| steady-state validation work | ~1.20 s | 62% |
+
+**Control** (`WarmVaried`) — the above revalidates one file, which page cache flatters.
+Rotating four *distinct* 100k-read pairs, uncompressed:
+
+```
+iter  0 [var0]: 1.661 s   <- cold
+iter  1 [var1]: 0.883 s
+iter  2 [var2]: 0.910 s
+iter  3 [var3]: 0.822 s
+iter  4..11:  ~0.81 s     <- steady, still rotating inputs
+```
+
+Cold to warm is **1.661 s -> ~0.81 s, a 51% saving** — larger with distinct inputs, not
+smaller, so it is not a caching artefact. Reproduced independently at 1.660 s / ~0.83 s.
+
+Corroborated from the other direction: `-XX:TieredStopAtLevel=1`, which blocks C2, makes
+the 50 MB case **51% worse** (1.88 s -> 2.85 s). That flag is the best possible choice
+for an empty input and the worst for a real one — worth knowing before anyone reaches
+for it as a "startup" fix.
+
+**Implication:** a warm, reusable JVM is worth ~50% per validation here. That is a much
+larger change than this branch attempts, but it is the single biggest lever found.
+
+`WarmConcurrent`, 4 concurrent validations of 4 distinct pairs in one warm JVM on 4
+cores: **~0.31 s per validation** steady state, all results correct across 5 rounds
+(`paired=true` for every pair). Note that 4 rounds of correct output is evidence, not
+proof, of thread-safety.
+
+## 2. Cost is flat above 100k reads
+
+Quick mode (`ValidateCli`'s default, `QUICK_READ_LIMIT = 100_000`) stops after 100k
+reads per file, so beyond ~35 MB of input the cost stops growing:
+
+| input (decompressed, per mate) | reads read | gz | plain |
+|---|---|---|---|
+| tiny (1 read) | 1 | 152 ms | — |
+| 5 MB | 14,368 | 859 ms | 769 ms |
+| 50 MB | 100,000 (capped) | 1.972 s | 1.707 s |
+| **500 MB** | 100,000 (capped) | **1.969 s** | 1.636 s |
+
+500 MB and 50 MB are indistinguishable. The gz-vs-plain delta (~0.27 s, ~14%) is the
+gzip inflate cost; it is measured by differencing rather than read off the profile,
+because JFR under-samples native `Inflater` work.
+
+## 3. Steady-state profile
+
+JFR `settings=profile`, 540 execution samples, 99.8% attributed to a readtools/htsjdk/
+Guava frame (requires `--stack-depth 40`; the default of 5 leaves ~45% unattributed).
+
+| share | owning frame | what it is |
+|---|---|---|
+| **28.0%** | `InsdcReadsValidator.validate` | per-read IUPAC base check |
+| 16.5% | htsjdk `FastqReader.readLineConditionallySkippingBlanks` | FASTQ line reading |
+| 15.9% | `FastqReadsValidator.validateQualityScores` | quality scoring |
+| ~22.7% | Guava `hash.*` (`munch`, `putUnencodedChars`, `BloomFilter`) | pairing Bloom filter |
+| 11.9% | `PairedFastqReadsValidator.getNonCasavaReadIndex` / `...NameWithoutIndex` | read-name regex |
+| 3.0% | `QualityEncodingDetector` | encoding sniff |
+
+The single hottest *leaf* frame was `java.util.HashMap.getNode` (136 of 540 samples),
+which is what pointed at the base check.
+
+## 4. What this branch changes
+
+**`InsdcReadsValidator`** — the per-base check was:
+
+```java
+for (char base : effectiveBases.toUpperCase().toCharArray()) {
+  if (iupacSet.contains(base)) { ... }   // iupacSet is a HashSet<Character>
+```
+
+Two allocations per read (uppercased `String`, `char[]`), then a boxed `Character`
+lookup per base. At 64 bp x 100k reads x 2 mates that is ~12.8M boxed `HashMap`
+lookups — hence `HashMap.getNode` topping the profile. Replaced with two case-folded
+`boolean[128]` tables indexed by the raw char.
+
+**`PairedFastqReadsValidator`** — the read name and pair index came from the same regex
+match but were computed by two separate methods, each running *both* patterns. So every
+read name was matched twice over. Now matched once, both groups read from the one match.
+
+### The non-ASCII case
+
+`String.toUpperCase()` folds U+017F (`ſ`, long s) to `S`, which *is* a valid IUPAC code,
+so the original accepts it. A plain lookup table rejects it — which would fail
+submissions that ENA's own webin-cli accepts, since it drives this same class. Reads
+containing any non-ASCII character therefore fall back to the original `toUpperCase()`
+path; pure-ASCII reads, i.e. all real data, take the fast path.
+
+This was caught by the `nonascii` edge case in `gen-edgecases.sh`, and it is the reason
+that script exists.
+
+## 5. Measured effect
+
+Two independent measurements, on different JDKs and different machine load. Both are
+steady-state CPU time, four distinct 100k-read pairs rotated through one JVM, pinned to
+one core.
+
+**Run A — JDK 21, machine under load from other JVMs:**
+
+| rep | v1.0.0 | this branch | |
+|---|---|---|---|
+| 1 | 0.867 s | 0.779 s | 10% *(outlier, cold page cache)* |
+| 2 | 0.869 s | 0.640 s | 26% |
+| 3 | 0.836 s | 0.629 s | 25% |
+| 4 | 0.855 s | 0.649 s | 24% |
+
+**Run B — JDK 17, otherwise-idle machine, reproduced later from a clean checkout using
+`scripts/run-benchmark.sh`:**
+
+| rep | v1.0.0 | this branch | |
+|---|---|---|---|
+| 2 | 0.927 s | 0.639 s | 31% |
+| 3 | 0.904 s | 0.624 s | 31% |
+| 4 | 0.974 s | 0.582 s | 40% |
+| 5 | 0.905 s | 0.664 s | 27% |
+| 6 | 1.055 s | 0.636 s | 40% |
+
+(rep 1 discarded in both runs — cold page cache.)
+
+**Take the range, not a single figure: ~25-31% less CPU in steady state**, median 25% in
+run A and 31% in run B. Cold-JVM CPU is ~21% lower in run A and ~28% lower in run B
+(e.g. 1.13 s -> 0.83 s).
+
+Run B is the cleaner measurement — idle machine, and produced by the scripts in this
+directory rather than by hand — but it is on a different JDK, so the two are not a
+controlled A/B of load alone. The honest summary is that the win is somewhere in the
+mid-20s to low-30s percent, and comfortably real in both.
+
+Correctness: byte-identical stdout+stderr and exit status vs the `v1.0.0` jar across all
+20 comparisons emitted by `scripts/check-equivalence.sh` — 1-read/5 MB/50 MB/500 MB,
+gzipped and plain, four distinct pairs, single-end, plus the seven edge cases (lowercase,
+mixed case, full IUPAC alphabet, two invalid-base files rejected identically with exit 1,
+non-ASCII). The repository's 227 tests pass.
+
+## 6. JVM-level options that did *not* help
+
+Tried because they are cheap, reported because the negative results save someone else
+the time. All at one core, on the real (100k-read) workload:
+
+| change | effect |
+|---|---|
+| Temurin JDK 25 instead of JDK 21 | 1.966 s vs 1.971 s — nothing |
+| `-XX:+UseCompactObjectHeaders` | 1.922 s vs 1.905 s — nothing (it is a footprint flag) |
+| Recompiling to Java 25 bytecode | 2.004 s vs 1.939 s — nothing, possibly slightly worse |
+| `-XX:TieredStopAtLevel=1` | **+51% worse** (1.88 s -> 2.85 s) |
+| AppCDS archive | ~35 ms off fixed cost only |
+
+Two notes worth keeping:
+
+- **conda-forge's `openjdk` ships no CDS archive**, so `-version` reports `mixed mode`
+  rather than `mixed mode, sharing` and AppCDS fails outright with
+  `-XX:ArchiveClassesAtExit is unsupported when base CDS archive is not loaded`. A single
+  `java -Xshare:dump` creates it and unblocks AppCDS. Worth ~30 ms — real, but small
+  next to everything above.
+- **On JDK 25, Guava triggers `WARNING: A terminally deprecated method in sun.misc.Unsafe
+  has been called` on stderr.** Anything parsing readtools' stderr to build a user-facing
+  error message should be checked before bumping the JDK.
+
+Recompiling to Java 25 bytecode also required Gradle 7.2 -> 9.1, the shadow plugin
+`com.github.johnrengelman` 7.1.2 -> `com.gradleup.shadow` 8.3.6, and moving
+`sourceCompatibility` into a `java { }` block — for no measurable gain.

benchmarks/harness/WarmConcurrent.java

@@ -0,0 +1,34 @@
+import java.io.File;
+import java.util.*;
+import java.util.concurrent.*;
+import uk.ac.ebi.ena.readtools.v2.FileFormat;
+import uk.ac.ebi.ena.readtools.v2.validator.ValidatorWrapper;
+
+/** Warm JVM + N concurrent validations: tests thread-safety and throughput. */
+public class WarmConcurrent {
+  public static void main(String[] a) throws Exception {
+    int threads = Integer.parseInt(a[0]), rounds = Integer.parseInt(a[1]);
+    List<List<File>> pairs = new ArrayList<>();
+    for (int i = 2; i + 1 < a.length; i += 2)
+      pairs.add(List.of(new File(a[i]), new File(a[i+1])));
+    ExecutorService ex = Executors.newFixedThreadPool(threads);
+    for (int r = 0; r < rounds; r++) {
+      long t0 = System.nanoTime();
+      List<Future<String>> fs = new ArrayList<>();
+      for (int t = 0; t < threads; t++) {
+        List<File> p = pairs.get(t % pairs.size());
+        fs.add(ex.submit(() -> {
+          ValidatorWrapper w = new ValidatorWrapper(p, FileFormat.FASTQ, 100_000L);
+          w.run();
+          return p.get(0).getName()+":paired="+w.isPaired();
+        }));
+      }
+      Set<String> res = new TreeSet<>();
+      for (Future<String> f : fs) res.add(f.get());
+      double s = (System.nanoTime()-t0)/1e9;
+      System.err.printf("round %d: %d concurrent in %.3f s -> %.3f s/validation  %s%n",
+          r, threads, s, s/threads, res);
+    }
+    ex.shutdown();
+  }
+}

benchmarks/harness/WarmCpu.java

@@ -0,0 +1,28 @@
+import java.io.File;
+import java.util.*;
+import java.lang.management.*;
+import uk.ac.ebi.ena.readtools.v2.FileFormat;
+import uk.ac.ebi.ena.readtools.v2.validator.ValidatorWrapper;
+
+/** Reports per-iteration CPU time (immune to other processes stealing wall-clock). */
+public class WarmCpu {
+  public static void main(String[] a) throws Exception {
+    ThreadMXBean tm = ManagementFactory.getThreadMXBean();
+    int n = Integer.parseInt(a[0]);
+    List<List<File>> pairs = new ArrayList<>();
+    for (int i = 1; i + 1 < a.length; i += 2)
+      pairs.add(List.of(new File(a[i]), new File(a[i+1])));
+    double[] cpu = new double[n], wall = new double[n];
+    for (int i = 0; i < n; i++) {
+      List<File> p = pairs.get(i % pairs.size());
+      long c0 = tm.getCurrentThreadCpuTime(), w0 = System.nanoTime();
+      new ValidatorWrapper(p, FileFormat.FASTQ, 100_000L).run();
+      cpu[i] = (tm.getCurrentThreadCpuTime()-c0)/1e9; wall[i] = (System.nanoTime()-w0)/1e9;
+    }
+    // discard first 6 (cold + JIT warmup), report min and median of the rest
+    double[] s = Arrays.copyOfRange(cpu, 6, n); Arrays.sort(s);
+    double[] sw = Arrays.copyOfRange(wall, 6, n); Arrays.sort(sw);
+    System.err.printf("cold-cpu %.3f | steady CPU min %.3f med %.3f | steady WALL min %.3f med %.3f%n",
+        cpu[0], s[0], s[s.length/2], sw[0], sw[sw.length/2]);
+  }
+}