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 #[must_use] 33 pub fn $pass() -> TimingToken { 34 details::start_pass($enum::$pass) 35 } 36 )+ 37 } 38 } 39 40 // Pass definitions. 41 define_passes! { 42 Pass, NUM_PASSES, DESCRIPTIONS; 43 44 // All these are used in other crates but defined here so they appear in the unified 45 // `PassTimes` output. 46 process_file: "Processing test file", 47 parse_text: "Parsing textual Cranelift IR", 48 wasm_translate_module: "Translate WASM module", 49 wasm_translate_function: "Translate WASM function", 50 51 verifier: "Verify Cranelift IR", 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 gvn: "Global value numbering", 61 licm: "Loop invariant code motion", 62 unreachable_code: "Remove unreachable blocks", 63 remove_constant_phis: "Remove constant phi-nodes", 64 65 vcode_lower: "VCode lowering", 66 vcode_emit: "VCode emission", 67 vcode_emit_finish: "VCode emission finalization", 68 69 regalloc: "Register allocation", 70 regalloc_checker: "Register allocation symbolic verification", 71 binemit: "Binary machine code emission", 72 layout_renumber: "Layout full renumbering", 73 74 canonicalize_nans: "Canonicalization of NaNs", 75 } 76 77 impl Pass { 78 pub fn idx(self) -> usize { 79 self as usize 80 } 81 } 82 83 impl fmt::Display for Pass { 84 fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { 85 match DESCRIPTIONS.get(self.idx()) { 86 Some(s) => f.write_str(s), 87 None => f.write_str("<no pass>"), 88 } 89 } 90 } 91 92 /// Implementation details. 93 /// 94 /// This whole module can be gated on a `cfg` feature to provide a dummy implementation for 95 /// performance-sensitive builds or restricted environments. The dummy implementation must provide 96 /// `TimingToken` and `PassTimes` types and `take_current`, `add_to_current`, and `start_pass` funcs 97 #[cfg(feature = "std")] 98 mod details { 99 use super::{Pass, DESCRIPTIONS, NUM_PASSES}; 100 use std::cell::{Cell, RefCell}; 101 use std::fmt; 102 use std::mem; 103 use std::time::{Duration, Instant}; 104 105 /// A timing token is responsible for timing the currently running pass. Timing starts when it 106 /// is created and ends when it is dropped. 107 /// 108 /// Multiple passes can be active at the same time, but they must be started and stopped in a 109 /// LIFO fashion. 110 pub struct TimingToken { 111 /// Start time for this pass. 112 start: Instant, 113 114 // Pass being timed by this token. 115 pass: Pass, 116 117 // The previously active pass which will be restored when this token is dropped. 118 prev: Pass, 119 } 120 121 /// Accumulated timing information for a single pass. 122 #[derive(Default, Copy, Clone)] 123 struct PassTime { 124 /// Total time spent running this pass including children. 125 total: Duration, 126 127 /// Time spent running in child passes. 128 child: Duration, 129 } 130 131 /// Accumulated timing for all passes. 132 pub struct PassTimes { 133 pass: [PassTime; NUM_PASSES], 134 } 135 136 impl PassTimes { 137 /// Returns the total amount of time taken by all the passes measured. 138 pub fn total(&self) -> Duration { 139 self.pass.iter().map(|p| p.total - p.child).sum() 140 } 141 } 142 143 impl Default for PassTimes { 144 fn default() -> Self { 145 Self { 146 pass: [Default::default(); NUM_PASSES], 147 } 148 } 149 } 150 151 impl fmt::Display for PassTimes { 152 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> = const { 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. 189 pub(super) fn start_pass(pass: Pass) -> TimingToken { 190 let prev = CURRENT_PASS.with(|p| p.replace(pass)); 191 log::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 { 201 fn drop(&mut self) { 202 let duration = self.start.elapsed(); 203 log::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. 217 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. 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` 241 pub fn take_current() -> PassTimes { 242 PassTimes 243 } 244 /// does nothing 245 pub fn add_to_current(_times: PassTimes) {} 246 247 /// does nothing 248 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] 259 fn display() { 260 assert_eq!(Pass::None.to_string(), "<no pass>"); 261 assert_eq!(Pass::regalloc.to_string(), "Register allocation"); 262 } 263 } 264