Struct ProfileCollector

Source

pub struct ProfileCollector { /* private fields */ }

Implementations§

Source §

impl ProfileCollector

Source

pub fn new() -> Self

Source

pub fn record_invocation( &mut self, fingerprint: &str, exec_us: u64, executor: ExecutorKind, )

Source

pub fn record_shape_invocation(&mut self, label: &str, exec_us: u64)

Source

pub fn record_shape_work(&mut self, label: &str, exec_us: u64, visits: u64)

Record one evaluation together with the evidence nodes it visited.

Source

pub fn records(&self) -> &[QueryRecord]

Source

pub fn shape_records(&self) -> &[ShapeRecord]

Examples found in repository ?

examples/probe_evidence_cost.rs (line 243)

28fn main() {
29    let mut shapes_path = PathBuf::new();
30    let mut data_path = PathBuf::new();
31    let mut no_infer = false;
32    let mut top = 15usize;
33    let mut dump_json: Option<PathBuf> = None;
34    let mut argv = std::env::args().skip(1);
35    while let Some(flag) = argv.next() {
36        let mut value = || {
37            argv.next()
38                .unwrap_or_else(|| panic!("{flag} needs a value"))
39        };
40        match flag.as_str() {
41            "--shapes" => shapes_path = PathBuf::from(value()),
42            "--data" => data_path = PathBuf::from(value()),
43            "--no-infer" => no_infer = true,
44            "--top" => top = value().parse().expect("--top must be an integer"),
45            "--dump-json" => dump_json = Some(PathBuf::from(value())),
46            other => panic!("unknown flag {other}"),
47        }
48    }
49    assert!(!shapes_path.as_os_str().is_empty(), "--shapes is required");
50    assert!(!data_path.as_os_str().is_empty(), "--data is required");
51
52    let shapes_bytes = fs::read(&shapes_path).expect("cannot read --shapes");
53    let shapes = shifty_parse::load_turtle(&shapes_bytes, None).expect("cannot parse --shapes");
54    let compiled = CompiledShapes::compile(shapes).expect("cannot compile shapes");
55
56    let data_bytes = fs::read(&data_path).expect("cannot read --data");
57    let data = shifty_parse::load_turtle(&data_bytes, None).expect("cannot parse --data");
58    let data_graph = if no_infer {
59        data.graph.clone()
60    } else {
61        compiled
62            .session(
63                SessionData::Separate(data.graph.clone()),
64                SessionOptions {
65                    inference: true,
66                    ..SessionOptions::default()
67                },
68            )
69            .expect("inference")
70            .data()
71            .clone()
72    };
73
74    let prepared = PreparedEvidenceValidator::with_graphs(
75        &data_graph,
76        &compiled.source().graph,
77        compiled.authored_schema(),
78        ValidationGraphMode::Union,
79    )
80    .expect("stratifiable");
81    let options = ValidationOptions::default();
82    let scan_options = ConformanceOptions::default();
83
84    println!("model: {}", data_path.display());
85    println!("normalized arena nodes: {}", prepared.schema().arena.len());
86    println!(
87        "normalized statements:  {}",
88        prepared.schema().statements.len()
89    );
90    println!();
91
92    // ---- arm A: conformance only ------------------------------------------
93    profile::enable();
94    let _ = profile::take_evidence_visits();
95    let start = Instant::now();
96    let conformance = prepared.validate_conformance(&scan_options);
97    let conformance_ms = start.elapsed().as_secs_f64() * 1e3;
98    let conformance_visits = profile::take_evidence_visits();
99    let conformance_probes = profile::take_path_probes();
100    let conformance_cache = profile::take().expect("profiling enabled");
101    let conformance_cache = conformance_cache.shape_cache().clone();
102
103    // ---- arm B: dual evidence ----------------------------------------------
104    profile::enable();
105    let start = Instant::now();
106    let run = prepared.validate(&options);
107    let evidence_ms = start.elapsed().as_secs_f64() * 1e3;
108    let evidence_visits = profile::take_evidence_visits();
109    let evidence_probes = profile::take_path_probes();
110    let collector = profile::take().expect("profiling enabled");
111    let evidence_cache = collector.shape_cache().clone();
112
113    // ---- arm C: on-demand ---------------------------------------------------
114    // What a caller pays who wants explanations only for what failed: one
115    // conformance pass that also records the failing pairs, then evidence
116    // materialized for those pairs alone.
117    profile::enable();
118    let start = Instant::now();
119    let (_, failures) = prepared.find_failures(&scan_options);
120    let find_ms = start.elapsed().as_secs_f64() * 1e3;
121    let start = Instant::now();
122    let explained: usize = failures
123        .iter()
124        .map(|pair| prepared.explain(pair).len())
125        .sum();
126    let explain_ms = start.elapsed().as_secs_f64() * 1e3;
127    let _ = profile::take();
128    let _ = profile::take_evidence_visits();
129    let _ = profile::take_path_probes();
130
131    let pairs = conformance.selected_pairs.max(1) as f64;
132    let retained = run.walk().len();
133
134    // ---- compact encoding --------------------------------------------------
135    let full_json = run.to_json().expect("evidence run serializes");
136    // Split so the encoding's own cost is separable from the intermediate
137    // `Value` tree it currently has to be handed: compaction is worth doing
138    // inline only if the total stays under the validation it describes.
139    let to_value_start = Instant::now();
140    let run_value = serde_json::to_value(&run).expect("run serializes");
141    let to_value_ms = to_value_start.elapsed().as_secs_f64() * 1e3;
142    let intern_start = Instant::now();
143    let interned = shifty_engine::compact_value(run_value, true);
144    let intern_ms = intern_start.elapsed().as_secs_f64() * 1e3;
145    let emit_start = Instant::now();
146    let compact_json = serde_json::to_string(&interned).expect("compact encoding serializes");
147    let emit_ms = emit_start.elapsed().as_secs_f64() * 1e3;
148    let compact_ms = to_value_ms + intern_ms + emit_ms;
149    drop(interned);
150    let compact_no_catalog =
151        shifty_engine::to_compact_json(&run, false).expect("compact encoding succeeds");
152    println!();
153    println!(
154        "serialized full:           {:>10.2} MB  ({:.0} bytes/pair)",
155        full_json.len() as f64 / 1e6,
156        full_json.len() as f64 / pairs
157    );
158    println!(
159        "compact (with catalog):    {:>10.2} MB  ({:.0} bytes/pair, {:.1}% smaller, {compact_ms:.0} ms \
160         = {to_value_ms:.0} to_value + {intern_ms:.0} intern + {emit_ms:.0} emit)",
161        compact_json.len() as f64 / 1e6,
162        compact_json.len() as f64 / pairs,
163        100.0 * (full_json.len() - compact_json.len()) as f64 / full_json.len() as f64
164    );
165    println!(
166        "compact (catalog elided):  {:>10.2} MB  ({:.0} bytes/pair, {:.1}% smaller)",
167        compact_no_catalog.len() as f64 / 1e6,
168        compact_no_catalog.len() as f64 / pairs,
169        100.0 * (full_json.len() - compact_no_catalog.len()) as f64 / full_json.len() as f64
170    );
171
172    if let Some(path) = &dump_json {
173        fs::write(path, run.to_json().expect("evidence run serializes"))
174            .expect("cannot write --dump-json");
175        eprintln!("wrote {}", path.display());
176    }
177
178    println!("                        conformance        evidence");
179    println!("  wall ms               {conformance_ms:>11.1}  {evidence_ms:>14.1}");
180    println!(
181        "  memo lookups          {:>11}  {:>14}",
182        conformance_cache.hits + conformance_cache.misses,
183        evidence_cache.hits + evidence_cache.misses
184    );
185    println!(
186        "  memo hits             {:>11}  {:>14}",
187        conformance_cache.hits, evidence_cache.hits
188    );
189    println!(
190        "  memo misses           {:>11}  {:>14}",
191        conformance_cache.misses, evidence_cache.misses
192    );
193    println!(
194        "  memo entries (peak)   {:>11}  {:>14}",
195        conformance_cache.peak_entries, evidence_cache.peak_entries
196    );
197    println!(
198        "  back-edges            {:>11}  {:>14}",
199        conformance_cache.recursion_back_edges, evidence_cache.recursion_back_edges
200    );
201    println!(
202        "  uncacheable results   {:>11}  {:>14}",
203        conformance_cache.non_cacheable_results, evidence_cache.non_cacheable_results
204    );
205    println!("  evidence visits       {conformance_visits:>11}  {evidence_visits:>14}");
206    println!("  path_support probes   {conformance_probes:>11}  {evidence_probes:>14}");
207    println!();
208    println!(
209        "path probes per visit:     {:.1}",
210        evidence_probes as f64 / evidence_visits.max(1) as f64
211    );
212
213    println!("selected pairs:            {}", conformance.selected_pairs);
214    println!("retained evidence nodes:   {retained}");
215    println!(
216        "visited / retained:        {:.1}x",
217        evidence_visits as f64 / retained.max(1) as f64
218    );
219    println!(
220        "visits per pair:           {:.0}",
221        evidence_visits as f64 / pairs
222    );
223    println!(
224        "distinct (shape,node) that a cache could collapse to at most: {}",
225        evidence_cache.peak_entries
226    );
227    println!(
228        "visits / distinct pairs:   {:.1}x",
229        evidence_visits as f64 / evidence_cache.peak_entries.max(1) as f64
230    );
231    println!();
232    println!(
233        "per-visit cost:            {:.2} us",
234        evidence_ms * 1e3 / evidence_visits.max(1) as f64
235    );
236    println!(
237        "per-memo-lookup cost:      {:.2} us",
238        conformance_ms * 1e3 / (conformance_cache.hits + conformance_cache.misses).max(1) as f64
239    );
240
241    // ---- attribution: which statements own the time ------------------------
242    let (selection, materialization): (Vec<_>, Vec<_>) = collector
243        .shape_records()
244        .iter()
245        .partition(|record| record.label.starts_with("select:"));
246    let selection_us: u64 = selection.iter().map(|record| record.total_us).sum();
247    let materialization_us: u64 = materialization.iter().map(|record| record.total_us).sum();
248
249    println!();
250    println!(
251        "target selection total:    {:.1} ms over {} statement(s)",
252        selection_us as f64 / 1e3,
253        selection.len()
254    );
255    println!(
256        "materialization total:     {:.1} ms over {} statement(s)",
257        materialization_us as f64 / 1e3,
258        materialization.len()
259    );
260    println!();
261    println!(
262        "on-demand: {} failing pair(s) of {} selected -> {} explanation(s)",
263        failures.len(),
264        conformance.selected_pairs,
265        explained
266    );
267    println!(
268        "  find_failures {find_ms:.1} ms + explain {explain_ms:.1} ms = {:.1} ms  \
269         ({:.2}x the full evidence run, {:.2}x conformance alone)",
270        find_ms + explain_ms,
271        (find_ms + explain_ms) / evidence_ms.max(f64::MIN_POSITIVE),
272        (find_ms + explain_ms) / conformance_ms.max(f64::MIN_POSITIVE)
273    );
274
275    let mut ranked = materialization;
276    ranked.sort_by_key(|record| std::cmp::Reverse(record.total_us));
277    println!();
278    println!("top statements by evidence-materialization time:");
279    println!(
280        "  {:>8}  {:>7}  {:>6}  {:>10}  {:>12}  {:>10}  shape",
281        "ms", "share", "foci", "us/focus", "visits", "visits/foci"
282    );
283    for record in ranked.iter().take(top) {
284        println!(
285            "  {:>8.1}  {:>6.1}%  {:>6}  {:>10.1}  {:>12}  {:>10.0}  {}",
286            record.total_us as f64 / 1e3,
287            100.0 * record.total_us as f64 / materialization_us.max(1) as f64,
288            record.invocations,
289            record.total_us as f64 / record.invocations.max(1) as f64,
290            record.visits,
291            record.visits as f64 / record.invocations.max(1) as f64,
292            record.label,
293        );
294    }
295
296    let mut ranked_selection = selection;
297    ranked_selection.sort_by_key(|record| std::cmp::Reverse(record.total_us));
298    println!();
299    println!("top statements by target-selection time:");
300    for record in ranked_selection.iter().take(5) {
301        println!(
302            "  {:>8.1} ms  {}",
303            record.total_us as f64 / 1e3,
304            record.label
305        );
306    }
307}

