detcore_model/
summary.rs

1/*
2 * Copyright (c) Meta Platforms, Inc. and affiliates.
3 * All rights reserved.
4 *
5 * This source code is licensed under the BSD-style license found in the
6 * LICENSE file in the root directory of this source tree.
7 */
8
9//! Summaries of complete hermit runs.
10
11use std::fmt;
12use std::time::Duration;
13
14/// The backend dispatch record a run summary carries, re-exported so readers of
15/// summaries and verification reports need no direct Reverie dependency.
16pub use reverie::DispatchStats;
17use serde::Deserialize;
18use serde::Serialize;
19
20use crate::pid::DetTid;
21use crate::time::LogicalTime;
22
23/// Per-execution SaBRe path evidence written as one JSON object per line.
24///
25/// The Hermit SaBRe runner produces this record at the path named by
26/// `HERMIT_SABRE_PATH_EVIDENCE`; the manifest runner reads the same type before
27/// deciding whether a SaBRe cell exercised the intended path. Keep the wire
28/// fields here rather than independently defining the producer and reader
29/// shapes: a missing or renamed counter changes whether a cell is accepted.
30#[derive(Clone, Debug, Deserialize, Eq, PartialEq, Serialize)]
31#[serde(deny_unknown_fields)]
32pub struct PathEvidence {
33    pub schema: u8,
34    pub guest_rpc_observed: bool,
35    pub ptrace_fallback_sites: usize,
36    pub trusted_shared_object_sites: usize,
37    pub trusted_shared_objects: Vec<String>,
38}
39
40impl PathEvidence {
41    pub const SCHEMA: u8 = 1;
42}
43
44// AUTONOMOUS-BOT-IMPLEMENTED
45// TODO-HUMAN-REVIEW(#252): Confirm the overflow and rounding policy for long-running guests.
46/// Running distribution statistics over timeslice durations, measured in virtual
47/// nanoseconds. A "timeslice" is the span of virtual time a thread runs between
48/// two consecutive scheduler yields (i.e. between `end_of_timeslice` resets).
49#[derive(Debug, Serialize, Deserialize, Clone, Copy, PartialEq, Eq, Default)]
50pub struct TimesliceStats {
51    /// Number of completed timeslices recorded.
52    pub count: u64,
53    /// Sum of all timeslice durations, in virtual nanoseconds.
54    pub sum_ns: u64,
55    /// Smallest timeslice duration observed, in virtual nanoseconds (valid when `count > 0`).
56    pub min_ns: u64,
57    /// Largest timeslice duration observed, in virtual nanoseconds (valid when `count > 0`).
58    pub max_ns: u64,
59}
60
61impl TimesliceStats {
62    /// Record one completed timeslice of `ns` virtual nanoseconds.
63    pub fn record(&mut self, ns: u64) {
64        if self.count == 0 {
65            self.min_ns = ns;
66            self.max_ns = ns;
67        } else {
68            self.min_ns = self.min_ns.min(ns);
69            self.max_ns = self.max_ns.max(ns);
70        }
71        self.sum_ns += ns;
72        self.count += 1;
73    }
74
75    /// Fold another distribution into this one.
76    pub fn merge(&mut self, other: &TimesliceStats) {
77        if other.count == 0 {
78            return;
79        }
80        if self.count == 0 {
81            *self = *other;
82            return;
83        }
84        self.min_ns = self.min_ns.min(other.min_ns);
85        self.max_ns = self.max_ns.max(other.max_ns);
86        self.sum_ns += other.sum_ns;
87        self.count += other.count;
88    }
89
90    /// Mean timeslice duration in virtual nanoseconds (0 when no slices recorded).
91    pub fn mean_ns(&self) -> u64 {
92        self.sum_ns.checked_div(self.count).unwrap_or(0)
93    }
94
95    /// Whether any timeslices have been recorded.
96    pub fn is_empty(&self) -> bool {
97        self.count == 0
98    }
99}
100
101/// Statistics that summarize a hermit run.
102#[derive(Debug, Serialize, Deserialize, Clone, Default)]
103pub struct RunSummary {
104    /// Internal number of steps taken by the scheduler.
105    pub sched_turns: u64,
106
107    /// **Trace replay:** SchedEvents read and replayed from the input recording.
108    pub schedevent_replayed: u64,
109    /// **Trace replay:** SchedEvents recorded to disk during execution.
110    pub schedevent_recorded: u64,
111    /// **Trace replay:** Desync events that occurred while replaying SchedEvents.
112    pub schedevent_desynced: u64,
113
114    /// A human-readable summary of the desyncs that occurred.
115    pub desync_descrip: Option<String>,
116
117    /// A summary of when threads where preempted and reprioritized (for --chaos mode), e.g. --record-preemptions-to.
118    pub reprio_descrip: Option<String>,
119
120    /// A summary of the thread topology spawned by the guest.
121    pub threads_descrip: String,
122
123    /// The number of threads that were group leaders, i.e. processes.
124    pub num_processes: u64,
125    /// The number of total system threads that were created during the execution.
126    pub num_threads: u64,
127
128    /// Total syscalls completed by all guest threads.
129    #[serde(default, skip_serializing_if = "Option::is_none")]
130    pub syscalls: Option<u64>,
131
132    /// Deterministic virtual nanoseconds elapsed while computing.
133    pub virttime_elapsed: u64,
134    /// Absolute (virtual) time in nanoseconds since epoch at program completion.
135    pub virttime_final: u64,
136
137    /// **Nondeterministic:** Realtime in nanoseconds, i.e. wall-clock time elapsed.
138    pub realtime_elapsed: Option<Duration>,
139
140    /// Aggregate distribution of scheduler timeslice durations (virtual ns),
141    /// summed over all threads.
142    pub timeslice_stats: TimesliceStats,
143
144    /// Per-thread timeslice distributions, sorted by `DetTid` for deterministic
145    /// output.
146    pub per_thread_timeslice: Vec<(DetTid, TimesliceStats)>,
147
148    /// How the backend dispatched guest syscalls: through signals, patched
149    /// direct calls, or ptrace stops. The record carries its own schema
150    /// version. Absent when the run did not collect it or the backend has no
151    /// such dispatch (KVM). Deliberately not part of the human-readable
152    /// summary, whose INFO view is compared by `--verify`.
153    #[serde(default, skip_serializing_if = "Option::is_none")]
154    pub dispatch_stats: Option<DispatchStats>,
155}
156
157/// A human-readable, multi-line summary. Serialized report fields are unchanged.
158impl fmt::Display for RunSummary {
159    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
160        self.fmt_summary(f, true, self.reprio_descrip.as_deref())
161    }
162}
163
164/// INFO view built with the producer's preemption description, before its host
165/// destination is appended. It does not alter the full report or serialized fields.
166pub struct RunSummaryInfo<'a> {
167    summary: &'a RunSummary,
168    reprio_description: Option<&'a str>,
169}
170
171impl fmt::Display for RunSummaryInfo<'_> {
172    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
173        self.summary.fmt_summary(f, false, self.reprio_description)
174    }
175}
176
177impl RunSummary {
178    pub fn info<'a>(&'a self, reprio_description: Option<&'a str>) -> RunSummaryInfo<'a> {
179        RunSummaryInfo {
180            summary: self,
181            reprio_description,
182        }
183    }
184
185    fn fmt_summary(
186        &self,
187        f: &mut fmt::Formatter<'_>,
188        include_replay_bookkeeping: bool,
189        reprio_description: Option<&str>,
190    ) -> fmt::Result {
191        let RunSummary {
192            sched_turns,
193            schedevent_replayed,
194            schedevent_recorded,
195            schedevent_desynced,
196            desync_descrip,
197            reprio_descrip: _,
198            num_processes,
199            num_threads,
200            syscalls,
201            virttime_elapsed,
202            virttime_final,
203            realtime_elapsed,
204            threads_descrip,
205            timeslice_stats,
206            per_thread_timeslice,
207            dispatch_stats: _,
208        } = self;
209        writeln!(f, "Final thread-tree was: {}", threads_descrip)?;
210        writeln!(
211            f,
212            "There were {} group leaders of {} thread(s) total.",
213            num_processes, num_threads
214        )?;
215        if let Some(syscalls) = syscalls {
216            writeln!(f, "Guest threads completed {syscalls} syscalls.")?;
217        }
218        if include_replay_bookkeeping {
219            writeln!(
220                f,
221                "Internally, the hermit scheduler ran {} turns, recorded {} events, replayed {} events ({} desynced)",
222                sched_turns, schedevent_recorded, schedevent_replayed, schedevent_desynced,
223            )?;
224        } else {
225            writeln!(
226                f,
227                "Internally, the hermit scheduler ran {} turns, recorded {} events ({} desynced)",
228                sched_turns, schedevent_recorded, schedevent_desynced,
229            )?;
230        }
231
232        if let Some(txt) = desync_descrip {
233            write!(f, "{}", txt)?;
234        }
235        if let Some(txt) = reprio_description {
236            write!(f, "{}", txt)?;
237        }
238
239        writeln!(
240            f,
241            "Final virtual global (cpu) time: {}",
242            LogicalTime::from_nanos(*virttime_final)
243        )?;
244        writeln!(
245            f,
246            "Elapsed virtual global (cpu) time: {}",
247            LogicalTime::from_nanos(*virttime_elapsed)
248        )?;
249
250        if timeslice_stats.is_empty() {
251            writeln!(f, "Timeslice stats: none recorded")?;
252        } else {
253            writeln!(
254                f,
255                "Timeslice stats: min={}ns max={}ns mean={}ns count={}",
256                timeslice_stats.min_ns,
257                timeslice_stats.max_ns,
258                timeslice_stats.mean_ns(),
259                timeslice_stats.count,
260            )?;
261            // Per-thread breakdown (only informative when more than one thread
262            // recorded slices); shown as part of the report body.
263            if per_thread_timeslice.len() > 1 {
264                for (dettid, st) in per_thread_timeslice {
265                    if st.is_empty() {
266                        continue;
267                    }
268                    writeln!(
269                        f,
270                        "  timeslice thread {}: min={}ns max={}ns mean={}ns count={}",
271                        dettid,
272                        st.min_ns,
273                        st.max_ns,
274                        st.mean_ns(),
275                        st.count,
276                    )?;
277                }
278            }
279        }
280
281        if let Some(rt) = realtime_elapsed {
282            writeln!(f, "Nondeterministic realtime elapsed: {:?}", rt)?
283        };
284
285        Ok(())
286    }
287}
288
289/*
290  ------------------------------ hermit run report ------------------------------
291Final thread-tree was: [3]
292There were 1 group leaders of 1 thread(s) total.
293Internally, the hermit scheduler ran 8 turns, recorded 0 events, replayed 0 events (0 desynced)
294Nondeterministic realtime elapsed: 27.08914ms
295Final virtual global (cpu) time: 1_640_995_199.005_045_040s
296Elapsed virtual global (cpu) time: 5_045_040ns
297Timeslice stats: min=199999995ns max=200000000ns mean=199999998ns count=4
298*/
299
300#[cfg(test)]
301mod tests {
302    use super::PathEvidence;
303    use super::RunSummary;
304    use super::TimesliceStats;
305
306    #[test]
307    fn path_evidence_json_is_exact() {
308        let evidence = PathEvidence {
309            schema: PathEvidence::SCHEMA,
310            guest_rpc_observed: true,
311            ptrace_fallback_sites: 0,
312            trusted_shared_object_sites: 1,
313            trusted_shared_objects: vec!["/usr/lib/libc.so.6".into()],
314        };
315        let json = serde_json::to_string(&evidence).unwrap();
316        assert_eq!(
317            json,
318            r#"{"schema":1,"guest_rpc_observed":true,"ptrace_fallback_sites":0,"trusted_shared_object_sites":1,"trusted_shared_objects":["/usr/lib/libc.so.6"]}"#
319        );
320        assert_eq!(
321            serde_json::from_str::<PathEvidence>(&json).unwrap(),
322            evidence
323        );
324
325        let unknown = json.replace(
326            r#""trusted_shared_objects""#,
327            r#""unexpected":0,"trusted_shared_objects""#,
328        );
329        let error = serde_json::from_str::<PathEvidence>(&unknown).unwrap_err();
330        assert!(error.to_string().contains("unknown field `unexpected`"));
331
332        let missing = json.replace(r#""guest_rpc_observed":true,"#, "");
333        let error = serde_json::from_str::<PathEvidence>(&missing).unwrap_err();
334        assert!(
335            error
336                .to_string()
337                .contains("missing field `guest_rpc_observed`")
338        );
339    }
340
341    #[test]
342    fn timeslice_stats_empty() {
343        let s = TimesliceStats::default();
344        assert!(s.is_empty());
345        assert_eq!(s.count, 0);
346        assert_eq!(s.mean_ns(), 0); // no divide-by-zero
347    }
348
349    #[test]
350    fn timeslice_stats_record() {
351        let mut s = TimesliceStats::default();
352        s.record(10);
353        s.record(30);
354        s.record(20);
355        assert!(!s.is_empty());
356        assert_eq!(s.count, 3);
357        assert_eq!(s.min_ns, 10);
358        assert_eq!(s.max_ns, 30);
359        assert_eq!(s.sum_ns, 60);
360        assert_eq!(s.mean_ns(), 20);
361    }
362
363    #[test]
364    fn timeslice_stats_merge() {
365        let mut a = TimesliceStats::default();
366        a.record(10);
367        a.record(40);
368        let mut b = TimesliceStats::default();
369        b.record(5);
370        b.record(100);
371        a.merge(&b);
372        assert_eq!(a.count, 4);
373        assert_eq!(a.min_ns, 5);
374        assert_eq!(a.max_ns, 100);
375        assert_eq!(a.sum_ns, 155);
376
377        // Merging an empty distribution is a no-op.
378        let before = a;
379        a.merge(&TimesliceStats::default());
380        assert_eq!(a, before);
381
382        // Merging into an empty distribution adopts the other.
383        let mut empty = TimesliceStats::default();
384        empty.merge(&b);
385        assert_eq!(empty, b);
386    }
387
388    #[test]
389    fn older_summary_json_keeps_an_unrecorded_syscall_total_absent() {
390        let value = serde_json::to_value(RunSummary::default()).unwrap();
391        let mut object = value.as_object().unwrap().clone();
392        object.remove("syscalls");
393        let parsed: RunSummary = serde_json::from_value(object.into()).unwrap();
394        assert_eq!(parsed.syscalls, None);
395
396        let measured = RunSummary {
397            syscalls: Some(0),
398            ..Default::default()
399        };
400        let value = serde_json::to_value(&measured).unwrap();
401        assert_eq!(value["syscalls"], 0);
402        let parsed: RunSummary = serde_json::from_value(value).unwrap();
403        assert_eq!(parsed.syscalls, Some(0));
404    }
405}
detcore_model/summary.rs

detcore_model/
summary.rs
