src/librustc/util/profiling.rs

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