src/librustc_data_structures/profiling.rs

   1 use std::error::Error;
   2 use std::fs;
   3 use std::mem::{self, Discriminant};
   4 use std::path::Path;
   5 use std::process;
   6 use std::sync::Arc;
   7 use std::thread::ThreadId;
   8 use std::time::{Duration, Instant};
   9 use std::u32;
  10
  11 use measureme::StringId;
  12
  13 /// MmapSerializatioSink is faster on macOS and Linux
  14 /// but FileSerializationSink is faster on Windows
  15 #[cfg(not(windows))]
  16 type SerializationSink = measureme::MmapSerializationSink;
  17 #[cfg(windows)]
  18 type SerializationSink = measureme::FileSerializationSink;
  19
  20 type Profiler = measureme::Profiler<SerializationSink>;
  21
  22 pub trait QueryName: Sized + Copy {
  23     fn discriminant(self) -> Discriminant<Self>;
  24     fn as_str(self) -> &'static str;
  25 }
  26
  27 #[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)]
  28 pub enum ProfileCategory {
  29     Parsing,
  30     Expansion,
  31     TypeChecking,
  32     BorrowChecking,
  33     Codegen,
  34     Linking,
  35     Other,
  36 }
  37
  38 bitflags::bitflags! {
  39     struct EventFilter: u32 {
  40         const GENERIC_ACTIVITIES = 1 << 0;
  41         const QUERY_PROVIDERS    = 1 << 1;
  42         const QUERY_CACHE_HITS   = 1 << 2;
  43         const QUERY_BLOCKED      = 1 << 3;
  44         const INCR_CACHE_LOADS   = 1 << 4;
  45
  46         const DEFAULT = Self::GENERIC_ACTIVITIES.bits |
  47                         Self::QUERY_PROVIDERS.bits |
  48                         Self::QUERY_BLOCKED.bits |
  49                         Self::INCR_CACHE_LOADS.bits;
  50
  51         // empty() and none() aren't const-fns unfortunately
  52         const NONE = 0;
  53         const ALL  = !Self::NONE.bits;
  54     }
  55 }
  56
  57 const EVENT_FILTERS_BY_NAME: &[(&str, EventFilter)] = &[
  58     ("none", EventFilter::NONE),
  59     ("all", EventFilter::ALL),
  60     ("generic-activity", EventFilter::GENERIC_ACTIVITIES),
  61     ("query-provider", EventFilter::QUERY_PROVIDERS),
  62     ("query-cache-hit", EventFilter::QUERY_CACHE_HITS),
  63     ("query-blocked", EventFilter::QUERY_BLOCKED),
  64     ("incr-cache-load", EventFilter::INCR_CACHE_LOADS),
  65 ];
  66
  67 fn thread_id_to_u32(tid: ThreadId) -> u32 {
  68     unsafe { mem::transmute::<ThreadId, u64>(tid) as u32 }
  69 }
  70
  71 /// A reference to the SelfProfiler. It can be cloned and sent across thread
  72 /// boundaries at will.
  73 #[derive(Clone)]
  74 pub struct SelfProfilerRef {
  75     // This field is `None` if self-profiling is disabled for the current
  76     // compilation session.
  77     profiler: Option<Arc<SelfProfiler>>,
  78
  79     // We store the filter mask directly in the reference because that doesn't
  80     // cost anything and allows for filtering with checking if the profiler is
  81     // actually enabled.
  82     event_filter_mask: EventFilter,
  83
  84     // Print verbose generic activities to stdout
  85     print_verbose_generic_activities: bool,
  86
  87     // Print extra verbose generic activities to stdout
  88     print_extra_verbose_generic_activities: bool,
  89 }
  90
  91 impl SelfProfilerRef {
  92     pub fn new(
  93         profiler: Option<Arc<SelfProfiler>>,
  94         print_verbose_generic_activities: bool,
  95         print_extra_verbose_generic_activities: bool,
  96     ) -> SelfProfilerRef {
  97         // If there is no SelfProfiler then the filter mask is set to NONE,
  98         // ensuring that nothing ever tries to actually access it.
  99         let event_filter_mask =
 100             profiler.as_ref().map(|p| p.event_filter_mask).unwrap_or(EventFilter::NONE);
 101
 102         SelfProfilerRef {
 103             profiler,
 104             event_filter_mask,
 105             print_verbose_generic_activities,
 106             print_extra_verbose_generic_activities,
 107         }
 108     }
 109
 110     // This shim makes sure that calls only get executed if the filter mask
 111     // lets them pass. It also contains some trickery to make sure that
 112     // code is optimized for non-profiling compilation sessions, i.e. anything
 113     // past the filter check is never inlined so it doesn't clutter the fast
 114     // path.
 115     #[inline(always)]
 116     fn exec<F>(&self, event_filter: EventFilter, f: F) -> TimingGuard<'_>
 117     where
 118         F: for<'a> FnOnce(&'a SelfProfiler) -> TimingGuard<'a>,
 119     {
 120         #[inline(never)]
 121         fn cold_call<F>(profiler_ref: &SelfProfilerRef, f: F) -> TimingGuard<'_>
 122         where
 123             F: for<'a> FnOnce(&'a SelfProfiler) -> TimingGuard<'a>,
 124         {
 125             let profiler = profiler_ref.profiler.as_ref().unwrap();
 126             f(&**profiler)
 127         }
 128
 129         if unlikely!(self.event_filter_mask.contains(event_filter)) {
 130             cold_call(self, f)
 131         } else {
 132             TimingGuard::none()
 133         }
 134     }
 135
 136     /// Start profiling a verbose generic activity. Profiling continues until the
 137     /// VerboseTimingGuard returned from this call is dropped. In addition to recording
 138     /// a measureme event, "verbose" generic activities also print a timing entry to
 139     /// stdout if the compiler is invoked with -Ztime or -Ztime-passes.
 140     #[inline(always)]
 141     pub fn verbose_generic_activity<'a>(&'a self, event_id: &'a str) -> VerboseTimingGuard<'a> {
 142         VerboseTimingGuard::start(
 143             event_id,
 144             self.print_verbose_generic_activities,
 145             self.generic_activity(event_id),
 146         )
 147     }
 148
 149     /// Start profiling a extra verbose generic activity. Profiling continues until the
 150     /// VerboseTimingGuard returned from this call is dropped. In addition to recording
 151     /// a measureme event, "extra verbose" generic activities also print a timing entry to
 152     /// stdout if the compiler is invoked with -Ztime-passes.
 153     #[inline(always)]
 154     pub fn extra_verbose_generic_activity<'a>(
 155         &'a self,
 156         event_id: &'a str,
 157     ) -> VerboseTimingGuard<'a> {
 158         // FIXME: This does not yet emit a measureme event
 159         // because callers encode arguments into `event_id`.
 160         VerboseTimingGuard::start(
 161             event_id,
 162             self.print_extra_verbose_generic_activities,
 163             TimingGuard::none(),
 164         )
 165     }
 166
 167     /// Start profiling a generic activity. Profiling continues until the
 168     /// TimingGuard returned from this call is dropped.
 169     #[inline(always)]
 170     pub fn generic_activity(&self, event_id: &str) -> TimingGuard<'_> {
 171         self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
 172             let event_id = profiler.profiler.alloc_string(event_id);
 173             TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id)
 174         })
 175     }
 176
 177     /// Start profiling a query provider. Profiling continues until the
 178     /// TimingGuard returned from this call is dropped.
 179     #[inline(always)]
 180     pub fn query_provider(&self, query_name: impl QueryName) -> TimingGuard<'_> {
 181         self.exec(EventFilter::QUERY_PROVIDERS, |profiler| {
 182             let event_id = SelfProfiler::get_query_name_string_id(query_name);
 183             TimingGuard::start(profiler, profiler.query_event_kind, event_id)
 184         })
 185     }
 186
 187     /// Record a query in-memory cache hit.
 188     #[inline(always)]
 189     pub fn query_cache_hit(&self, query_name: impl QueryName) {
 190         self.instant_query_event(
 191             |profiler| profiler.query_cache_hit_event_kind,
 192             query_name,
 193             EventFilter::QUERY_CACHE_HITS,
 194         );
 195     }
 196
 197     /// Start profiling a query being blocked on a concurrent execution.
 198     /// Profiling continues until the TimingGuard returned from this call is
 199     /// dropped.
 200     #[inline(always)]
 201     pub fn query_blocked(&self, query_name: impl QueryName) -> TimingGuard<'_> {
 202         self.exec(EventFilter::QUERY_BLOCKED, |profiler| {
 203             let event_id = SelfProfiler::get_query_name_string_id(query_name);
 204             TimingGuard::start(profiler, profiler.query_blocked_event_kind, event_id)
 205         })
 206     }
 207
 208     /// Start profiling how long it takes to load a query result from the
 209     /// incremental compilation on-disk cache. Profiling continues until the
 210     /// TimingGuard returned from this call is dropped.
 211     #[inline(always)]
 212     pub fn incr_cache_loading(&self, query_name: impl QueryName) -> TimingGuard<'_> {
 213         self.exec(EventFilter::INCR_CACHE_LOADS, |profiler| {
 214             let event_id = SelfProfiler::get_query_name_string_id(query_name);
 215             TimingGuard::start(profiler, profiler.incremental_load_result_event_kind, event_id)
 216         })
 217     }
 218
 219     #[inline(always)]
 220     fn instant_query_event(
 221         &self,
 222         event_kind: fn(&SelfProfiler) -> StringId,
 223         query_name: impl QueryName,
 224         event_filter: EventFilter,
 225     ) {
 226         drop(self.exec(event_filter, |profiler| {
 227             let event_id = SelfProfiler::get_query_name_string_id(query_name);
 228             let thread_id = thread_id_to_u32(std::thread::current().id());
 229
 230             profiler.profiler.record_instant_event(event_kind(profiler), event_id, thread_id);
 231
 232             TimingGuard::none()
 233         }));
 234     }
 235
 236     pub fn register_queries(&self, f: impl FnOnce(&SelfProfiler)) {
 237         if let Some(profiler) = &self.profiler {
 238             f(&profiler)
 239         }
 240     }
 241 }
 242
 243 pub struct SelfProfiler {
 244     profiler: Profiler,
 245     event_filter_mask: EventFilter,
 246     query_event_kind: StringId,
 247     generic_activity_event_kind: StringId,
 248     incremental_load_result_event_kind: StringId,
 249     query_blocked_event_kind: StringId,
 250     query_cache_hit_event_kind: StringId,
 251 }
 252
 253 impl SelfProfiler {
 254     pub fn new(
 255         output_directory: &Path,
 256         crate_name: Option<&str>,
 257         event_filters: &Option<Vec<String>>,
 258     ) -> Result<SelfProfiler, Box<dyn Error>> {
 259         fs::create_dir_all(output_directory)?;
 260
 261         let crate_name = crate_name.unwrap_or("unknown-crate");
 262         let filename = format!("{}-{}.rustc_profile", crate_name, process::id());
 263         let path = output_directory.join(&filename);
 264         let profiler = Profiler::new(&path)?;
 265
 266         let query_event_kind = profiler.alloc_string("Query");
 267         let generic_activity_event_kind = profiler.alloc_string("GenericActivity");
 268         let incremental_load_result_event_kind = profiler.alloc_string("IncrementalLoadResult");
 269         let query_blocked_event_kind = profiler.alloc_string("QueryBlocked");
 270         let query_cache_hit_event_kind = profiler.alloc_string("QueryCacheHit");
 271
 272         let mut event_filter_mask = EventFilter::empty();
 273
 274         if let Some(ref event_filters) = *event_filters {
 275             let mut unknown_events = vec![];
 276             for item in event_filters {
 277                 if let Some(&(_, mask)) =
 278                     EVENT_FILTERS_BY_NAME.iter().find(|&(name, _)| name == item)
 279                 {
 280                     event_filter_mask |= mask;
 281                 } else {
 282                     unknown_events.push(item.clone());
 283                 }
 284             }
 285
 286             // Warn about any unknown event names
 287             if unknown_events.len() > 0 {
 288                 unknown_events.sort();
 289                 unknown_events.dedup();
 290
 291                 warn!(
 292                     "Unknown self-profiler events specified: {}. Available options are: {}.",
 293                     unknown_events.join(", "),
 294                     EVENT_FILTERS_BY_NAME
 295                         .iter()
 296                         .map(|&(name, _)| name.to_string())
 297                         .collect::<Vec<_>>()
 298                         .join(", ")
 299                 );
 300             }
 301         } else {
 302             event_filter_mask = EventFilter::DEFAULT;
 303         }
 304
 305         Ok(SelfProfiler {
 306             profiler,
 307             event_filter_mask,
 308             query_event_kind,
 309             generic_activity_event_kind,
 310             incremental_load_result_event_kind,
 311             query_blocked_event_kind,
 312             query_cache_hit_event_kind,
 313         })
 314     }
 315
 316     fn get_query_name_string_id(query_name: impl QueryName) -> StringId {
 317         let discriminant =
 318             unsafe { mem::transmute::<Discriminant<_>, u64>(query_name.discriminant()) };
 319
 320         StringId::reserved(discriminant as u32)
 321     }
 322
 323     pub fn register_query_name(&self, query_name: impl QueryName) {
 324         let id = SelfProfiler::get_query_name_string_id(query_name);
 325         self.profiler.alloc_string_with_reserved_id(id, query_name.as_str());
 326     }
 327 }
 328
 329 #[must_use]
 330 pub struct TimingGuard<'a>(Option<measureme::TimingGuard<'a, SerializationSink>>);
 331
 332 impl<'a> TimingGuard<'a> {
 333     #[inline]
 334     pub fn start(
 335         profiler: &'a SelfProfiler,
 336         event_kind: StringId,
 337         event_id: StringId,
 338     ) -> TimingGuard<'a> {
 339         let thread_id = thread_id_to_u32(std::thread::current().id());
 340         let raw_profiler = &profiler.profiler;
 341         let timing_guard =
 342             raw_profiler.start_recording_interval_event(event_kind, event_id, thread_id);
 343         TimingGuard(Some(timing_guard))
 344     }
 345
 346     #[inline]
 347     pub fn none() -> TimingGuard<'a> {
 348         TimingGuard(None)
 349     }
 350 }
 351
 352 #[must_use]
 353 pub struct VerboseTimingGuard<'a> {
 354     event_id: &'a str,
 355     start: Option<Instant>,
 356     _guard: TimingGuard<'a>,
 357 }
 358
 359 impl<'a> VerboseTimingGuard<'a> {
 360     pub fn start(event_id: &'a str, verbose: bool, _guard: TimingGuard<'a>) -> Self {
 361         VerboseTimingGuard {
 362             event_id,
 363             _guard,
 364             start: if unlikely!(verbose) { Some(Instant::now()) } else { None },
 365         }
 366     }
 367
 368     #[inline(always)]
 369     pub fn run<R>(self, f: impl FnOnce() -> R) -> R {
 370         let _timer = self;
 371         f()
 372     }
 373 }
 374
 375 impl Drop for VerboseTimingGuard<'_> {
 376     fn drop(&mut self) {
 377         self.start.map(|start| print_time_passes_entry(true, self.event_id, start.elapsed()));
 378     }
 379 }
 380
 381 pub fn print_time_passes_entry(do_it: bool, what: &str, dur: Duration) {
 382     if !do_it {
 383         return;
 384     }
 385
 386     let mem_string = match get_resident() {
 387         Some(n) => {
 388             let mb = n as f64 / 1_000_000.0;
 389             format!("; rss: {}MB", mb.round() as usize)
 390         }
 391         None => String::new(),
 392     };
 393     println!("time: {}{}\t{}", duration_to_secs_str(dur), mem_string, what);
 394 }
 395
 396 // Hack up our own formatting for the duration to make it easier for scripts
 397 // to parse (always use the same number of decimal places and the same unit).
 398 pub fn duration_to_secs_str(dur: std::time::Duration) -> String {
 399     const NANOS_PER_SEC: f64 = 1_000_000_000.0;
 400     let secs = dur.as_secs() as f64 + dur.subsec_nanos() as f64 / NANOS_PER_SEC;
 401
 402     format!("{:.3}", secs)
 403 }
 404
 405 // Memory reporting
 406 #[cfg(unix)]
 407 fn get_resident() -> Option<usize> {
 408     let field = 1;
 409     let contents = fs::read("/proc/self/statm").ok()?;
 410     let contents = String::from_utf8(contents).ok()?;
 411     let s = contents.split_whitespace().nth(field)?;
 412     let npages = s.parse::<usize>().ok()?;
 413     Some(npages * 4096)
 414 }
 415
 416 #[cfg(windows)]
 417 fn get_resident() -> Option<usize> {
 418     type BOOL = i32;
 419     type DWORD = u32;
 420     type HANDLE = *mut u8;
 421     use libc::size_t;
 422     #[repr(C)]
 423     #[allow(non_snake_case)]
 424     struct PROCESS_MEMORY_COUNTERS {
 425         cb: DWORD,
 426         PageFaultCount: DWORD,
 427         PeakWorkingSetSize: size_t,
 428         WorkingSetSize: size_t,
 429         QuotaPeakPagedPoolUsage: size_t,
 430         QuotaPagedPoolUsage: size_t,
 431         QuotaPeakNonPagedPoolUsage: size_t,
 432         QuotaNonPagedPoolUsage: size_t,
 433         PagefileUsage: size_t,
 434         PeakPagefileUsage: size_t,
 435     }
 436     #[allow(non_camel_case_types)]
 437     type PPROCESS_MEMORY_COUNTERS = *mut PROCESS_MEMORY_COUNTERS;
 438     #[link(name = "psapi")]
 439     extern "system" {
 440         fn GetCurrentProcess() -> HANDLE;
 441         fn GetProcessMemoryInfo(
 442             Process: HANDLE,
 443             ppsmemCounters: PPROCESS_MEMORY_COUNTERS,
 444             cb: DWORD,
 445         ) -> BOOL;
 446     }
 447     let mut pmc: PROCESS_MEMORY_COUNTERS = unsafe { mem::zeroed() };
 448     pmc.cb = mem::size_of_val(&pmc) as DWORD;
 449     match unsafe { GetProcessMemoryInfo(GetCurrentProcess(), &mut pmc, pmc.cb) } {
 450         0 => None,
 451         _ => Some(pmc.WorkingSetSize as usize),
 452     }
 453 }