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 log::debug;
112     use std::cell::{Cell, RefCell};
113     use std::fmt;
114     use std::mem;
115     use std::time::{Duration, Instant};
116 
117     /// A timing token is responsible for timing the currently running pass. Timing starts when it
118     /// is created and ends when it is dropped.
119     ///
120     /// Multiple passes can be active at the same time, but they must be started and stopped in a
121     /// LIFO fashion.
122     pub struct TimingToken {
123         /// Start time for this pass.
124         start: Instant,
125 
126         // Pass being timed by this token.
127         pass: Pass,
128 
129         // The previously active pass which will be restored when this token is dropped.
130         prev: Pass,
131     }
132 
133     /// Accumulated timing information for a single pass.
134     #[derive(Default, Copy, Clone)]
135     struct PassTime {
136         /// Total time spent running this pass including children.
137         total: Duration,
138 
139         /// Time spent running in child passes.
140         child: Duration,
141     }
142 
143     /// Accumulated timing for all passes.
144     pub struct PassTimes {
145         pass: [PassTime; NUM_PASSES],
146     }
147 
148     impl Default for PassTimes {
149         fn default() -> Self {
150             Self {
151                 pass: [Default::default(); NUM_PASSES],
152             }
153         }
154     }
155 
156     impl fmt::Display for PassTimes {
157         fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
158             writeln!(f, "======== ========  ==================================")?;
159             writeln!(f, "   Total     Self  Pass")?;
160             writeln!(f, "-------- --------  ----------------------------------")?;
161             for (time, desc) in self.pass.iter().zip(&DESCRIPTIONS[..]) {
162                 // Omit passes that haven't run.
163                 if time.total == Duration::default() {
164                     continue;
165                 }
166 
167                 // Write a duration as secs.millis, trailing space.
168                 fn fmtdur(mut dur: Duration, f: &mut fmt::Formatter) -> fmt::Result {
169                     // Round to nearest ms by adding 500us.
170                     dur += Duration::new(0, 500_000);
171                     let ms = dur.subsec_millis();
172                     write!(f, "{:4}.{:03} ", dur.as_secs(), ms)
173                 }
174 
175                 fmtdur(time.total, f)?;
176                 if let Some(s) = time.total.checked_sub(time.child) {
177                     fmtdur(s, f)?;
178                 }
179                 writeln!(f, " {}", desc)?;
180             }
181             writeln!(f, "======== ========  ==================================")
182         }
183     }
184 
185     // Information about passes in a single thread.
186     thread_local! {
187         static CURRENT_PASS: Cell<Pass> = Cell::new(Pass::None);
188         static PASS_TIME: RefCell<PassTimes> = RefCell::new(Default::default());
189     }
190 
191     /// Start timing `pass` as a child of the currently running pass, if any.
192     ///
193     /// This function is called by the publicly exposed pass functions.
194     pub(super) fn start_pass(pass: Pass) -> TimingToken {
195         let prev = CURRENT_PASS.with(|p| p.replace(pass));
196         debug!("timing: Starting {}, (during {})", pass, prev);
197         TimingToken {
198             start: Instant::now(),
199             pass,
200             prev,
201         }
202     }
203 
204     /// Dropping a timing token indicated the end of the pass.
205     impl Drop for TimingToken {
206         fn drop(&mut self) {
207             let duration = self.start.elapsed();
208             debug!("timing: Ending {}", self.pass);
209             let old_cur = CURRENT_PASS.with(|p| p.replace(self.prev));
210             debug_assert_eq!(self.pass, old_cur, "Timing tokens dropped out of order");
211             PASS_TIME.with(|rc| {
212                 let mut table = rc.borrow_mut();
213                 table.pass[self.pass.idx()].total += duration;
214                 if let Some(parent) = table.pass.get_mut(self.prev.idx()) {
215                     parent.child += duration;
216                 }
217             })
218         }
219     }
220 
221     /// Take the current accumulated pass timings and reset the timings for the current thread.
222     pub fn take_current() -> PassTimes {
223         PASS_TIME.with(|rc| mem::replace(&mut *rc.borrow_mut(), Default::default()))
224     }
225 
226     /// Add `timings` to the accumulated timings for the current thread.
227     pub fn add_to_current(times: &PassTimes) {
228         PASS_TIME.with(|rc| {
229             for (a, b) in rc.borrow_mut().pass.iter_mut().zip(&times.pass[..]) {
230                 a.total += b.total;
231                 a.child += b.child;
232             }
233         })
234     }
235 }
236 
237 /// Dummy `debug` implementation
238 #[cfg(not(feature = "std"))]
239 mod details {
240     use super::Pass;
241     /// Dummy `TimingToken`
242     pub struct TimingToken;
243     /// Dummy `PassTimes`
244     pub struct PassTimes;
245     /// Returns dummy `PassTimes`
246     pub fn take_current() -> PassTimes {
247         PassTimes
248     }
249     /// does nothing
250     pub fn add_to_current(_times: PassTimes) {}
251 
252     /// does nothing
253     pub(super) fn start_pass(_pass: Pass) -> TimingToken {
254         TimingToken
255     }
256 }
257 
258 #[cfg(test)]
259 mod tests {
260     use super::*;
261     use alloc::string::ToString;
262 
263     #[test]
264     fn display() {
265         assert_eq!(Pass::None.to_string(), "<no pass>");
266         assert_eq!(Pass::regalloc.to_string(), "Register allocation");
267     }
268 }
269