1 //! Pass timing.
2 //!
3 //! This modules provides facilities for timing the execution of individual compilation passes.
4 
5 use core::fmt;
6 
7 pub use self::details::{add_to_current, take_current, PassTimes, TimingToken};
8 
9 // Each pass that can be timed is predefined with the `define_passes!` macro. Each pass has a
10 // snake_case name and a plain text description used when printing out the timing report.
11 //
12 // This macro defines:
13 //
14 // - A C-style enum containing all the pass names and a `None` variant.
15 // - A usize constant with the number of defined passes.
16 // - A const array of pass descriptions.
17 // - A public function per pass used to start the timing of that pass.
18 macro_rules! define_passes {
19     { $enum:ident, $num_passes:ident, $descriptions:ident;
20       $($pass:ident: $desc:expr,)+
21     } => {
22         #[allow(non_camel_case_types)]
23         #[derive(Clone, Copy, Debug, PartialEq, Eq)]
24         enum $enum { $($pass,)+ None}
25 
26         const $num_passes: usize = $enum::None as usize;
27 
28         const $descriptions: [&str; $num_passes] = [ $($desc),+ ];
29 
30         $(
31             #[doc=$desc]
32             pub fn $pass() -> TimingToken {
33                 details::start_pass($enum::$pass)
34             }
35         )+
36     }
37 }
38 
39 // Pass definitions.
40 define_passes! {
41     Pass, NUM_PASSES, DESCRIPTIONS;
42 
43     process_file: "Processing test file",
44     parse_text: "Parsing textual Cranelift IR",
45     wasm_translate_module: "Translate WASM module",
46     wasm_translate_function: "Translate WASM function",
47 
48     verifier: "Verify Cranelift IR",
49     verify_cssa: "Verify CSSA",
50     verify_liveness: "Verify live ranges",
51     verify_locations: "Verify value locations",
52     verify_flags: "Verify CPU flags",
53 
54     compile: "Compilation passes",
55     flowgraph: "Control flow graph",
56     domtree: "Dominator tree",
57     loop_analysis: "Loop analysis",
58     preopt: "Pre-legalization rewriting",
59     dce: "Dead code elimination",
60     legalize: "Legalization",
61     gvn: "Global value numbering",
62     licm: "Loop invariant code motion",
63     unreachable_code: "Remove unreachable blocks",
64     remove_constant_phis: "Remove constant phi-nodes",
65 
66     vcode_lower: "VCode lowering",
67     vcode_post_ra: "VCode post-register allocation finalization",
68     vcode_emit: "VCode emission",
69     vcode_emit_finish: "VCode emission finalization",
70 
71     regalloc: "Register allocation",
72     ra_liveness: "RA liveness analysis",
73     ra_cssa: "RA coalescing CSSA",
74     ra_spilling: "RA spilling",
75     ra_reload: "RA reloading",
76     ra_coloring: "RA coloring",
77 
78     prologue_epilogue: "Prologue/epilogue insertion",
79     shrink_instructions: "Instruction encoding shrinking",
80     relax_branches: "Branch relaxation",
81     binemit: "Binary machine code emission",
82     layout_renumber: "Layout full renumbering",
83 
84     canonicalize_nans: "Canonicalization of NaNs",
85 }
86 
87 impl Pass {
88     pub fn idx(self) -> usize {
89         self as usize
90     }
91 }
92 
93 impl fmt::Display for Pass {
94     fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
95         match DESCRIPTIONS.get(self.idx()) {
96             Some(s) => f.write_str(s),
97             None => f.write_str("<no pass>"),
98         }
99     }
100 }
101 
102 /// Implementation details.
103 ///
104 /// This whole module can be gated on a `cfg` feature to provide a dummy implementation for
105 /// performance-sensitive builds or restricted environments. The dummy implementation must provide
106 /// `TimingToken` and `PassTimes` types and `take_current`, `add_to_current`, and `start_pass` funcs
107 #[cfg(feature = "std")]
108 mod details {
109     use super::{Pass, DESCRIPTIONS, NUM_PASSES};
110     use std::cell::{Cell, RefCell};
111     use std::fmt;
112     use std::mem;
113     use std::time::{Duration, Instant};
114 
115     /// A timing token is responsible for timing the currently running pass. Timing starts when it
116     /// is created and ends when it is dropped.
117     ///
118     /// Multiple passes can be active at the same time, but they must be started and stopped in a
119     /// LIFO fashion.
120     pub struct TimingToken {
121         /// Start time for this pass.
122         start: Instant,
123 
124         // Pass being timed by this token.
125         pass: Pass,
126 
127         // The previously active pass which will be restored when this token is dropped.
128         prev: Pass,
129     }
130 
131     /// Accumulated timing information for a single pass.
132     #[derive(Default, Copy, Clone)]
133     struct PassTime {
134         /// Total time spent running this pass including children.
135         total: Duration,
136 
137         /// Time spent running in child passes.
138         child: Duration,
139     }
140 
141     /// Accumulated timing for all passes.
142     pub struct PassTimes {
143         pass: [PassTime; NUM_PASSES],
144     }
145 
146     impl Default for PassTimes {
147         fn default() -> Self {
148             Self {
149                 pass: [Default::default(); NUM_PASSES],
150             }
151         }
152     }
153 
154     impl fmt::Display for PassTimes {
155         fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
156             writeln!(f, "======== ========  ==================================")?;
157             writeln!(f, "   Total     Self  Pass")?;
158             writeln!(f, "-------- --------  ----------------------------------")?;
159             for (time, desc) in self.pass.iter().zip(&DESCRIPTIONS[..]) {
160                 // Omit passes that haven't run.
161                 if time.total == Duration::default() {
162                     continue;
163                 }
164 
165                 // Write a duration as secs.millis, trailing space.
166                 fn fmtdur(mut dur: Duration, f: &mut fmt::Formatter) -> fmt::Result {
167                     // Round to nearest ms by adding 500us.
168                     dur += Duration::new(0, 500_000);
169                     let ms = dur.subsec_millis();
170                     write!(f, "{:4}.{:03} ", dur.as_secs(), ms)
171                 }
172 
173                 fmtdur(time.total, f)?;
174                 if let Some(s) = time.total.checked_sub(time.child) {
175                     fmtdur(s, f)?;
176                 }
177                 writeln!(f, " {}", desc)?;
178             }
179             writeln!(f, "======== ========  ==================================")
180         }
181     }
182 
183     // Information about passes in a single thread.
184     thread_local! {
185         static CURRENT_PASS: Cell<Pass> = Cell::new(Pass::None);
186         static PASS_TIME: RefCell<PassTimes> = RefCell::new(Default::default());
187     }
188 
189     /// Start timing `pass` as a child of the currently running pass, if any.
190     ///
191     /// This function is called by the publicly exposed pass functions.
192     pub(super) fn start_pass(pass: Pass) -> TimingToken {
193         let prev = CURRENT_PASS.with(|p| p.replace(pass));
194         log::debug!("timing: Starting {}, (during {})", pass, prev);
195         TimingToken {
196             start: Instant::now(),
197             pass,
198             prev,
199         }
200     }
201 
202     /// Dropping a timing token indicated the end of the pass.
203     impl Drop for TimingToken {
204         fn drop(&mut self) {
205             let duration = self.start.elapsed();
206             log::debug!("timing: Ending {}", self.pass);
207             let old_cur = CURRENT_PASS.with(|p| p.replace(self.prev));
208             debug_assert_eq!(self.pass, old_cur, "Timing tokens dropped out of order");
209             PASS_TIME.with(|rc| {
210                 let mut table = rc.borrow_mut();
211                 table.pass[self.pass.idx()].total += duration;
212                 if let Some(parent) = table.pass.get_mut(self.prev.idx()) {
213                     parent.child += duration;
214                 }
215             })
216         }
217     }
218 
219     /// Take the current accumulated pass timings and reset the timings for the current thread.
220     pub fn take_current() -> PassTimes {
221         PASS_TIME.with(|rc| mem::replace(&mut *rc.borrow_mut(), Default::default()))
222     }
223 
224     /// Add `timings` to the accumulated timings for the current thread.
225     pub fn add_to_current(times: &PassTimes) {
226         PASS_TIME.with(|rc| {
227             for (a, b) in rc.borrow_mut().pass.iter_mut().zip(&times.pass[..]) {
228                 a.total += b.total;
229                 a.child += b.child;
230             }
231         })
232     }
233 }
234 
235 /// Dummy `debug` implementation
236 #[cfg(not(feature = "std"))]
237 mod details {
238     use super::Pass;
239     /// Dummy `TimingToken`
240     pub struct TimingToken;
241     /// Dummy `PassTimes`
242     pub struct PassTimes;
243     /// Returns dummy `PassTimes`
244     pub fn take_current() -> PassTimes {
245         PassTimes
246     }
247     /// does nothing
248     pub fn add_to_current(_times: PassTimes) {}
249 
250     /// does nothing
251     pub(super) fn start_pass(_pass: Pass) -> TimingToken {
252         TimingToken
253     }
254 }
255 
256 #[cfg(test)]
257 mod tests {
258     use super::*;
259     use alloc::string::ToString;
260 
261     #[test]
262     fn display() {
263         assert_eq!(Pass::None.to_string(), "<no pass>");
264         assert_eq!(Pass::regalloc.to_string(), "Register allocation");
265     }
266 }
267