]> git.lizzy.rs Git - rust.git/blob - compiler/rustc_data_structures/src/profiling.rs
Auto merge of #89120 - In-line:remove_unneded_visible_parents_map, r=estebank
[rust.git] / compiler / rustc_data_structures / src / profiling.rs
1 //! # Rust Compiler Self-Profiling
2 //!
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.
8 //!
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.
14 //!
15 //!
16 //! ## Event Overview
17 //!
18 //! Events have a few properties:
19 //!
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.
28 //!
29 //!
30 //! ## Event Filtering
31 //!
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.
37 //!
38 //!
39 //! ## `event_id` Assignment
40 //!
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:
45 //!
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.
53 //!
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.
61 //!
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()`.
66 //!
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.
72 //!
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`.
81 //!
82 //! [mm]: https://github.com/rust-lang/measureme/
83
84 use crate::cold_path;
85 use crate::fx::FxHashMap;
86
87 use std::borrow::Borrow;
88 use std::collections::hash_map::Entry;
89 use std::convert::Into;
90 use std::error::Error;
91 use std::fs;
92 use std::path::Path;
93 use std::process;
94 use std::sync::Arc;
95 use std::time::{Duration, Instant};
96
97 pub use measureme::EventId;
98 use measureme::{EventIdBuilder, Profiler, SerializableString, StringId};
99 use parking_lot::RwLock;
100
101 bitflags::bitflags! {
102     struct EventFilter: u32 {
103         const GENERIC_ACTIVITIES  = 1 << 0;
104         const QUERY_PROVIDERS     = 1 << 1;
105         const QUERY_CACHE_HITS    = 1 << 2;
106         const QUERY_BLOCKED       = 1 << 3;
107         const INCR_CACHE_LOADS    = 1 << 4;
108
109         const QUERY_KEYS          = 1 << 5;
110         const FUNCTION_ARGS       = 1 << 6;
111         const LLVM                = 1 << 7;
112         const INCR_RESULT_HASHING = 1 << 8;
113
114         const DEFAULT = Self::GENERIC_ACTIVITIES.bits |
115                         Self::QUERY_PROVIDERS.bits |
116                         Self::QUERY_BLOCKED.bits |
117                         Self::INCR_CACHE_LOADS.bits |
118                         Self::INCR_RESULT_HASHING.bits;
119
120         const ARGS = Self::QUERY_KEYS.bits | Self::FUNCTION_ARGS.bits;
121     }
122 }
123
124 // keep this in sync with the `-Z self-profile-events` help message in rustc_session/options.rs
125 const EVENT_FILTERS_BY_NAME: &[(&str, EventFilter)] = &[
126     ("none", EventFilter::empty()),
127     ("all", EventFilter::all()),
128     ("default", EventFilter::DEFAULT),
129     ("generic-activity", EventFilter::GENERIC_ACTIVITIES),
130     ("query-provider", EventFilter::QUERY_PROVIDERS),
131     ("query-cache-hit", EventFilter::QUERY_CACHE_HITS),
132     ("query-blocked", EventFilter::QUERY_BLOCKED),
133     ("incr-cache-load", EventFilter::INCR_CACHE_LOADS),
134     ("query-keys", EventFilter::QUERY_KEYS),
135     ("function-args", EventFilter::FUNCTION_ARGS),
136     ("args", EventFilter::ARGS),
137     ("llvm", EventFilter::LLVM),
138     ("incr-result-hashing", EventFilter::INCR_RESULT_HASHING),
139 ];
140
141 /// Something that uniquely identifies a query invocation.
142 pub struct QueryInvocationId(pub u32);
143
144 /// A reference to the SelfProfiler. It can be cloned and sent across thread
145 /// boundaries at will.
146 #[derive(Clone)]
147 pub struct SelfProfilerRef {
148     // This field is `None` if self-profiling is disabled for the current
149     // compilation session.
150     profiler: Option<Arc<SelfProfiler>>,
151
152     // We store the filter mask directly in the reference because that doesn't
153     // cost anything and allows for filtering with checking if the profiler is
154     // actually enabled.
155     event_filter_mask: EventFilter,
156
157     // Print verbose generic activities to stdout
158     print_verbose_generic_activities: bool,
159
160     // Print extra verbose generic activities to stdout
161     print_extra_verbose_generic_activities: bool,
162 }
163
164 impl SelfProfilerRef {
165     pub fn new(
166         profiler: Option<Arc<SelfProfiler>>,
167         print_verbose_generic_activities: bool,
168         print_extra_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);
174
175         SelfProfilerRef {
176             profiler,
177             event_filter_mask,
178             print_verbose_generic_activities,
179             print_extra_verbose_generic_activities,
180         }
181     }
182
183     // This shim makes sure that calls only get executed if the filter mask
184     // lets them pass. It also contains some trickery to make sure that
185     // code is optimized for non-profiling compilation sessions, i.e. anything
186     // past the filter check is never inlined so it doesn't clutter the fast
187     // path.
188     #[inline(always)]
189     fn exec<F>(&self, event_filter: EventFilter, f: F) -> TimingGuard<'_>
190     where
191         F: for<'a> FnOnce(&'a SelfProfiler) -> TimingGuard<'a>,
192     {
193         #[inline(never)]
194         fn cold_call<F>(profiler_ref: &SelfProfilerRef, f: F) -> TimingGuard<'_>
195         where
196             F: for<'a> FnOnce(&'a SelfProfiler) -> TimingGuard<'a>,
197         {
198             let profiler = profiler_ref.profiler.as_ref().unwrap();
199             f(&**profiler)
200         }
201
202         if unlikely!(self.event_filter_mask.contains(event_filter)) {
203             cold_call(self, f)
204         } else {
205             TimingGuard::none()
206         }
207     }
208
209     /// Start profiling a verbose generic activity. Profiling continues until the
210     /// VerboseTimingGuard returned from this call is dropped. In addition to recording
211     /// a measureme event, "verbose" generic activities also print a timing entry to
212     /// stdout if the compiler is invoked with -Ztime or -Ztime-passes.
213     pub fn verbose_generic_activity<'a>(
214         &'a self,
215         event_label: &'static str,
216     ) -> VerboseTimingGuard<'a> {
217         let message =
218             if self.print_verbose_generic_activities { Some(event_label.to_owned()) } else { None };
219
220         VerboseTimingGuard::start(message, self.generic_activity(event_label))
221     }
222
223     /// Start profiling an extra verbose generic activity. Profiling continues until the
224     /// VerboseTimingGuard returned from this call is dropped. In addition to recording
225     /// a measureme event, "extra verbose" generic activities also print a timing entry to
226     /// stdout if the compiler is invoked with -Ztime-passes.
227     pub fn extra_verbose_generic_activity<'a, A>(
228         &'a self,
229         event_label: &'static str,
230         event_arg: A,
231     ) -> VerboseTimingGuard<'a>
232     where
233         A: Borrow<str> + Into<String>,
234     {
235         let message = if self.print_extra_verbose_generic_activities {
236             Some(format!("{}({})", event_label, event_arg.borrow()))
237         } else {
238             None
239         };
240
241         VerboseTimingGuard::start(message, self.generic_activity_with_arg(event_label, event_arg))
242     }
243
244     /// Start profiling a generic activity. Profiling continues until the
245     /// TimingGuard returned from this call is dropped.
246     #[inline(always)]
247     pub fn generic_activity(&self, event_label: &'static str) -> TimingGuard<'_> {
248         self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
249             let event_label = profiler.get_or_alloc_cached_string(event_label);
250             let event_id = EventId::from_label(event_label);
251             TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id)
252         })
253     }
254
255     /// Start profiling with some event filter for a given event. Profiling continues until the
256     /// TimingGuard returned from this call is dropped.
257     #[inline(always)]
258     pub fn generic_activity_with_event_id(&self, event_id: EventId) -> TimingGuard<'_> {
259         self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
260             TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id)
261         })
262     }
263
264     /// Start profiling a generic activity. Profiling continues until the
265     /// TimingGuard returned from this call is dropped.
266     #[inline(always)]
267     pub fn generic_activity_with_arg<A>(
268         &self,
269         event_label: &'static str,
270         event_arg: A,
271     ) -> TimingGuard<'_>
272     where
273         A: Borrow<str> + Into<String>,
274     {
275         self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
276             let builder = EventIdBuilder::new(&profiler.profiler);
277             let event_label = profiler.get_or_alloc_cached_string(event_label);
278             let event_id = if profiler.event_filter_mask.contains(EventFilter::FUNCTION_ARGS) {
279                 let event_arg = profiler.get_or_alloc_cached_string(event_arg);
280                 builder.from_label_and_arg(event_label, event_arg)
281             } else {
282                 builder.from_label(event_label)
283             };
284             TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id)
285         })
286     }
287
288     #[inline(always)]
289     pub fn generic_activity_with_args(
290         &self,
291         event_label: &'static str,
292         event_args: &[String],
293     ) -> TimingGuard<'_> {
294         self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
295             let builder = EventIdBuilder::new(&profiler.profiler);
296             let event_label = profiler.get_or_alloc_cached_string(event_label);
297             let event_id = if profiler.event_filter_mask.contains(EventFilter::FUNCTION_ARGS) {
298                 let event_args: Vec<_> = event_args
299                     .iter()
300                     .map(|s| profiler.get_or_alloc_cached_string(&s[..]))
301                     .collect();
302                 builder.from_label_and_args(event_label, &event_args)
303             } else {
304                 builder.from_label(event_label)
305             };
306             TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id)
307         })
308     }
309
310     /// Start profiling a query provider. Profiling continues until the
311     /// TimingGuard returned from this call is dropped.
312     #[inline(always)]
313     pub fn query_provider(&self) -> TimingGuard<'_> {
314         self.exec(EventFilter::QUERY_PROVIDERS, |profiler| {
315             TimingGuard::start(profiler, profiler.query_event_kind, EventId::INVALID)
316         })
317     }
318
319     /// Record a query in-memory cache hit.
320     #[inline(always)]
321     pub fn query_cache_hit(&self, query_invocation_id: QueryInvocationId) {
322         self.instant_query_event(
323             |profiler| profiler.query_cache_hit_event_kind,
324             query_invocation_id,
325             EventFilter::QUERY_CACHE_HITS,
326         );
327     }
328
329     /// Start profiling a query being blocked on a concurrent execution.
330     /// Profiling continues until the TimingGuard returned from this call is
331     /// dropped.
332     #[inline(always)]
333     pub fn query_blocked(&self) -> TimingGuard<'_> {
334         self.exec(EventFilter::QUERY_BLOCKED, |profiler| {
335             TimingGuard::start(profiler, profiler.query_blocked_event_kind, EventId::INVALID)
336         })
337     }
338
339     /// Start profiling how long it takes to load a query result from the
340     /// incremental compilation on-disk cache. Profiling continues until the
341     /// TimingGuard returned from this call is dropped.
342     #[inline(always)]
343     pub fn incr_cache_loading(&self) -> TimingGuard<'_> {
344         self.exec(EventFilter::INCR_CACHE_LOADS, |profiler| {
345             TimingGuard::start(
346                 profiler,
347                 profiler.incremental_load_result_event_kind,
348                 EventId::INVALID,
349             )
350         })
351     }
352
353     /// Start profiling how long it takes to hash query results for incremental compilation.
354     /// Profiling continues until the TimingGuard returned from this call is dropped.
355     #[inline(always)]
356     pub fn incr_result_hashing(&self) -> TimingGuard<'_> {
357         self.exec(EventFilter::INCR_RESULT_HASHING, |profiler| {
358             TimingGuard::start(
359                 profiler,
360                 profiler.incremental_result_hashing_event_kind,
361                 EventId::INVALID,
362             )
363         })
364     }
365
366     #[inline(always)]
367     fn instant_query_event(
368         &self,
369         event_kind: fn(&SelfProfiler) -> StringId,
370         query_invocation_id: QueryInvocationId,
371         event_filter: EventFilter,
372     ) {
373         drop(self.exec(event_filter, |profiler| {
374             let event_id = StringId::new_virtual(query_invocation_id.0);
375             let thread_id = std::thread::current().id().as_u64().get() as u32;
376
377             profiler.profiler.record_instant_event(
378                 event_kind(profiler),
379                 EventId::from_virtual(event_id),
380                 thread_id,
381             );
382
383             TimingGuard::none()
384         }));
385     }
386
387     pub fn with_profiler(&self, f: impl FnOnce(&SelfProfiler)) {
388         if let Some(profiler) = &self.profiler {
389             f(&profiler)
390         }
391     }
392
393     /// Gets a `StringId` for the given string. This method makes sure that
394     /// any strings going through it will only be allocated once in the
395     /// profiling data.
396     /// Returns `None` if the self-profiling is not enabled.
397     pub fn get_or_alloc_cached_string(&self, s: &str) -> Option<StringId> {
398         self.profiler.as_ref().map(|p| p.get_or_alloc_cached_string(s))
399     }
400
401     #[inline]
402     pub fn enabled(&self) -> bool {
403         self.profiler.is_some()
404     }
405
406     #[inline]
407     pub fn llvm_recording_enabled(&self) -> bool {
408         self.event_filter_mask.contains(EventFilter::LLVM)
409     }
410     #[inline]
411     pub fn get_self_profiler(&self) -> Option<Arc<SelfProfiler>> {
412         self.profiler.clone()
413     }
414 }
415
416 pub struct SelfProfiler {
417     profiler: Profiler,
418     event_filter_mask: EventFilter,
419
420     string_cache: RwLock<FxHashMap<String, StringId>>,
421
422     query_event_kind: StringId,
423     generic_activity_event_kind: StringId,
424     incremental_load_result_event_kind: StringId,
425     incremental_result_hashing_event_kind: StringId,
426     query_blocked_event_kind: StringId,
427     query_cache_hit_event_kind: StringId,
428 }
429
430 impl SelfProfiler {
431     pub fn new(
432         output_directory: &Path,
433         crate_name: Option<&str>,
434         event_filters: &Option<Vec<String>>,
435     ) -> Result<SelfProfiler, Box<dyn Error + Send + Sync>> {
436         fs::create_dir_all(output_directory)?;
437
438         let crate_name = crate_name.unwrap_or("unknown-crate");
439         let filename = format!("{}-{}.rustc_profile", crate_name, process::id());
440         let path = output_directory.join(&filename);
441         let profiler = Profiler::new(&path)?;
442
443         let query_event_kind = profiler.alloc_string("Query");
444         let generic_activity_event_kind = profiler.alloc_string("GenericActivity");
445         let incremental_load_result_event_kind = profiler.alloc_string("IncrementalLoadResult");
446         let incremental_result_hashing_event_kind =
447             profiler.alloc_string("IncrementalResultHashing");
448         let query_blocked_event_kind = profiler.alloc_string("QueryBlocked");
449         let query_cache_hit_event_kind = profiler.alloc_string("QueryCacheHit");
450
451         let mut event_filter_mask = EventFilter::empty();
452
453         if let Some(ref event_filters) = *event_filters {
454             let mut unknown_events = vec![];
455             for item in event_filters {
456                 if let Some(&(_, mask)) =
457                     EVENT_FILTERS_BY_NAME.iter().find(|&(name, _)| name == item)
458                 {
459                     event_filter_mask |= mask;
460                 } else {
461                     unknown_events.push(item.clone());
462                 }
463             }
464
465             // Warn about any unknown event names
466             if !unknown_events.is_empty() {
467                 unknown_events.sort();
468                 unknown_events.dedup();
469
470                 warn!(
471                     "Unknown self-profiler events specified: {}. Available options are: {}.",
472                     unknown_events.join(", "),
473                     EVENT_FILTERS_BY_NAME
474                         .iter()
475                         .map(|&(name, _)| name.to_string())
476                         .collect::<Vec<_>>()
477                         .join(", ")
478                 );
479             }
480         } else {
481             event_filter_mask = EventFilter::DEFAULT;
482         }
483
484         Ok(SelfProfiler {
485             profiler,
486             event_filter_mask,
487             string_cache: RwLock::new(FxHashMap::default()),
488             query_event_kind,
489             generic_activity_event_kind,
490             incremental_load_result_event_kind,
491             incremental_result_hashing_event_kind,
492             query_blocked_event_kind,
493             query_cache_hit_event_kind,
494         })
495     }
496
497     /// Allocates a new string in the profiling data. Does not do any caching
498     /// or deduplication.
499     pub fn alloc_string<STR: SerializableString + ?Sized>(&self, s: &STR) -> StringId {
500         self.profiler.alloc_string(s)
501     }
502
503     /// Gets a `StringId` for the given string. This method makes sure that
504     /// any strings going through it will only be allocated once in the
505     /// profiling data.
506     pub fn get_or_alloc_cached_string<A>(&self, s: A) -> StringId
507     where
508         A: Borrow<str> + Into<String>,
509     {
510         // Only acquire a read-lock first since we assume that the string is
511         // already present in the common case.
512         {
513             let string_cache = self.string_cache.read();
514
515             if let Some(&id) = string_cache.get(s.borrow()) {
516                 return id;
517             }
518         }
519
520         let mut string_cache = self.string_cache.write();
521         // Check if the string has already been added in the small time window
522         // between dropping the read lock and acquiring the write lock.
523         match string_cache.entry(s.into()) {
524             Entry::Occupied(e) => *e.get(),
525             Entry::Vacant(e) => {
526                 let string_id = self.profiler.alloc_string(&e.key()[..]);
527                 *e.insert(string_id)
528             }
529         }
530     }
531
532     pub fn map_query_invocation_id_to_string(&self, from: QueryInvocationId, to: StringId) {
533         let from = StringId::new_virtual(from.0);
534         self.profiler.map_virtual_to_concrete_string(from, to);
535     }
536
537     pub fn bulk_map_query_invocation_id_to_single_string<I>(&self, from: I, to: StringId)
538     where
539         I: Iterator<Item = QueryInvocationId> + ExactSizeIterator,
540     {
541         let from = from.map(|qid| StringId::new_virtual(qid.0));
542         self.profiler.bulk_map_virtual_to_single_concrete_string(from, to);
543     }
544
545     pub fn query_key_recording_enabled(&self) -> bool {
546         self.event_filter_mask.contains(EventFilter::QUERY_KEYS)
547     }
548
549     pub fn event_id_builder(&self) -> EventIdBuilder<'_> {
550         EventIdBuilder::new(&self.profiler)
551     }
552 }
553
554 #[must_use]
555 pub struct TimingGuard<'a>(Option<measureme::TimingGuard<'a>>);
556
557 impl<'a> TimingGuard<'a> {
558     #[inline]
559     pub fn start(
560         profiler: &'a SelfProfiler,
561         event_kind: StringId,
562         event_id: EventId,
563     ) -> TimingGuard<'a> {
564         let thread_id = std::thread::current().id().as_u64().get() as u32;
565         let raw_profiler = &profiler.profiler;
566         let timing_guard =
567             raw_profiler.start_recording_interval_event(event_kind, event_id, thread_id);
568         TimingGuard(Some(timing_guard))
569     }
570
571     #[inline]
572     pub fn finish_with_query_invocation_id(self, query_invocation_id: QueryInvocationId) {
573         if let Some(guard) = self.0 {
574             cold_path(|| {
575                 let event_id = StringId::new_virtual(query_invocation_id.0);
576                 let event_id = EventId::from_virtual(event_id);
577                 guard.finish_with_override_event_id(event_id);
578             });
579         }
580     }
581
582     #[inline]
583     pub fn none() -> TimingGuard<'a> {
584         TimingGuard(None)
585     }
586
587     #[inline(always)]
588     pub fn run<R>(self, f: impl FnOnce() -> R) -> R {
589         let _timer = self;
590         f()
591     }
592 }
593
594 #[must_use]
595 pub struct VerboseTimingGuard<'a> {
596     start_and_message: Option<(Instant, Option<usize>, String)>,
597     _guard: TimingGuard<'a>,
598 }
599
600 impl<'a> VerboseTimingGuard<'a> {
601     pub fn start(message: Option<String>, _guard: TimingGuard<'a>) -> Self {
602         VerboseTimingGuard {
603             _guard,
604             start_and_message: message.map(|msg| (Instant::now(), get_resident_set_size(), msg)),
605         }
606     }
607
608     #[inline(always)]
609     pub fn run<R>(self, f: impl FnOnce() -> R) -> R {
610         let _timer = self;
611         f()
612     }
613 }
614
615 impl Drop for VerboseTimingGuard<'_> {
616     fn drop(&mut self) {
617         if let Some((start_time, start_rss, ref message)) = self.start_and_message {
618             let end_rss = get_resident_set_size();
619             print_time_passes_entry(&message[..], start_time.elapsed(), start_rss, end_rss);
620         }
621     }
622 }
623
624 pub fn print_time_passes_entry(
625     what: &str,
626     dur: Duration,
627     start_rss: Option<usize>,
628     end_rss: Option<usize>,
629 ) {
630     let rss_to_mb = |rss| (rss as f64 / 1_000_000.0).round() as usize;
631     let rss_change_to_mb = |rss| (rss as f64 / 1_000_000.0).round() as i128;
632
633     let mem_string = match (start_rss, end_rss) {
634         (Some(start_rss), Some(end_rss)) => {
635             let change_rss = end_rss as i128 - start_rss as i128;
636
637             format!(
638                 "; rss: {:>4}MB -> {:>4}MB ({:>+5}MB)",
639                 rss_to_mb(start_rss),
640                 rss_to_mb(end_rss),
641                 rss_change_to_mb(change_rss),
642             )
643         }
644         (Some(start_rss), None) => format!("; rss start: {:>4}MB", rss_to_mb(start_rss)),
645         (None, Some(end_rss)) => format!("; rss end: {:>4}MB", rss_to_mb(end_rss)),
646         (None, None) => String::new(),
647     };
648
649     eprintln!("time: {:>7}{}\t{}", duration_to_secs_str(dur), mem_string, what);
650 }
651
652 // Hack up our own formatting for the duration to make it easier for scripts
653 // to parse (always use the same number of decimal places and the same unit).
654 pub fn duration_to_secs_str(dur: std::time::Duration) -> String {
655     format!("{:.3}", dur.as_secs_f64())
656 }
657
658 // Memory reporting
659 cfg_if! {
660     if #[cfg(windows)] {
661         pub fn get_resident_set_size() -> Option<usize> {
662             use std::mem::{self, MaybeUninit};
663             use winapi::shared::minwindef::DWORD;
664             use winapi::um::processthreadsapi::GetCurrentProcess;
665             use winapi::um::psapi::{GetProcessMemoryInfo, PROCESS_MEMORY_COUNTERS};
666
667             let mut pmc = MaybeUninit::<PROCESS_MEMORY_COUNTERS>::uninit();
668             match unsafe {
669                 GetProcessMemoryInfo(GetCurrentProcess(), pmc.as_mut_ptr(), mem::size_of_val(&pmc) as DWORD)
670             } {
671                 0 => None,
672                 _ => {
673                     let pmc = unsafe { pmc.assume_init() };
674                     Some(pmc.WorkingSetSize as usize)
675                 }
676             }
677         }
678     } else if #[cfg(unix)] {
679         pub fn get_resident_set_size() -> Option<usize> {
680             let field = 1;
681             let contents = fs::read("/proc/self/statm").ok()?;
682             let contents = String::from_utf8(contents).ok()?;
683             let s = contents.split_whitespace().nth(field)?;
684             let npages = s.parse::<usize>().ok()?;
685             Some(npages * 4096)
686         }
687     } else {
688         pub fn get_resident_set_size() -> Option<usize> {
689             None
690         }
691     }
692 }