src/librustc/util/profiling.rs

   1 // Copyright 2018 The Rust Project Developers. See the COPYRIGHT
   2 // file at the top-level directory of this distribution and at
   3 // http://rust-lang.org/COPYRIGHT.
   4 //
   5 // Licensed under the Apache License, Version 2.0 <LICENSE-APACHE or
   6 // http://www.apache.org/licenses/LICENSE-2.0> or the MIT license
   7 // <LICENSE-MIT or http://opensource.org/licenses/MIT>, at your
   8 // option. This file may not be copied, modified, or distributed
   9 // except according to those terms.
  10
  11 use session::config::Options;
  12
  13 use std::fs;
  14 use std::io::{self, StdoutLock, Write};
  15 use std::time::Instant;
  16
  17 #[derive(Clone, Copy, Debug, PartialEq, Eq, Hash)]
  18 pub enum ProfileCategory {
  19     Parsing,
  20     Expansion,
  21     TypeChecking,
  22     BorrowChecking,
  23     Codegen,
  24     Linking,
  25     Other,
  26 }
  27
  28 struct Categories<T> {
  29     parsing: T,
  30     expansion: T,
  31     type_checking: T,
  32     borrow_checking: T,
  33     codegen: T,
  34     linking: T,
  35     other: T,
  36 }
  37
  38 impl<T: Default> Categories<T> {
  39     fn new() -> Categories<T> {
  40         Categories {
  41             parsing: T::default(),
  42             expansion: T::default(),
  43             type_checking: T::default(),
  44             borrow_checking: T::default(),
  45             codegen: T::default(),
  46             linking: T::default(),
  47             other: T::default(),
  48         }
  49     }
  50 }
  51
  52 impl<T> Categories<T> {
  53     fn get(&self, category: ProfileCategory) -> &T {
  54         match category {
  55             ProfileCategory::Parsing => &self.parsing,
  56             ProfileCategory::Expansion => &self.expansion,
  57             ProfileCategory::TypeChecking => &self.type_checking,
  58             ProfileCategory::BorrowChecking => &self.borrow_checking,
  59             ProfileCategory::Codegen => &self.codegen,
  60             ProfileCategory::Linking => &self.linking,
  61             ProfileCategory::Other => &self.other,
  62         }
  63     }
  64
  65     fn set(&mut self, category: ProfileCategory, value: T) {
  66         match category {
  67             ProfileCategory::Parsing => self.parsing = value,
  68             ProfileCategory::Expansion => self.expansion = value,
  69             ProfileCategory::TypeChecking => self.type_checking = value,
  70             ProfileCategory::BorrowChecking => self.borrow_checking = value,
  71             ProfileCategory::Codegen => self.codegen = value,
  72             ProfileCategory::Linking => self.linking = value,
  73             ProfileCategory::Other => self.other = value,
  74         }
  75     }
  76 }
  77
  78 struct CategoryData {
  79     times: Categories<u64>,
  80     query_counts: Categories<(u64, u64)>,
  81 }
  82
  83 impl CategoryData {
  84     fn new() -> CategoryData {
  85         CategoryData {
  86             times: Categories::new(),
  87             query_counts: Categories::new(),
  88         }
  89     }
  90
  91     fn print(&self, lock: &mut StdoutLock) {
  92         macro_rules! p {
  93             ($name:tt, $rustic_name:ident) => {
  94                 let (hits, total) = self.query_counts.$rustic_name;
  95                 let (hits, total) = if total > 0 {
  96                     (format!("{:.2}", (((hits as f32) / (total as f32)) * 100.0)), total.to_string())
  97                 } else {
  98                     ("".into(), "".into())
  99                 };
 100
 101                 writeln!(
 102                    lock,
 103                    "| {0: <16} | {1: <14} | {2: <14} | {3: <8} |",
 104                    $name,
 105                    self.times.$rustic_name / 1_000_000,
 106                    total,
 107                    hits
 108                 ).unwrap();
 109             };
 110         }
 111
 112         writeln!(lock, "| Phase            | Time (ms)      | Queries        | Hits (%) |").unwrap();
 113         writeln!(lock, "| ---------------- | -------------- | -------------- | -------- |").unwrap();
 114
 115         p!("Parsing", parsing);
 116         p!("Expansion", expansion);
 117         p!("TypeChecking", type_checking);
 118         p!("BorrowChecking", borrow_checking);
 119         p!("Codegen", codegen);
 120         p!("Linking", linking);
 121         p!("Other", other);
 122     }
 123
 124     fn json(&self) -> String {
 125         macro_rules! j {
 126             ($category:tt, $rustic_name:ident) => {{
 127                 let (hits, total) = self.query_counts.$rustic_name;
 128
 129                 format!("{{ \"category\": {}, \"time_ms\": {}, \"query_count\": {}, \"query_hits\": {} }}",
 130                     stringify!($category),
 131                     self.times.$rustic_name / 1_000_000,
 132                     total,
 133                     format!("{:.2}", (((hits as f32) / (total as f32)) * 100.0))
 134                 )
 135             }}
 136         }
 137
 138         format!("[
 139             {},
 140             {},
 141             {},
 142             {},
 143             {},
 144             {},
 145             {}
 146         ]",
 147             j!("Parsing", parsing),
 148             j!("Expansion", expansion),
 149             j!("TypeChecking", type_checking),
 150             j!("BorrowChecking", borrow_checking),
 151             j!("Codegen", codegen),
 152             j!("Linking", linking),
 153             j!("Other", other)
 154         )
 155     }
 156 }
 157
 158 pub struct SelfProfiler {
 159     timer_stack: Vec<ProfileCategory>,
 160     data: CategoryData,
 161     current_timer: Instant,
 162 }
 163
 164 pub struct ProfilerActivity<'a>(ProfileCategory, &'a mut SelfProfiler);
 165
 166 impl<'a> Drop for ProfilerActivity<'a> {
 167     fn drop(&mut self) {
 168         let ProfilerActivity (category, profiler) = self;
 169
 170         profiler.end_activity(*category);
 171     }
 172 }
 173
 174 impl SelfProfiler {
 175     pub fn new() -> SelfProfiler {
 176         let mut profiler = SelfProfiler {
 177             timer_stack: Vec::new(),
 178             data: CategoryData::new(),
 179             current_timer: Instant::now(),
 180         };
 181
 182         profiler.start_activity(ProfileCategory::Other);
 183
 184         profiler
 185     }
 186
 187     pub fn start_activity(&mut self, category: ProfileCategory) {
 188         match self.timer_stack.last().cloned() {
 189             None => {
 190                 self.current_timer = Instant::now();
 191             },
 192             Some(current_category) if current_category == category => {
 193                 //since the current category is the same as the new activity's category,
 194                 //we don't need to do anything with the timer, we just need to push it on the stack
 195             }
 196             Some(current_category) => {
 197                 let elapsed = self.stop_timer();
 198
 199                 //record the current category's time
 200                 let new_time = self.data.times.get(current_category) + elapsed;
 201                 self.data.times.set(current_category, new_time);
 202             }
 203         }
 204
 205         //push the new category
 206         self.timer_stack.push(category);
 207     }
 208
 209     pub fn record_query(&mut self, category: ProfileCategory) {
 210         let (hits, total) = *self.data.query_counts.get(category);
 211         self.data.query_counts.set(category, (hits, total + 1));
 212     }
 213
 214     pub fn record_query_hit(&mut self, category: ProfileCategory) {
 215         let (hits, total) = *self.data.query_counts.get(category);
 216         self.data.query_counts.set(category, (hits + 1, total));
 217     }
 218
 219     pub fn end_activity(&mut self, category: ProfileCategory) {
 220         match self.timer_stack.pop() {
 221             None => bug!("end_activity() was called but there was no running activity"),
 222             Some(c) =>
 223                 assert!(
 224                     c == category,
 225                     "end_activity() was called but a different activity was running"),
 226         }
 227
 228         //check if the new running timer is in the same category as this one
 229         //if it is, we don't need to do anything
 230         if let Some(c) = self.timer_stack.last() {
 231             if *c == category {
 232                 return;
 233             }
 234         }
 235
 236         //the new timer is different than the previous, so record the elapsed time and start a new timer
 237         let elapsed = self.stop_timer();
 238         let new_time = self.data.times.get(category) + elapsed;
 239         self.data.times.set(category, new_time);
 240     }
 241
 242     fn stop_timer(&mut self) -> u64 {
 243         let elapsed = self.current_timer.elapsed();
 244
 245         self.current_timer = Instant::now();
 246
 247         (elapsed.as_secs() * 1_000_000_000) + (elapsed.subsec_nanos() as u64)
 248     }
 249
 250     pub fn print_results(&mut self, opts: &Options) {
 251         self.end_activity(ProfileCategory::Other);
 252
 253         assert!(self.timer_stack.is_empty(), "there were timers running when print_results() was called");
 254
 255         let out = io::stdout();
 256         let mut lock = out.lock();
 257
 258         let crate_name = opts.crate_name.as_ref().map(|n| format!(" for {}", n)).unwrap_or_default();
 259
 260         writeln!(lock, "Self profiling results{}:", crate_name).unwrap();
 261         writeln!(lock).unwrap();
 262
 263         self.data.print(&mut lock);
 264
 265         writeln!(lock).unwrap();
 266         writeln!(lock, "Optimization level: {:?}", opts.optimize).unwrap();
 267
 268         let incremental = if opts.incremental.is_some() { "on" } else { "off" };
 269         writeln!(lock, "Incremental: {}", incremental).unwrap();
 270     }
 271
 272     pub fn save_results(&self, opts: &Options) {
 273         let category_data = self.data.json();
 274         let compilation_options = format!("{{ \"optimization_level\": \"{:?}\", \"incremental\": {} }}",
 275                                     opts.optimize,
 276                                     if opts.incremental.is_some() { "true" } else { "false" });
 277
 278         let json = format!("{{ \"category_data\": {}, \"compilation_options\": {} }}",
 279                         category_data,
 280                         compilation_options);
 281
 282         fs::write("self_profiler_results.json", json).unwrap();
 283     }
 284
 285     pub fn record_activity<'a>(&'a mut self, category: ProfileCategory) -> ProfilerActivity<'a> {
 286         self.start_activity(category);
 287
 288         ProfilerActivity(category, self)
 289     }
 290 }