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