Source

pub fn shape_cache(&self) -> &ShapeCacheRecord

Examples found in repository ?

examples/probe_evidence_cost.rs (line 101)

28fn main() {
29    let mut shapes_path = PathBuf::new();
30    let mut data_path = PathBuf::new();
31    let mut no_infer = false;
32    let mut top = 15usize;
33    let mut dump_json: Option<PathBuf> = None;
34    let mut argv = std::env::args().skip(1);
35    while let Some(flag) = argv.next() {
36        let mut value = || {
37            argv.next()
38                .unwrap_or_else(|| panic!("{flag} needs a value"))
39        };
40        match flag.as_str() {
41            "--shapes" => shapes_path = PathBuf::from(value()),
42            "--data" => data_path = PathBuf::from(value()),
43            "--no-infer" => no_infer = true,
44            "--top" => top = value().parse().expect("--top must be an integer"),
45            "--dump-json" => dump_json = Some(PathBuf::from(value())),
46            other => panic!("unknown flag {other}"),
47        }
48    }
49    assert!(!shapes_path.as_os_str().is_empty(), "--shapes is required");
50    assert!(!data_path.as_os_str().is_empty(), "--data is required");
51
52    let shapes_bytes = fs::read(&shapes_path).expect("cannot read --shapes");
53    let shapes = shifty_parse::load_turtle(&shapes_bytes, None).expect("cannot parse --shapes");
54    let compiled = CompiledShapes::compile(shapes).expect("cannot compile shapes");
55
56    let data_bytes = fs::read(&data_path).expect("cannot read --data");
57    let data = shifty_parse::load_turtle(&data_bytes, None).expect("cannot parse --data");
58    let data_graph = if no_infer {
59        data.graph.clone()
60    } else {
61        compiled
62            .session(
63                SessionData::Separate(data.graph.clone()),
64                SessionOptions {
65                    inference: true,
66                    ..SessionOptions::default()
67                },
68            )
69            .expect("inference")
70            .data()
71            .clone()
72    };
73
74    let prepared = PreparedEvidenceValidator::with_graphs(
75        &data_graph,
76        &compiled.source().graph,
77        compiled.authored_schema(),
78        ValidationGraphMode::Union,
79    )
80    .expect("stratifiable");
81    let options = ValidationOptions::default();
82    let scan_options = ConformanceOptions::default();
83
84    println!("model: {}", data_path.display());
85    println!("normalized arena nodes: {}", prepared.schema().arena.len());
86    println!(
87        "normalized statements:  {}",
88        prepared.schema().statements.len()
89    );
90    println!();
91
92    // ---- arm A: conformance only ------------------------------------------
93    profile::enable();
94    let _ = profile::take_evidence_visits();
95    let start = Instant::now();
96    let conformance = prepared.validate_conformance(&scan_options);
97    let conformance_ms = start.elapsed().as_secs_f64() * 1e3;
98    let conformance_visits = profile::take_evidence_visits();
99    let conformance_probes = profile::take_path_probes();
100    let conformance_cache = profile::take().expect("profiling enabled");
101    let conformance_cache = conformance_cache.shape_cache().clone();
102
103    // ---- arm B: dual evidence ----------------------------------------------
104    profile::enable();
105    let start = Instant::now();
106    let run = prepared.validate(&options);
107    let evidence_ms = start.elapsed().as_secs_f64() * 1e3;
108    let evidence_visits = profile::take_evidence_visits();
109    let evidence_probes = profile::take_path_probes();
110    let collector = profile::take().expect("profiling enabled");
111    let evidence_cache = collector.shape_cache().clone();
112
113    // ---- arm C: on-demand ---------------------------------------------------
114    // What a caller pays who wants explanations only for what failed: one
115    // conformance pass that also records the failing pairs, then evidence
116    // materialized for those pairs alone.
117    profile::enable();
118    let start = Instant::now();
119    let (_, failures) = prepared.find_failures(&scan_options);
120    let find_ms = start.elapsed().as_secs_f64() * 1e3;
121    let start = Instant::now();
122    let explained: usize = failures
123        .iter()
124        .map(|pair| prepared.explain(pair).len())
125        .sum();
126    let explain_ms = start.elapsed().as_secs_f64() * 1e3;
127    let _ = profile::take();
128    let _ = profile::take_evidence_visits();
129    let _ = profile::take_path_probes();
130
131    let pairs = conformance.selected_pairs.max(1) as f64;
132    let retained = run.walk().len();
133
134    // ---- compact encoding --------------------------------------------------
135    let full_json = run.to_json().expect("evidence run serializes");
136    // Split so the encoding's own cost is separable from the intermediate
137    // `Value` tree it currently has to be handed: compaction is worth doing
138    // inline only if the total stays under the validation it describes.
139    let to_value_start = Instant::now();
140    let run_value = serde_json::to_value(&run).expect("run serializes");
141    let to_value_ms = to_value_start.elapsed().as_secs_f64() * 1e3;
142    let intern_start = Instant::now();
143    let interned = shifty_engine::compact_value(run_value, true);
144    let intern_ms = intern_start.elapsed().as_secs_f64() * 1e3;
145    let emit_start = Instant::now();
146    let compact_json = serde_json::to_string(&interned).expect("compact encoding serializes");
147    let emit_ms = emit_start.elapsed().as_secs_f64() * 1e3;
148    let compact_ms = to_value_ms + intern_ms + emit_ms;
149    drop(interned);
150    let compact_no_catalog =
151        shifty_engine::to_compact_json(&run, false).expect("compact encoding succeeds");
152    println!();
153    println!(
154        "serialized full:           {:>10.2} MB  ({:.0} bytes/pair)",
155        full_json.len() as f64 / 1e6,
156        full_json.len() as f64 / pairs
157    );
158    println!(
159        "compact (with catalog):    {:>10.2} MB  ({:.0} bytes/pair, {:.1}% smaller, {compact_ms:.0} ms \
160         = {to_value_ms:.0} to_value + {intern_ms:.0} intern + {emit_ms:.0} emit)",
161        compact_json.len() as f64 / 1e6,
162        compact_json.len() as f64 / pairs,
163        100.0 * (full_json.len() - compact_json.len()) as f64 / full_json.len() as f64
164    );
165    println!(
166        "compact (catalog elided):  {:>10.2} MB  ({:.0} bytes/pair, {:.1}% smaller)",
167        compact_no_catalog.len() as f64 / 1e6,
168        compact_no_catalog.len() as f64 / pairs,
169        100.0 * (full_json.len() - compact_no_catalog.len()) as f64 / full_json.len() as f64
170    );
171
172    if let Some(path) = &dump_json {
173        fs::write(path, run.to_json().expect("evidence run serializes"))
174            .expect("cannot write --dump-json");
175        eprintln!("wrote {}", path.display());
176    }
177
178    println!("                        conformance        evidence");
179    println!("  wall ms               {conformance_ms:>11.1}  {evidence_ms:>14.1}");
180    println!(
181        "  memo lookups          {:>11}  {:>14}",
182        conformance_cache.hits + conformance_cache.misses,
183        evidence_cache.hits + evidence_cache.misses
184    );
185    println!(
186        "  memo hits             {:>11}  {:>14}",
187        conformance_cache.hits, evidence_cache.hits
188    );
189    println!(
190        "  memo misses           {:>11}  {:>14}",
191        conformance_cache.misses, evidence_cache.misses
192    );
193    println!(
194        "  memo entries (peak)   {:>11}  {:>14}",
195        conformance_cache.peak_entries, evidence_cache.peak_entries
196    );
197    println!(
198        "  back-edges            {:>11}  {:>14}",
199        conformance_cache.recursion_back_edges, evidence_cache.recursion_back_edges
200    );
201    println!(
202        "  uncacheable results   {:>11}  {:>14}",
203        conformance_cache.non_cacheable_results, evidence_cache.non_cacheable_results
204    );
205    println!("  evidence visits       {conformance_visits:>11}  {evidence_visits:>14}");
206    println!("  path_support probes   {conformance_probes:>11}  {evidence_probes:>14}");
207    println!();
208    println!(
209        "path probes per visit:     {:.1}",
210        evidence_probes as f64 / evidence_visits.max(1) as f64
211    );
212
213    println!("selected pairs:            {}", conformance.selected_pairs);
214    println!("retained evidence nodes:   {retained}");
215    println!(
216        "visited / retained:        {:.1}x",
217        evidence_visits as f64 / retained.max(1) as f64
218    );
219    println!(
220        "visits per pair:           {:.0}",
221        evidence_visits as f64 / pairs
222    );
223    println!(
224        "distinct (shape,node) that a cache could collapse to at most: {}",
225        evidence_cache.peak_entries
226    );
227    println!(
228        "visits / distinct pairs:   {:.1}x",
229        evidence_visits as f64 / evidence_cache.peak_entries.max(1) as f64
230    );
231    println!();
232    println!(
233        "per-visit cost:            {:.2} us",
234        evidence_ms * 1e3 / evidence_visits.max(1) as f64
235    );
236    println!(
237        "per-memo-lookup cost:      {:.2} us",
238        conformance_ms * 1e3 / (conformance_cache.hits + conformance_cache.misses).max(1) as f64
239    );
240
241    // ---- attribution: which statements own the time ------------------------
242    let (selection, materialization): (Vec<_>, Vec<_>) = collector
243        .shape_records()
244        .iter()
245        .partition(|record| record.label.starts_with("select:"));
246    let selection_us: u64 = selection.iter().map(|record| record.total_us).sum();
247    let materialization_us: u64 = materialization.iter().map(|record| record.total_us).sum();
248
249    println!();
250    println!(
251        "target selection total:    {:.1} ms over {} statement(s)",
252        selection_us as f64 / 1e3,
253        selection.len()
254    );
255    println!(
256        "materialization total:     {:.1} ms over {} statement(s)",
257        materialization_us as f64 / 1e3,
258        materialization.len()
259    );
260    println!();
261    println!(
262        "on-demand: {} failing pair(s) of {} selected -> {} explanation(s)",
263        failures.len(),
264        conformance.selected_pairs,
265        explained
266    );
267    println!(
268        "  find_failures {find_ms:.1} ms + explain {explain_ms:.1} ms = {:.1} ms  \
269         ({:.2}x the full evidence run, {:.2}x conformance alone)",
270        find_ms + explain_ms,
271        (find_ms + explain_ms) / evidence_ms.max(f64::MIN_POSITIVE),
272        (find_ms + explain_ms) / conformance_ms.max(f64::MIN_POSITIVE)
273    );
274
275    let mut ranked = materialization;
276    ranked.sort_by_key(|record| std::cmp::Reverse(record.total_us));
277    println!();
278    println!("top statements by evidence-materialization time:");
279    println!(
280        "  {:>8}  {:>7}  {:>6}  {:>10}  {:>12}  {:>10}  shape",
281        "ms", "share", "foci", "us/focus", "visits", "visits/foci"
282    );
283    for record in ranked.iter().take(top) {
284        println!(
285            "  {:>8.1}  {:>6.1}%  {:>6}  {:>10.1}  {:>12}  {:>10.0}  {}",
286            record.total_us as f64 / 1e3,
287            100.0 * record.total_us as f64 / materialization_us.max(1) as f64,
288            record.invocations,
289            record.total_us as f64 / record.invocations.max(1) as f64,
290            record.visits,
291            record.visits as f64 / record.invocations.max(1) as f64,
292            record.label,
293        );
294    }
295
296    let mut ranked_selection = selection;
297    ranked_selection.sort_by_key(|record| std::cmp::Reverse(record.total_us));
298    println!();
299    println!("top statements by target-selection time:");
300    for record in ranked_selection.iter().take(5) {
301        println!(
302            "  {:>8.1} ms  {}",
303            record.total_us as f64 / 1e3,
304            record.label
305        );
306    }
307}