qcode_vm/stats.rs
1//! Where a run's time and work actually go.
2//!
3//! A machine like this has three phases, and they have wildly different costs
4//! per occurrence and wildly different frequencies:
5//!
6//! * **Fetch** — reading instruction bytes out of guest memory, through the
7//! MMU's execute permission.
8//! * **Decode and lift** — turning those bytes into QCode, plus the cleanup
9//! round over the result.
10//! * **Execute** — interpreting the QCode.
11//!
12//! Fetch and lift happen once per *distinct* instruction; execute happens once
13//! per instruction *executed*. So the split depends entirely on the workload: a
14//! tight loop is almost all execute, while a long straight-line run is dominated
15//! by lifting. Reporting one number for "throughput" without saying which
16//! workload produced it is how a benchmark misleads.
17//!
18//! Counting is always on and costs a few increments. Timing is only taken
19//! around lifting, which is rare; putting a clock read around each interpreter
20//! step would cost more than the step. Execute time is therefore derived —
21//! wall clock minus the measured phases — rather than measured directly.
22
23use std::time::Duration;
24
25/// Counters and timings for one machine's run.
26#[derive(Debug, Default, Clone)]
27pub struct Stats {
28 /// P-code operations retired.
29 pub steps: u64,
30 /// Times an address had to be lifted: a translation-cache **miss**.
31 pub lifts: u64,
32 /// Times execution left a block and the target was already lifted: a
33 /// translation-cache **hit** at the VM level.
34 ///
35 /// Both counters only see transitions that reach the VM. Most control flow
36 /// never does: a branch inside the lifted graph is a direct block
37 /// reference the interpreter follows without consulting any address index,
38 /// so a steady-state loop performs *no* translation-cache lookups at all.
39 /// Read a low `resolves` next to a high `steps` as "control flow is
40 /// already resolved", not as "the cache is missing".
41 pub resolves: u64,
42 /// Block bodies executed by an installed [`BlockExecutor`](crate::BlockExecutor)
43 /// rather than interpreted.
44 pub native_bodies: u64,
45 /// Blocks folded into a predecessor as a guest basic block was discovered,
46 /// each one a unit the machine no longer enters and leaves separately.
47 pub absorbed: u64,
48 /// Instruction bytes read from guest memory.
49 pub fetch_bytes: u64,
50 /// Time spent reading instruction bytes.
51 pub fetch: Duration,
52 /// Time spent decoding and lowering to QCode.
53 pub decode_lift: Duration,
54 /// Time spent in the block-local cleanup round.
55 pub optimize: Duration,
56 /// Loads forwarded to their stored value by the cleanup round.
57 pub forwarded_loads: u64,
58 /// Stores removed by the cleanup round.
59 pub removed_stores: u64,
60}
61
62impl Stats {
63 /// Total time in the fetch and translation phases.
64 pub fn translation(&self) -> Duration {
65 self.fetch + self.decode_lift + self.optimize
66 }
67
68 /// The share of `elapsed` spent executing rather than translating.
69 ///
70 /// Derived, so it also absorbs whatever the VM spends on its own
71 /// bookkeeping; it is an upper bound on interpretation cost, not an exact
72 /// measure of it.
73 pub fn execute(&self, elapsed: Duration) -> Duration {
74 elapsed.saturating_sub(self.translation())
75 }
76
77 /// Translation-cache hit rate over the transitions the VM observed.
78 /// `None` when there were no transitions to rate.
79 pub fn hit_rate(&self) -> Option<f64> {
80 let total = self.lifts + self.resolves;
81 (total > 0).then(|| self.resolves as f64 / total as f64)
82 }
83
84 /// A one-line breakdown suitable for a benchmark to print.
85 pub fn report(&self, elapsed: Duration) -> String {
86 let percent = |part: Duration| {
87 if elapsed.is_zero() {
88 0.0
89 } else {
90 part.as_secs_f64() / elapsed.as_secs_f64() * 100.0
91 }
92 };
93 format!(
94 "steps={} lifts={} (translated) resolves={} (re-entered) lookup_hit_rate={} | \
95 fetch={:?} ({:.1}%) decode+lift={:?} ({:.1}%) optimize={:?} ({:.1}%) \
96 execute={:?} ({:.1}%)",
97 self.steps,
98 self.lifts,
99 self.resolves,
100 self.hit_rate()
101 .map_or_else(|| "n/a".to_owned(), |rate| format!("{:.1}%", rate * 100.0)),
102 self.fetch,
103 percent(self.fetch),
104 self.decode_lift,
105 percent(self.decode_lift),
106 self.optimize,
107 percent(self.optimize),
108 self.execute(elapsed),
109 percent(self.execute(elapsed)),
110 )
111 }
112}
113
114#[cfg(test)]
115mod tests {
116 use super::*;
117
118 #[test]
119 fn execute_time_is_what_translation_did_not_take() {
120 let stats = Stats {
121 fetch: Duration::from_millis(10),
122 decode_lift: Duration::from_millis(30),
123 optimize: Duration::from_millis(10),
124 ..Stats::default()
125 };
126 assert_eq!(stats.translation(), Duration::from_millis(50));
127 assert_eq!(
128 stats.execute(Duration::from_millis(200)),
129 Duration::from_millis(150)
130 );
131 }
132
133 #[test]
134 fn execute_time_never_goes_negative() {
135 // Timer skew must not produce a nonsense figure.
136 let stats = Stats {
137 decode_lift: Duration::from_millis(100),
138 ..Stats::default()
139 };
140 assert_eq!(stats.execute(Duration::from_millis(10)), Duration::ZERO);
141 }
142
143 #[test]
144 fn hit_rate_needs_transitions_to_rate() {
145 assert_eq!(Stats::default().hit_rate(), None);
146 let stats = Stats {
147 lifts: 1,
148 resolves: 3,
149 ..Stats::default()
150 };
151 assert_eq!(stats.hit_rate(), Some(0.75));
152 }
153}