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