gex-gl: per-opcode host timing (Gl::time_ops) and a native trace replay example

`cargo run --release -p gex-gl --example replay -- TRACE [FRAMES]` replays
a recorded guest GL stream on the native host (the device natively run
games use) and prints the CPU time a frame in Gl::run and the commands by
host time over the last FRAMES frames. Hollow Knight's menu on edger's
NVIDIA: 0.84 and 1.03 ms a frame (docs/gl-path.md).

Co-Authored-By: Claude Opus 5.5 (1M context) <[email protected]>
Claude-Session: https://claude.ai/code/session_d2453757b8a84fdbb4ee7c9e093141df

crates/gex-gl/examples/replay.rs

@@ -0,0 +1,79 @@
+//! Replay a recorded guest GL stream (`crates/gex-gl/src/trace.rs`) on the
+//! native host (gex-gl's `Gl`, the device natively run games use), timing it:
+//!
+//!   cargo run --release -p gex-gl --example replay -- TRACE [FRAMES]
+//!
+//! Prints, over the last FRAMES frames (a batch with PRESENT ends a frame):
+//! wall ms per frame inside `Gl::run`, batches per frame, and the commands
+//! by host time.
+use gex_gl::host::Gl;
+use gex_gl::proto::{op, Commands};
+use gex_gl::trace;
+use std::time::Instant;
+
+fn main() {
+    let args: Vec<String> = std::env::args().collect();
+    let path = &args[1];
+    let frames: usize = args.get(2).and_then(|v| v.parse().ok()).unwrap_or(300);
+    let bytes = std::fs::read(path).expect("trace");
+    let t = trace::parse(&bytes).expect("a trace");
+    let mut gl = Gl::new(t.info.width.max(1) as i32, t.info.height.max(1) as i32).expect("host GL");
+    let presents: Vec<bool> = t
+        .batches
+        .iter()
+        .map(|b| {
+            let mut c = Commands::new(&b.bytes);
+            let mut present = false;
+            while let Some(Ok((o, _))) = c.next() {
+                present |= o == op::PRESENT;
+            }
+            present
+        })
+        .collect();
+    let total = presents.iter().filter(|p| **p).count();
+    let start_frame = total.saturating_sub(frames);
+    let (mut frame, mut ms, mut nb, mut measuring) = (0usize, 0f64, 0usize, false);
+    let mut per = Vec::new();
+    let mut fms = 0f64;
+    let t_all = Instant::now();
+    for (i, b) in t.batches.iter().enumerate() {
+        if !measuring && frame >= start_frame {
+            measuring = true;
+            gl.time_ops(true);
+        }
+        let t0 = Instant::now();
+        let (_, status, _) = gl.run(&b.bytes);
+        let e = t0.elapsed().as_secs_f64() * 1e3;
+        if status != 0 {
+            eprintln!("batch {i}: status {status}");
+        }
+        if measuring {
+            ms += e;
+            fms += e;
+            nb += 1;
+        }
+        if presents[i] {
+            if measuring {
+                per.push(fms);
+            }
+            fms = 0.0;
+            frame += 1;
+        }
+    }
+    let n = per.len().max(1);
+    per.sort_by(|a, b| a.partial_cmp(b).unwrap());
+    println!(
+        "{total} frames ({:.1} s to replay all); last {n}: {:.3} ms a frame in Gl::run (median {:.3}, p90 {:.3}), {:.2} batches a frame",
+        t_all.elapsed().as_secs_f64(),
+        ms / n as f64,
+        per[n / 2],
+        per[n * 9 / 10],
+        nb as f64 / n as f64
+    );
+    let ops = gl.take_op_times();
+    let sum: u64 = ops.iter().map(|o| o.2).sum();
+    println!("commands: {:.3} ms a frame in all", sum as f64 / 1e6 / n as f64);
+    for (o, c, ns) in ops.iter().take(30) {
+        println!("  op {o:5} {:8.1}/frame {:8.3} ms/frame", *c as f64 / n as f64, *ns as f64 / 1e6 / n as f64);
+    }
+}

crates/gex-gl/src/host.rs

@@ -465,6 +465,9 @@ pub struct Gl {
     /// `op::CLIENT_ARRAY`'s bytes by slot: GL keeps the pointer, so they
     /// stay until the slot's next one.
     client_arrays: std::collections::HashMap<u32, Vec<u8>>,
+    /// Per opcode: commands run and nanoseconds in them, when asked for
+    /// ([`Gl::time_ops`]; the replay tool's profile).
+    op_times: Option<std::collections::HashMap<u32, (u64, u64)>>,
 }
 
 /// `GEX_GL_READBACK_EVERY=N`: read back (and hand on) only every Nth
@@ -665,6 +668,7 @@ impl Gl {
                 frame: None,
                 presents: 0,
                 client_arrays: std::collections::HashMap::new(),
+                op_times: None,
             })
         }
     }
@@ -819,6 +823,19 @@ impl Gl {
         Ok(())
     }
 
+    /// Time every command by opcode from now on ([`Gl::take_op_times`]).
+    pub fn time_ops(&mut self, on: bool) {
+        self.op_times = on.then(std::collections::HashMap::new);
+    }
+
+    /// Commands and nanoseconds by opcode since the last call.
+    pub fn take_op_times(&mut self) -> Vec<(u32, u64, u64)> {
+        let Some(m) = self.op_times.as_mut() else { return Vec::new() };
+        let mut v: Vec<_> = m.drain().map(|(k, (c, n))| (k, c, n)).collect();
+        v.sort_by(|a, b| b.2.cmp(&a.2));
+        v
+    }
+
     /// Whether the context is a desktop one (fixed function available).
     pub fn is_desktop(&self) -> bool {
         self.compat.is_some()
@@ -893,7 +910,14 @@ impl Gl {
                 None => return (reply, error::NONE, index),
                 Some(Err(())) => return (reply, error::TRUNCATED, index),
                 Some(Ok((opcode, body))) => {
-                    if !self.one(opcode, body, &mut reply) {
+                    let t = self.op_times.is_some().then(std::time::Instant::now);
+                    let ok = self.one(opcode, body, &mut reply);
+                    if let (Some(t), Some(m)) = (t, self.op_times.as_mut()) {
+                        let e = m.entry(opcode).or_insert((0, 0));
+                        e.0 += 1;
+                        e.1 += t.elapsed().as_nanos() as u64;
+                    }
+                    if !ok {
                         return (reply, error::BAD_OPCODE, index);
                     }
                     gl_error_check(opcode);