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 impl SelfProfiler {
 165     pub fn new() -> SelfProfiler {
 166         let mut profiler = SelfProfiler {
 167             timer_stack: Vec::new(),
 168             data: CategoryData::new(),
 169             current_timer: Instant::now(),
 170         };
 171
 172         profiler.start_activity(ProfileCategory::Other);
 173
 174         profiler
 175     }
 176
 177     pub fn start_activity(&mut self, category: ProfileCategory) {
 178         match self.timer_stack.last().cloned() {
 179             None => {
 180                 self.current_timer = Instant::now();
 181             },
 182             Some(current_category) if current_category == category => {
 183                 //since the current category is the same as the new activity's category,
 184                 //we don't need to do anything with the timer, we just need to push it on the stack
 185             }
 186             Some(current_category) => {
 187                 let elapsed = self.stop_timer();
 188
 189                 //record the current category's time
 190                 let new_time = self.data.times.get(current_category) + elapsed;
 191                 self.data.times.set(current_category, new_time);
 192             }
 193         }
 194
 195         //push the new category
 196         self.timer_stack.push(category);
 197     }
 198
 199     pub fn record_query(&mut self, category: ProfileCategory) {
 200         let (hits, total) = *self.data.query_counts.get(category);
 201         self.data.query_counts.set(category, (hits, total + 1));
 202     }
 203
 204     pub fn record_query_hit(&mut self, category: ProfileCategory) {
 205         let (hits, total) = *self.data.query_counts.get(category);
 206         self.data.query_counts.set(category, (hits + 1, total));
 207     }
 208
 209     pub fn end_activity(&mut self, category: ProfileCategory) {
 210         match self.timer_stack.pop() {
 211             None => bug!("end_activity() was called but there was no running activity"),
 212             Some(c) =>
 213                 assert!(
 214                     c == category,
 215                     "end_activity() was called but a different activity was running"),
 216         }
 217
 218         //check if the new running timer is in the same category as this one
 219         //if it is, we don't need to do anything
 220         if let Some(c) = self.timer_stack.last() {
 221             if *c == category {
 222                 return;
 223             }
 224         }
 225
 226         //the new timer is different than the previous, so record the elapsed time and start a new timer
 227         let elapsed = self.stop_timer();
 228         let new_time = self.data.times.get(category) + elapsed;
 229         self.data.times.set(category, new_time);
 230     }
 231
 232     fn stop_timer(&mut self) -> u64 {
 233         let elapsed = self.current_timer.elapsed();
 234
 235         self.current_timer = Instant::now();
 236
 237         (elapsed.as_secs() * 1_000_000_000) + (elapsed.subsec_nanos() as u64)
 238     }
 239
 240     pub fn print_results(&mut self, opts: &Options) {
 241         self.end_activity(ProfileCategory::Other);
 242
 243         assert!(self.timer_stack.is_empty(), "there were timers running when print_results() was called");
 244
 245         let out = io::stdout();
 246         let mut lock = out.lock();
 247
 248         let crate_name = opts.crate_name.as_ref().map(|n| format!(" for {}", n)).unwrap_or_default();
 249
 250         writeln!(lock, "Self profiling results{}:", crate_name).unwrap();
 251         writeln!(lock).unwrap();
 252
 253         self.data.print(&mut lock);
 254
 255         writeln!(lock).unwrap();
 256         writeln!(lock, "Optimization level: {:?}", opts.optimize).unwrap();
 257
 258         let incremental = if opts.incremental.is_some() { "on" } else { "off" };
 259         writeln!(lock, "Incremental: {}", incremental).unwrap();
 260     }
 261
 262     pub fn save_results(&self, opts: &Options) {
 263         let category_data = self.data.json();
 264         let compilation_options = format!("{{ \"optimization_level\": \"{:?}\", \"incremental\": {} }}",
 265                                     opts.optimize,
 266                                     if opts.incremental.is_some() { "true" } else { "false" });
 267
 268         let json = format!("{{ \"category_data\": {}, \"compilation_options\": {} }}",
 269                         category_data,
 270                         compilation_options);
 271
 272         fs::write("self_profiler_results.json", json).unwrap();
 273     }
 274 }