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