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