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/
85 use crate::fx
::FxHashMap
;
87 use std
::borrow
::Borrow
;
88 use std
::collections
::hash_map
::Entry
;
89 use std
::convert
::Into
;
90 use std
::error
::Error
;
95 use std
::time
::{Duration, Instant}
;
97 use measureme
::{EventId, EventIdBuilder, SerializableString, StringId}
;
98 use parking_lot
::RwLock
;
101 if #[cfg(any(windows, target_os = "wasi"))] {
102 /// FileSerializationSink is faster on Windows
103 type SerializationSink
= measureme
::FileSerializationSink
;
104 } else if #[cfg(target_arch = "wasm32")] {
105 type SerializationSink
= measureme
::ByteVecSink
;
107 /// MmapSerializatioSink is faster on macOS and Linux
108 type SerializationSink
= measureme
::MmapSerializationSink
;
112 type Profiler
= measureme
::Profiler
<SerializationSink
>;
114 #[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)]
115 pub enum ProfileCategory
{
125 bitflags
::bitflags
! {
126 struct EventFilter
: u32 {
127 const GENERIC_ACTIVITIES
= 1 << 0;
128 const QUERY_PROVIDERS
= 1 << 1;
129 const QUERY_CACHE_HITS
= 1 << 2;
130 const QUERY_BLOCKED
= 1 << 3;
131 const INCR_CACHE_LOADS
= 1 << 4;
133 const QUERY_KEYS
= 1 << 5;
134 const FUNCTION_ARGS
= 1 << 6;
137 const DEFAULT
= Self::GENERIC_ACTIVITIES
.bits
|
138 Self::QUERY_PROVIDERS
.bits
|
139 Self::QUERY_BLOCKED
.bits
|
140 Self::INCR_CACHE_LOADS
.bits
;
142 const ARGS
= Self::QUERY_KEYS
.bits
| Self::FUNCTION_ARGS
.bits
;
146 // keep this in sync with the `-Z self-profile-events` help message in librustc_session/options.rs
147 const EVENT_FILTERS_BY_NAME
: &[(&str, EventFilter
)] = &[
148 ("none", EventFilter
::empty()),
149 ("all", EventFilter
::all()),
150 ("default", EventFilter
::DEFAULT
),
151 ("generic-activity", EventFilter
::GENERIC_ACTIVITIES
),
152 ("query-provider", EventFilter
::QUERY_PROVIDERS
),
153 ("query-cache-hit", EventFilter
::QUERY_CACHE_HITS
),
154 ("query-blocked", EventFilter
::QUERY_BLOCKED
),
155 ("incr-cache-load", EventFilter
::INCR_CACHE_LOADS
),
156 ("query-keys", EventFilter
::QUERY_KEYS
),
157 ("function-args", EventFilter
::FUNCTION_ARGS
),
158 ("args", EventFilter
::ARGS
),
159 ("llvm", EventFilter
::LLVM
),
162 /// Something that uniquely identifies a query invocation.
163 pub struct QueryInvocationId(pub u32);
165 /// A reference to the SelfProfiler. It can be cloned and sent across thread
166 /// boundaries at will.
168 pub struct SelfProfilerRef
{
169 // This field is `None` if self-profiling is disabled for the current
170 // compilation session.
171 profiler
: Option
<Arc
<SelfProfiler
>>,
173 // We store the filter mask directly in the reference because that doesn't
174 // cost anything and allows for filtering with checking if the profiler is
176 event_filter_mask
: EventFilter
,
178 // Print verbose generic activities to stdout
179 print_verbose_generic_activities
: bool
,
181 // Print extra verbose generic activities to stdout
182 print_extra_verbose_generic_activities
: bool
,
185 impl SelfProfilerRef
{
187 profiler
: Option
<Arc
<SelfProfiler
>>,
188 print_verbose_generic_activities
: bool
,
189 print_extra_verbose_generic_activities
: bool
,
190 ) -> SelfProfilerRef
{
191 // If there is no SelfProfiler then the filter mask is set to NONE,
192 // ensuring that nothing ever tries to actually access it.
193 let event_filter_mask
=
194 profiler
.as_ref().map(|p
| p
.event_filter_mask
).unwrap_or(EventFilter
::empty());
199 print_verbose_generic_activities
,
200 print_extra_verbose_generic_activities
,
204 // This shim makes sure that calls only get executed if the filter mask
205 // lets them pass. It also contains some trickery to make sure that
206 // code is optimized for non-profiling compilation sessions, i.e. anything
207 // past the filter check is never inlined so it doesn't clutter the fast
210 fn exec
<F
>(&self, event_filter
: EventFilter
, f
: F
) -> TimingGuard
<'_
>
212 F
: for<'a
> FnOnce(&'a SelfProfiler
) -> TimingGuard
<'a
>,
215 fn cold_call
<F
>(profiler_ref
: &SelfProfilerRef
, f
: F
) -> TimingGuard
<'_
>
217 F
: for<'a
> FnOnce(&'a SelfProfiler
) -> TimingGuard
<'a
>,
219 let profiler
= profiler_ref
.profiler
.as_ref().unwrap();
223 if unlikely
!(self.event_filter_mask
.contains(event_filter
)) {
230 /// Start profiling a verbose generic activity. Profiling continues until the
231 /// VerboseTimingGuard returned from this call is dropped. In addition to recording
232 /// a measureme event, "verbose" generic activities also print a timing entry to
233 /// stdout if the compiler is invoked with -Ztime or -Ztime-passes.
234 pub fn verbose_generic_activity
<'a
>(
236 event_label
: &'
static str,
237 ) -> VerboseTimingGuard
<'a
> {
239 if self.print_verbose_generic_activities { Some(event_label.to_owned()) }
else { None }
;
241 VerboseTimingGuard
::start(message
, self.generic_activity(event_label
))
244 /// Start profiling a extra verbose generic activity. Profiling continues until the
245 /// VerboseTimingGuard returned from this call is dropped. In addition to recording
246 /// a measureme event, "extra verbose" generic activities also print a timing entry to
247 /// stdout if the compiler is invoked with -Ztime-passes.
248 pub fn extra_verbose_generic_activity
<'a
, A
>(
250 event_label
: &'
static str,
252 ) -> VerboseTimingGuard
<'a
>
254 A
: Borrow
<str> + Into
<String
>,
256 let message
= if self.print_extra_verbose_generic_activities
{
257 Some(format
!("{}({})", event_label
, event_arg
.borrow()))
262 VerboseTimingGuard
::start(message
, self.generic_activity_with_arg(event_label
, event_arg
))
265 /// Start profiling a generic activity. Profiling continues until the
266 /// TimingGuard returned from this call is dropped.
268 pub fn generic_activity(&self, event_label
: &'
static str) -> TimingGuard
<'_
> {
269 self.exec(EventFilter
::GENERIC_ACTIVITIES
, |profiler
| {
270 let event_label
= profiler
.get_or_alloc_cached_string(event_label
);
271 let event_id
= EventId
::from_label(event_label
);
272 TimingGuard
::start(profiler
, profiler
.generic_activity_event_kind
, event_id
)
276 /// Start profiling a generic activity. Profiling continues until the
277 /// TimingGuard returned from this call is dropped.
279 pub fn generic_activity_with_arg
<A
>(
281 event_label
: &'
static str,
285 A
: Borrow
<str> + Into
<String
>,
287 self.exec(EventFilter
::GENERIC_ACTIVITIES
, |profiler
| {
288 let builder
= EventIdBuilder
::new(&profiler
.profiler
);
289 let event_label
= profiler
.get_or_alloc_cached_string(event_label
);
290 let event_id
= if profiler
.event_filter_mask
.contains(EventFilter
::FUNCTION_ARGS
) {
291 let event_arg
= profiler
.get_or_alloc_cached_string(event_arg
);
292 builder
.from_label_and_arg(event_label
, event_arg
)
294 builder
.from_label(event_label
)
296 TimingGuard
::start(profiler
, profiler
.generic_activity_event_kind
, event_id
)
300 /// Start profiling a query provider. Profiling continues until the
301 /// TimingGuard returned from this call is dropped.
303 pub fn query_provider(&self) -> TimingGuard
<'_
> {
304 self.exec(EventFilter
::QUERY_PROVIDERS
, |profiler
| {
305 TimingGuard
::start(profiler
, profiler
.query_event_kind
, EventId
::INVALID
)
309 /// Record a query in-memory cache hit.
311 pub fn query_cache_hit(&self, query_invocation_id
: QueryInvocationId
) {
312 self.instant_query_event(
313 |profiler
| profiler
.query_cache_hit_event_kind
,
315 EventFilter
::QUERY_CACHE_HITS
,
319 /// Start profiling a query being blocked on a concurrent execution.
320 /// Profiling continues until the TimingGuard returned from this call is
323 pub fn query_blocked(&self) -> TimingGuard
<'_
> {
324 self.exec(EventFilter
::QUERY_BLOCKED
, |profiler
| {
325 TimingGuard
::start(profiler
, profiler
.query_blocked_event_kind
, EventId
::INVALID
)
329 /// Start profiling how long it takes to load a query result from the
330 /// incremental compilation on-disk cache. Profiling continues until the
331 /// TimingGuard returned from this call is dropped.
333 pub fn incr_cache_loading(&self) -> TimingGuard
<'_
> {
334 self.exec(EventFilter
::INCR_CACHE_LOADS
, |profiler
| {
337 profiler
.incremental_load_result_event_kind
,
344 fn instant_query_event(
346 event_kind
: fn(&SelfProfiler
) -> StringId
,
347 query_invocation_id
: QueryInvocationId
,
348 event_filter
: EventFilter
,
350 drop(self.exec(event_filter
, |profiler
| {
351 let event_id
= StringId
::new_virtual(query_invocation_id
.0);
352 let thread_id
= std
::thread
::current().id().as_u64().get() as u32;
354 profiler
.profiler
.record_instant_event(
355 event_kind(profiler
),
356 EventId
::from_virtual(event_id
),
364 pub fn with_profiler(&self, f
: impl FnOnce(&SelfProfiler
)) {
365 if let Some(profiler
) = &self.profiler
{
371 pub fn enabled(&self) -> bool
{
372 self.profiler
.is_some()
376 pub fn llvm_recording_enabled(&self) -> bool
{
377 self.event_filter_mask
.contains(EventFilter
::LLVM
)
380 pub fn get_self_profiler(&self) -> Option
<Arc
<SelfProfiler
>> {
381 self.profiler
.clone()
385 pub struct SelfProfiler
{
387 event_filter_mask
: EventFilter
,
389 string_cache
: RwLock
<FxHashMap
<String
, StringId
>>,
391 query_event_kind
: StringId
,
392 generic_activity_event_kind
: StringId
,
393 incremental_load_result_event_kind
: StringId
,
394 query_blocked_event_kind
: StringId
,
395 query_cache_hit_event_kind
: StringId
,
400 output_directory
: &Path
,
401 crate_name
: Option
<&str>,
402 event_filters
: &Option
<Vec
<String
>>,
403 ) -> Result
<SelfProfiler
, Box
<dyn Error
>> {
404 fs
::create_dir_all(output_directory
)?
;
406 let crate_name
= crate_name
.unwrap_or("unknown-crate");
407 let filename
= format
!("{}-{}.rustc_profile", crate_name
, process
::id());
408 let path
= output_directory
.join(&filename
);
409 let profiler
= Profiler
::new(&path
)?
;
411 let query_event_kind
= profiler
.alloc_string("Query");
412 let generic_activity_event_kind
= profiler
.alloc_string("GenericActivity");
413 let incremental_load_result_event_kind
= profiler
.alloc_string("IncrementalLoadResult");
414 let query_blocked_event_kind
= profiler
.alloc_string("QueryBlocked");
415 let query_cache_hit_event_kind
= profiler
.alloc_string("QueryCacheHit");
417 let mut event_filter_mask
= EventFilter
::empty();
419 if let Some(ref event_filters
) = *event_filters
{
420 let mut unknown_events
= vec
![];
421 for item
in event_filters
{
422 if let Some(&(_
, mask
)) =
423 EVENT_FILTERS_BY_NAME
.iter().find(|&(name
, _
)| name
== item
)
425 event_filter_mask
|= mask
;
427 unknown_events
.push(item
.clone());
431 // Warn about any unknown event names
432 if !unknown_events
.is_empty() {
433 unknown_events
.sort();
434 unknown_events
.dedup();
437 "Unknown self-profiler events specified: {}. Available options are: {}.",
438 unknown_events
.join(", "),
439 EVENT_FILTERS_BY_NAME
441 .map(|&(name
, _
)| name
.to_string())
447 event_filter_mask
= EventFilter
::DEFAULT
;
453 string_cache
: RwLock
::new(FxHashMap
::default()),
455 generic_activity_event_kind
,
456 incremental_load_result_event_kind
,
457 query_blocked_event_kind
,
458 query_cache_hit_event_kind
,
462 /// Allocates a new string in the profiling data. Does not do any caching
463 /// or deduplication.
464 pub fn alloc_string
<STR
: SerializableString
+ ?Sized
>(&self, s
: &STR
) -> StringId
{
465 self.profiler
.alloc_string(s
)
468 /// Gets a `StringId` for the given string. This method makes sure that
469 /// any strings going through it will only be allocated once in the
471 pub fn get_or_alloc_cached_string
<A
>(&self, s
: A
) -> StringId
473 A
: Borrow
<str> + Into
<String
>,
475 // Only acquire a read-lock first since we assume that the string is
476 // already present in the common case.
478 let string_cache
= self.string_cache
.read();
480 if let Some(&id
) = string_cache
.get(s
.borrow()) {
485 let mut string_cache
= self.string_cache
.write();
486 // Check if the string has already been added in the small time window
487 // between dropping the read lock and acquiring the write lock.
488 match string_cache
.entry(s
.into()) {
489 Entry
::Occupied(e
) => *e
.get(),
490 Entry
::Vacant(e
) => {
491 let string_id
= self.profiler
.alloc_string(&e
.key()[..]);
497 pub fn map_query_invocation_id_to_string(&self, from
: QueryInvocationId
, to
: StringId
) {
498 let from
= StringId
::new_virtual(from
.0);
499 self.profiler
.map_virtual_to_concrete_string(from
, to
);
502 pub fn bulk_map_query_invocation_id_to_single_string
<I
>(&self, from
: I
, to
: StringId
)
504 I
: Iterator
<Item
= QueryInvocationId
> + ExactSizeIterator
,
506 let from
= from
.map(|qid
| StringId
::new_virtual(qid
.0));
507 self.profiler
.bulk_map_virtual_to_single_concrete_string(from
, to
);
510 pub fn query_key_recording_enabled(&self) -> bool
{
511 self.event_filter_mask
.contains(EventFilter
::QUERY_KEYS
)
514 pub fn event_id_builder(&self) -> EventIdBuilder
<'_
, SerializationSink
> {
515 EventIdBuilder
::new(&self.profiler
)
520 pub struct TimingGuard
<'a
>(Option
<measureme
::TimingGuard
<'a
, SerializationSink
>>);
522 impl<'a
> TimingGuard
<'a
> {
525 profiler
: &'a SelfProfiler
,
526 event_kind
: StringId
,
528 ) -> TimingGuard
<'a
> {
529 let thread_id
= std
::thread
::current().id().as_u64().get() as u32;
530 let raw_profiler
= &profiler
.profiler
;
532 raw_profiler
.start_recording_interval_event(event_kind
, event_id
, thread_id
);
533 TimingGuard(Some(timing_guard
))
537 pub fn finish_with_query_invocation_id(self, query_invocation_id
: QueryInvocationId
) {
538 if let Some(guard
) = self.0 {
540 let event_id
= StringId
::new_virtual(query_invocation_id
.0);
541 let event_id
= EventId
::from_virtual(event_id
);
542 guard
.finish_with_override_event_id(event_id
);
548 pub fn none() -> TimingGuard
<'a
> {
553 pub fn run
<R
>(self, f
: impl FnOnce() -> R
) -> R
{
560 pub struct VerboseTimingGuard
<'a
> {
561 start_and_message
: Option
<(Instant
, String
)>,
562 _guard
: TimingGuard
<'a
>,
565 impl<'a
> VerboseTimingGuard
<'a
> {
566 pub fn start(message
: Option
<String
>, _guard
: TimingGuard
<'a
>) -> Self {
567 VerboseTimingGuard { _guard, start_and_message: message.map(|msg| (Instant::now(), msg)) }
571 pub fn run
<R
>(self, f
: impl FnOnce() -> R
) -> R
{
577 impl Drop
for VerboseTimingGuard
<'_
> {
579 if let Some((start
, ref message
)) = self.start_and_message
{
580 print_time_passes_entry(true, &message
[..], start
.elapsed());
585 pub fn print_time_passes_entry(do_it
: bool
, what
: &str, dur
: Duration
) {
590 let mem_string
= match get_resident() {
592 let mb
= n
as f64 / 1_000_000.0;
593 format
!("; rss: {}MB", mb
.round() as usize)
595 None
=> String
::new(),
597 println
!("time: {}{}\t{}", duration_to_secs_str(dur
), mem_string
, what
);
600 // Hack up our own formatting for the duration to make it easier for scripts
601 // to parse (always use the same number of decimal places and the same unit).
602 pub fn duration_to_secs_str(dur
: std
::time
::Duration
) -> String
{
603 const NANOS_PER_SEC
: f64 = 1_000_000_000.0;
604 let secs
= dur
.as_secs() as f64 + dur
.subsec_nanos() as f64 / NANOS_PER_SEC
;
606 format
!("{:.3}", secs
)
612 fn get_resident() -> Option
<usize> {
613 use std
::mem
::{self, MaybeUninit}
;
614 use winapi
::shared
::minwindef
::DWORD
;
615 use winapi
::um
::processthreadsapi
::GetCurrentProcess
;
616 use winapi
::um
::psapi
::{GetProcessMemoryInfo, PROCESS_MEMORY_COUNTERS}
;
618 let mut pmc
= MaybeUninit
::<PROCESS_MEMORY_COUNTERS
>::uninit();
620 GetProcessMemoryInfo(GetCurrentProcess(), pmc
.as_mut_ptr(), mem
::size_of_val(&pmc
) as DWORD
)
624 let pmc
= unsafe { pmc.assume_init() }
;
625 Some(pmc
.WorkingSetSize
as usize)
629 } else if #[cfg(unix)] {
630 fn get_resident() -> Option
<usize> {
632 let contents
= fs
::read("/proc/self/statm").ok()?
;
633 let contents
= String
::from_utf8(contents
).ok()?
;
634 let s
= contents
.split_whitespace().nth(field
)?
;
635 let npages
= s
.parse
::<usize>().ok()?
;
639 fn get_resident() -> Option
<usize> {