Bench: edits timed at the drawn tile; per-cycle document counts; posted chords

crates/ely-lok/src/view.rs

@@ -471,15 +471,11 @@ impl LokView {
                     log::warn!("lok: a tile came back the wrong size");
                     return;
                 };
-                let entry = TileEntry {
-                    image: Arc::new(RenderImage::new([Frame::new(image)])),
-                    stale: false,
-                };
-                log::debug!("lok: tile {key:?} shown");
-                if let Some(old) = self.tiles.insert(key, entry) {
+                let image = Arc::new(RenderImage::new([Frame::new(image)]));
+                self.clock.painted(tile.generation, Arc::as_ptr(&image) as usize);
+                if let Some(old) = self.tiles.insert(key, TileEntry { image, stale: false }) {
                     self.retired.push(old.image);
                 }
-                self.clock.painted(tile.generation);
                 cx.notify();
             }
             Ok(_) => cx.notify(),

crates/ely-lok/src/view/clock.rs

@@ -7,6 +7,8 @@ type Edit = (Instant, Option<u64>, Option<u64>);
 #[derive(Default)]
 pub(super) struct EditClock {
     edit: Option<Edit>,
+    /// The tile that shows the edit, until it is drawn.
+    awaited: Option<usize>,
     /// The last generation bump: its revision and generation.
     bumped: (u64, u64),
 }
@@ -42,16 +44,30 @@ impl EditClock {
         }
     }
 
-    /// A tile of `generation` came; logs the edit it shows.
-    pub(super) fn painted(&mut self, generation: u64) {
-        if let Some((at, _, Some(shown))) = self.edit
+    /// A tile of `generation` came as `tile`; it awaits drawing.
+    pub(super) fn painted(&mut self, generation: u64, tile: usize) {
+        if let Some((_, _, Some(shown))) = self.edit
             && generation >= shown
         {
-            log::debug!("lok: edit to tile {} ms", at.elapsed().as_millis());
-            self.edit = None;
+            self.awaited = Some(tile);
         }
     }
 
+    /// `tile` reached the window; the edit it shows is timed.
+    pub(super) fn drawn(&mut self, tile: usize) {
+        if self.awaited == Some(tile)
+            && let Some((at, ..)) = self.edit.take()
+        {
+            log::debug!("lok: edit to tile {} ms", at.elapsed().as_millis());
+            self.awaited = None;
+        }
+    }
+
+    /// Whether a drawn `tile` would end the timing.
+    pub(super) fn awaits(&self, tile: usize) -> bool {
+        self.awaited == Some(tile)
+    }
+
     #[cfg(test)]
     fn running(&self) -> bool {
         self.edit.is_some()
@@ -68,9 +84,12 @@ mod tests {
         clock.sent();
         clock.bumped(7, 3);
         clock.landed(Some(7));
-        clock.painted(2);
+        clock.painted(2, 20);
+        clock.drawn(20);
         assert!(clock.running(), "an older picture leaves it running");
-        clock.painted(3);
+        clock.painted(3, 30);
+        assert!(clock.running(), "arriving is not yet drawn");
+        clock.drawn(30);
         assert!(!clock.running(), "the edit's own picture ends it");
     }
 
@@ -80,10 +99,12 @@ mod tests {
         clock.sent();
         clock.bumped(6, 3);
         clock.landed(Some(7));
-        clock.painted(3);
+        clock.painted(3, 30);
+        clock.drawn(30);
         assert!(clock.running(), "a batch before the edit shows the old text");
         clock.bumped(7, 4);
-        clock.painted(4);
+        clock.painted(4, 40);
+        clock.drawn(40);
         assert!(!clock.running());
     }
 
@@ -94,4 +115,16 @@ mod tests {
         clock.landed(None);
         assert!(!clock.running());
     }
+
+    #[test]
+    fn a_tile_that_never_draws_keeps_the_edit_open() {
+        let mut clock = EditClock::default();
+        clock.sent();
+        clock.bumped(5, 2);
+        clock.landed(Some(5));
+        clock.painted(2, 50);
+        assert!(clock.awaits(50));
+        clock.drawn(51);
+        assert!(clock.running(), "another tile's drawing does not count");
+    }
 }

crates/ely-lok/src/view/render.rs

@@ -110,7 +110,13 @@ impl Render for LokView {
                                             )
                                         });
                                         match painted {
-                                            Ok(()) => drawn = true,
+                                            Ok(()) => {
+                                                drawn = true;
+                                                let tile = Arc::as_ptr(image) as usize;
+                                                if this.read(app).clock.awaits(tile) {
+                                                    this.update(app, |view, _| view.clock.drawn(tile));
+                                                }
+                                            }
                                             Err(error) => log::error!("lok: tile paint failed: {error}"),
                                         }
                                     }

tests/perf/bench.py

@@ -29,7 +29,7 @@ def sh(*args, **kw):
 
 
 def tools(folder):
-    for tool in ["ax-values", "ax-press", "click"]:
+    for tool in ["ax-values", "ax-press", "click", "chord"]:
         sh("swiftc", "-O", "-o", os.path.join(folder, tool), os.path.join(ROOT, "tests", "scripts", tool + ".swift"))
 
 
