1 //! # Rust Compiler Self-Profiling
3 //! This module implements the basic framework for the compiler's self-
4 //! profiling support. It provides the `SelfProfiler` type which enables
5 //! recording "events". An event is something that starts and ends at a given
6 //! point in time and has an ID and a kind attached to it. This allows for
7 //! tracing the compiler's activity.
9 //! Internally this module uses the custom tailored [measureme][mm] crate for
10 //! efficiently recording events to disk in a compact format that can be
11 //! post-processed and analyzed by the suite of tools in the `measureme`
12 //! project. The highest priority for the tracing framework is on incurring as
13 //! little overhead as possible.
18 //! Events have a few properties:
20 //! - The `event_kind` designates the broad category of an event (e.g. does it
21 //! correspond to the execution of a query provider or to loading something
22 //! from the incr. comp. on-disk cache, etc).
23 //! - The `event_id` designates the query invocation or function call it
24 //! corresponds to, possibly including the query key or function arguments.
25 //! - Each event stores the ID of the thread it was recorded on.
26 //! - The timestamp stores beginning and end of the event, or the single point
27 //! in time it occurred at for "instant" events.
30 //! ## Event Filtering
32 //! Event generation can be filtered by event kind. Recording all possible
33 //! events generates a lot of data, much of which is not needed for most kinds
34 //! of analysis. So, in order to keep overhead as low as possible for a given
35 //! use case, the `SelfProfiler` will only record the kinds of events that
36 //! pass the filter specified as a command line argument to the compiler.
39 //! ## `event_id` Assignment
41 //! As far as `measureme` is concerned, `event_id`s are just strings. However,
42 //! it would incur too much overhead to generate and persist each `event_id`
43 //! string at the point where the event is recorded. In order to make this more
44 //! efficient `measureme` has two features:
46 //! - Strings can share their content, so that re-occurring parts don't have to
47 //! be copied over and over again. One allocates a string in `measureme` and
48 //! gets back a `StringId`. This `StringId` is then used to refer to that
49 //! string. `measureme` strings are actually DAGs of string components so that
50 //! arbitrary sharing of substrings can be done efficiently. This is useful
51 //! because `event_id`s contain lots of redundant text like query names or
52 //! def-path components.
54 //! - `StringId`s can be "virtual" which means that the client picks a numeric
55 //! ID according to some application-specific scheme and can later make that
56 //! ID be mapped to an actual string. This is used to cheaply generate
57 //! `event_id`s while the events actually occur, causing little timing
58 //! distortion, and then later map those `StringId`s, in bulk, to actual
59 //! `event_id` strings. This way the largest part of the tracing overhead is
60 //! localized to one contiguous chunk of time.
62 //! How are these `event_id`s generated in the compiler? For things that occur
63 //! infrequently (e.g. "generic activities"), we just allocate the string the
64 //! first time it is used and then keep the `StringId` in a hash table. This
65 //! is implemented in `SelfProfiler::get_or_alloc_cached_string()`.
67 //! For queries it gets more interesting: First we need a unique numeric ID for
68 //! each query invocation (the `QueryInvocationId`). This ID is used as the
69 //! virtual `StringId` we use as `event_id` for a given event. This ID has to
70 //! be available both when the query is executed and later, together with the
71 //! query key, when we allocate the actual `event_id` strings in bulk.
73 //! We could make the compiler generate and keep track of such an ID for each
74 //! query invocation but luckily we already have something that fits all the
75 //! the requirements: the query's `DepNodeIndex`. So we use the numeric value
76 //! of the `DepNodeIndex` as `event_id` when recording the event and then,
77 //! just before the query context is dropped, we walk the entire query cache
78 //! (which stores the `DepNodeIndex` along with the query key for each
79 //! invocation) and allocate the corresponding strings together with a mapping
80 //! for `DepNodeIndex as StringId`.
82 //! [mm]: https://github.com/rust-lang/measureme/
84 use crate::fx::FxHashMap;
86 use std::error::Error;
91 use std::thread::ThreadId;
92 use std::time::{Duration, Instant};
95 use measureme::{EventId, EventIdBuilder, SerializableString, StringId};
96 use parking_lot::RwLock;
98 /// MmapSerializatioSink is faster on macOS and Linux
99 /// but FileSerializationSink is faster on Windows
101 type SerializationSink = measureme::MmapSerializationSink;
103 type SerializationSink = measureme::FileSerializationSink;
105 type Profiler = measureme::Profiler<SerializationSink>;
107 #[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)]
108 pub enum ProfileCategory {
118 bitflags::bitflags! {
119 struct EventFilter: u32 {
120 const GENERIC_ACTIVITIES = 1 << 0;
121 const QUERY_PROVIDERS = 1 << 1;
122 const QUERY_CACHE_HITS = 1 << 2;
123 const QUERY_BLOCKED = 1 << 3;
124 const INCR_CACHE_LOADS = 1 << 4;
126 const QUERY_KEYS = 1 << 5;
128 const DEFAULT = Self::GENERIC_ACTIVITIES.bits |
129 Self::QUERY_PROVIDERS.bits |
130 Self::QUERY_BLOCKED.bits |
131 Self::INCR_CACHE_LOADS.bits;
133 // empty() and none() aren't const-fns unfortunately
135 const ALL = !Self::NONE.bits;
139 const EVENT_FILTERS_BY_NAME: &[(&str, EventFilter)] = &[
140 ("none", EventFilter::NONE),
141 ("all", EventFilter::ALL),
142 ("generic-activity", EventFilter::GENERIC_ACTIVITIES),
143 ("query-provider", EventFilter::QUERY_PROVIDERS),
144 ("query-cache-hit", EventFilter::QUERY_CACHE_HITS),
145 ("query-blocked", EventFilter::QUERY_BLOCKED),
146 ("incr-cache-load", EventFilter::INCR_CACHE_LOADS),
147 ("query-keys", EventFilter::QUERY_KEYS),
150 fn thread_id_to_u32(tid: ThreadId) -> u32 {
151 unsafe { std::mem::transmute::<ThreadId, u64>(tid) as u32 }
154 /// Something that uniquely identifies a query invocation.
155 pub struct QueryInvocationId(pub u32);
157 /// A reference to the SelfProfiler. It can be cloned and sent across thread
158 /// boundaries at will.
160 pub struct SelfProfilerRef {
161 // This field is `None` if self-profiling is disabled for the current
162 // compilation session.
163 profiler: Option<Arc<SelfProfiler>>,
165 // We store the filter mask directly in the reference because that doesn't
166 // cost anything and allows for filtering with checking if the profiler is
168 event_filter_mask: EventFilter,
170 // Print verbose generic activities to stdout
171 print_verbose_generic_activities: bool,
173 // Print extra verbose generic activities to stdout
174 print_extra_verbose_generic_activities: bool,
177 impl SelfProfilerRef {
179 profiler: Option<Arc<SelfProfiler>>,
180 print_verbose_generic_activities: bool,
181 print_extra_verbose_generic_activities: bool,
182 ) -> SelfProfilerRef {
183 // If there is no SelfProfiler then the filter mask is set to NONE,
184 // ensuring that nothing ever tries to actually access it.
185 let event_filter_mask =
186 profiler.as_ref().map(|p| p.event_filter_mask).unwrap_or(EventFilter::NONE);
191 print_verbose_generic_activities,
192 print_extra_verbose_generic_activities,
196 // This shim makes sure that calls only get executed if the filter mask
197 // lets them pass. It also contains some trickery to make sure that
198 // code is optimized for non-profiling compilation sessions, i.e. anything
199 // past the filter check is never inlined so it doesn't clutter the fast
202 fn exec<F>(&self, event_filter: EventFilter, f: F) -> TimingGuard<'_>
204 F: for<'a> FnOnce(&'a SelfProfiler) -> TimingGuard<'a>,
207 fn cold_call<F>(profiler_ref: &SelfProfilerRef, f: F) -> TimingGuard<'_>
209 F: for<'a> FnOnce(&'a SelfProfiler) -> TimingGuard<'a>,
211 let profiler = profiler_ref.profiler.as_ref().unwrap();
215 if unlikely!(self.event_filter_mask.contains(event_filter)) {
222 /// Start profiling a verbose generic activity. Profiling continues until the
223 /// VerboseTimingGuard returned from this call is dropped. In addition to recording
224 /// a measureme event, "verbose" generic activities also print a timing entry to
225 /// stdout if the compiler is invoked with -Ztime or -Ztime-passes.
227 pub fn verbose_generic_activity<'a>(
229 event_id: &'static str,
230 ) -> VerboseTimingGuard<'a> {
231 VerboseTimingGuard::start(
233 self.print_verbose_generic_activities,
234 self.generic_activity(event_id),
238 /// Start profiling a extra verbose generic activity. Profiling continues until the
239 /// VerboseTimingGuard returned from this call is dropped. In addition to recording
240 /// a measureme event, "extra verbose" generic activities also print a timing entry to
241 /// stdout if the compiler is invoked with -Ztime-passes.
243 pub fn extra_verbose_generic_activity<'a>(
246 ) -> VerboseTimingGuard<'a> {
247 // FIXME: This does not yet emit a measureme event
248 // because callers encode arguments into `event_id`.
249 VerboseTimingGuard::start(
251 self.print_extra_verbose_generic_activities,
256 /// Start profiling a generic activity. Profiling continues until the
257 /// TimingGuard returned from this call is dropped.
259 pub fn generic_activity(&self, event_id: &'static str) -> TimingGuard<'_> {
260 self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
261 let event_id = profiler.get_or_alloc_cached_string(event_id);
262 let event_id = EventId::from_label(event_id);
263 TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id)
267 /// Start profiling a query provider. Profiling continues until the
268 /// TimingGuard returned from this call is dropped.
270 pub fn query_provider(&self) -> TimingGuard<'_> {
271 self.exec(EventFilter::QUERY_PROVIDERS, |profiler| {
272 TimingGuard::start(profiler, profiler.query_event_kind, EventId::INVALID)
276 /// Record a query in-memory cache hit.
278 pub fn query_cache_hit(&self, query_invocation_id: QueryInvocationId) {
279 self.instant_query_event(
280 |profiler| profiler.query_cache_hit_event_kind,
282 EventFilter::QUERY_CACHE_HITS,
286 /// Start profiling a query being blocked on a concurrent execution.
287 /// Profiling continues until the TimingGuard returned from this call is
290 pub fn query_blocked(&self) -> TimingGuard<'_> {
291 self.exec(EventFilter::QUERY_BLOCKED, |profiler| {
292 TimingGuard::start(profiler, profiler.query_blocked_event_kind, EventId::INVALID)
296 /// Start profiling how long it takes to load a query result from the
297 /// incremental compilation on-disk cache. Profiling continues until the
298 /// TimingGuard returned from this call is dropped.
300 pub fn incr_cache_loading(&self) -> TimingGuard<'_> {
301 self.exec(EventFilter::INCR_CACHE_LOADS, |profiler| {
304 profiler.incremental_load_result_event_kind,
311 fn instant_query_event(
313 event_kind: fn(&SelfProfiler) -> StringId,
314 query_invocation_id: QueryInvocationId,
315 event_filter: EventFilter,
317 drop(self.exec(event_filter, |profiler| {
318 let event_id = StringId::new_virtual(query_invocation_id.0);
319 let thread_id = thread_id_to_u32(std::thread::current().id());
321 profiler.profiler.record_instant_event(
322 event_kind(profiler),
323 EventId::from_virtual(event_id),
331 pub fn with_profiler(&self, f: impl FnOnce(&SelfProfiler)) {
332 if let Some(profiler) = &self.profiler {
338 pub fn enabled(&self) -> bool {
339 self.profiler.is_some()
343 pub struct SelfProfiler {
345 event_filter_mask: EventFilter,
347 string_cache: RwLock<FxHashMap<&'static str, StringId>>,
349 query_event_kind: StringId,
350 generic_activity_event_kind: StringId,
351 incremental_load_result_event_kind: StringId,
352 query_blocked_event_kind: StringId,
353 query_cache_hit_event_kind: StringId,
358 output_directory: &Path,
359 crate_name: Option<&str>,
360 event_filters: &Option<Vec<String>>,
361 ) -> Result<SelfProfiler, Box<dyn Error>> {
362 fs::create_dir_all(output_directory)?;
364 let crate_name = crate_name.unwrap_or("unknown-crate");
365 let filename = format!("{}-{}.rustc_profile", crate_name, process::id());
366 let path = output_directory.join(&filename);
367 let profiler = Profiler::new(&path)?;
369 let query_event_kind = profiler.alloc_string("Query");
370 let generic_activity_event_kind = profiler.alloc_string("GenericActivity");
371 let incremental_load_result_event_kind = profiler.alloc_string("IncrementalLoadResult");
372 let query_blocked_event_kind = profiler.alloc_string("QueryBlocked");
373 let query_cache_hit_event_kind = profiler.alloc_string("QueryCacheHit");
375 let mut event_filter_mask = EventFilter::empty();
377 if let Some(ref event_filters) = *event_filters {
378 let mut unknown_events = vec![];
379 for item in event_filters {
380 if let Some(&(_, mask)) =
381 EVENT_FILTERS_BY_NAME.iter().find(|&(name, _)| name == item)
383 event_filter_mask |= mask;
385 unknown_events.push(item.clone());
389 // Warn about any unknown event names
390 if unknown_events.len() > 0 {
391 unknown_events.sort();
392 unknown_events.dedup();
395 "Unknown self-profiler events specified: {}. Available options are: {}.",
396 unknown_events.join(", "),
397 EVENT_FILTERS_BY_NAME
399 .map(|&(name, _)| name.to_string())
405 event_filter_mask = EventFilter::DEFAULT;
411 string_cache: RwLock::new(FxHashMap::default()),
413 generic_activity_event_kind,
414 incremental_load_result_event_kind,
415 query_blocked_event_kind,
416 query_cache_hit_event_kind,
420 /// Allocates a new string in the profiling data. Does not do any caching
421 /// or deduplication.
422 pub fn alloc_string<STR: SerializableString + ?Sized>(&self, s: &STR) -> StringId {
423 self.profiler.alloc_string(s)
426 /// Gets a `StringId` for the given string. This method makes sure that
427 /// any strings going through it will only be allocated once in the
429 pub fn get_or_alloc_cached_string(&self, s: &'static str) -> StringId {
430 // Only acquire a read-lock first since we assume that the string is
431 // already present in the common case.
433 let string_cache = self.string_cache.read();
435 if let Some(&id) = string_cache.get(s) {
440 let mut string_cache = self.string_cache.write();
441 // Check if the string has already been added in the small time window
442 // between dropping the read lock and acquiring the write lock.
443 *string_cache.entry(s).or_insert_with(|| self.profiler.alloc_string(s))
446 pub fn map_query_invocation_id_to_string(&self, from: QueryInvocationId, to: StringId) {
447 let from = StringId::new_virtual(from.0);
448 self.profiler.map_virtual_to_concrete_string(from, to);
451 pub fn bulk_map_query_invocation_id_to_single_string<I>(&self, from: I, to: StringId)
453 I: Iterator<Item = QueryInvocationId> + ExactSizeIterator,
455 let from = from.map(|qid| StringId::new_virtual(qid.0));
456 self.profiler.bulk_map_virtual_to_single_concrete_string(from, to);
459 pub fn query_key_recording_enabled(&self) -> bool {
460 self.event_filter_mask.contains(EventFilter::QUERY_KEYS)
463 pub fn event_id_builder(&self) -> EventIdBuilder<'_, SerializationSink> {
464 EventIdBuilder::new(&self.profiler)
469 pub struct TimingGuard<'a>(Option<measureme::TimingGuard<'a, SerializationSink>>);
471 impl<'a> TimingGuard<'a> {
474 profiler: &'a SelfProfiler,
475 event_kind: StringId,
477 ) -> TimingGuard<'a> {
478 let thread_id = thread_id_to_u32(std::thread::current().id());
479 let raw_profiler = &profiler.profiler;
481 raw_profiler.start_recording_interval_event(event_kind, event_id, thread_id);
482 TimingGuard(Some(timing_guard))
486 pub fn finish_with_query_invocation_id(self, query_invocation_id: QueryInvocationId) {
487 if let Some(guard) = self.0 {
488 let event_id = StringId::new_virtual(query_invocation_id.0);
489 let event_id = EventId::from_virtual(event_id);
490 guard.finish_with_override_event_id(event_id);
495 pub fn none() -> TimingGuard<'a> {
501 pub struct VerboseTimingGuard<'a> {
503 start: Option<Instant>,
504 _guard: TimingGuard<'a>,
507 impl<'a> VerboseTimingGuard<'a> {
508 pub fn start(event_id: &'a str, verbose: bool, _guard: TimingGuard<'a>) -> Self {
512 start: if unlikely!(verbose) { Some(Instant::now()) } else { None },
517 pub fn run<R>(self, f: impl FnOnce() -> R) -> R {
523 impl Drop for VerboseTimingGuard<'_> {
525 self.start.map(|start| print_time_passes_entry(true, self.event_id, start.elapsed()));
529 pub fn print_time_passes_entry(do_it: bool, what: &str, dur: Duration) {
534 let mem_string = match get_resident() {
536 let mb = n as f64 / 1_000_000.0;
537 format!("; rss: {}MB", mb.round() as usize)
539 None => String::new(),
541 println!("time: {}{}\t{}", duration_to_secs_str(dur), mem_string, what);
544 // Hack up our own formatting for the duration to make it easier for scripts
545 // to parse (always use the same number of decimal places and the same unit).
546 pub fn duration_to_secs_str(dur: std::time::Duration) -> String {
547 const NANOS_PER_SEC: f64 = 1_000_000_000.0;
548 let secs = dur.as_secs() as f64 + dur.subsec_nanos() as f64 / NANOS_PER_SEC;
550 format!("{:.3}", secs)
555 fn get_resident() -> Option<usize> {
557 let contents = fs::read("/proc/self/statm").ok()?;
558 let contents = String::from_utf8(contents).ok()?;
559 let s = contents.split_whitespace().nth(field)?;
560 let npages = s.parse::<usize>().ok()?;
565 fn get_resident() -> Option<usize> {
568 type HANDLE = *mut u8;
571 #[allow(non_snake_case)]
572 struct PROCESS_MEMORY_COUNTERS {
574 PageFaultCount: DWORD,
575 PeakWorkingSetSize: size_t,
576 WorkingSetSize: size_t,
577 QuotaPeakPagedPoolUsage: size_t,
578 QuotaPagedPoolUsage: size_t,
579 QuotaPeakNonPagedPoolUsage: size_t,
580 QuotaNonPagedPoolUsage: size_t,
581 PagefileUsage: size_t,
582 PeakPagefileUsage: size_t,
584 #[allow(non_camel_case_types)]
585 type PPROCESS_MEMORY_COUNTERS = *mut PROCESS_MEMORY_COUNTERS;
586 #[link(name = "psapi")]
588 fn GetCurrentProcess() -> HANDLE;
589 fn GetProcessMemoryInfo(
591 ppsmemCounters: PPROCESS_MEMORY_COUNTERS,
595 let mut pmc: PROCESS_MEMORY_COUNTERS = unsafe { std::mem::zeroed() };
596 pmc.cb = std::mem::size_of_val(&pmc) as DWORD;
597 match unsafe { GetProcessMemoryInfo(GetCurrentProcess(), &mut pmc, pmc.cb) } {
599 _ => Some(pmc.WorkingSetSize as usize),