Add baseline benchmark for history write path (pre Phase 1 concurrency fixes)

build.gradle.kts

@@ -18,11 +18,28 @@ var revision: String by extra("")
 var buildNumber by extra("")
 var date: String by extra("")
 ext {
-    val git: Grgit = Grgit.open {
-        dir = File("$rootDir/.git")
+    // In a `git worktree` checkout (used e.g. by parallel agent sandboxes), `.git` is a pointer
+    // file rather than the git directory itself, and JGit (used by Grgit) does not resolve the
+    // worktree's `commondir` indirection the way native git does, so Grgit.open() throws even
+    // though `git` commands work fine in the same directory. Fall back to placeholder date/
+    // revision values in that case (these are informational only, used in fawe.properties/
+    // version string) - but only in the detected-worktree case, so a genuinely broken .git in a
+    // normal checkout still fails the build loudly instead of silently shipping "no.git.id".
+    val isWorktreeCheckout = File("$rootDir/.git").isFile
+    try {
+        val git: Grgit = Grgit.open {
+            dir = File("$rootDir/.git")
+        }
+        date = git.head().dateTime.format(DateTimeFormatter.ofPattern("yy.MM.dd"))
+        revision = "-${git.head().abbreviatedId}"
+    } catch (e: Exception) {
+        if (!isWorktreeCheckout) {
+            throw e
+        }
+        logger.warn("Error opening git repository for date/revision (worktree checkout); using placeholders", e)
+        date = DateTimeFormatter.ofPattern("yy.MM.dd").format(java.time.LocalDate.now())
+        revision = "-no.git.id"
     }
-    date = git.head().dateTime.format(DateTimeFormatter.ofPattern("yy.MM.dd"))
-    revision = "-${git.head().abbreviatedId}"
     buildNumber = if (project.hasProperty("buildnumber")) {
         snapshot + "-" + project.properties["buildnumber"] as String
     } else {

worldedit-core/build.gradle.kts

@@ -62,6 +62,22 @@ dependencies {
     // Tests
     testRuntimeOnly(libs.log4j.core)
     testImplementation(libs.parallelgzip)
+    // lz4-java is compileOnly for main (provided by the platform module at runtime); the
+    // history write-path benchmark needs it available on the test runtime classpath since it
+    // exercises MainUtil's compression stream directly. See HistoryWriteBenchmark. Runtime-only
+    // since no test source references lz4 types at compile time.
+    testRuntimeOnly(libs.lz4Java) { isTransitive = false }
+}
+
+tasks.register<JavaExec>("historyBenchmark") {
+    group = "benchmark"
+    description = "Runs the hand-rolled com.fastasyncworldedit.core.history write-path baseline benchmark."
+    dependsOn(tasks.named("testClasses"))
+    classpath = sourceSets["test"].runtimeClasspath
+    mainClass.set("com.fastasyncworldedit.core.history.HistoryWriteBenchmark")
+    // The benchmark is disk/CPU bound and prints its own report; stream output live.
+    standardOutput = System.out
+    errorOutput = System.err
 }
 
 tasks.test {

worldedit-core/src/test/java/com/fastasyncworldedit/core/history/HistoryWriteBenchmark.java

@@ -0,0 +1,281 @@
+package com.fastasyncworldedit.core.history;
+
+import com.fastasyncworldedit.core.history.changeset.FaweStreamChangeSet;
+import com.sk89q.worldedit.util.io.file.SafeFiles;
+import com.sk89q.worldedit.world.NullWorld;
+import com.sk89q.worldedit.world.World;
+
+import java.io.File;
+import java.io.IOException;
+import java.nio.file.Files;
+import java.nio.file.Path;
+import java.util.ArrayList;
+import java.util.List;
+import java.util.UUID;
+import java.util.concurrent.CountDownLatch;
+import java.util.concurrent.ExecutionException;
+import java.util.concurrent.ExecutorService;
+import java.util.concurrent.Executors;
+import java.util.concurrent.Future;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+
+/**
+ * Hand-rolled micro-benchmark for the {@code com.fastasyncworldedit.core.history} write hot path
+ * ({@link DiskStorageHistory} and {@link MemoryOptimizedHistory}).
+ *
+ * <p>This is intentionally NOT a JMH benchmark. Wiring the {@code me.champeau.jmh} plugin into this
+ * repository's Gradle 9 multi-module build (custom ANTLR source generation, annotation processors,
+ * platform sub-modules) was judged likely to eat more time than the number itself was worth, so a
+ * plain warmup + measured-loop benchmark using {@link System#nanoTime()} was used instead, per the
+ * task's documented fallback. The goal is a repeatable, comparable number across a "before" and
+ * "after" run of the Phase 1 concurrency fixes, not a polished benchmarking harness.</p>
+ *
+ * <p>Covers, per the write hot path that Phase 1 touches:</p>
+ * <ul>
+ *     <li>single-threaded {@code add(x, y, z, from, to)} throughput for both change set types</li>
+ *     <li>a contended variant with multiple threads calling {@code add(...)} concurrently on the
+ *     <em>same</em> instance, which exercises the lazy stream-init ({@code getBlockOS}) and the
+ *     non-atomic {@code blockSize++} counter -- exactly the paths Phase 1's fixes touch</li>
+ * </ul>
+ *
+ * <p>Run via the {@code historyBenchmark} Gradle task added in {@code worldedit-core/build.gradle.kts}:</p>
+ * <pre>{@code ./gradlew :worldedit-core:historyBenchmark}</pre>
+ */
+public final class HistoryWriteBenchmark {
+
+    private static final int WARMUP_OPS = 500_000;
+    private static final int MEASURED_OPS = 5_000_000;
+    private static final int TRIALS = 5;
+    private static final int THREADS = Math.max(2, Math.min(8, Runtime.getRuntime().availableProcessors()));
+
+    private HistoryWriteBenchmark() {
+    }
+
+    public static void main(String[] args) throws Exception {
+        System.out.println("=== FAWE history write-path baseline benchmark ===");
+        // Contended trials split MEASURED_OPS across THREADS with integer division, so the actual
+        // op count they run can be slightly less than MEASURED_OPS when THREADS doesn't divide it
+        // evenly - report() itself always uses the real per-trial count for throughput, but print
+        // the two separately here so this header doesn't overclaim a single measuredOps for every
+        // benchmark variant.
+        int contendedMeasuredOps = (MEASURED_OPS / THREADS) * THREADS;
+        System.out.printf(
+                "warmupOps=%d measuredOps=%d (contended runs: %d actual, %d threads) trials=%d%n%n",
+                WARMUP_OPS, MEASURED_OPS, contendedMeasuredOps, THREADS, TRIALS
+        );
+
+        runSingleThreaded("DiskStorageHistory (single-thread)", HistoryWriteBenchmark::newDiskStorageHistory);
+        runSingleThreaded("MemoryOptimizedHistory (single-thread)", HistoryWriteBenchmark::newMemoryOptimizedHistory);
+        runContended("DiskStorageHistory (contended, " + THREADS + " threads)", HistoryWriteBenchmark::newDiskStorageHistory);
+        runContended(
+                "MemoryOptimizedHistory (contended, " + THREADS + " threads)",
+                HistoryWriteBenchmark::newMemoryOptimizedHistory
+        );
+
+        System.out.println("=== done ===");
+    }
+
+    private interface HistoryFactory {
+
+        FaweStreamChangeSet create() throws IOException;
+
+    }
+
+    /**
+     * {@link NullWorld} whose {@code getMinY()}/{@code getMaxY()} do not reach into
+     * {@code WorldEdit.getInstance()} (which would require a fully bootstrapped platform). Every
+     * other call used by the write hot path is already a no-op / dummy in {@link NullWorld}.
+     */
+    private static final class BenchWorld extends NullWorld {
+
+        @Override
+        public int getMinY() {
+            return -64;
+        }
+
+        @Override
+        public int getMaxY() {
+            return 319;
+        }
+
+    }
+
+    private static World world() {
+        return new BenchWorld();
+    }
+
+    private static FaweStreamChangeSet newDiskStorageHistory() throws IOException {
+        Path dir = Files.createTempDirectory("fawe-history-bench-");
+        return new DiskStorageHistory(dir.toFile(), world(), UUID.randomUUID(), 0);
+    }
+
+    private static FaweStreamChangeSet newMemoryOptimizedHistory() {
+        return new MemoryOptimizedHistory(world());
+    }
+
+    private static void doAdd(FaweStreamChangeSet changeSet, int i) {
+        // Bitmasks rather than i % 256 / i % 384: 384 is not a power of two, so that modulo
+        // compiles to an actual integer division, which would otherwise inflate the measured
+        // per-op cost with work that has nothing to do with add() itself. y needs the 384-value
+        // range of BenchWorld's height (-64..319), so fold the 9-bit 0..511 mask down to 0..383
+        // with a single conditional subtract (still no division), then offset by minY.
+        int x = i & 0xFF;
+        int rawY = (i >>> 8) & 0x1FF;
+        int y = (rawY >= 384 ? rawY - 384 : rawY) - 64;
+        int z = (i >>> 17) & 0xFF;
+        changeSet.add(x, y, z, 1, 2);
+    }
+
+    private static void closeAndCleanup(FaweStreamChangeSet changeSet) {
+        try {
+            changeSet.close();
+        } catch (Exception e) {
+            // The contended benchmark deliberately hammers the pre-fix DCL race in getBlockOS(),
+            // which can leave the underlying (non-thread-safe) compression stream corrupted.
+            // close()/flush() can then throw unchecked exceptions (e.g. AIOOBE from LZ4). That is
+            // itself a data point (see the error count printed by report()), not a benchmark bug -
+            // swallow it here so remaining trials still run. Only Exception, not Throwable: a
+            // real Error (OutOfMemoryError, StackOverflowError) must still propagate and stop the
+            // run rather than being treated as expected race noise.
+            System.err.println("  (close() threw " + e + ")");
+        }
+        if (changeSet instanceof DiskStorageHistory dsh) {
+            File dir = dsh.getBDFile().getParentFile();
+            try {
+                SafeFiles.tryHardToDeleteDir(dir.toPath());
+            } catch (IOException e) {
+                // Not fatal to the benchmark, but silently ignoring this let failed cleanups
+                // accumulate unnoticed across repeated runs (this benchmark can create sizeable
+                // on-disk histories). At least report it so it's diagnosable.
+                System.err.println("  (failed to clean up " + dir + ": " + e + ")");
+            }
+        }
+    }
+
+    private static void runSingleThreaded(String label, HistoryFactory factory) throws Exception {
+        long[] elapsedNanos = new long[TRIALS];
+        for (int trial = 0; trial < TRIALS; trial++) {
+            FaweStreamChangeSet changeSet = factory.create();
+            int i = 0;
+            for (; i < WARMUP_OPS; i++) {
+                doAdd(changeSet, i);
+            }
+            long start = System.nanoTime();
+            for (int j = 0; j < MEASURED_OPS; j++, i++) {
+                doAdd(changeSet, i);
+            }
+            elapsedNanos[trial] = System.nanoTime() - start;
+            closeAndCleanup(changeSet);
+        }
+        report(label, elapsedNanos, MEASURED_OPS, 0);
+    }
+
+    private static void runContended(String label, HistoryFactory factory) throws Exception {
+        int opsPerThread = MEASURED_OPS / THREADS;
+        long[] elapsedNanos = new long[TRIALS];
+        long totalErrors = 0;
+        for (int trial = 0; trial < TRIALS; trial++) {
+            // Warm up JIT/class-loading on a throwaway instance rather than the measured one: the
+            // measured instance must still start with uninitialized lazy streams so this trial
+            // keeps exercising the lazy stream-init race under contention, which is the entire
+            // point of the contended variant.
+            FaweStreamChangeSet warmupChangeSet = factory.create();
+            for (int i = 0; i < WARMUP_OPS; i++) {
+                doAdd(warmupChangeSet, i);
+            }
+            closeAndCleanup(warmupChangeSet);
+
+            FaweStreamChangeSet changeSet = factory.create();
+            ExecutorService pool = Executors.newFixedThreadPool(THREADS);
+            CountDownLatch ready = new CountDownLatch(THREADS);
+            CountDownLatch go = new CountDownLatch(1);
+            AtomicLong errorCount = new AtomicLong();
+            // submit() discards its Future by default, and a FutureTask captures any Throwable
+            // (Exception or Error) rather than propagating it to the calling thread - so an
+            // Error escaping the loop below would previously vanish silently instead of actually
+            // propagating, contradicting the comment inside the loop. Keep the futures and check
+            // them after the pool finishes so a real Error is still surfaced.
+            List<Future<?>> futures = new ArrayList<>(THREADS);
+            for (int t = 0; t < THREADS; t++) {
+                final int base = t * opsPerThread;
+                futures.add(pool.submit(() -> {
+                    ready.countDown();
+                    try {
+                        go.await();
+                    } catch (InterruptedException e) {
+                        Thread.currentThread().interrupt();
+                        return;
+                    }
+                    for (int j = 0; j < opsPerThread; j++) {
+                        try {
+                            doAdd(changeSet, base + j);
+                        } catch (Exception t2) {
+                            // Only Exception: a real Error must propagate rather than being
+                            // counted as expected race noise (see closeAndCleanup above).
+                            errorCount.incrementAndGet();
+                        }
+                    }
+                }));
+            }
+            if (!ready.await(1, TimeUnit.MINUTES)) {
+                pool.shutdownNow();
+                throw new IllegalStateException("Benchmark worker threads did not all start in time");
+            }
+            long start = System.nanoTime();
+            go.countDown();
+            pool.shutdown();
+            if (!pool.awaitTermination(5, TimeUnit.MINUTES)) {
+                pool.shutdownNow();
+                throw new IllegalStateException("Benchmark threads did not finish in time");
+            }
+            for (Future<?> future : futures) {
+                try {
+                    future.get();
+                } catch (ExecutionException e) {
+                    throw new IllegalStateException("Benchmark worker thread failed", e.getCause());
+                }
+            }
+            elapsedNanos[trial] = System.nanoTime() - start;
+            totalErrors += errorCount.get();
+            closeAndCleanup(changeSet);
+        }
+        report(label, elapsedNanos, (long) opsPerThread * THREADS, totalErrors);
+    }
+
+    private static void report(String label, long[] elapsedNanos, long opsPerTrial, long totalErrors) {
+        System.out.println(label + ":");
+        long totalElapsedNanos = 0;
+        for (int trial = 0; trial < elapsedNanos.length; trial++) {
+            double seconds = elapsedNanos[trial] / 1_000_000_000.0;
+            double opsPerSec = opsPerTrial / seconds;
+            double nsPerOp = (double) elapsedNanos[trial] / opsPerTrial;
+            totalElapsedNanos += elapsedNanos[trial];
+            System.out.printf(
+                    "  trial %d: %.2f ms, %,.0f ops/sec, %.1f ns/op%n",
+                    trial + 1, elapsedNanos[trial] / 1_000_000.0, opsPerSec, nsPerOp
+            );
+        }
+        // Aggregate throughput (total ops / total time) rather than the mean of the per-trial
+        // rates, so a single slow/fast trial (GC pause, OS scheduling) is weighted by how long it
+        // actually ran instead of counting equally with the others.
+        long totalOps = opsPerTrial * elapsedNanos.length;
+        double avgOpsPerSec = totalOps / (totalElapsedNanos / 1_000_000_000.0);
+        System.out.printf("  average: %,.0f ops/sec (%.1f ns/op)", avgOpsPerSec, 1_000_000_000.0 / avgOpsPerSec);
+        if (totalErrors > 0) {
+            // This only counts exceptions that escape FaweStreamChangeSet#add(...) into this
+            // benchmark's own catch block. add() itself catches IOException internally and
+            // prints a stack trace rather than throwing, so IO-related failures from the race
+            // aren't reflected here - this is a lower bound on "ops threw", not a full count.
+            System.out.printf(
+                    " -- %d/%d ops threw past add() (unsynchronized shared stream access; add() itself "
+                            + "swallows some IOExceptions, so this undercounts total failures)%n",
+                    totalErrors, totalOps
+            );
+        } else {
+            System.out.println();
+        }
+        System.out.println();
+    }
+
+}