Tests: the shape builder and large edit guards count work instead of timing it

The Shape Builder, Live Paint and run_around tests in planar/tests.rs
measured elapsed time against a 5 s limit, and the large edit tests
(large_edits.rs, with the Lock and Hide All Artwork Above and perspective
Alt-drag tests that share `soon`) against 20 s. On a loaded machine they
failed without any change in the code.

- pathops: a test-only counter adds up the items `RectIndex::at` reads
  and the segments `nearest_u` searches. The four planar tests assert a
  bound on that count.
- doc: `tree_walks` counts, per thread, the walks of a document's tree
  that lookups by id make. `soon` fails when a command walks the tree
  more than 64 times, and keeps a 300 s wait for a hang. The tests that
  named a 20 s limit are renamed.

Looking objects up one at a time in Delete or Offset Path, or scanning
the whole index or ring in the planar code, makes these tests fail.

crates/doc/src/document.rs

@@ -352,6 +352,7 @@ impl Document {
             }
             false
         }
+        crate::id_index::note_tree_walk();
         let mut p = vec![];
         find(&self.layers, id, &mut p).then_some(p)
     }
@@ -393,6 +394,7 @@ impl Document {
             });
         }
         if !want.is_empty() {
+            crate::id_index::note_tree_walk();
             let mut rest = HashMap::with_capacity(want.len());
             walk(&self.layers, &want, &mut Vec::new(), &mut rest);
             out.extend(rest);

crates/doc/src/id_index.rs

@@ -90,6 +90,24 @@ impl Paths {
 /// object and look the next one up, again and again).
 const MISSES_PER_REBUILD: u32 = 4;
 
+thread_local! {
+    /// [`tree_walks`] of this thread.
+    static TREE_WALKS: std::cell::Cell<u64> = const { std::cell::Cell::new(0) };
+}
+
+/// How many times lookups by id on this thread have walked a document's tree, reading up to all of
+/// its nodes: one count per search of the tree and per rebuild of the cache. An edit that looks its
+/// objects up one at a time counts about one walk per object; one that looks them all up at once
+/// counts a few.
+pub fn tree_walks() -> u64 {
+    TREE_WALKS.get()
+}
+
+/// Adds one to [`tree_walks`].
+pub(crate) fn note_tree_walk() {
+    TREE_WALKS.set(TREE_WALKS.get().saturating_add(1));
+}
+
 /// The cache, shared by clones of a document (each checks every path it uses against its own tree).
 #[derive(Default)]
 pub struct IdIndex(RwLock<Option<Arc<Paths>>>, std::sync::atomic::AtomicU32);
@@ -125,6 +143,7 @@ impl IdIndex {
                 }
             }
         }
+        note_tree_walk();
         let mut out = Paths::default();
         walk(layers, u32::MAX, &mut out);
         let out = Arc::new(out);

crates/doc/src/lib.rs

@@ -19,6 +19,7 @@ pub mod graph;
 mod halftone_radii;
 pub mod hit;
 mod id_index;
+pub use id_index::tree_walks;
 pub mod inks;
 mod inline;
 pub mod intertwine;

crates/engine/src/tests/large_edits.rs

@@ -1,6 +1,6 @@
-//! Commands that remove, insert or copy many objects, and an Alt-drag that copies them, each finish
-//! within 20 s on one layer of 25,000 to 100,000 objects, and objects in two layers and inside a
-//! group keep their order and ids.
+//! Commands that remove, insert or copy many objects, and an Alt-drag that copies them, each walk
+//! the document's tree a few times on one layer of 25,000 to 100,000 objects, and objects in two
+//! layers and inside a group keep their order and ids.
 
 use std::sync::Arc;
 use std::time::Duration;
@@ -65,14 +65,22 @@ fn in_turn(a: &[NodeId], b: &[NodeId]) -> Vec<NodeId> {
     a.iter().zip(b).flat_map(|(a, b)| [*a, *b]).collect()
 }
 
