bench: break screening down per change

bench_screening tells what screening costs in all, not where. Print,
per change judged, what decoding it, placing its operations
(inspect::Inspector) and judging it (rules::judge) cost; of judging,
what reading the policy costs, and one read for scale. Judged as
screening judges most changes: at the heads after the first ones,
whose maps flush the batch.

1 files changed, 103 insertions, 0 deletions

diff --git a/src/document/bench.rs b/src/document/bench.rs
index 467dc2f..026cf7b 100644
--- a/src/document/bench.rs
+++ b/src/document/bench.rs
@@ -680,6 +680,109 @@ fn screening_costs(workload: &str, doc: &Document) {
         unjudged,
         &[("screened", screened.saturating_sub(unjudged))],
     );
+    screening_parts(&changes());
+}
+
+/// Where screening `changes` spends its time, per change judged: decoding them, their
+/// operations placed (`inspect::Inspector`), and judging them (`rules::judge`), of which
+/// reading the policy (`policy::of`) and, for scale, one read (the committer's member
+/// entry). As screening judges most: the first ones in (the maps they make, which flush
+/// the batch), the rest judged at the heads after them (`screen`'s frontier).
+fn screening_parts(changes: &[automerge::Change]) {
+    use crate::access::{policy, rules};
+    use crate::document::at::At;
+    use crate::document::inspect::{Inspector, Op, Path};
+    use std::collections::{BTreeSet, HashMap};
+
+    let warm = changes.len().min(400);
+    let mut base = Document::new();
+    base.apply_changes(changes[..warm].to_vec()).expect("apply");
+    let rest = &changes[warm..];
+    let seen = base.get_heads();
+    let mut authors: HashMap<automerge::ActorId, String> = HashMap::new();
+    let committers: Vec<Option<String>> = rest
+        .iter()
+        .map(|change| {
+            let actor = change.actor_id();
+            let named = change
+                .author()
+                .or_else(|| base.get_author_for_actor(actor))
+                .and_then(|author| {
+                    std::str::from_utf8(author.as_bytes())
+                        .ok()
+                        .map(str::to_owned)
+                })
+                .or_else(|| authors.get(actor).cloned());
+            if let Some(named) = &named {
+                authors.insert(actor.clone(), named.clone());
+            }
+            named
+        })
+        .collect();
+
+    let mut decoded = Vec::new();
+    let decode = median(3, || {
+        let started = Instant::now();
+        decoded = rest.iter().map(automerge::Change::decode).collect();
+        started.elapsed()
+    });
+    let mut ops: Vec<Vec<Op>> = Vec::new();
+    let place = median(3, || {
+        let started = Instant::now();
+        ops = Inspector::new(&base).ops(&decoded);
+        started.elapsed()
+    });
+    let paths: Vec<BTreeSet<Path>> = ops
+        .iter()
+        .map(|ops| ops.iter().map(|op| op.path.clone()).collect())
+        .collect();
+    let judge = median(3, || {
+        let started = Instant::now();
+        for (index, change) in rest.iter().enumerate() {
+            let judged = rules::judge(
+                &base,
+                Epoch::GENESIS,
+                &rules::Change {
+                    hash: change.hash(),
+                    deps: change.deps(),
+                    seen: &seen,
+                    committer: committers[index].as_deref(),
+                    user: None,
+                    paths: &paths[index],
+                    ops: &ops[index],
+                },
+            );
+            assert_eq!(judged, Ok(()), "every change taken");
+        }
+        started.elapsed()
+    });
+    let read_policy = median(3, || {
+        let started = Instant::now();
+        for _ in rest {
+            let at = At::new(&base, &seen).expect("heads");
+            std::hint::black_box(policy::of(&at));
+        }
+        started.elapsed()
+    });
+    let entry = crate::swarm::members::member_path(WRITER.node);
+    let one_read = median(3, || {
+        let started = Instant::now();
+        for _ in rest {
+            let at = At::new(&base, &seen).expect("heads");
+            std::hint::black_box(store::read_path(&at, &entry).ok());
+        }
+        started.elapsed()
+    });
+    let per = |d: Duration| d.as_secs_f64() * 1e6 / rest.len().max(1) as f64;
+    println!(
+        "{:<40} per change: decode {:.2} µs, place {:.2} µs, judge {:.2} µs (policy::of {:.2} µs, one read {:.2} µs)",
+        "",
+        per(decode),
+        per(place),
+        per(judge),
+        per(read_policy),
+        per(one_read),
+    );
 }
 
 #[test]