src/librustc/util/profiling.rs

   1 use std::fs;
   2 use std::io::{BufWriter, Write};
   3 use std::mem;
   4 use std::process;
   5 use std::thread::ThreadId;
   6 use std::time::{Duration, Instant, SystemTime};
   7
   8 use crate::session::config::Options;
   9
  10 use rustc_data_structures::fx::FxHashMap;
  11
  12 #[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)]
  13 pub enum ProfileCategory {
  14     Parsing,
  15     Expansion,
  16     TypeChecking,
  17     BorrowChecking,
  18     Codegen,
  19     Linking,
  20     Other,
  21 }
  22
  23 #[derive(Clone, Copy, Debug, Eq, PartialEq)]
  24 pub enum ProfilerEvent {
  25     QueryStart { query_name: &'static str, category: ProfileCategory, time: u64 },
  26     QueryEnd { query_name: &'static str, category: ProfileCategory, time: u64 },
  27     GenericActivityStart { category: ProfileCategory, time: u64 },
  28     GenericActivityEnd { category: ProfileCategory, time: u64 },
  29     IncrementalLoadResultStart { query_name: &'static str, time: u64 },
  30     IncrementalLoadResultEnd { query_name: &'static str, time: u64 },
  31     QueryCacheHit { query_name: &'static str, category: ProfileCategory, time: u64 },
  32     QueryCount { query_name: &'static str, category: ProfileCategory, count: usize, time: u64 },
  33     QueryBlockedStart { query_name: &'static str, category: ProfileCategory, time: u64 },
  34     QueryBlockedEnd { query_name: &'static str, category: ProfileCategory, time: u64 },
  35 }
  36
  37 impl ProfilerEvent {
  38     fn timestamp(&self) -> u64 {
  39         use self::ProfilerEvent::*;
  40
  41         match self {
  42             QueryStart { time, .. } |
  43             QueryEnd { time, .. } |
  44             GenericActivityStart { time, .. } |
  45             GenericActivityEnd { time, .. } |
  46             QueryCacheHit { time, .. } |
  47             QueryCount { time, .. } |
  48             IncrementalLoadResultStart { time, .. } |
  49             IncrementalLoadResultEnd { time, .. } |
  50             QueryBlockedStart { time, .. } |
  51             QueryBlockedEnd { time, .. } => *time
  52         }
  53     }
  54 }
  55
  56 fn thread_id_to_u64(tid: ThreadId) -> u64 {
  57     unsafe { mem::transmute::<ThreadId, u64>(tid) }
  58 }
  59
  60 pub struct SelfProfiler {
  61     events: FxHashMap<ThreadId, Vec<ProfilerEvent>>,
  62     start_time: SystemTime,
  63     start_instant: Instant,
  64 }
  65
  66 impl SelfProfiler {
  67     pub fn new() -> SelfProfiler {
  68         let profiler = SelfProfiler {
  69             events: Default::default(),
  70             start_time: SystemTime::now(),
  71             start_instant: Instant::now(),
  72         };
  73
  74         profiler
  75     }
  76
  77     #[inline]
  78     pub fn start_activity(&mut self, category: ProfileCategory) {
  79         self.record(ProfilerEvent::GenericActivityStart {
  80             category,
  81             time: self.get_time_from_start(),
  82         })
  83     }
  84
  85     #[inline]
  86     pub fn end_activity(&mut self, category: ProfileCategory) {
  87         self.record(ProfilerEvent::GenericActivityEnd {
  88             category,
  89             time: self.get_time_from_start(),
  90         })
  91     }
  92
  93     #[inline]
  94     pub fn record_computed_queries(
  95         &mut self,
  96         query_name: &'static str,
  97         category: ProfileCategory,
  98         count: usize)
  99         {
 100         self.record(ProfilerEvent::QueryCount {
 101             query_name,
 102             category,
 103             count,
 104             time: self.get_time_from_start(),
 105         })
 106     }
 107
 108     #[inline]
 109     pub fn record_query_hit(&mut self, query_name: &'static str, category: ProfileCategory) {
 110         self.record(ProfilerEvent::QueryCacheHit {
 111             query_name,
 112             category,
 113             time: self.get_time_from_start(),
 114         })
 115     }
 116
 117     #[inline]
 118     pub fn start_query(&mut self, query_name: &'static str, category: ProfileCategory) {
 119         self.record(ProfilerEvent::QueryStart {
 120             query_name,
 121             category,
 122             time: self.get_time_from_start(),
 123         });
 124     }
 125
 126     #[inline]
 127     pub fn end_query(&mut self, query_name: &'static str, category: ProfileCategory) {
 128         self.record(ProfilerEvent::QueryEnd {
 129             query_name,
 130             category,
 131             time: self.get_time_from_start(),
 132         })
 133     }
 134
 135     #[inline]
 136     pub fn incremental_load_result_start(&mut self, query_name: &'static str) {
 137         self.record(ProfilerEvent::IncrementalLoadResultStart {
 138             query_name,
 139             time: self.get_time_from_start(),
 140         })
 141     }
 142
 143     #[inline]
 144     pub fn incremental_load_result_end(&mut self, query_name: &'static str) {
 145         self.record(ProfilerEvent::IncrementalLoadResultEnd {
 146             query_name,
 147             time: self.get_time_from_start(),
 148         })
 149     }
 150
 151     #[inline]
 152     pub fn query_blocked_start(&mut self, query_name: &'static str, category: ProfileCategory) {
 153         self.record(ProfilerEvent::QueryBlockedStart {
 154             query_name,
 155             category,
 156             time: self.get_time_from_start(),
 157         })
 158     }
 159
 160     #[inline]
 161     pub fn query_blocked_end(&mut self, query_name: &'static str, category: ProfileCategory) {
 162         self.record(ProfilerEvent::QueryBlockedEnd {
 163             query_name,
 164             category,
 165             time: self.get_time_from_start(),
 166         })
 167     }
 168
 169     #[inline]
 170     fn record(&mut self, event: ProfilerEvent) {
 171         let thread_id = std::thread::current().id();
 172         let events = self.events.entry(thread_id).or_default();
 173
 174         events.push(event);
 175     }
 176
 177     #[inline]
 178     fn get_time_from_start(&self) -> u64 {
 179         let duration = Instant::now() - self.start_instant;
 180         duration.as_nanos() as u64
 181     }
 182
 183     pub fn dump_raw_events(&self, opts: &Options) {
 184         use self::ProfilerEvent::*;
 185
 186         let pid = process::id();
 187
 188         let filename =
 189             format!("{}.profile_events.json", opts.crate_name.clone().unwrap_or_default());
 190
 191         let mut file = BufWriter::new(fs::File::create(filename).unwrap());
 192
 193         let threads: Vec<_> =
 194             self.events
 195                 .keys()
 196                 .into_iter()
 197                 .map(|tid| format!("{}", thread_id_to_u64(*tid)))
 198                 .collect();
 199
 200         write!(file,
 201             "{{\
 202                 \"processes\": {{\
 203                     \"{}\": {{\
 204                         \"threads\": [{}],\
 205                         \"crate_name\": \"{}\",\
 206                         \"opt_level\": \"{:?}\",\
 207                         \"incremental\": {}\
 208                     }}\
 209                 }},\
 210                 \"events\": [\
 211              ",
 212             pid,
 213             threads.join(","),
 214             opts.crate_name.clone().unwrap_or_default(),
 215             opts.optimize,
 216             if opts.incremental.is_some() { "true" } else { "false" },
 217         ).unwrap();
 218
 219         let mut is_first = true;
 220         for (thread_id, events) in &self.events {
 221             let thread_id = thread_id_to_u64(*thread_id);
 222
 223             for event in events {
 224                 if is_first {
 225                     is_first = false;
 226                 } else {
 227                     writeln!(file, ",").unwrap();
 228                 }
 229
 230                 let (secs, nanos) = {
 231                     let time = self.start_time + Duration::from_nanos(event.timestamp());
 232                     let time_since_unix =
 233                         time.duration_since(SystemTime::UNIX_EPOCH).unwrap_or_default();
 234                     (time_since_unix.as_secs(), time_since_unix.subsec_nanos())
 235                 };
 236
 237                 match event {
 238                     QueryStart { query_name, category, time: _ } =>
 239                         write!(file,
 240                             "{{ \
 241                                 \"QueryStart\": {{ \
 242                                     \"query_name\": \"{}\",\
 243                                     \"category\": \"{:?}\",\
 244                                     \"time\": {{\
 245                                         \"secs\": {},\
 246                                         \"nanos\": {}\
 247                                     }},\
 248                                     \"thread_id\": {}\
 249                                 }}\
 250                             }}",
 251                             query_name,
 252                             category,
 253                             secs,
 254                             nanos,
 255                             thread_id,
 256                         ).unwrap(),
 257                     QueryEnd { query_name, category, time: _ } =>
 258                         write!(file,
 259                             "{{\
 260                                 \"QueryEnd\": {{\
 261                                     \"query_name\": \"{}\",\
 262                                     \"category\": \"{:?}\",\
 263                                     \"time\": {{\
 264                                         \"secs\": {},\
 265                                         \"nanos\": {}\
 266                                     }},\
 267                                     \"thread_id\": {}\
 268                                 }}\
 269                             }}",
 270                             query_name,
 271                             category,
 272                             secs,
 273                             nanos,
 274                             thread_id,
 275                         ).unwrap(),
 276                     GenericActivityStart { category, time: _ } =>
 277                         write!(file,
 278                             "{{
 279                                 \"GenericActivityStart\": {{\
 280                                     \"category\": \"{:?}\",\
 281                                     \"time\": {{\
 282                                         \"secs\": {},\
 283                                         \"nanos\": {}\
 284                                     }},\
 285                                     \"thread_id\": {}\
 286                                 }}\
 287                             }}",
 288                             category,
 289                             secs,
 290                             nanos,
 291                             thread_id,
 292                         ).unwrap(),
 293                     GenericActivityEnd { category, time: _ } =>
 294                         write!(file,
 295                             "{{\
 296                                 \"GenericActivityEnd\": {{\
 297                                     \"category\": \"{:?}\",\
 298                                     \"time\": {{\
 299                                         \"secs\": {},\
 300                                         \"nanos\": {}\
 301                                     }},\
 302                                     \"thread_id\": {}\
 303                                 }}\
 304                             }}",
 305                             category,
 306                             secs,
 307                             nanos,
 308                             thread_id,
 309                         ).unwrap(),
 310                     QueryCacheHit { query_name, category, time: _ } =>
 311                         write!(file,
 312                             "{{\
 313                                 \"QueryCacheHit\": {{\
 314                                     \"query_name\": \"{}\",\
 315                                     \"category\": \"{:?}\",\
 316                                     \"time\": {{\
 317                                         \"secs\": {},\
 318                                         \"nanos\": {}\
 319                                     }},\
 320                                     \"thread_id\": {}\
 321                                 }}\
 322                             }}",
 323                             query_name,
 324                             category,
 325                             secs,
 326                             nanos,
 327                             thread_id,
 328                         ).unwrap(),
 329                     QueryCount { query_name, category, count, time: _ } =>
 330                         write!(file,
 331                             "{{\
 332                                 \"QueryCount\": {{\
 333                                     \"query_name\": \"{}\",\
 334                                     \"category\": \"{:?}\",\
 335                                     \"count\": {},\
 336                                     \"time\": {{\
 337                                         \"secs\": {},\
 338                                         \"nanos\": {}\
 339                                     }},\
 340                                     \"thread_id\": {}\
 341                                 }}\
 342                             }}",
 343                             query_name,
 344                             category,
 345                             count,
 346                             secs,
 347                             nanos,
 348                             thread_id,
 349                         ).unwrap(),
 350                     IncrementalLoadResultStart { query_name, time: _ } =>
 351                         write!(file,
 352                             "{{\
 353                                 \"IncrementalLoadResultStart\": {{\
 354                                     \"query_name\": \"{}\",\
 355                                     \"time\": {{\
 356                                         \"secs\": {},\
 357                                         \"nanos\": {}\
 358                                     }},\
 359                                     \"thread_id\": {}\
 360                                 }}\
 361                             }}",
 362                             query_name,
 363                             secs,
 364                             nanos,
 365                             thread_id,
 366                         ).unwrap(),
 367                     IncrementalLoadResultEnd { query_name, time: _ } =>
 368                         write!(file,
 369                             "{{\
 370                                 \"IncrementalLoadResultEnd\": {{\
 371                                     \"query_name\": \"{}\",\
 372                                     \"time\": {{\
 373                                         \"secs\": {},\
 374                                         \"nanos\": {}\
 375                                     }},\
 376                                     \"thread_id\": {}\
 377                                 }}\
 378                             }}",
 379                             query_name,
 380                             secs,
 381                             nanos,
 382                             thread_id,
 383                         ).unwrap(),
 384                     QueryBlockedStart { query_name, category, time: _ } =>
 385                         write!(file,
 386                             "{{\
 387                                 \"QueryBlockedStart\": {{\
 388                                     \"query_name\": \"{}\",\
 389                                     \"category\": \"{:?}\",\
 390                                     \"time\": {{\
 391                                         \"secs\": {},\
 392                                         \"nanos\": {}\
 393                                     }},\
 394                                     \"thread_id\": {}\
 395                                 }}\
 396                             }}",
 397                             query_name,
 398                             category,
 399                             secs,
 400                             nanos,
 401                             thread_id,
 402                         ).unwrap(),
 403                     QueryBlockedEnd { query_name, category, time: _ } =>
 404                         write!(file,
 405                             "{{\
 406                                 \"QueryBlockedEnd\": {{\
 407                                     \"query_name\": \"{}\",\
 408                                     \"category\": \"{:?}\",\
 409                                     \"time\": {{\
 410                                         \"secs\": {},\
 411                                         \"nanos\": {}\
 412                                     }},\
 413                                     \"thread_id\": {}\
 414                                 }}\
 415                             }}",
 416                             query_name,
 417                             category,
 418                             secs,
 419                             nanos,
 420                             thread_id,
 421                         ).unwrap()
 422                 }
 423             }
 424         }
 425
 426         write!(file, "] }}").unwrap();
 427     }
 428 }