@@ -98,9 +98,6 @@ class App:
     def memory_mb(self):
         return self.family()[1] / 1024
 
-    def files(self):
-        return sum(self.handles().values())
-
     def handles(self):
         """Open handles of the app and its children, as type and name."""
         ours, _ = self.family()
@@ -207,6 +204,9 @@ def perf02(work, runs):
         lines = app.lines()
     finally:
         app.stop()
+    failed = [line for line in lines if re.search(PAINT_FAILED, line)]
+    if failed:
+        raise RuntimeError(f"ely-doc: a tile failed to draw while typing: {failed[0]}")
     ticks = [int(m.group(1)) for line in lines if (m := re.search(tick, line))]
     if len(ticks) != runs:
         raise RuntimeError(f"ely-doc: {runs} keys gave {len(ticks)} timings")
@@ -269,8 +269,8 @@ def perf08(work, cycles=40):
     """New and close a document; memory, handles and live documents."""
     app = App("ely-doc", os.path.join(work, "home-cycles"))
 
-    def open_docs():
-        return documents_open(app.lines())
+    def open_docs(since=0):
+        return documents_open(app.lines()[since:])
 
     try:
         app.wait("opened Untitled")
@@ -280,19 +280,24 @@ def perf08(work, cycles=40):
         baseline = (app.memory_mb(), sum(before.values()), open_docs())
         seen, extra = [], None
         for n in range(cycles):
-            keys('keystroke "n" using command down')
+            cursor = len(app.lines())
+            sh(os.path.join(work, "chord"), str(app.process.pid), "45")
             for _ in range(40):
                 if "title=Use template" in app.ax():
                     break
                 time.sleep(0.25)
             sh(os.path.join(work, "ax-press"), str(app.process.pid), "Use template", "AXButton")
             app.wait(f"opened Untitled {n + 2} ", timeout=30)
+            # This cycle's own report, not an earlier one.
+            if open_docs(cursor) != baseline[2] + 1:
+                raise RuntimeError(f"ely-doc: cycle {n + 1} opened, yet {open_docs(cursor)} documents")
+            cursor = len(app.lines())
             time.sleep(1)
             # A keystroke can miss a window still taking focus.
             for _ in range(3):
                 app.front()
                 raise_main(app)
-                keys('keystroke "w" using command down')
+                sh(os.path.join(work, "chord"), str(app.process.pid), "13")
                 try:
                     app.wait(f"office: closed Untitled {n + 2}$", timeout=5)
                     break
@@ -304,17 +309,20 @@ def perf08(work, cycles=40):
             else:
                 said = [line for line in app.lines() if re.search("clos|dialog|opened|focus", line)]
                 raise RuntimeError(f"ely-doc: Untitled {n + 2} never closed: {said[-8:]}")
-            # The kernel lets go in the background.
+            # The kernel lets go later; a fresh report must come.
             for _ in range(100):
-                if open_docs() == baseline[2]:
-                    break
+                try:
+                    if open_docs(cursor) == baseline[2]:
+                        break
+                except RuntimeError:
+                    pass
                 time.sleep(0.05)
             else:
-                raise RuntimeError(f"ely-doc: {open_docs()} documents after closing, not {baseline[2]}")
+                raise RuntimeError(f"ely-doc: cycle {n + 1} closed, yet no report of {baseline[2]} documents")
             time.sleep(0.5)
             now = app.handles()
             extra = handles_kept(before, now, extra, n + 1)
-            seen.append((app.memory_mb(), sum(now.values()), open_docs()))
+            seen.append((app.memory_mb(), sum(now.values()), open_docs(cursor)))
     finally:
         app.stop()
     return baseline, seen

tests/perf/test_bench.py

@@ -35,6 +35,12 @@ class Verdicts(unittest.TestCase):
         with self.assertRaisesRegex(RuntimeError, "no document count"):
             bench.documents_open(["office: closed Untitled 2"])
 
+    def test_a_cycle_needs_its_own_count(self):
+        log = ["lok-worker: 1 documents open", "ely-doc: opened Untitled 2 as tab 1", "office: closed Untitled 2"]
+        cursor = 1
+        with self.assertRaisesRegex(RuntimeError, "no document count"):
+            bench.documents_open(log[cursor:])
+
 
 if __name__ == "__main__":
     unittest.main()

tests/scripts/chord.swift

@@ -0,0 +1,14 @@
+// Posts Command plus a key to one process, flag included.
+import CoreGraphics
+import Foundation
+
+// chord <pid> <virtual key code>
+let pid = pid_t(CommandLine.arguments[1])!
+let code = CGKeyCode(CommandLine.arguments[2])!
+let source = CGEventSource(stateID: .privateState)
+for down in [true, false] {
+    let event = CGEvent(keyboardEventSource: source, virtualKey: code, keyDown: down)!
+    event.flags = .maskCommand
+    event.postToPid(pid)
+    usleep(30_000)
+}