-/// Runs `f` on `s` on a thread of its own and fails the test when it takes more than 20 s.
+/// Most walks of the document's tree ([`vectorcraft_doc::tree_walks`]) that [`soon`] allows, however
+/// many objects the document holds. A command that looks its objects up one at a time walks the tree
+/// about once per object.
+const MOST_TREE_WALKS: u64 = 64;
+
+/// Runs `f` on `s` on a thread of its own and fails the test when it walks the document's tree more
+/// than [`MOST_TREE_WALKS`] times or has not ended after 300 s.
 pub(crate) fn soon<T: Send + 'static>(mut s: Session, what: &'static str, f: impl FnOnce(&mut Session) -> T + Send + 'static) -> (Session, T) {
     let (tx, rx) = std::sync::mpsc::channel();
     std::thread::spawn(move || {
         let r = f(&mut s);
-        tx.send((s, r)).ok();
+        tx.send((s, r, vectorcraft_doc::tree_walks())).ok();
     });
-    rx.recv_timeout(Duration::from_secs(20)).unwrap_or_else(|_| panic!("{what} did not finish within 20 s"))
+    let (s, r, walks) = rx.recv_timeout(Duration::from_secs(300)).unwrap_or_else(|_| panic!("{what} did not finish within 300 s"));
+    assert!(walks <= MOST_TREE_WALKS, "{what} walked the document's tree {walks} times");
+    (s, r)
 }
 
 /// Runs command `cmd` with `params` through [`soon`] and returns its result.
@@ -103,7 +111,7 @@ fn bounds(s: &Session, id: NodeId) -> Rect {
 }
 
 #[test]
