add timing recorder for measuring BSP performance

src/main/java/me/jellysquid/mods/sodium/client/render/chunk/RenderSectionManager.java

@@ -31,6 +31,7 @@
 import me.jellysquid.mods.sodium.client.render.chunk.terrain.TerrainRenderPass;
 import me.jellysquid.mods.sodium.client.render.chunk.translucent_sorting.CameraMovement;
 import me.jellysquid.mods.sodium.client.render.chunk.translucent_sorting.TranslucentSorting;
+import me.jellysquid.mods.sodium.client.render.chunk.translucent_sorting.bsp_tree.TimingRecorder;
 import me.jellysquid.mods.sodium.client.render.chunk.translucent_sorting.data.TopoSortDynamicData;
 import me.jellysquid.mods.sodium.client.render.chunk.translucent_sorting.data.TranslucentData;
 import me.jellysquid.mods.sodium.client.render.chunk.vertex.format.ChunkMeshFormats;
@@ -115,6 +116,8 @@ public RenderSectionManager(ClientWorld world, int renderDistance, CommandList c
         for (var type : ChunkUpdateType.values()) {
             this.taskLists.put(type, new ArrayDeque<>());
         }
+
+        TimingRecorder.resetAll();
     }
 
     public void updateCameraState(Vector3dc cameraPosition, Camera camera) {

src/main/java/me/jellysquid/mods/sodium/client/render/chunk/translucent_sorting/bsp_tree/TimingRecorder.java

@@ -0,0 +1,118 @@
+package me.jellysquid.mods.sodium.client.render.chunk.translucent_sorting.bsp_tree;
+
+import java.util.ArrayList;
+
+import it.unimi.dsi.fastutil.objects.ReferenceArrayList;
+
+/**
+ * test scenario: test world, 1991 events, total 538121 quads, 32 rd, 15 chunk
+ * builder threads
+ * 
+ * at 128406c9743eab8ec90dfceeac34af6fe932af97
+ * (baseline):
+ * sort 15-23ns per quad avg, build 230-233ns per quad avg
+ * 
+ * at 2aabb0a7a6a54f139db3cc2beb83881219561678
+ * (with compression of interval points as longs):
+ * sort 15-23ns per quad avg, build 150-165ns per quad avg
+ * 
+ * at 4f1fb35495b3e5adab2bbc9823cbd6cbf2e5b438
+ * (with sorting compressed interval points as longs):
+ * sort 15-23ns per quad avg, build 130-140ns per quad avg
+ */
+public class TimingRecorder {
+    static record TimedEvent(int size, long ns) {
+    }
+
+    private static final int WARMUP_COUNT = 500;
+    private static ArrayList<TimingRecorder> recorders = new ArrayList<>();
+
+    private ReferenceArrayList<TimedEvent> events = new ReferenceArrayList<>(1000);
+    private boolean warmedUp = false;
+
+    private final String name;
+    private int remainingWarmup;
+    private boolean printEvents;
+
+    public TimingRecorder(String name, int warmupCount, boolean printEvents) {
+        this.name = name;
+        this.remainingWarmup = warmupCount;
+        this.printEvents = printEvents;
+
+        recorders.add(this);
+    }
+
+    public TimingRecorder(String name) {
+        this(name, WARMUP_COUNT, false);
+    }
+
+    public void recordNow(int size, long startNanos) {
+        this.recordDelta(size, System.nanoTime() - startNanos);
+    }
+
+    synchronized public void recordDelta(int size, long delta) {
+        if (!this.warmedUp) {
+            this.remainingWarmup--;
+            if (this.remainingWarmup == 0) {
+                System.out.println("Warmed up recorder " + this.name);
+            }
+            return;
+        }
+
+        this.events.add(new TimedEvent(size, delta));
+
+        if (this.printEvents) {
+            System.out.println("Event for " + this.name + ": " + size + " quads, " + delta + "ns " +
+                    "(" + (delta / size) + "ns per quad)");
+        }
+    }
+
+    public void print() {
+        var builder = new StringBuilder();
+        builder.append("size,ns\n");
+
+        long totalTime = 0;
+        long minTime = Long.MAX_VALUE;
+        long maxTime = 0;
+        long totalSize = 0;
+
+        for (var event : this.events) {
+            builder.append(event.size).append(",").append(event.ns).append(";");
+            totalTime += event.ns;
+            minTime = Math.min(minTime, event.ns);
+            maxTime = Math.max(maxTime, event.ns);
+            totalSize += event.size;
+        }
+
+        int eventCount = this.events.size();
+        System.out.println("Timings for " + this.name + ":");
+        System.out.println("min " + minTime +
+                "ns, max " + maxTime +
+                "ns, avg " + (totalTime / eventCount) +
+                "ns. Total size " + totalSize +
+                ", avg size " + (totalSize / eventCount) +
+                ". Avg time per quad " + (totalTime / totalSize) +
+                "ns. Avg quads per event " + (totalSize / eventCount) +
+                ". " + eventCount + " events.");
+        // System.out.println(builder.toString());
+    }
+
+    private void resetAfterWarmup() {
+        if (this.remainingWarmup <= 0) {
+            if (!this.events.isEmpty()) {
+                this.print();
+            }
+
+            this.warmedUp = true;
+            System.out.println("Started recorder " + this.name);
+        }
+
+        this.events.clear();
+    }
+
+    public static void resetAll() {
+        for (var recorder : recorders) {
+            recorder.resetAfterWarmup();
+        }
+    }
+}

src/main/java/me/jellysquid/mods/sodium/client/render/chunk/translucent_sorting/data/BSPDynamicData.java

@@ -7,6 +7,7 @@
 import me.jellysquid.mods.sodium.client.render.chunk.translucent_sorting.TQuad;
 import me.jellysquid.mods.sodium.client.render.chunk.translucent_sorting.bsp_tree.BSPNode;
 import me.jellysquid.mods.sodium.client.render.chunk.translucent_sorting.bsp_tree.BSPResult;
+import me.jellysquid.mods.sodium.client.render.chunk.translucent_sorting.bsp_tree.TimingRecorder;
 import me.jellysquid.mods.sodium.client.util.NativeBuffer;
 import net.minecraft.util.math.ChunkSectionPos;
 
@@ -25,9 +26,17 @@ private BSPDynamicData(ChunkSectionPos sectionPos,
 
     @Override
     public void sortOnTrigger(Vector3fc cameraPos) {
+        var start = System.nanoTime();
         this.sort(cameraPos);
+        sortTriggerRecorder.recordNow(this.getLength(), start);
     }
 
+    // /tp ~ ~-100 ~
+    public static final TimingRecorder sortInitialRecorder = new TimingRecorder("BSP sort initial");
+    public static final TimingRecorder sortTriggerRecorder = new TimingRecorder("BSP sort trigger");
+    public static final TimingRecorder buildRecorder = new TimingRecorder("BSP build");
+    public static final TimingRecorder partialUpdateRecorder = new TimingRecorder("BSP partial update", 10, true);
+
     private void sort(Vector3fc cameraPos) {
         this.unsetReuseUploadedData();
 
@@ -48,13 +57,23 @@ public static BSPDynamicData fromMesh(BuiltSectionMeshParts translucentMesh,
             // (times the section has been built)
             prepareNodeReuse = generation >= NODE_REUSE_MIN_GENERATION;
         }
+
+        var start = System.nanoTime();
         var result = BSPNode.buildBSP(quads, sectionPos, oldRoot, prepareNodeReuse);
+        if (oldRoot == null) {
+            buildRecorder.recordNow(quads.length, start);
+        } else {
+            partialUpdateRecorder.recordNow(quads.length, start);
+        }
 
         VertexRange range = TranslucentData.getUnassignedVertexRange(translucentMesh);
         buffer = PresentTranslucentData.nativeBufferForQuads(buffer, quads);
 
         var dynamicData = new BSPDynamicData(sectionPos, buffer, range, result, generation);
+
+        start = System.nanoTime();
         dynamicData.sort(cameraPos);
+        sortInitialRecorder.recordNow(quads.length, start);
 
         // prepare accumulation groups for integration into GFNI triggering
         // TODO: combine this and the similar code in TopoSortDynamicData