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     postopt: "Post-legalization rewriting",
59     preopt: "Pre-legalization rewriting",
60     dce: "Dead code elimination",
61     legalize: "Legalization",
62     gvn: "Global value numbering",
63     licm: "Loop invariant code motion",
64     unreachable_code: "Remove unreachable blocks",
65     remove_constant_phis: "Remove constant phi-nodes",
66 
67     vcode_lower: "VCode lowering",
68     vcode_post_ra: "VCode post-register allocation finalization",
69     vcode_emit: "VCode emission",
70     vcode_emit_finish: "VCode emission finalization",
71 
72     regalloc: "Register allocation",
73     ra_liveness: "RA liveness analysis",
74     ra_cssa: "RA coalescing CSSA",
75     ra_spilling: "RA spilling",
76     ra_reload: "RA reloading",
77     ra_coloring: "RA coloring",
78 
79     prologue_epilogue: "Prologue/epilogue insertion",
80     shrink_instructions: "Instruction encoding shrinking",
81     relax_branches: "Branch relaxation",
82     binemit: "Binary machine code emission",
83     layout_renumber: "Layout full renumbering",
84 
85     canonicalize_nans: "Canonicalization of NaNs",
86 }
87 
88 impl Pass {
89     pub fn idx(self) -> usize {
90         self as usize
91     }
92 }
93 
94 impl fmt::Display for Pass {
95     fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
96         match DESCRIPTIONS.get(self.idx()) {
97             Some(s) => f.write_str(s),
98             None => f.write_str("<no pass>"),
99         }
100     }
101 }
102 
103 /// Implementation details.
104 ///
105 /// This whole module can be gated on a `cfg` feature to provide a dummy implementation for
106 /// performance-sensitive builds or restricted environments. The dummy implementation must provide
107 /// `TimingToken` and `PassTimes` types and `take_current`, `add_to_current`, and `start_pass` funcs
108 #[cfg(feature = "std")]
109 mod details {
110     use super::{Pass, DESCRIPTIONS, NUM_PASSES};
111     use std::cell::{Cell, RefCell};
112     use std::fmt;
113     use std::mem;
114     use std::time::{Duration, Instant};
115 
116     /// A timing token is responsible for timing the currently running pass. Timing starts when it
117     /// is created and ends when it is dropped.
118     ///
119     /// Multiple passes can be active at the same time, but they must be started and stopped in a
120     /// LIFO fashion.
121     pub struct TimingToken {
122         /// Start time for this pass.
123         start: Instant,
124 
125         // Pass being timed by this token.
126         pass: Pass,
127 
128         // The previously active pass which will be restored when this token is dropped.
129         prev: Pass,
130     }
131 
132     /// Accumulated timing information for a single pass.
133     #[derive(Default, Copy, Clone)]
134     struct PassTime {
135         /// Total time spent running this pass including children.
136         total: Duration,
137 
138         /// Time spent running in child passes.
139         child: Duration,
140     }
141 
142     /// Accumulated timing for all passes.
143     pub struct PassTimes {
144         pass: [PassTime; NUM_PASSES],
145     }
146 
147     impl Default for PassTimes {
148         fn default() -> Self {
149             Self {
150                 pass: [Default::default(); NUM_PASSES],
151             }
152         }
153     }
154 
155     impl fmt::Display for PassTimes {
156         fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
157             writeln!(f, "======== ========  ==================================")?;
158             writeln!(f, "   Total     Self  Pass")?;
159             writeln!(f, "-------- --------  ----------------------------------")?;
160             for (time, desc) in self.pass.iter().zip(&DESCRIPTIONS[..]) {
161                 // Omit passes that haven't run.
162                 if time.total == Duration::default() {
163                     continue;
164                 }
165 
166                 // Write a duration as secs.millis, trailing space.
167                 fn fmtdur(mut dur: Duration, f: &mut fmt::Formatter) -> fmt::Result {
168                     // Round to nearest ms by adding 500us.
169                     dur += Duration::new(0, 500_000);
170                     let ms = dur.subsec_millis();
171                     write!(f, "{:4}.{:03} ", dur.as_secs(), ms)
172                 }
173 
174                 fmtdur(time.total, f)?;
175                 if let Some(s) = time.total.checked_sub(time.child) {
176                     fmtdur(s, f)?;
177                 }
178                 writeln!(f, " {}", desc)?;
179             }
180             writeln!(f, "======== ========  ==================================")
181         }
182     }
183 
184     // Information about passes in a single thread.
185     thread_local! {
186         static CURRENT_PASS: Cell<Pass> = Cell::new(Pass::None);
187         static PASS_TIME: RefCell<PassTimes> = RefCell::new(Default::default());
188     }
189 
190     /// Start timing `pass` as a child of the currently running pass, if any.
191     ///
192     /// This function is called by the publicly exposed pass functions.
193     pub(super) fn start_pass(pass: Pass) -> TimingToken {
194         let prev = CURRENT_PASS.with(|p| p.replace(pass));
195         log::debug!("timing: Starting {}, (during {})", pass, prev);
196         TimingToken {
197             start: Instant::now(),
198             pass,
199             prev,
200         }
201     }
202 
203     /// Dropping a timing token indicated the end of the pass.
204     impl Drop for TimingToken {
205         fn drop(&mut self) {
206             let duration = self.start.elapsed();
207             log::debug!("timing: Ending {}", self.pass);
208             let old_cur = CURRENT_PASS.with(|p| p.replace(self.prev));
209             debug_assert_eq!(self.pass, old_cur, "Timing tokens dropped out of order");
210             PASS_TIME.with(|rc| {
211                 let mut table = rc.borrow_mut();
212                 table.pass[self.pass.idx()].total += duration;
213                 if let Some(parent) = table.pass.get_mut(self.prev.idx()) {
214                     parent.child += duration;
215                 }
216             })
217         }
218     }
219 
220     /// Take the current accumulated pass timings and reset the timings for the current thread.
221     pub fn take_current() -> PassTimes {
222         PASS_TIME.with(|rc| mem::replace(&mut *rc.borrow_mut(), Default::default()))
223     }
224 
225     /// Add `timings` to the accumulated timings for the current thread.
226     pub fn add_to_current(times: &PassTimes) {
227         PASS_TIME.with(|rc| {
228             for (a, b) in rc.borrow_mut().pass.iter_mut().zip(&times.pass[..]) {
229                 a.total += b.total;
230                 a.child += b.child;
231             }
232         })
233     }
234 }
235 
236 /// Dummy `debug` implementation
237 #[cfg(not(feature = "std"))]
238 mod details {
239     use super::Pass;
240     /// Dummy `TimingToken`
241     pub struct TimingToken;
242     /// Dummy `PassTimes`
243     pub struct PassTimes;
244     /// Returns dummy `PassTimes`
245     pub fn take_current() -> PassTimes {
246         PassTimes
247     }
248     /// does nothing
249     pub fn add_to_current(_times: PassTimes) {}
250 
251     /// does nothing
252     pub(super) fn start_pass(_pass: Pass) -> TimingToken {
253         TimingToken
254     }
255 }
256 
257 #[cfg(test)]
258 mod tests {
259     use super::*;
260     use alloc::string::ToString;
261 
262     #[test]
263     fn display() {
264         assert_eq!(Pass::None.to_string(), "<no pass>");
265         assert_eq!(Pass::regalloc.to_string(), "Register allocation");
266     }
267 }
268