-fn delete_of_100000_objects_finishes_within_20_s() {
+fn delete_of_100000_objects_takes_few_tree_walks() {
     let s = session(100_000, square);
     let before = s.doc().unwrap().doc.clone();
     let (mut s, _) = run_soon(s, "edit.clear", json!({}));
@@ -113,7 +121,7 @@ fn delete_of_100000_objects_finishes_within_20_s() {
 }
 
 #[test]
-fn delete_selection_of_100000_rows_finishes_within_20_s() {
+fn delete_selection_of_100000_rows_takes_few_tree_walks() {
     let s = session(100_000, square);
     let (before, ids) = (s.doc().unwrap().doc.clone(), layer(&s, 0));
     let (mut s, r) = run_soon(s, "layer.delete", json!({"ids": ids}));
@@ -124,7 +132,7 @@ fn delete_selection_of_100000_rows_finishes_within_20_s() {
 }
 
 #[test]
-fn clean_up_of_100000_unpainted_paths_finishes_within_20_s() {
+fn clean_up_of_100000_unpainted_paths_takes_few_tree_walks() {
     let s = session(100_000, |d, k| Node::path(d.alloc_id(), shapes::rectangle(square_at(k)), Appearance::default()));
     let before = s.doc().unwrap().doc.clone();
     let (mut s, r) = run_soon(s, "object.path.cleanUp", json!({}));
@@ -135,7 +143,7 @@ fn clean_up_of_100000_unpainted_paths_finishes_within_20_s() {
 }
 
 #[test]
-fn group_of_50000_objects_finishes_within_20_s() {
+fn group_of_50000_objects_takes_few_tree_walks() {
     let s = session(50_000, square);
     let (before, ids) = (s.doc().unwrap().doc.clone(), layer(&s, 0));
     let (mut s, r) = run_soon(s, "object.group", json!({}));
@@ -147,7 +155,7 @@ fn group_of_50000_objects_finishes_within_20_s() {
 }
 
 #[test]
-fn clipping_mask_of_50000_objects_finishes_within_20_s() {
+fn clipping_mask_of_50000_objects_takes_few_tree_walks() {
     let s = session(50_000, square);
     let (before, ids) = (s.doc().unwrap().doc.clone(), layer(&s, 0));
     let (mut s, r) = run_soon(s, "object.clippingMask.make", json!({}));
@@ -165,7 +173,7 @@ fn clipping_mask_of_50000_objects_finishes_within_20_s() {
 }
 
 #[test]
-fn duplicate_of_50000_objects_finishes_within_20_s() {
+fn duplicate_of_50000_objects_takes_few_tree_walks() {
     let s = session(50_000, square);
     let (before, ids, first) = (s.doc().unwrap().doc.clone(), layer(&s, 0), s.doc().unwrap().doc.peek_next_id());
     let (mut s, r) = run_soon(s, "edit.duplicate", json!({"dx": 5}));
@@ -179,7 +187,7 @@ fn duplicate_of_50000_objects_finishes_within_20_s() {
 }
 
 #[test]
-fn transform_with_copy_of_50000_objects_finishes_within_20_s() {
+fn transform_with_copy_of_50000_objects_takes_few_tree_walks() {
     let s = session(50_000, square);
     let (before, ids, first) = (s.doc().unwrap().doc.clone(), layer(&s, 0), s.doc().unwrap().doc.peek_next_id());
     let (mut s, r) = run_soon(s, "object.transform", json!({"matrix": [1, 0, 0, 1, 5, 0], "copy": true}));
@@ -194,7 +202,7 @@ fn transform_with_copy_of_50000_objects_finishes_within_20_s() {
 }
 
 #[test]
-fn transform_each_with_copy_of_50000_objects_finishes_within_20_s() {
+fn transform_each_with_copy_of_50000_objects_takes_few_tree_walks() {
     let s = session(50_000, square);
     let (before, ids, first) = (s.doc().unwrap().doc.clone(), layer(&s, 0), s.doc().unwrap().doc.peek_next_id());
     let (mut s, r) = run_soon(s, "object.transformEach", json!({"moveH": 5, "copy": true}));
@@ -207,7 +215,7 @@ fn transform_each_with_copy_of_50000_objects_finishes_within_20_s() {
 }
 
 #[test]
-fn offset_path_of_50000_objects_finishes_within_20_s() {
+fn offset_path_of_50000_objects_takes_few_tree_walks() {
     let s = session(50_000, square);
     let (before, ids, first) = (s.doc().unwrap().doc.clone(), layer(&s, 0), s.doc().unwrap().doc.peek_next_id());
     let (mut s, r) = run_soon(s, "object.path.offsetPath", json!({"offset": 1}));
@@ -222,7 +230,7 @@ fn offset_path_of_50000_objects_finishes_within_20_s() {
 }
 
 #[test]
-fn compound_path_of_100000_objects_finishes_within_20_s() {
+fn compound_path_of_100000_objects_takes_few_tree_walks() {
     let s = session(100_000, square);
     let (before, ids) = (s.doc().unwrap().doc.clone(), layer(&s, 0));
     let (mut s, r) = run_soon(s, "object.compoundPath.make", json!({}));
@@ -234,7 +242,7 @@ fn compound_path_of_100000_objects_finishes_within_20_s() {
 }
 
 #[test]
-fn send_to_current_layer_of_100000_objects_finishes_within_20_s() {
+fn send_to_current_layer_of_100000_objects_takes_few_tree_walks() {
     let mut s = session(100_000, square);
     let ids = layer(&s, 0);
     let to = NodeId(s.execute("layer.new", &json!({})).unwrap()["id"].as_u64().unwrap());
@@ -249,7 +257,7 @@ fn send_to_current_layer_of_100000_objects_finishes_within_20_s() {
 }
 
 #[test]
-fn row_drag_of_100000_rows_finishes_within_20_s() {
+fn row_drag_of_100000_rows_takes_few_tree_walks() {
     let mut s = session(100_000, square);
     let ids = layer(&s, 0);
     let to = NodeId(s.execute("layer.new", &json!({})).unwrap()["id"].as_u64().unwrap());
@@ -263,7 +271,7 @@ fn row_drag_of_100000_rows_finishes_within_20_s() {
 }
 
 #[test]
-fn merge_selected_of_100000_objects_finishes_within_20_s() {
+fn merge_selected_of_100000_objects_takes_few_tree_walks() {
     let mut s = session(100_000, square);
     let (from, ids) = (s.doc().unwrap().doc.layers[0].id, layer(&s, 0));
     let into = NodeId(s.execute("layer.new", &json!({})).unwrap()["id"].as_u64().unwrap());
@@ -277,7 +285,7 @@ fn merge_selected_of_100000_objects_finishes_within_20_s() {
 }
 
 #[test]
-fn ungroup_of_25000_groups_finishes_within_20_s() {
+fn ungroup_of_25000_groups_takes_few_tree_walks() {
     // Each group holds two squares, and ungrouping one adds an object to the layer.
     let s = session(25_000, |d, k| {
         let pair = [square(d, 2 * k), square(d, 2 * k + 1)].map(Arc::new);
@@ -292,7 +300,7 @@ fn ungroup_of_25000_groups_finishes_within_20_s() {
 }
 
 #[test]
-fn compound_path_release_of_25000_compound_paths_finishes_within_20_s() {
+fn compound_path_release_of_25000_compound_paths_takes_few_tree_walks() {
     let s = session(25_000, |d, k| {
         let pair = [square(d, 2 * k), square(d, 2 * k + 1)].map(Arc::new);
         Node::new(d.alloc_id(), NodeKind::Compound { children: pair.to_vec(), rule: FillRule::NonZero })
@@ -306,7 +314,7 @@ fn compound_path_release_of_25000_compound_paths_finishes_within_20_s() {
 }
 
 #[test]
-fn release_to_layers_of_100000_objects_finishes_within_20_s() {
+fn release_to_layers_of_100000_objects_takes_few_tree_walks() {
     let s = session(100_000, square);
     let doc = &s.doc().unwrap().doc;
     let (before, l, ids, first) = (doc.clone(), doc.layers[0].id, layer(&s, 0), doc.peek_next_id());
@@ -329,7 +337,7 @@ fn release_to_layers_of_100000_objects_finishes_within_20_s() {
 }
 
 #[test]
-fn outline_stroke_of_25000_objects_finishes_within_20_s() {
+fn outline_stroke_of_25000_objects_takes_few_tree_walks() {
     let s = session(25_000, square);
     let (before, first) = (s.doc().unwrap().doc.clone(), s.doc().unwrap().doc.peek_next_id());
     let (mut s, r) = run_soon(s, "object.path.outlineStroke", json!({}));
@@ -347,7 +355,7 @@ fn outline_stroke_of_25000_objects_finishes_within_20_s() {
 /// With Alt held, a Selection tool press on one of 30,000 selected squares, four moves of 20 pt
 /// and the release copy the squares once, as one undo step.
 #[test]
-fn alt_drag_of_30000_objects_finishes_within_20_s() {
+fn alt_drag_of_30000_objects_takes_few_tree_walks() {
     let s = session(30_000, square);
     let (before, ids, first) = (s.doc().unwrap().doc.clone(), layer(&s, 0), s.doc().unwrap().doc.peek_next_id());
     // The press lands on a square in the middle of the art, away from the handles of the

crates/engine/src/tests/menucmds.rs

@@ -257,10 +257,10 @@ fn tiles_under_squares() -> (Session, Vec<NodeId>, Vec<NodeId>) {
 }
 
 /// With 1,000 tiles selected under 50,000 squares, Lock › All Artwork Above locks every square in one
-/// undo step and Hide › All Artwork Above hides every square, each within 20 s, and the tiles stay
-/// selected.
+/// undo step and Hide › All Artwork Above hides every square, each in a few walks of the tree, and
+/// the tiles stay selected.
 #[test]
-fn lock_and_hide_all_artwork_above_1000_tiles_under_50000_objects_finish_within_20_s() {
+fn lock_and_hide_all_artwork_above_1000_tiles_under_50000_objects_take_few_tree_walks() {
     let (mut s, tiles, squares) = tiles_under_squares();
     sel(&mut s, &tiles);
     let before = s.doc().unwrap().doc.clone();
@@ -280,9 +280,10 @@ fn lock_and_hide_all_artwork_above_1000_tiles_under_50000_objects_finish_within_
 }
 
 /// With all 51,000 objects of [`tiles_under_squares`] selected, Lock › All Artwork Above and Hide ›
-/// All Artwork Above each find nothing to lock or hide within 20 s and record no undo step.
+/// All Artwork Above each find nothing to lock or hide in a few walks of the tree and record no undo
+/// step.
 #[test]
-fn lock_and_hide_all_artwork_above_with_51000_objects_selected_finish_within_20_s() {
+fn lock_and_hide_all_artwork_above_with_51000_objects_selected_take_few_tree_walks() {
     let (s, tiles, squares) = tiles_under_squares();
     let (steps, all) = (undo_len(&s), [tiles, squares].concat());
     assert!(selected(&s) == all, "everything is selected");

crates/engine/src/tests/xform.rs

@@ -407,7 +407,7 @@ fn an_alt_drag_in_perspective_on_a_grid_from_an_older_file_attaches_the_copies()
 /// first one kept, and the drag leaves what one `perspective.move` with copy leaves, as one undo
 /// step.
 #[test]
-fn alt_drag_in_perspective_of_30000_objects_finishes_within_20_s() {
+fn alt_drag_in_perspective_of_30000_objects_takes_few_tree_walks() {
     // The squares are 6 pt wide and 10 pt apart, in rows of 150, between the left vanishing point
     // of the two-point grid and its origin.
     let on_the_left = |d: &mut Document, k: usize| {

crates/pathops/src/planar.rs

@@ -34,7 +34,7 @@ mod shape_builder;
 
 pub(crate) use graph::pin_ends;
 #[cfg(test)]
-use index::{Crossings, RectIndex, reference_budget, segment_footprint};
+use index::{Crossings, RectIndex, reference_budget, segment_footprint, work_done};
 pub use live_paint::{find_gaps, live_paint, live_paint_with_gaps};
 pub use map::interior_point;
 pub(crate) use map::{Map, Rest, map};

crates/pathops/src/planar/index.rs

@@ -61,6 +61,25 @@ impl WindingNumber for Crossings {
     }
 }
 
+#[cfg(test)]
+thread_local! {
+    /// [`work_done`] of this thread.
+    static WORK: std::cell::Cell<u64> = const { std::cell::Cell::new(0) };
+}
+
+/// How many items [`RectIndex::at`] has read and segments [`run_around`](super::run_around) has
+/// searched for the nearest point on a whole piece, on this thread.
+#[cfg(test)]
+pub(super) fn work_done() -> u64 {
+    WORK.get()
+}
+
+/// Adds `n` to [`work_done`].
+#[cfg(test)]
+pub(super) fn note_work(n: usize) {
+    WORK.set(WORK.get().saturating_add(n as u64));
+}
+
 /// A point in the middle of a run of segments.
 pub(super) fn mid(segs: &[Seg]) -> Option<Point> {
     segs.get(segs.len() / 2).map(|s| s.c.eval(0.5))
@@ -202,6 +221,8 @@ impl<T> RectIndex<T> {
         }
         found.sort_unstable();
         found.dedup();
+        #[cfg(test)]
+        note_work(found.len());
         found.into_iter().filter_map(move |i| self.items.get(i)).filter(move |(r, _)| r.inflate(tol, tol).contains(p)).map(|(_, t)| t)
     }
 }

crates/pathops/src/planar/shape_builder.rs

@@ -274,6 +274,8 @@ pub fn run_around(piece: &SubPath, stops: &[Point], at: Point, tol: f64) -> Opti
 /// The point of `sp` nearest `p`, as a parameter `segment + t`, with its distance.
 fn nearest_u(sp: &SubPath, p: Point) -> Option<(f64, f64)> {
     use kurbo::ParamCurveNearest;
+    #[cfg(test)]
+    super::index::note_work(sp.segment_count());
     (0..sp.segment_count())
         .map(|k| {
             let n = sp.segment(k).nearest(p, 1e-9);

crates/pathops/src/planar/tests.rs

@@ -606,18 +606,23 @@ fn shape_builder_stays_quick_up_to_its_cap() {
         .collect();
     let mut s = vec![Shape::new(PathData::single(SubPath::polyline(&ring, true)), FillRule::NonZero, 0)];
     // Closed paths alone are swept for the gaps they enclose.
-    let started = std::time::Instant::now();
+    let started = work_done();
     assert_eq!(shape_builder(&s, false).regions.len(), 1, "the ring encloses no gap");
-    assert!(started.elapsed().as_secs_f64() < 5.0, "{:?}", started.elapsed());
+    // Reads of indexed items stay in proportion to the ring. Scanning the ring for each edge's
+    // source would read about `n` items per edge.
+    let most = 64 * n as u64;
+    let work = work_done() - started;
+    assert!(work <= most, "{work} reads");
     for k in 0..4 {
         let y = -60.0 + 40.0 * f64::from(k);
         s.push(line((-150.0, y), (150.0, y + 7.0), 1));
     }
-    let started = std::time::Instant::now();
+    let started = work_done();
     let BuilderArrangement { regions, lines, .. } = shape_builder(&s, false);
     assert!(regions.len() >= 5, "the ring cut in five bands at least (the waves make pockets)");
     assert!(lines.len() >= 12, "{}", lines.len());
-    assert!(started.elapsed().as_secs_f64() < 5.0, "{:?}", started.elapsed());
+    let work = work_done() - started;
+    assert!(work <= most, "{work} reads");
     // Past the cap, only the filled areas count.
     s.push(line((0.0, 0.0), (1.0, 1.0), 2));
     s[0].path.subpaths[0].anchors.extend((0..16).map(|k| vectorcraft_geom::Anchor::corner(Point::new(100.0, f64::from(k)))));
@@ -966,12 +971,13 @@ fn run_around_a_ring_of_4000_sides_measures_only_the_stops_it_reaches() {
         .collect();
     let ring = poly(&pts, true);
     let stops: Vec<Point> = ring.anchors.iter().map(|a| a.p).collect();
-    let start = std::time::Instant::now();
+    let started = work_done();
     for k in (0..n).step_by(200) {
         let run = run_around(&ring, &stops, ring.segment(k).eval(0.5), 1e-3).expect("a side");
         assert_eq!(ends(&run), (stops[k], stops[(k + 1) % n]), "side {k}");
     }
-    assert!(start.elapsed().as_secs_f64() < 5.0, "20 runs took {:?}", start.elapsed());
+    let work = work_done() - started;
+    assert!(work <= 1_000_000, "20 runs made {work} searches");
 }
 
 /// Proptest shrank a failure of `pieces_cut_out_of_their_inputs` to this input with linesweeper
@@ -1095,10 +1101,11 @@ fn many_lines_stay_quick() {
             line((50.0 + 80.0 * t.cos(), 50.0 + 80.0 * t.sin()), (50.0 - 80.0 * (t + 1.1).cos(), 50.0 - 80.0 * (t + 1.1).sin()), 0)
         })
         .collect();
-    let started = std::time::Instant::now();
+    let started = work_done();
     let (faces, _) = live_paint(&lines);
     assert!(faces.len() > 500, "{}", faces.len());
-    assert!(started.elapsed().as_secs_f64() < 5.0, "{:?}", started.elapsed());
+    let work = work_done() - started;
+    assert!(work <= 150_000, "{work} reads");
 }
 
 #[test]