diff --git a/benchmarks/README.md b/benchmarks/README.md new file mode 100644 index 0000000..bcf3fab --- /dev/null +++ b/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 --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. diff --git a/benchmarks/RESULTS.md b/benchmarks/RESULTS.md new file mode 100644 index 0000000..f04f1cc --- /dev/null +++ b/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 +``` + +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. diff --git a/benchmarks/harness/WarmConcurrent.java b/benchmarks/harness/WarmConcurrent.java new file mode 100644 index 0000000..9e55467 --- /dev/null +++ b/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> 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> fs = new ArrayList<>(); + for (int t = 0; t < threads; t++) { + List 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 res = new TreeSet<>(); + for (Future 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(); + } +} diff --git a/benchmarks/harness/WarmCpu.java b/benchmarks/harness/WarmCpu.java new file mode 100644 index 0000000..ce6563d --- /dev/null +++ b/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> 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 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]); + } +} diff --git a/benchmarks/harness/WarmLoop.java b/benchmarks/harness/WarmLoop.java new file mode 100644 index 0000000..b1dece7 --- /dev/null +++ b/benchmarks/harness/WarmLoop.java @@ -0,0 +1,24 @@ +import java.io.File; +import java.util.List; +import java.util.ArrayList; +import java.lang.management.ManagementFactory; +import uk.ac.ebi.ena.readtools.v2.FileFormat; +import uk.ac.ebi.ena.readtools.v2.validator.ValidatorWrapper; + +public class WarmLoop { + public static void main(String[] args) throws Exception { + // JVM uptime at entry to main = boot cost (VM init + classload of main) + double bootMs = ManagementFactory.getRuntimeMXBean().getUptime(); + System.err.printf("jvm-boot-to-main: %.3f s%n", bootMs / 1000.0); + int n = Integer.parseInt(args[0]); + List files = new ArrayList<>(); + for (int i = 1; i < args.length; i++) files.add(new File(args[i])); + for (int i = 0; i < n; i++) { + long t0 = System.nanoTime(); + new ValidatorWrapper(files, FileFormat.FASTQ, 100_000L).run(); + long t1 = System.nanoTime(); + System.err.printf("iter %2d: %.3f s (jvm uptime at end %.3f s)%n", + i, (t1 - t0) / 1e9, ManagementFactory.getRuntimeMXBean().getUptime() / 1000.0); + } + } +} diff --git a/benchmarks/harness/WarmVaried.java b/benchmarks/harness/WarmVaried.java new file mode 100644 index 0000000..47064e1 --- /dev/null +++ b/benchmarks/harness/WarmVaried.java @@ -0,0 +1,24 @@ +import java.io.File; +import java.util.*; +import java.lang.management.ManagementFactory; +import uk.ac.ebi.ena.readtools.v2.FileFormat; +import uk.ac.ebi.ena.readtools.v2.validator.ValidatorWrapper; + +/** Cycles through DISTINCT file pairs so warm-up isn't flattered by re-reading one file. */ +public class WarmVaried { + public static void main(String[] a) throws Exception { + System.err.printf("jvm-boot-to-main: %.3f s%n", + ManagementFactory.getRuntimeMXBean().getUptime()/1000.0); + int n = Integer.parseInt(a[0]); + List> 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]))); + for (int i = 0; i < n; i++) { + List p = pairs.get(i % pairs.size()); + long t0 = System.nanoTime(); + new ValidatorWrapper(p, FileFormat.FASTQ, 100_000L).run(); + System.err.printf("iter %2d [%s]: %.3f s%n", i, p.get(0).getName(), + (System.nanoTime()-t0)/1e9); + } + } +} diff --git a/benchmarks/scripts/check-equivalence.sh b/benchmarks/scripts/check-equivalence.sh new file mode 100755 index 0000000..a70bb9d --- /dev/null +++ b/benchmarks/scripts/check-equivalence.sh @@ -0,0 +1,45 @@ +#!/bin/bash +# Assert a candidate jar produces byte-identical CLI output to a reference jar. +# +# Usage: scripts/check-equivalence.sh [edgedir] +# +# Compares combined stdout+stderr AND exit status, so the rejection path is covered +# as well as the happy path. Exits non-zero on any difference. +set -uo pipefail +REF=$1; CAND=$2; DATA=$3; EDGE=${4:-} +JAVA=${JAVA:-java} +fail=0 + +cmp_pair() { # cmp_pair