src/librustc/util/profiling.rs

   1 use std::collections::{BTreeMap, HashMap};
   2 use std::fs;
   3 use std::io::{self, Write};
   4 use std::thread::ThreadId;
   5 use std::time::Instant;
   6
   7 use crate::session::config::{Options, OptLevel};
   8
   9 #[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)]
  10 pub enum ProfileCategory {
  11     Parsing,
  12     Expansion,
  13     TypeChecking,
  14     BorrowChecking,
  15     Codegen,
  16     Linking,
  17     Other,
  18 }
  19
  20 #[derive(Clone, Copy, Debug, Eq, PartialEq)]
  21 pub enum ProfilerEvent {
  22     QueryStart { query_name: &'static str, category: ProfileCategory, time: Instant },
  23     QueryEnd { query_name: &'static str, category: ProfileCategory, time: Instant },
  24     GenericActivityStart { category: ProfileCategory, time: Instant },
  25     GenericActivityEnd { category: ProfileCategory, time: Instant },
  26     QueryCacheHit { query_name: &'static str, category: ProfileCategory },
  27     QueryCount { query_name: &'static str, category: ProfileCategory, count: usize },
  28 }
  29
  30 impl ProfilerEvent {
  31     fn is_start_event(&self) -> bool {
  32         use self::ProfilerEvent::*;
  33
  34         match self {
  35             QueryStart { .. } | GenericActivityStart { .. } => true,
  36             QueryEnd { .. } | GenericActivityEnd { .. } |
  37             QueryCacheHit { .. } | QueryCount { .. } => false,
  38         }
  39     }
  40 }
  41
  42 pub struct SelfProfiler {
  43     events: HashMap<ThreadId, Vec<ProfilerEvent>>,
  44 }
  45
  46 struct CategoryResultData {
  47     query_times: BTreeMap<&'static str, u64>,
  48     query_cache_stats: BTreeMap<&'static str, (u64, u64)>, //(hits, total)
  49 }
  50
  51 impl CategoryResultData {
  52     fn new() -> CategoryResultData {
  53         CategoryResultData {
  54             query_times: BTreeMap::new(),
  55             query_cache_stats: BTreeMap::new(),
  56         }
  57     }
  58
  59     fn total_time(&self) -> u64 {
  60         let mut total = 0;
  61         for (_, time) in &self.query_times {
  62             total += time;
  63         }
  64
  65         total
  66     }
  67
  68     fn total_cache_data(&self) -> (u64, u64) {
  69         let (mut hits, mut total) = (0, 0);
  70
  71         for (_, (h, t)) in &self.query_cache_stats {
  72             hits += h;
  73             total += t;
  74         }
  75
  76         (hits, total)
  77     }
  78 }
  79
  80 impl Default for CategoryResultData {
  81     fn default() -> CategoryResultData {
  82         CategoryResultData::new()
  83     }
  84 }
  85
  86 struct CalculatedResults {
  87     categories: BTreeMap<ProfileCategory, CategoryResultData>,
  88     crate_name: Option<String>,
  89     optimization_level: OptLevel,
  90     incremental: bool,
  91     verbose: bool,
  92 }
  93
  94 impl CalculatedResults {
  95     fn new() -> CalculatedResults {
  96         CalculatedResults {
  97             categories: BTreeMap::new(),
  98             crate_name: None,
  99             optimization_level: OptLevel::No,
 100             incremental: false,
 101             verbose: false,
 102         }
 103     }
 104
 105     fn consolidate(mut cr1: CalculatedResults, cr2: CalculatedResults) -> CalculatedResults {
 106         for (category, data) in cr2.categories {
 107             let cr1_data = cr1.categories.entry(category).or_default();
 108
 109             for (query, time) in data.query_times {
 110                 *cr1_data.query_times.entry(query).or_default() += time;
 111             }
 112
 113             for (query, (hits, total)) in data.query_cache_stats {
 114                 let (h, t) = cr1_data.query_cache_stats.entry(query).or_insert((0, 0));
 115                 *h += hits;
 116                 *t += total;
 117             }
 118         }
 119
 120         cr1
 121     }
 122
 123     fn total_time(&self) -> u64 {
 124         let mut total = 0;
 125
 126         for (_, data) in &self.categories {
 127             total += data.total_time();
 128         }
 129
 130         total
 131     }
 132
 133     fn with_options(mut self, opts: &Options) -> CalculatedResults {
 134         self.crate_name = opts.crate_name.clone();
 135         self.optimization_level = opts.optimize;
 136         self.incremental = opts.incremental.is_some();
 137         self.verbose = opts.debugging_opts.verbose;
 138
 139         self
 140     }
 141 }
 142
 143 fn time_between_ns(start: Instant, end: Instant) -> u64 {
 144     if start < end {
 145         let time = end - start;
 146         (time.as_secs() * 1_000_000_000) + (time.subsec_nanos() as u64)
 147     } else {
 148         debug!("time_between_ns: ignorning instance of end < start");
 149         0
 150     }
 151 }
 152
 153 fn calculate_percent(numerator: u64, denominator: u64) -> f32 {
 154     if denominator > 0 {
 155         ((numerator as f32) / (denominator as f32)) * 100.0
 156     } else {
 157         0.0
 158     }
 159 }
 160
 161 impl SelfProfiler {
 162     pub fn new() -> SelfProfiler {
 163         let mut profiler = SelfProfiler {
 164             events: HashMap::new(),
 165         };
 166
 167         profiler.start_activity(ProfileCategory::Other);
 168
 169         profiler
 170     }
 171
 172     #[inline]
 173     pub fn start_activity(&mut self, category: ProfileCategory) {
 174         self.record(ProfilerEvent::GenericActivityStart {
 175             category,
 176             time: Instant::now(),
 177         })
 178     }
 179
 180     #[inline]
 181     pub fn end_activity(&mut self, category: ProfileCategory) {
 182         self.record(ProfilerEvent::GenericActivityEnd {
 183             category,
 184             time: Instant::now(),
 185         })
 186     }
 187
 188     #[inline]
 189     pub fn record_computed_queries(
 190         &mut self,
 191         query_name: &'static str,
 192         category: ProfileCategory,
 193         count: usize)
 194         {
 195         self.record(ProfilerEvent::QueryCount {
 196             query_name,
 197             category,
 198             count,
 199         })
 200     }
 201
 202     #[inline]
 203     pub fn record_query_hit(&mut self, query_name: &'static str, category: ProfileCategory) {
 204         self.record(ProfilerEvent::QueryCacheHit {
 205             query_name,
 206             category,
 207         })
 208     }
 209
 210     #[inline]
 211     pub fn start_query(&mut self, query_name: &'static str, category: ProfileCategory) {
 212         self.record(ProfilerEvent::QueryStart {
 213             query_name,
 214             category,
 215             time: Instant::now(),
 216         });
 217     }
 218
 219     #[inline]
 220     pub fn end_query(&mut self, query_name: &'static str, category: ProfileCategory) {
 221         self.record(ProfilerEvent::QueryEnd {
 222             query_name,
 223             category,
 224             time: Instant::now(),
 225         })
 226     }
 227
 228     #[inline]
 229     fn record(&mut self, event: ProfilerEvent) {
 230         let thread_id = std::thread::current().id();
 231         let events = self.events.entry(thread_id).or_default();
 232
 233         events.push(event);
 234     }
 235
 236     fn calculate_thread_results(events: &Vec<ProfilerEvent>) -> CalculatedResults {
 237         use self::ProfilerEvent::*;
 238
 239         assert!(
 240             events.last().map(|e| !e.is_start_event()).unwrap_or(true),
 241             "there was an event running when calculate_reslts() was called"
 242         );
 243
 244         let mut results = CalculatedResults::new();
 245
 246         //(event, child time to subtract)
 247         let mut query_stack = Vec::new();
 248
 249         for event in events {
 250             match event {
 251                 QueryStart { .. } | GenericActivityStart { .. } => {
 252                     query_stack.push((event, 0));
 253                 },
 254                 QueryEnd { query_name, category, time: end_time } => {
 255                     let previous_query = query_stack.pop();
 256                     if let Some((QueryStart {
 257                                     query_name: p_query_name,
 258                                     time: start_time,
 259                                     category: _ }, child_time_to_subtract)) = previous_query {
 260                         assert_eq!(
 261                             p_query_name,
 262                             query_name,
 263                             "Saw a query end but the previous query wasn't the corresponding start"
 264                         );
 265
 266                         let time_ns = time_between_ns(*start_time, *end_time);
 267                         let self_time_ns = time_ns - child_time_to_subtract;
 268                         let result_data = results.categories.entry(*category).or_default();
 269
 270                         *result_data.query_times.entry(query_name).or_default() += self_time_ns;
 271
 272                         if let Some((_, child_time_to_subtract)) = query_stack.last_mut() {
 273                             *child_time_to_subtract += time_ns;
 274                         }
 275                     } else {
 276                         bug!("Saw a query end but the previous event wasn't a query start");
 277                     }
 278                 }
 279                 GenericActivityEnd { category, time: end_time } => {
 280                     let previous_event = query_stack.pop();
 281                     if let Some((GenericActivityStart {
 282                                     category: previous_category,
 283                                     time: start_time }, child_time_to_subtract)) = previous_event {
 284                         assert_eq!(
 285                             previous_category,
 286                             category,
 287                             "Saw an end but the previous event wasn't the corresponding start"
 288                         );
 289
 290                         let time_ns = time_between_ns(*start_time, *end_time);
 291                         let self_time_ns = time_ns - child_time_to_subtract;
 292                         let result_data = results.categories.entry(*category).or_default();
 293
 294                         *result_data.query_times
 295                             .entry("{time spent not running queries}")
 296                             .or_default() += self_time_ns;
 297
 298                         if let Some((_, child_time_to_subtract)) = query_stack.last_mut() {
 299                             *child_time_to_subtract += time_ns;
 300                         }
 301                     } else {
 302                         bug!("Saw an activity end but the previous event wasn't an activity start");
 303                     }
 304                 },
 305                 QueryCacheHit { category, query_name } => {
 306                     let result_data = results.categories.entry(*category).or_default();
 307
 308                     let (hits, total) =
 309                         result_data.query_cache_stats.entry(query_name).or_insert((0, 0));
 310                     *hits += 1;
 311                     *total += 1;
 312                 },
 313                 QueryCount { category, query_name, count } => {
 314                     let result_data = results.categories.entry(*category).or_default();
 315
 316                     let (_, totals) =
 317                         result_data.query_cache_stats.entry(query_name).or_insert((0, 0));
 318                     *totals += *count as u64;
 319                 },
 320             }
 321         }
 322
 323         //normalize the times to ms
 324         for (_, data) in &mut results.categories {
 325             for (_, time) in &mut data.query_times {
 326                 *time = *time / 1_000_000;
 327             }
 328         }
 329
 330         results
 331     }
 332
 333     fn get_results(&self, opts: &Options) -> CalculatedResults {
 334         self.events
 335             .iter()
 336             .map(|(_, r)| SelfProfiler::calculate_thread_results(r))
 337             .fold(CalculatedResults::new(), CalculatedResults::consolidate)
 338             .with_options(opts)
 339     }
 340
 341     pub fn print_results(&mut self, opts: &Options) {
 342         self.end_activity(ProfileCategory::Other);
 343
 344         let results = self.get_results(opts);
 345
 346         let total_time = results.total_time() as f32;
 347
 348         let out = io::stderr();
 349         let mut lock = out.lock();
 350
 351         let crate_name = results.crate_name.map(|n| format!(" for {}", n)).unwrap_or_default();
 352
 353         writeln!(lock, "Self profiling results{}:", crate_name).unwrap();
 354         writeln!(lock).unwrap();
 355
 356         writeln!(lock, "| Phase                                     | Time (ms)      \
 357                         | Time (%) | Queries        | Hits (%)")
 358             .unwrap();
 359         writeln!(lock, "| ----------------------------------------- | -------------- \
 360                         | -------- | -------------- | --------")
 361             .unwrap();
 362
 363         let mut categories: Vec<_> = results.categories.iter().collect();
 364         categories.sort_by(|(_, data1), (_, data2)| data2.total_time().cmp(&data1.total_time()));
 365
 366         for (category, data) in categories {
 367             let (category_hits, category_total) = data.total_cache_data();
 368             let category_hit_percent = calculate_percent(category_hits, category_total);
 369
 370             writeln!(
 371                 lock,
 372                 "| {0: <41} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}",
 373                 format!("{:?}", category),
 374                 data.total_time(),
 375                 ((data.total_time() as f32) / total_time) * 100.0,
 376                 category_total,
 377                 format!("{:.2}", category_hit_percent),
 378             ).unwrap();
 379
 380             //in verbose mode, show individual query data
 381             if results.verbose {
 382                 //don't show queries that took less than 1ms
 383                 let mut times: Vec<_> = data.query_times.iter().filter(|(_, t)| **t > 0).collect();
 384                 times.sort_by(|(_, time1), (_, time2)| time2.cmp(time1));
 385
 386                 for (query, time) in times {
 387                     let (hits, total) = data.query_cache_stats.get(query).unwrap_or(&(0, 0));
 388                     let hit_percent = calculate_percent(*hits, *total);
 389
 390                     writeln!(
 391                         lock,
 392                         "| - {0: <39} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}",
 393                         query,
 394                         time,
 395                         ((*time as f32) / total_time) * 100.0,
 396                         total,
 397                         format!("{:.2}", hit_percent),
 398                     ).unwrap();
 399                 }
 400             }
 401         }
 402
 403         writeln!(lock).unwrap();
 404         writeln!(lock, "Optimization level: {:?}", opts.optimize).unwrap();
 405         writeln!(lock, "Incremental: {}", if results.incremental { "on" } else { "off" }).unwrap();
 406     }
 407
 408     pub fn save_results(&self, opts: &Options) {
 409         let results = self.get_results(opts);
 410
 411         let compilation_options =
 412             format!("{{ \"optimization_level\": \"{:?}\", \"incremental\": {} }}",
 413                     results.optimization_level,
 414                     if results.incremental { "true" } else { "false" });
 415
 416         let mut category_data = String::new();
 417
 418         for (category, data) in &results.categories {
 419             let (hits, total) = data.total_cache_data();
 420             let hit_percent = calculate_percent(hits, total);
 421
 422             category_data.push_str(&format!("{{ \"category\": \"{:?}\", \"time_ms\": {}, \
 423                                                 \"query_count\": {}, \"query_hits\": {} }}",
 424                                             category,
 425                                             data.total_time(),
 426                                             total,
 427                                             format!("{:.2}", hit_percent)));
 428         }
 429
 430         let json = format!("{{ \"category_data\": {}, \"compilation_options\": {} }}",
 431                         category_data,
 432                         compilation_options);
 433
 434         fs::write("self_profiler_results.json", json).unwrap();
 435     }
 436 }