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