]> git.proxmox.com Git - rustc.git/blame - compiler/rustc_data_structures/src/profiling.rs
New upstream version 1.56.0~beta.4+dfsg1
[rustc.git] / compiler / rustc_data_structures / src / profiling.rs
CommitLineData
dfeec247
XL
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
74b04a01 84use crate::cold_path;
dfeec247
XL
85use crate::fx::FxHashMap;
86
74b04a01
XL
87use std::borrow::Borrow;
88use std::collections::hash_map::Entry;
89use std::convert::Into;
48663c56 90use std::error::Error;
dc9dc135 91use std::fs;
dc9dc135 92use std::path::Path;
532ac7d7 93use std::process;
e74abb32 94use std::sync::Arc;
dfeec247 95use std::time::{Duration, Instant};
b7449926 96
136023e0
XL
97pub use measureme::EventId;
98use measureme::{EventIdBuilder, Profiler, SerializableString, StringId};
dfeec247 99use parking_lot::RwLock;
48663c56 100
60c5eb7d 101bitflags::bitflags! {
48663c56 102 struct EventFilter: u32 {
136023e0
XL
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;
48663c56 108
136023e0
XL
109 const QUERY_KEYS = 1 << 5;
110 const FUNCTION_ARGS = 1 << 6;
111 const LLVM = 1 << 7;
112 const INCR_RESULT_HASHING = 1 << 8;
dfeec247 113
48663c56
XL
114 const DEFAULT = Self::GENERIC_ACTIVITIES.bits |
115 Self::QUERY_PROVIDERS.bits |
116 Self::QUERY_BLOCKED.bits |
136023e0
XL
117 Self::INCR_CACHE_LOADS.bits |
118 Self::INCR_RESULT_HASHING.bits;
74b04a01
XL
119
120 const ARGS = Self::QUERY_KEYS.bits | Self::FUNCTION_ARGS.bits;
9fa01778
XL
121 }
122}
b7449926 123
136023e0 124// keep this in sync with the `-Z self-profile-events` help message in rustc_session/options.rs
48663c56 125const EVENT_FILTERS_BY_NAME: &[(&str, EventFilter)] = &[
dfeec247
XL
126 ("none", EventFilter::empty()),
127 ("all", EventFilter::all()),
128 ("default", EventFilter::DEFAULT),
48663c56
XL
129 ("generic-activity", EventFilter::GENERIC_ACTIVITIES),
130 ("query-provider", EventFilter::QUERY_PROVIDERS),
131 ("query-cache-hit", EventFilter::QUERY_CACHE_HITS),
dfeec247 132 ("query-blocked", EventFilter::QUERY_BLOCKED),
48663c56 133 ("incr-cache-load", EventFilter::INCR_CACHE_LOADS),
dfeec247 134 ("query-keys", EventFilter::QUERY_KEYS),
74b04a01
XL
135 ("function-args", EventFilter::FUNCTION_ARGS),
136 ("args", EventFilter::ARGS),
137 ("llvm", EventFilter::LLVM),
136023e0 138 ("incr-result-hashing", EventFilter::INCR_RESULT_HASHING),
48663c56
XL
139];
140
dfeec247
XL
141/// Something that uniquely identifies a query invocation.
142pub struct QueryInvocationId(pub u32);
e74abb32
XL
143
144/// A reference to the SelfProfiler. It can be cloned and sent across thread
145/// boundaries at will.
146#[derive(Clone)]
147pub 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,
dfeec247
XL
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,
e74abb32
XL
162}
163
164impl SelfProfilerRef {
dfeec247
XL
165 pub fn new(
166 profiler: Option<Arc<SelfProfiler>>,
167 print_verbose_generic_activities: bool,
168 print_extra_verbose_generic_activities: bool,
169 ) -> SelfProfilerRef {
e74abb32
XL
170 // If there is no SelfProfiler then the filter mask is set to NONE,
171 // ensuring that nothing ever tries to actually access it.
dfeec247 172 let event_filter_mask =
5869c6ff 173 profiler.as_ref().map_or(EventFilter::empty(), |p| p.event_filter_mask);
e74abb32
XL
174
175 SelfProfilerRef {
176 profiler,
177 event_filter_mask,
dfeec247
XL
178 print_verbose_generic_activities,
179 print_extra_verbose_generic_activities,
e74abb32
XL
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<'_>
dfeec247
XL
190 where
191 F: for<'a> FnOnce(&'a SelfProfiler) -> TimingGuard<'a>,
e74abb32
XL
192 {
193 #[inline(never)]
194 fn cold_call<F>(profiler_ref: &SelfProfilerRef, f: F) -> TimingGuard<'_>
dfeec247
XL
195 where
196 F: for<'a> FnOnce(&'a SelfProfiler) -> TimingGuard<'a>,
e74abb32
XL
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
dfeec247
XL
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.
dfeec247
XL
213 pub fn verbose_generic_activity<'a>(
214 &'a self,
74b04a01 215 event_label: &'static str,
dfeec247 216 ) -> VerboseTimingGuard<'a> {
74b04a01
XL
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))
dfeec247
XL
221 }
222
94222f64 223 /// Start profiling an extra verbose generic activity. Profiling continues until the
dfeec247
XL
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.
74b04a01 227 pub fn extra_verbose_generic_activity<'a, A>(
dfeec247 228 &'a self,
74b04a01
XL
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 })
dfeec247
XL
253 }
254
136023e0
XL
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
e74abb32
XL
264 /// Start profiling a generic activity. Profiling continues until the
265 /// TimingGuard returned from this call is dropped.
266 #[inline(always)]
74b04a01
XL
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 {
e74abb32 275 self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
74b04a01
XL
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 };
dfeec247 284 TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id)
e74abb32
XL
285 })
286 }
287
fc512014
XL
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
e74abb32
XL
310 /// Start profiling a query provider. Profiling continues until the
311 /// TimingGuard returned from this call is dropped.
312 #[inline(always)]
dfeec247 313 pub fn query_provider(&self) -> TimingGuard<'_> {
e74abb32 314 self.exec(EventFilter::QUERY_PROVIDERS, |profiler| {
dfeec247 315 TimingGuard::start(profiler, profiler.query_event_kind, EventId::INVALID)
e74abb32
XL
316 })
317 }
318
319 /// Record a query in-memory cache hit.
320 #[inline(always)]
dfeec247 321 pub fn query_cache_hit(&self, query_invocation_id: QueryInvocationId) {
60c5eb7d 322 self.instant_query_event(
e74abb32 323 |profiler| profiler.query_cache_hit_event_kind,
dfeec247 324 query_invocation_id,
e74abb32 325 EventFilter::QUERY_CACHE_HITS,
e74abb32
XL
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)]
dfeec247 333 pub fn query_blocked(&self) -> TimingGuard<'_> {
e74abb32 334 self.exec(EventFilter::QUERY_BLOCKED, |profiler| {
dfeec247 335 TimingGuard::start(profiler, profiler.query_blocked_event_kind, EventId::INVALID)
e74abb32
XL
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)]
dfeec247 343 pub fn incr_cache_loading(&self) -> TimingGuard<'_> {
e74abb32 344 self.exec(EventFilter::INCR_CACHE_LOADS, |profiler| {
e74abb32
XL
345 TimingGuard::start(
346 profiler,
347 profiler.incremental_load_result_event_kind,
dfeec247 348 EventId::INVALID,
e74abb32
XL
349 )
350 })
351 }
352
136023e0
XL
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
e74abb32 366 #[inline(always)]
60c5eb7d 367 fn instant_query_event(
e74abb32
XL
368 &self,
369 event_kind: fn(&SelfProfiler) -> StringId,
dfeec247 370 query_invocation_id: QueryInvocationId,
e74abb32 371 event_filter: EventFilter,
e74abb32
XL
372 ) {
373 drop(self.exec(event_filter, |profiler| {
dfeec247 374 let event_id = StringId::new_virtual(query_invocation_id.0);
ba9703b0 375 let thread_id = std::thread::current().id().as_u64().get() as u32;
e74abb32 376
60c5eb7d 377 profiler.profiler.record_instant_event(
e74abb32 378 event_kind(profiler),
dfeec247 379 EventId::from_virtual(event_id),
e74abb32 380 thread_id,
e74abb32
XL
381 );
382
383 TimingGuard::none()
384 }));
385 }
60c5eb7d 386
dfeec247 387 pub fn with_profiler(&self, f: impl FnOnce(&SelfProfiler)) {
60c5eb7d
XL
388 if let Some(profiler) = &self.profiler {
389 f(&profiler)
390 }
391 }
dfeec247 392
136023e0
XL
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
dfeec247
XL
401 #[inline]
402 pub fn enabled(&self) -> bool {
403 self.profiler.is_some()
404 }
74b04a01
XL
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 }
e74abb32
XL
414}
415
532ac7d7 416pub struct SelfProfiler {
48663c56
XL
417 profiler: Profiler,
418 event_filter_mask: EventFilter,
dfeec247 419
74b04a01 420 string_cache: RwLock<FxHashMap<String, StringId>>,
dfeec247 421
48663c56
XL
422 query_event_kind: StringId,
423 generic_activity_event_kind: StringId,
424 incremental_load_result_event_kind: StringId,
136023e0 425 incremental_result_hashing_event_kind: StringId,
48663c56
XL
426 query_blocked_event_kind: StringId,
427 query_cache_hit_event_kind: StringId,
b7449926
XL
428}
429
430impl SelfProfiler {
dc9dc135
XL
431 pub fn new(
432 output_directory: &Path,
433 crate_name: Option<&str>,
dfeec247 434 event_filters: &Option<Vec<String>>,
29967ef6 435 ) -> Result<SelfProfiler, Box<dyn Error + Send + Sync>> {
dc9dc135
XL
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)?;
48663c56
XL
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");
136023e0
XL
446 let incremental_result_hashing_event_kind =
447 profiler.alloc_string("IncrementalResultHashing");
48663c56
XL
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 {
dfeec247
XL
456 if let Some(&(_, mask)) =
457 EVENT_FILTERS_BY_NAME.iter().find(|&(name, _)| name == item)
458 {
48663c56
XL
459 event_filter_mask |= mask;
460 } else {
461 unknown_events.push(item.clone());
462 }
463 }
464
465 // Warn about any unknown event names
74b04a01 466 if !unknown_events.is_empty() {
48663c56
XL
467 unknown_events.sort();
468 unknown_events.dedup();
469
dfeec247
XL
470 warn!(
471 "Unknown self-profiler events specified: {}. Available options are: {}.",
48663c56 472 unknown_events.join(", "),
dfeec247
XL
473 EVENT_FILTERS_BY_NAME
474 .iter()
475 .map(|&(name, _)| name.to_string())
476 .collect::<Vec<_>>()
477 .join(", ")
478 );
48663c56
XL
479 }
480 } else {
481 event_filter_mask = EventFilter::DEFAULT;
482 }
483
484 Ok(SelfProfiler {
485 profiler,
486 event_filter_mask,
dfeec247 487 string_cache: RwLock::new(FxHashMap::default()),
48663c56
XL
488 query_event_kind,
489 generic_activity_event_kind,
490 incremental_load_result_event_kind,
136023e0 491 incremental_result_hashing_event_kind,
48663c56
XL
492 query_blocked_event_kind,
493 query_cache_hit_event_kind,
494 })
495 }
496
dfeec247
XL
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.
74b04a01
XL
506 pub fn get_or_alloc_cached_string<A>(&self, s: A) -> StringId
507 where
508 A: Borrow<str> + Into<String>,
509 {
dfeec247
XL
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
74b04a01 515 if let Some(&id) = string_cache.get(s.borrow()) {
dfeec247
XL
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.
74b04a01
XL
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 }
dfeec247
XL
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 }
b7449926 536
dfeec247
XL
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);
48663c56
XL
543 }
544
dfeec247
XL
545 pub fn query_key_recording_enabled(&self) -> bool {
546 self.event_filter_mask.contains(EventFilter::QUERY_KEYS)
547 }
548
29967ef6 549 pub fn event_id_builder(&self) -> EventIdBuilder<'_> {
dfeec247 550 EventIdBuilder::new(&self.profiler)
b7449926 551 }
e74abb32 552}
b7449926 553
e74abb32 554#[must_use]
29967ef6 555pub struct TimingGuard<'a>(Option<measureme::TimingGuard<'a>>);
9fa01778 556
e74abb32 557impl<'a> TimingGuard<'a> {
9fa01778 558 #[inline]
e74abb32
XL
559 pub fn start(
560 profiler: &'a SelfProfiler,
561 event_kind: StringId,
dfeec247 562 event_id: EventId,
e74abb32 563 ) -> TimingGuard<'a> {
ba9703b0 564 let thread_id = std::thread::current().id().as_u64().get() as u32;
e74abb32 565 let raw_profiler = &profiler.profiler;
dfeec247
XL
566 let timing_guard =
567 raw_profiler.start_recording_interval_event(event_kind, event_id, thread_id);
e74abb32 568 TimingGuard(Some(timing_guard))
9fa01778
XL
569 }
570
dfeec247
XL
571 #[inline]
572 pub fn finish_with_query_invocation_id(self, query_invocation_id: QueryInvocationId) {
573 if let Some(guard) = self.0 {
74b04a01
XL
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 });
dfeec247
XL
579 }
580 }
581
532ac7d7 582 #[inline]
e74abb32
XL
583 pub fn none() -> TimingGuard<'a> {
584 TimingGuard(None)
b7449926 585 }
dfeec247
XL
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]
595pub struct VerboseTimingGuard<'a> {
5869c6ff 596 start_and_message: Option<(Instant, Option<usize>, String)>,
dfeec247
XL
597 _guard: TimingGuard<'a>,
598}
599
600impl<'a> VerboseTimingGuard<'a> {
74b04a01 601 pub fn start(message: Option<String>, _guard: TimingGuard<'a>) -> Self {
5869c6ff
XL
602 VerboseTimingGuard {
603 _guard,
604 start_and_message: message.map(|msg| (Instant::now(), get_resident_set_size(), msg)),
605 }
dfeec247
XL
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
615impl Drop for VerboseTimingGuard<'_> {
616 fn drop(&mut self) {
5869c6ff
XL
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);
74b04a01 620 }
dfeec247
XL
621 }
622}
623
5869c6ff
XL
624pub 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 )
dfeec247 643 }
5869c6ff
XL
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(),
dfeec247 647 };
5869c6ff 648
6a06907d 649 eprintln!("time: {:>7}{}\t{}", duration_to_secs_str(dur), mem_string, what);
dfeec247
XL
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).
654pub fn duration_to_secs_str(dur: std::time::Duration) -> String {
1b1a35ee 655 format!("{:.3}", dur.as_secs_f64())
dfeec247
XL
656}
657
658// Memory reporting
f9f354fc
XL
659cfg_if! {
660 if #[cfg(windows)] {
5869c6ff 661 pub fn get_resident_set_size() -> Option<usize> {
f9f354fc
XL
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)] {
5869c6ff 679 pub fn get_resident_set_size() -> Option<usize> {
f9f354fc
XL
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 {
5869c6ff 688 pub fn get_resident_set_size() -> Option<usize> {
f9f354fc 689 None
dfeec247
XL
690 }
691 }
b7449926 692}