src/librustc/util/profiling.rs

   1 use crate::session::config::Options;
   2
   3 use std::fs;
   4 use std::io::{self, StderrLock, Write};
   5 use std::time::Instant;
   6
   7 macro_rules! define_categories {
   8     ($($name:ident,)*) => {
   9         #[derive(Clone, Copy, Debug, PartialEq, Eq)]
  10         pub enum ProfileCategory {
  11             $($name),*
  12         }
  13
  14         #[allow(nonstandard_style)]
  15         struct Categories<T> {
  16             $($name: T),*
  17         }
  18
  19         impl<T: Default> Categories<T> {
  20             fn new() -> Categories<T> {
  21                 Categories {
  22                     $($name: T::default()),*
  23                 }
  24             }
  25         }
  26
  27         impl<T> Categories<T> {
  28             fn get(&self, category: ProfileCategory) -> &T {
  29                 match category {
  30                     $(ProfileCategory::$name => &self.$name),*
  31                 }
  32             }
  33
  34             fn set(&mut self, category: ProfileCategory, value: T) {
  35                 match category {
  36                     $(ProfileCategory::$name => self.$name = value),*
  37                 }
  38             }
  39         }
  40
  41         struct CategoryData {
  42             times: Categories<u64>,
  43             query_counts: Categories<(u64, u64)>,
  44         }
  45
  46         impl CategoryData {
  47             fn new() -> CategoryData {
  48                 CategoryData {
  49                     times: Categories::new(),
  50                     query_counts: Categories::new(),
  51                 }
  52             }
  53
  54             fn print(&self, lock: &mut StderrLock<'_>) {
  55                 writeln!(lock, "| Phase            | Time (ms)      \
  56                                 | Time (%) | Queries        | Hits (%)")
  57                     .unwrap();
  58                 writeln!(lock, "| ---------------- | -------------- \
  59                                 | -------- | -------------- | --------")
  60                     .unwrap();
  61
  62                 let total_time = ($(self.times.$name + )* 0) as f32;
  63
  64                 $(
  65                     let (hits, computed) = self.query_counts.$name;
  66                     let total = hits + computed;
  67                     let (hits, total) = if total > 0 {
  68                         (format!("{:.2}",
  69                         (((hits as f32) / (total as f32)) * 100.0)), total.to_string())
  70                     } else {
  71                         (String::new(), String::new())
  72                     };
  73
  74                     writeln!(
  75                         lock,
  76                         "| {0: <16} | {1: <14} | {2: <8.2} | {3: <14} | {4: <8}",
  77                         stringify!($name),
  78                         self.times.$name / 1_000_000,
  79                         ((self.times.$name as f32) / total_time) * 100.0,
  80                         total,
  81                         hits,
  82                     ).unwrap();
  83                 )*
  84             }
  85
  86             fn json(&self) -> String {
  87                 let mut json = String::from("[");
  88
  89                 $(
  90                     let (hits, computed) = self.query_counts.$name;
  91                     let total = hits + computed;
  92
  93                     //normalize hits to 0%
  94                     let hit_percent =
  95                         if total > 0 {
  96                             ((hits as f32) / (total as f32)) * 100.0
  97                         } else {
  98                             0.0
  99                         };
 100
 101                     json.push_str(&format!(
 102                         "{{ \"category\": \"{}\", \"time_ms\": {},\
 103                             \"query_count\": {}, \"query_hits\": {} }},",
 104                         stringify!($name),
 105                         self.times.$name / 1_000_000,
 106                         total,
 107                         format!("{:.2}", hit_percent)
 108                     ));
 109                 )*
 110
 111                 //remove the trailing ',' character
 112                 json.pop();
 113
 114                 json.push(']');
 115
 116                 json
 117             }
 118         }
 119     }
 120 }
 121
 122 define_categories! {
 123     Parsing,
 124     Expansion,
 125     TypeChecking,
 126     BorrowChecking,
 127     Codegen,
 128     Linking,
 129     Other,
 130 }
 131
 132 pub struct SelfProfiler {
 133     timer_stack: Vec<ProfileCategory>,
 134     data: CategoryData,
 135     current_timer: Instant,
 136 }
 137
 138 impl SelfProfiler {
 139     pub fn new() -> SelfProfiler {
 140         let mut profiler = SelfProfiler {
 141             timer_stack: Vec::new(),
 142             data: CategoryData::new(),
 143             current_timer: Instant::now(),
 144         };
 145
 146         profiler.start_activity(ProfileCategory::Other);
 147
 148         profiler
 149     }
 150
 151     pub fn start_activity(&mut self, category: ProfileCategory) {
 152         match self.timer_stack.last().cloned() {
 153             None => {
 154                 self.current_timer = Instant::now();
 155             },
 156             Some(current_category) if current_category == category => {
 157                 //since the current category is the same as the new activity's category,
 158                 //we don't need to do anything with the timer, we just need to push it on the stack
 159             }
 160             Some(current_category) => {
 161                 let elapsed = self.stop_timer();
 162
 163                 //record the current category's time
 164                 let new_time = self.data.times.get(current_category) + elapsed;
 165                 self.data.times.set(current_category, new_time);
 166             }
 167         }
 168
 169         //push the new category
 170         self.timer_stack.push(category);
 171     }
 172
 173     pub fn record_computed_queries(&mut self, category: ProfileCategory, count: usize) {
 174         let (hits, computed) = *self.data.query_counts.get(category);
 175         self.data.query_counts.set(category, (hits, computed + count as u64));
 176     }
 177
 178     pub fn record_query_hit(&mut self, category: ProfileCategory) {
 179         let (hits, computed) = *self.data.query_counts.get(category);
 180         self.data.query_counts.set(category, (hits + 1, computed));
 181     }
 182
 183     pub fn end_activity(&mut self, category: ProfileCategory) {
 184         match self.timer_stack.pop() {
 185             None => bug!("end_activity() was called but there was no running activity"),
 186             Some(c) =>
 187                 assert!(
 188                     c == category,
 189                     "end_activity() was called but a different activity was running"),
 190         }
 191
 192         //check if the new running timer is in the same category as this one
 193         //if it is, we don't need to do anything
 194         if let Some(c) = self.timer_stack.last() {
 195             if *c == category {
 196                 return;
 197             }
 198         }
 199
 200         //the new timer is different than the previous,
 201         //so record the elapsed time and start a new timer
 202         let elapsed = self.stop_timer();
 203         let new_time = self.data.times.get(category) + elapsed;
 204         self.data.times.set(category, new_time);
 205     }
 206
 207     fn stop_timer(&mut self) -> u64 {
 208         let elapsed = self.current_timer.elapsed();
 209
 210         self.current_timer = Instant::now();
 211
 212         (elapsed.as_secs() * 1_000_000_000) + (elapsed.subsec_nanos() as u64)
 213     }
 214
 215     pub fn print_results(&mut self, opts: &Options) {
 216         self.end_activity(ProfileCategory::Other);
 217
 218         assert!(
 219             self.timer_stack.is_empty(),
 220             "there were timers running when print_results() was called");
 221
 222         let out = io::stderr();
 223         let mut lock = out.lock();
 224
 225         let crate_name =
 226             opts.crate_name
 227             .as_ref()
 228             .map(|n| format!(" for {}", n))
 229             .unwrap_or_default();
 230
 231         writeln!(lock, "Self profiling results{}:", crate_name).unwrap();
 232         writeln!(lock).unwrap();
 233
 234         self.data.print(&mut lock);
 235
 236         writeln!(lock).unwrap();
 237         writeln!(lock, "Optimization level: {:?}", opts.optimize).unwrap();
 238
 239         let incremental = if opts.incremental.is_some() { "on" } else { "off" };
 240         writeln!(lock, "Incremental: {}", incremental).unwrap();
 241     }
 242
 243     pub fn save_results(&self, opts: &Options) {
 244         let category_data = self.data.json();
 245         let compilation_options =
 246             format!("{{ \"optimization_level\": \"{:?}\", \"incremental\": {} }}",
 247                     opts.optimize,
 248                     if opts.incremental.is_some() { "true" } else { "false" });
 249
 250         let json = format!("{{ \"category_data\": {}, \"compilation_options\": {} }}",
 251                         category_data,
 252                         compilation_options);
 253
 254         fs::write("self_profiler_results.json", json).unwrap();
 255     }
 256 }