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