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 pub use measureme::EventId;
98 use measureme::{EventIdBuilder, Profiler, SerializableString, StringId};
99 use parking_lot::RwLock;
100 use smallvec::SmallVec;
102 bitflags::bitflags! {
103 struct EventFilter: u32 {
104 const GENERIC_ACTIVITIES = 1 << 0;
105 const QUERY_PROVIDERS = 1 << 1;
106 const QUERY_CACHE_HITS = 1 << 2;
107 const QUERY_BLOCKED = 1 << 3;
108 const INCR_CACHE_LOADS = 1 << 4;
110 const QUERY_KEYS = 1 << 5;
111 const FUNCTION_ARGS = 1 << 6;
113 const INCR_RESULT_HASHING = 1 << 8;
114 const ARTIFACT_SIZES = 1 << 9;
116 const DEFAULT = Self::GENERIC_ACTIVITIES.bits |
117 Self::QUERY_PROVIDERS.bits |
118 Self::QUERY_BLOCKED.bits |
119 Self::INCR_CACHE_LOADS.bits |
120 Self::INCR_RESULT_HASHING.bits |
121 Self::ARTIFACT_SIZES.bits;
123 const ARGS = Self::QUERY_KEYS.bits | Self::FUNCTION_ARGS.bits;
127 // keep this in sync with the `-Z self-profile-events` help message in rustc_session/options.rs
128 const EVENT_FILTERS_BY_NAME: &[(&str, EventFilter)] = &[
129 ("none", EventFilter::empty()),
130 ("all", EventFilter::all()),
131 ("default", EventFilter::DEFAULT),
132 ("generic-activity", EventFilter::GENERIC_ACTIVITIES),
133 ("query-provider", EventFilter::QUERY_PROVIDERS),
134 ("query-cache-hit", EventFilter::QUERY_CACHE_HITS),
135 ("query-blocked", EventFilter::QUERY_BLOCKED),
136 ("incr-cache-load", EventFilter::INCR_CACHE_LOADS),
137 ("query-keys", EventFilter::QUERY_KEYS),
138 ("function-args", EventFilter::FUNCTION_ARGS),
139 ("args", EventFilter::ARGS),
140 ("llvm", EventFilter::LLVM),
141 ("incr-result-hashing", EventFilter::INCR_RESULT_HASHING),
142 ("artifact-sizes", EventFilter::ARTIFACT_SIZES),
145 /// Something that uniquely identifies a query invocation.
146 pub struct QueryInvocationId(pub u32);
148 /// A reference to the SelfProfiler. It can be cloned and sent across thread
149 /// boundaries at will.
151 pub struct SelfProfilerRef {
152 // This field is `None` if self-profiling is disabled for the current
153 // compilation session.
154 profiler: Option<Arc<SelfProfiler>>,
156 // We store the filter mask directly in the reference because that doesn't
157 // cost anything and allows for filtering with checking if the profiler is
159 event_filter_mask: EventFilter,
161 // Print verbose generic activities to stderr?
162 print_verbose_generic_activities: bool,
165 impl SelfProfilerRef {
167 profiler: Option<Arc<SelfProfiler>>,
168 print_verbose_generic_activities: bool,
169 ) -> SelfProfilerRef {
170 // If there is no SelfProfiler then the filter mask is set to NONE,
171 // ensuring that nothing ever tries to actually access it.
172 let event_filter_mask =
173 profiler.as_ref().map_or(EventFilter::empty(), |p| p.event_filter_mask);
175 SelfProfilerRef { profiler, event_filter_mask, print_verbose_generic_activities }
178 /// This shim makes sure that calls only get executed if the filter mask
179 /// lets them pass. It also contains some trickery to make sure that
180 /// code is optimized for non-profiling compilation sessions, i.e. anything
181 /// past the filter check is never inlined so it doesn't clutter the fast
184 fn exec<F>(&self, event_filter: EventFilter, f: F) -> TimingGuard<'_>
186 F: for<'a> FnOnce(&'a SelfProfiler) -> TimingGuard<'a>,
190 fn cold_call<F>(profiler_ref: &SelfProfilerRef, f: F) -> TimingGuard<'_>
192 F: for<'a> FnOnce(&'a SelfProfiler) -> TimingGuard<'a>,
194 let profiler = profiler_ref.profiler.as_ref().unwrap();
198 if self.event_filter_mask.contains(event_filter) {
205 /// Start profiling a verbose generic activity. Profiling continues until the
206 /// VerboseTimingGuard returned from this call is dropped. In addition to recording
207 /// a measureme event, "verbose" generic activities also print a timing entry to
208 /// stderr if the compiler is invoked with -Ztime-passes.
209 pub fn verbose_generic_activity<'a>(
211 event_label: &'static str,
212 ) -> VerboseTimingGuard<'a> {
214 if self.print_verbose_generic_activities { Some(event_label.to_owned()) } else { None };
216 VerboseTimingGuard::start(message, self.generic_activity(event_label))
219 /// Like `verbose_generic_activity`, but with an extra arg.
220 pub fn verbose_generic_activity_with_arg<'a, A>(
222 event_label: &'static str,
224 ) -> VerboseTimingGuard<'a>
226 A: Borrow<str> + Into<String>,
228 let message = if self.print_verbose_generic_activities {
229 Some(format!("{}({})", event_label, event_arg.borrow()))
234 VerboseTimingGuard::start(message, self.generic_activity_with_arg(event_label, event_arg))
237 /// Start profiling a generic activity. Profiling continues until the
238 /// TimingGuard returned from this call is dropped.
240 pub fn generic_activity(&self, event_label: &'static str) -> TimingGuard<'_> {
241 self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
242 let event_label = profiler.get_or_alloc_cached_string(event_label);
243 let event_id = EventId::from_label(event_label);
244 TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id)
248 /// Start profiling with some event filter for a given event. Profiling continues until the
249 /// TimingGuard returned from this call is dropped.
251 pub fn generic_activity_with_event_id(&self, event_id: EventId) -> TimingGuard<'_> {
252 self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
253 TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id)
257 /// Start profiling a generic activity. Profiling continues until the
258 /// TimingGuard returned from this call is dropped.
260 pub fn generic_activity_with_arg<A>(
262 event_label: &'static str,
266 A: Borrow<str> + Into<String>,
268 self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
269 let builder = EventIdBuilder::new(&profiler.profiler);
270 let event_label = profiler.get_or_alloc_cached_string(event_label);
271 let event_id = if profiler.event_filter_mask.contains(EventFilter::FUNCTION_ARGS) {
272 let event_arg = profiler.get_or_alloc_cached_string(event_arg);
273 builder.from_label_and_arg(event_label, event_arg)
275 builder.from_label(event_label)
277 TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id)
281 /// Start profiling a generic activity, allowing costly arguments to be recorded. Profiling
282 /// continues until the `TimingGuard` returned from this call is dropped.
284 /// If the arguments to a generic activity are cheap to create, use `generic_activity_with_arg`
285 /// or `generic_activity_with_args` for their simpler API. However, if they are costly or
286 /// require allocation in sufficiently hot contexts, then this allows for a closure to be called
287 /// only when arguments were asked to be recorded via `-Z self-profile-events=args`.
289 /// In this case, the closure will be passed a `&mut EventArgRecorder`, to help with recording
290 /// one or many arguments within the generic activity being profiled, by calling its
291 /// `record_arg` method for example.
293 /// This `EventArgRecorder` may implement more specific traits from other rustc crates, e.g. for
294 /// richer handling of rustc-specific argument types, while keeping this single entry-point API
295 /// for recording arguments.
297 /// Note: recording at least one argument is *required* for the self-profiler to create the
298 /// `TimingGuard`. A panic will be triggered if that doesn't happen. This function exists
299 /// explicitly to record arguments, so it fails loudly when there are none to record.
302 pub fn generic_activity_with_arg_recorder<F>(
304 event_label: &'static str,
308 F: FnMut(&mut EventArgRecorder<'_>),
310 // Ensure this event will only be recorded when self-profiling is turned on.
311 self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
312 let builder = EventIdBuilder::new(&profiler.profiler);
313 let event_label = profiler.get_or_alloc_cached_string(event_label);
315 // Ensure the closure to create event arguments will only be called when argument
316 // recording is turned on.
317 let event_id = if profiler.event_filter_mask.contains(EventFilter::FUNCTION_ARGS) {
318 // Set up the builder and call the user-provided closure to record potentially
319 // costly event arguments.
320 let mut recorder = EventArgRecorder { profiler, args: SmallVec::new() };
323 // It is expected that the closure will record at least one argument. If that
324 // doesn't happen, it's a bug: we've been explicitly called in order to record
325 // arguments, so we fail loudly when there are none to record.
326 if recorder.args.is_empty() {
328 "The closure passed to `generic_activity_with_arg_recorder` needs to \
329 record at least one argument"
333 builder.from_label_and_args(event_label, &recorder.args)
335 builder.from_label(event_label)
337 TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id)
341 /// Record the size of an artifact that the compiler produces
343 /// `artifact_kind` is the class of artifact (e.g., query_cache, object_file, etc.)
344 /// `artifact_name` is an identifier to the specific artifact being stored (usually a filename)
346 pub fn artifact_size<A>(&self, artifact_kind: &str, artifact_name: A, size: u64)
348 A: Borrow<str> + Into<String>,
350 drop(self.exec(EventFilter::ARTIFACT_SIZES, |profiler| {
351 let builder = EventIdBuilder::new(&profiler.profiler);
352 let event_label = profiler.get_or_alloc_cached_string(artifact_kind);
353 let event_arg = profiler.get_or_alloc_cached_string(artifact_name);
354 let event_id = builder.from_label_and_arg(event_label, event_arg);
355 let thread_id = get_thread_id();
357 profiler.profiler.record_integer_event(
358 profiler.artifact_size_event_kind,
369 pub fn generic_activity_with_args(
371 event_label: &'static str,
372 event_args: &[String],
373 ) -> TimingGuard<'_> {
374 self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
375 let builder = EventIdBuilder::new(&profiler.profiler);
376 let event_label = profiler.get_or_alloc_cached_string(event_label);
377 let event_id = if profiler.event_filter_mask.contains(EventFilter::FUNCTION_ARGS) {
378 let event_args: Vec<_> = event_args
380 .map(|s| profiler.get_or_alloc_cached_string(&s[..]))
382 builder.from_label_and_args(event_label, &event_args)
384 builder.from_label(event_label)
386 TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id)
390 /// Start profiling a query provider. Profiling continues until the
391 /// TimingGuard returned from this call is dropped.
393 pub fn query_provider(&self) -> TimingGuard<'_> {
394 self.exec(EventFilter::QUERY_PROVIDERS, |profiler| {
395 TimingGuard::start(profiler, profiler.query_event_kind, EventId::INVALID)
399 /// Record a query in-memory cache hit.
401 pub fn query_cache_hit(&self, query_invocation_id: QueryInvocationId) {
402 self.instant_query_event(
403 |profiler| profiler.query_cache_hit_event_kind,
405 EventFilter::QUERY_CACHE_HITS,
409 /// Start profiling a query being blocked on a concurrent execution.
410 /// Profiling continues until the TimingGuard returned from this call is
413 pub fn query_blocked(&self) -> TimingGuard<'_> {
414 self.exec(EventFilter::QUERY_BLOCKED, |profiler| {
415 TimingGuard::start(profiler, profiler.query_blocked_event_kind, EventId::INVALID)
419 /// Start profiling how long it takes to load a query result from the
420 /// incremental compilation on-disk cache. Profiling continues until the
421 /// TimingGuard returned from this call is dropped.
423 pub fn incr_cache_loading(&self) -> TimingGuard<'_> {
424 self.exec(EventFilter::INCR_CACHE_LOADS, |profiler| {
427 profiler.incremental_load_result_event_kind,
433 /// Start profiling how long it takes to hash query results for incremental compilation.
434 /// Profiling continues until the TimingGuard returned from this call is dropped.
436 pub fn incr_result_hashing(&self) -> TimingGuard<'_> {
437 self.exec(EventFilter::INCR_RESULT_HASHING, |profiler| {
440 profiler.incremental_result_hashing_event_kind,
447 fn instant_query_event(
449 event_kind: fn(&SelfProfiler) -> StringId,
450 query_invocation_id: QueryInvocationId,
451 event_filter: EventFilter,
453 drop(self.exec(event_filter, |profiler| {
454 let event_id = StringId::new_virtual(query_invocation_id.0);
455 let thread_id = get_thread_id();
457 profiler.profiler.record_instant_event(
458 event_kind(profiler),
459 EventId::from_virtual(event_id),
467 pub fn with_profiler(&self, f: impl FnOnce(&SelfProfiler)) {
468 if let Some(profiler) = &self.profiler {
473 /// Gets a `StringId` for the given string. This method makes sure that
474 /// any strings going through it will only be allocated once in the
476 /// Returns `None` if the self-profiling is not enabled.
477 pub fn get_or_alloc_cached_string(&self, s: &str) -> Option<StringId> {
478 self.profiler.as_ref().map(|p| p.get_or_alloc_cached_string(s))
482 pub fn enabled(&self) -> bool {
483 self.profiler.is_some()
487 pub fn llvm_recording_enabled(&self) -> bool {
488 self.event_filter_mask.contains(EventFilter::LLVM)
491 pub fn get_self_profiler(&self) -> Option<Arc<SelfProfiler>> {
492 self.profiler.clone()
496 /// A helper for recording costly arguments to self-profiling events. Used with
497 /// `SelfProfilerRef::generic_activity_with_arg_recorder`.
498 pub struct EventArgRecorder<'p> {
499 /// The `SelfProfiler` used to intern the event arguments that users will ask to record.
500 profiler: &'p SelfProfiler,
502 /// The interned event arguments to be recorded in the generic activity event.
504 /// The most common case, when actually recording event arguments, is to have one argument. Then
505 /// followed by recording two, in a couple places.
506 args: SmallVec<[StringId; 2]>,
509 impl EventArgRecorder<'_> {
510 /// Records a single argument within the current generic activity being profiled.
512 /// Note: when self-profiling with costly event arguments, at least one argument
513 /// needs to be recorded. A panic will be triggered if that doesn't happen.
514 pub fn record_arg<A>(&mut self, event_arg: A)
516 A: Borrow<str> + Into<String>,
518 let event_arg = self.profiler.get_or_alloc_cached_string(event_arg);
519 self.args.push(event_arg);
523 pub struct SelfProfiler {
525 event_filter_mask: EventFilter,
527 string_cache: RwLock<FxHashMap<String, StringId>>,
529 query_event_kind: StringId,
530 generic_activity_event_kind: StringId,
531 incremental_load_result_event_kind: StringId,
532 incremental_result_hashing_event_kind: StringId,
533 query_blocked_event_kind: StringId,
534 query_cache_hit_event_kind: StringId,
535 artifact_size_event_kind: StringId,
540 output_directory: &Path,
541 crate_name: Option<&str>,
542 event_filters: Option<&[String]>,
544 ) -> Result<SelfProfiler, Box<dyn Error + Send + Sync>> {
545 fs::create_dir_all(output_directory)?;
547 let crate_name = crate_name.unwrap_or("unknown-crate");
548 // HACK(eddyb) we need to pad the PID, strange as it may seem, as its
549 // length can behave as a source of entropy for heap addresses, when
550 // ASLR is disabled and the heap is otherwise determinic.
551 let pid: u32 = process::id();
552 let filename = format!("{}-{:07}.rustc_profile", crate_name, pid);
553 let path = output_directory.join(&filename);
555 Profiler::with_counter(&path, measureme::counters::Counter::by_name(counter_name)?)?;
557 let query_event_kind = profiler.alloc_string("Query");
558 let generic_activity_event_kind = profiler.alloc_string("GenericActivity");
559 let incremental_load_result_event_kind = profiler.alloc_string("IncrementalLoadResult");
560 let incremental_result_hashing_event_kind =
561 profiler.alloc_string("IncrementalResultHashing");
562 let query_blocked_event_kind = profiler.alloc_string("QueryBlocked");
563 let query_cache_hit_event_kind = profiler.alloc_string("QueryCacheHit");
564 let artifact_size_event_kind = profiler.alloc_string("ArtifactSize");
566 let mut event_filter_mask = EventFilter::empty();
568 if let Some(event_filters) = event_filters {
569 let mut unknown_events = vec![];
570 for item in event_filters {
571 if let Some(&(_, mask)) =
572 EVENT_FILTERS_BY_NAME.iter().find(|&(name, _)| name == item)
574 event_filter_mask |= mask;
576 unknown_events.push(item.clone());
580 // Warn about any unknown event names
581 if !unknown_events.is_empty() {
582 unknown_events.sort();
583 unknown_events.dedup();
586 "Unknown self-profiler events specified: {}. Available options are: {}.",
587 unknown_events.join(", "),
588 EVENT_FILTERS_BY_NAME
590 .map(|&(name, _)| name.to_string())
596 event_filter_mask = EventFilter::DEFAULT;
602 string_cache: RwLock::new(FxHashMap::default()),
604 generic_activity_event_kind,
605 incremental_load_result_event_kind,
606 incremental_result_hashing_event_kind,
607 query_blocked_event_kind,
608 query_cache_hit_event_kind,
609 artifact_size_event_kind,
613 /// Allocates a new string in the profiling data. Does not do any caching
614 /// or deduplication.
615 pub fn alloc_string<STR: SerializableString + ?Sized>(&self, s: &STR) -> StringId {
616 self.profiler.alloc_string(s)
619 /// Gets a `StringId` for the given string. This method makes sure that
620 /// any strings going through it will only be allocated once in the
622 pub fn get_or_alloc_cached_string<A>(&self, s: A) -> StringId
624 A: Borrow<str> + Into<String>,
626 // Only acquire a read-lock first since we assume that the string is
627 // already present in the common case.
629 let string_cache = self.string_cache.read();
631 if let Some(&id) = string_cache.get(s.borrow()) {
636 let mut string_cache = self.string_cache.write();
637 // Check if the string has already been added in the small time window
638 // between dropping the read lock and acquiring the write lock.
639 match string_cache.entry(s.into()) {
640 Entry::Occupied(e) => *e.get(),
641 Entry::Vacant(e) => {
642 let string_id = self.profiler.alloc_string(&e.key()[..]);
648 pub fn map_query_invocation_id_to_string(&self, from: QueryInvocationId, to: StringId) {
649 let from = StringId::new_virtual(from.0);
650 self.profiler.map_virtual_to_concrete_string(from, to);
653 pub fn bulk_map_query_invocation_id_to_single_string<I>(&self, from: I, to: StringId)
655 I: Iterator<Item = QueryInvocationId> + ExactSizeIterator,
657 let from = from.map(|qid| StringId::new_virtual(qid.0));
658 self.profiler.bulk_map_virtual_to_single_concrete_string(from, to);
661 pub fn query_key_recording_enabled(&self) -> bool {
662 self.event_filter_mask.contains(EventFilter::QUERY_KEYS)
665 pub fn event_id_builder(&self) -> EventIdBuilder<'_> {
666 EventIdBuilder::new(&self.profiler)
671 pub struct TimingGuard<'a>(Option<measureme::TimingGuard<'a>>);
673 impl<'a> TimingGuard<'a> {
676 profiler: &'a SelfProfiler,
677 event_kind: StringId,
679 ) -> TimingGuard<'a> {
680 let thread_id = get_thread_id();
681 let raw_profiler = &profiler.profiler;
683 raw_profiler.start_recording_interval_event(event_kind, event_id, thread_id);
684 TimingGuard(Some(timing_guard))
688 pub fn finish_with_query_invocation_id(self, query_invocation_id: QueryInvocationId) {
689 if let Some(guard) = self.0 {
691 let event_id = StringId::new_virtual(query_invocation_id.0);
692 let event_id = EventId::from_virtual(event_id);
693 guard.finish_with_override_event_id(event_id);
699 pub fn none() -> TimingGuard<'a> {
704 pub fn run<R>(self, f: impl FnOnce() -> R) -> R {
711 pub struct VerboseTimingGuard<'a> {
712 start_and_message: Option<(Instant, Option<usize>, String)>,
713 _guard: TimingGuard<'a>,
716 impl<'a> VerboseTimingGuard<'a> {
717 pub fn start(message: Option<String>, _guard: TimingGuard<'a>) -> Self {
720 start_and_message: message.map(|msg| (Instant::now(), get_resident_set_size(), msg)),
725 pub fn run<R>(self, f: impl FnOnce() -> R) -> R {
731 impl Drop for VerboseTimingGuard<'_> {
733 if let Some((start_time, start_rss, ref message)) = self.start_and_message {
734 let end_rss = get_resident_set_size();
735 let dur = start_time.elapsed();
736 print_time_passes_entry(message, dur, start_rss, end_rss);
741 pub fn print_time_passes_entry(
744 start_rss: Option<usize>,
745 end_rss: Option<usize>,
747 // Print the pass if its duration is greater than 5 ms, or it changed the
749 let is_notable = || {
750 if dur.as_millis() > 5 {
754 if let (Some(start_rss), Some(end_rss)) = (start_rss, end_rss) {
755 let change_rss = end_rss.abs_diff(start_rss);
767 let rss_to_mb = |rss| (rss as f64 / 1_000_000.0).round() as usize;
768 let rss_change_to_mb = |rss| (rss as f64 / 1_000_000.0).round() as i128;
770 let mem_string = match (start_rss, end_rss) {
771 (Some(start_rss), Some(end_rss)) => {
772 let change_rss = end_rss as i128 - start_rss as i128;
775 "; rss: {:>4}MB -> {:>4}MB ({:>+5}MB)",
776 rss_to_mb(start_rss),
778 rss_change_to_mb(change_rss),
781 (Some(start_rss), None) => format!("; rss start: {:>4}MB", rss_to_mb(start_rss)),
782 (None, Some(end_rss)) => format!("; rss end: {:>4}MB", rss_to_mb(end_rss)),
783 (None, None) => String::new(),
786 eprintln!("time: {:>7}{}\t{}", duration_to_secs_str(dur), mem_string, what);
789 // Hack up our own formatting for the duration to make it easier for scripts
790 // to parse (always use the same number of decimal places and the same unit).
791 pub fn duration_to_secs_str(dur: std::time::Duration) -> String {
792 format!("{:.3}", dur.as_secs_f64())
795 fn get_thread_id() -> u32 {
796 std::thread::current().id().as_u64().get() as u32
802 pub fn get_resident_set_size() -> Option<usize> {
803 use std::mem::{self, MaybeUninit};
804 use winapi::shared::minwindef::DWORD;
805 use winapi::um::processthreadsapi::GetCurrentProcess;
806 use winapi::um::psapi::{GetProcessMemoryInfo, PROCESS_MEMORY_COUNTERS};
808 let mut pmc = MaybeUninit::<PROCESS_MEMORY_COUNTERS>::uninit();
810 GetProcessMemoryInfo(GetCurrentProcess(), pmc.as_mut_ptr(), mem::size_of_val(&pmc) as DWORD)
814 let pmc = unsafe { pmc.assume_init() };
815 Some(pmc.WorkingSetSize as usize)
819 } else if #[cfg(target_os = "macos")] {
820 pub fn get_resident_set_size() -> Option<usize> {
821 use libc::{c_int, c_void, getpid, proc_pidinfo, proc_taskinfo, PROC_PIDTASKINFO};
823 const PROC_TASKINFO_SIZE: c_int = mem::size_of::<proc_taskinfo>() as c_int;
826 let mut info: proc_taskinfo = mem::zeroed();
827 let info_ptr = &mut info as *mut proc_taskinfo as *mut c_void;
828 let pid = getpid() as c_int;
829 let ret = proc_pidinfo(pid, PROC_PIDTASKINFO, 0, info_ptr, PROC_TASKINFO_SIZE);
830 if ret == PROC_TASKINFO_SIZE {
831 Some(info.pti_resident_size as usize)
837 } else if #[cfg(unix)] {
838 pub fn get_resident_set_size() -> Option<usize> {
840 let contents = fs::read("/proc/self/statm").ok()?;
841 let contents = String::from_utf8(contents).ok()?;
842 let s = contents.split_whitespace().nth(field)?;
843 let npages = s.parse::<usize>().ok()?;
847 pub fn get_resident_set_size() -> Option<usize> {