]>
Commit | Line | Data |
---|---|---|
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 | 84 | use crate::cold_path; |
dfeec247 XL |
85 | use crate::fx::FxHashMap; |
86 | ||
74b04a01 XL |
87 | use std::borrow::Borrow; |
88 | use std::collections::hash_map::Entry; | |
48663c56 | 89 | use std::error::Error; |
49aad941 | 90 | use std::fmt::Display; |
dc9dc135 | 91 | use std::fs; |
9ffffee4 | 92 | use std::intrinsics::unlikely; |
dc9dc135 | 93 | use std::path::Path; |
532ac7d7 | 94 | use std::process; |
e74abb32 | 95 | use std::sync::Arc; |
dfeec247 | 96 | use std::time::{Duration, Instant}; |
b7449926 | 97 | |
136023e0 XL |
98 | pub use measureme::EventId; |
99 | use measureme::{EventIdBuilder, Profiler, SerializableString, StringId}; | |
dfeec247 | 100 | use parking_lot::RwLock; |
04454e1e | 101 | use smallvec::SmallVec; |
48663c56 | 102 | |
60c5eb7d | 103 | bitflags::bitflags! { |
49aad941 | 104 | struct EventFilter: u16 { |
136023e0 XL |
105 | const GENERIC_ACTIVITIES = 1 << 0; |
106 | const QUERY_PROVIDERS = 1 << 1; | |
107 | const QUERY_CACHE_HITS = 1 << 2; | |
108 | const QUERY_BLOCKED = 1 << 3; | |
109 | const INCR_CACHE_LOADS = 1 << 4; | |
48663c56 | 110 | |
136023e0 XL |
111 | const QUERY_KEYS = 1 << 5; |
112 | const FUNCTION_ARGS = 1 << 6; | |
113 | const LLVM = 1 << 7; | |
114 | const INCR_RESULT_HASHING = 1 << 8; | |
3c0e092e | 115 | const ARTIFACT_SIZES = 1 << 9; |
dfeec247 | 116 | |
48663c56 XL |
117 | const DEFAULT = Self::GENERIC_ACTIVITIES.bits | |
118 | Self::QUERY_PROVIDERS.bits | | |
119 | Self::QUERY_BLOCKED.bits | | |
136023e0 | 120 | Self::INCR_CACHE_LOADS.bits | |
3c0e092e XL |
121 | Self::INCR_RESULT_HASHING.bits | |
122 | Self::ARTIFACT_SIZES.bits; | |
74b04a01 XL |
123 | |
124 | const ARGS = Self::QUERY_KEYS.bits | Self::FUNCTION_ARGS.bits; | |
9fa01778 XL |
125 | } |
126 | } | |
b7449926 | 127 | |
136023e0 | 128 | // keep this in sync with the `-Z self-profile-events` help message in rustc_session/options.rs |
48663c56 | 129 | const EVENT_FILTERS_BY_NAME: &[(&str, EventFilter)] = &[ |
dfeec247 XL |
130 | ("none", EventFilter::empty()), |
131 | ("all", EventFilter::all()), | |
132 | ("default", EventFilter::DEFAULT), | |
48663c56 XL |
133 | ("generic-activity", EventFilter::GENERIC_ACTIVITIES), |
134 | ("query-provider", EventFilter::QUERY_PROVIDERS), | |
135 | ("query-cache-hit", EventFilter::QUERY_CACHE_HITS), | |
dfeec247 | 136 | ("query-blocked", EventFilter::QUERY_BLOCKED), |
48663c56 | 137 | ("incr-cache-load", EventFilter::INCR_CACHE_LOADS), |
dfeec247 | 138 | ("query-keys", EventFilter::QUERY_KEYS), |
74b04a01 XL |
139 | ("function-args", EventFilter::FUNCTION_ARGS), |
140 | ("args", EventFilter::ARGS), | |
141 | ("llvm", EventFilter::LLVM), | |
136023e0 | 142 | ("incr-result-hashing", EventFilter::INCR_RESULT_HASHING), |
3c0e092e | 143 | ("artifact-sizes", EventFilter::ARTIFACT_SIZES), |
48663c56 XL |
144 | ]; |
145 | ||
dfeec247 XL |
146 | /// Something that uniquely identifies a query invocation. |
147 | pub struct QueryInvocationId(pub u32); | |
e74abb32 | 148 | |
353b0b11 FG |
149 | /// Which format to use for `-Z time-passes` |
150 | #[derive(Clone, Copy, PartialEq, Hash, Debug)] | |
151 | pub enum TimePassesFormat { | |
152 | /// Emit human readable text | |
153 | Text, | |
154 | /// Emit structured JSON | |
155 | Json, | |
156 | } | |
157 | ||
e74abb32 XL |
158 | /// A reference to the SelfProfiler. It can be cloned and sent across thread |
159 | /// boundaries at will. | |
160 | #[derive(Clone)] | |
161 | pub struct SelfProfilerRef { | |
162 | // This field is `None` if self-profiling is disabled for the current | |
163 | // compilation session. | |
164 | profiler: Option<Arc<SelfProfiler>>, | |
165 | ||
166 | // We store the filter mask directly in the reference because that doesn't | |
167 | // cost anything and allows for filtering with checking if the profiler is | |
168 | // actually enabled. | |
169 | event_filter_mask: EventFilter, | |
dfeec247 | 170 | |
353b0b11 FG |
171 | // Print verbose generic activities to stderr. |
172 | print_verbose_generic_activities: Option<TimePassesFormat>, | |
e74abb32 XL |
173 | } |
174 | ||
175 | impl SelfProfilerRef { | |
dfeec247 XL |
176 | pub fn new( |
177 | profiler: Option<Arc<SelfProfiler>>, | |
353b0b11 | 178 | print_verbose_generic_activities: Option<TimePassesFormat>, |
dfeec247 | 179 | ) -> SelfProfilerRef { |
e74abb32 XL |
180 | // If there is no SelfProfiler then the filter mask is set to NONE, |
181 | // ensuring that nothing ever tries to actually access it. | |
dfeec247 | 182 | let event_filter_mask = |
5869c6ff | 183 | profiler.as_ref().map_or(EventFilter::empty(), |p| p.event_filter_mask); |
e74abb32 | 184 | |
2b03887a | 185 | SelfProfilerRef { profiler, event_filter_mask, print_verbose_generic_activities } |
e74abb32 XL |
186 | } |
187 | ||
04454e1e FG |
188 | /// This shim makes sure that calls only get executed if the filter mask |
189 | /// lets them pass. It also contains some trickery to make sure that | |
190 | /// code is optimized for non-profiling compilation sessions, i.e. anything | |
191 | /// past the filter check is never inlined so it doesn't clutter the fast | |
192 | /// path. | |
e74abb32 XL |
193 | #[inline(always)] |
194 | fn exec<F>(&self, event_filter: EventFilter, f: F) -> TimingGuard<'_> | |
dfeec247 XL |
195 | where |
196 | F: for<'a> FnOnce(&'a SelfProfiler) -> TimingGuard<'a>, | |
e74abb32 XL |
197 | { |
198 | #[inline(never)] | |
923072b8 | 199 | #[cold] |
e74abb32 | 200 | fn cold_call<F>(profiler_ref: &SelfProfilerRef, f: F) -> TimingGuard<'_> |
dfeec247 XL |
201 | where |
202 | F: for<'a> FnOnce(&'a SelfProfiler) -> TimingGuard<'a>, | |
e74abb32 XL |
203 | { |
204 | let profiler = profiler_ref.profiler.as_ref().unwrap(); | |
487cf647 | 205 | f(profiler) |
e74abb32 XL |
206 | } |
207 | ||
923072b8 | 208 | if self.event_filter_mask.contains(event_filter) { |
e74abb32 XL |
209 | cold_call(self, f) |
210 | } else { | |
211 | TimingGuard::none() | |
212 | } | |
213 | } | |
214 | ||
dfeec247 XL |
215 | /// Start profiling a verbose generic activity. Profiling continues until the |
216 | /// VerboseTimingGuard returned from this call is dropped. In addition to recording | |
217 | /// a measureme event, "verbose" generic activities also print a timing entry to | |
2b03887a | 218 | /// stderr if the compiler is invoked with -Ztime-passes. |
9c376795 | 219 | pub fn verbose_generic_activity(&self, event_label: &'static str) -> VerboseTimingGuard<'_> { |
353b0b11 FG |
220 | let message_and_format = |
221 | self.print_verbose_generic_activities.map(|format| (event_label.to_owned(), format)); | |
74b04a01 | 222 | |
353b0b11 | 223 | VerboseTimingGuard::start(message_and_format, self.generic_activity(event_label)) |
dfeec247 XL |
224 | } |
225 | ||
2b03887a | 226 | /// Like `verbose_generic_activity`, but with an extra arg. |
9c376795 FG |
227 | pub fn verbose_generic_activity_with_arg<A>( |
228 | &self, | |
74b04a01 XL |
229 | event_label: &'static str, |
230 | event_arg: A, | |
9c376795 | 231 | ) -> VerboseTimingGuard<'_> |
74b04a01 XL |
232 | where |
233 | A: Borrow<str> + Into<String>, | |
234 | { | |
353b0b11 | 235 | let message_and_format = self |
9ffffee4 | 236 | .print_verbose_generic_activities |
353b0b11 | 237 | .map(|format| (format!("{}({})", event_label, event_arg.borrow()), format)); |
74b04a01 | 238 | |
353b0b11 FG |
239 | VerboseTimingGuard::start( |
240 | message_and_format, | |
241 | self.generic_activity_with_arg(event_label, event_arg), | |
242 | ) | |
74b04a01 XL |
243 | } |
244 | ||
245 | /// Start profiling a generic activity. Profiling continues until the | |
246 | /// TimingGuard returned from this call is dropped. | |
247 | #[inline(always)] | |
248 | pub fn generic_activity(&self, event_label: &'static str) -> TimingGuard<'_> { | |
249 | self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| { | |
250 | let event_label = profiler.get_or_alloc_cached_string(event_label); | |
251 | let event_id = EventId::from_label(event_label); | |
252 | TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id) | |
253 | }) | |
dfeec247 XL |
254 | } |
255 | ||
136023e0 XL |
256 | /// Start profiling with some event filter for a given event. Profiling continues until the |
257 | /// TimingGuard returned from this call is dropped. | |
258 | #[inline(always)] | |
259 | pub fn generic_activity_with_event_id(&self, event_id: EventId) -> TimingGuard<'_> { | |
260 | self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| { | |
261 | TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id) | |
262 | }) | |
263 | } | |
264 | ||
e74abb32 XL |
265 | /// Start profiling a generic activity. Profiling continues until the |
266 | /// TimingGuard returned from this call is dropped. | |
267 | #[inline(always)] | |
74b04a01 XL |
268 | pub fn generic_activity_with_arg<A>( |
269 | &self, | |
270 | event_label: &'static str, | |
271 | event_arg: A, | |
272 | ) -> TimingGuard<'_> | |
273 | where | |
274 | A: Borrow<str> + Into<String>, | |
275 | { | |
e74abb32 | 276 | self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| { |
74b04a01 XL |
277 | let builder = EventIdBuilder::new(&profiler.profiler); |
278 | let event_label = profiler.get_or_alloc_cached_string(event_label); | |
279 | let event_id = if profiler.event_filter_mask.contains(EventFilter::FUNCTION_ARGS) { | |
280 | let event_arg = profiler.get_or_alloc_cached_string(event_arg); | |
281 | builder.from_label_and_arg(event_label, event_arg) | |
282 | } else { | |
283 | builder.from_label(event_label) | |
284 | }; | |
dfeec247 | 285 | TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id) |
e74abb32 XL |
286 | }) |
287 | } | |
288 | ||
04454e1e FG |
289 | /// Start profiling a generic activity, allowing costly arguments to be recorded. Profiling |
290 | /// continues until the `TimingGuard` returned from this call is dropped. | |
291 | /// | |
292 | /// If the arguments to a generic activity are cheap to create, use `generic_activity_with_arg` | |
293 | /// or `generic_activity_with_args` for their simpler API. However, if they are costly or | |
294 | /// require allocation in sufficiently hot contexts, then this allows for a closure to be called | |
295 | /// only when arguments were asked to be recorded via `-Z self-profile-events=args`. | |
296 | /// | |
297 | /// In this case, the closure will be passed a `&mut EventArgRecorder`, to help with recording | |
298 | /// one or many arguments within the generic activity being profiled, by calling its | |
299 | /// `record_arg` method for example. | |
300 | /// | |
301 | /// This `EventArgRecorder` may implement more specific traits from other rustc crates, e.g. for | |
302 | /// richer handling of rustc-specific argument types, while keeping this single entry-point API | |
303 | /// for recording arguments. | |
304 | /// | |
305 | /// Note: recording at least one argument is *required* for the self-profiler to create the | |
306 | /// `TimingGuard`. A panic will be triggered if that doesn't happen. This function exists | |
307 | /// explicitly to record arguments, so it fails loudly when there are none to record. | |
308 | /// | |
309 | #[inline(always)] | |
310 | pub fn generic_activity_with_arg_recorder<F>( | |
311 | &self, | |
312 | event_label: &'static str, | |
313 | mut f: F, | |
314 | ) -> TimingGuard<'_> | |
315 | where | |
316 | F: FnMut(&mut EventArgRecorder<'_>), | |
317 | { | |
318 | // Ensure this event will only be recorded when self-profiling is turned on. | |
319 | self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| { | |
320 | let builder = EventIdBuilder::new(&profiler.profiler); | |
321 | let event_label = profiler.get_or_alloc_cached_string(event_label); | |
322 | ||
323 | // Ensure the closure to create event arguments will only be called when argument | |
324 | // recording is turned on. | |
325 | let event_id = if profiler.event_filter_mask.contains(EventFilter::FUNCTION_ARGS) { | |
326 | // Set up the builder and call the user-provided closure to record potentially | |
327 | // costly event arguments. | |
328 | let mut recorder = EventArgRecorder { profiler, args: SmallVec::new() }; | |
329 | f(&mut recorder); | |
330 | ||
331 | // It is expected that the closure will record at least one argument. If that | |
332 | // doesn't happen, it's a bug: we've been explicitly called in order to record | |
333 | // arguments, so we fail loudly when there are none to record. | |
334 | if recorder.args.is_empty() { | |
335 | panic!( | |
336 | "The closure passed to `generic_activity_with_arg_recorder` needs to \ | |
337 | record at least one argument" | |
338 | ); | |
339 | } | |
340 | ||
341 | builder.from_label_and_args(event_label, &recorder.args) | |
342 | } else { | |
343 | builder.from_label(event_label) | |
344 | }; | |
345 | TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id) | |
346 | }) | |
347 | } | |
348 | ||
3c0e092e XL |
349 | /// Record the size of an artifact that the compiler produces |
350 | /// | |
351 | /// `artifact_kind` is the class of artifact (e.g., query_cache, object_file, etc.) | |
352 | /// `artifact_name` is an identifier to the specific artifact being stored (usually a filename) | |
353 | #[inline(always)] | |
354 | pub fn artifact_size<A>(&self, artifact_kind: &str, artifact_name: A, size: u64) | |
355 | where | |
356 | A: Borrow<str> + Into<String>, | |
357 | { | |
358 | drop(self.exec(EventFilter::ARTIFACT_SIZES, |profiler| { | |
359 | let builder = EventIdBuilder::new(&profiler.profiler); | |
360 | let event_label = profiler.get_or_alloc_cached_string(artifact_kind); | |
361 | let event_arg = profiler.get_or_alloc_cached_string(artifact_name); | |
362 | let event_id = builder.from_label_and_arg(event_label, event_arg); | |
363 | let thread_id = get_thread_id(); | |
364 | ||
365 | profiler.profiler.record_integer_event( | |
366 | profiler.artifact_size_event_kind, | |
367 | event_id, | |
368 | thread_id, | |
369 | size, | |
370 | ); | |
371 | ||
372 | TimingGuard::none() | |
373 | })) | |
374 | } | |
375 | ||
fc512014 XL |
376 | #[inline(always)] |
377 | pub fn generic_activity_with_args( | |
378 | &self, | |
379 | event_label: &'static str, | |
380 | event_args: &[String], | |
381 | ) -> TimingGuard<'_> { | |
382 | self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| { | |
383 | let builder = EventIdBuilder::new(&profiler.profiler); | |
384 | let event_label = profiler.get_or_alloc_cached_string(event_label); | |
385 | let event_id = if profiler.event_filter_mask.contains(EventFilter::FUNCTION_ARGS) { | |
386 | let event_args: Vec<_> = event_args | |
387 | .iter() | |
388 | .map(|s| profiler.get_or_alloc_cached_string(&s[..])) | |
389 | .collect(); | |
390 | builder.from_label_and_args(event_label, &event_args) | |
391 | } else { | |
392 | builder.from_label(event_label) | |
393 | }; | |
394 | TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id) | |
395 | }) | |
396 | } | |
397 | ||
e74abb32 XL |
398 | /// Start profiling a query provider. Profiling continues until the |
399 | /// TimingGuard returned from this call is dropped. | |
400 | #[inline(always)] | |
dfeec247 | 401 | pub fn query_provider(&self) -> TimingGuard<'_> { |
e74abb32 | 402 | self.exec(EventFilter::QUERY_PROVIDERS, |profiler| { |
dfeec247 | 403 | TimingGuard::start(profiler, profiler.query_event_kind, EventId::INVALID) |
e74abb32 XL |
404 | }) |
405 | } | |
406 | ||
407 | /// Record a query in-memory cache hit. | |
408 | #[inline(always)] | |
dfeec247 | 409 | pub fn query_cache_hit(&self, query_invocation_id: QueryInvocationId) { |
9ffffee4 FG |
410 | #[inline(never)] |
411 | #[cold] | |
412 | fn cold_call(profiler_ref: &SelfProfilerRef, query_invocation_id: QueryInvocationId) { | |
413 | profiler_ref.instant_query_event( | |
414 | |profiler| profiler.query_cache_hit_event_kind, | |
415 | query_invocation_id, | |
416 | ); | |
417 | } | |
418 | ||
419 | if unlikely(self.event_filter_mask.contains(EventFilter::QUERY_CACHE_HITS)) { | |
420 | cold_call(self, query_invocation_id); | |
421 | } | |
e74abb32 XL |
422 | } |
423 | ||
424 | /// Start profiling a query being blocked on a concurrent execution. | |
425 | /// Profiling continues until the TimingGuard returned from this call is | |
426 | /// dropped. | |
427 | #[inline(always)] | |
dfeec247 | 428 | pub fn query_blocked(&self) -> TimingGuard<'_> { |
e74abb32 | 429 | self.exec(EventFilter::QUERY_BLOCKED, |profiler| { |
dfeec247 | 430 | TimingGuard::start(profiler, profiler.query_blocked_event_kind, EventId::INVALID) |
e74abb32 XL |
431 | }) |
432 | } | |
433 | ||
434 | /// Start profiling how long it takes to load a query result from the | |
435 | /// incremental compilation on-disk cache. Profiling continues until the | |
436 | /// TimingGuard returned from this call is dropped. | |
437 | #[inline(always)] | |
dfeec247 | 438 | pub fn incr_cache_loading(&self) -> TimingGuard<'_> { |
e74abb32 | 439 | self.exec(EventFilter::INCR_CACHE_LOADS, |profiler| { |
e74abb32 XL |
440 | TimingGuard::start( |
441 | profiler, | |
442 | profiler.incremental_load_result_event_kind, | |
dfeec247 | 443 | EventId::INVALID, |
e74abb32 XL |
444 | ) |
445 | }) | |
446 | } | |
447 | ||
136023e0 XL |
448 | /// Start profiling how long it takes to hash query results for incremental compilation. |
449 | /// Profiling continues until the TimingGuard returned from this call is dropped. | |
450 | #[inline(always)] | |
451 | pub fn incr_result_hashing(&self) -> TimingGuard<'_> { | |
452 | self.exec(EventFilter::INCR_RESULT_HASHING, |profiler| { | |
453 | TimingGuard::start( | |
454 | profiler, | |
455 | profiler.incremental_result_hashing_event_kind, | |
456 | EventId::INVALID, | |
457 | ) | |
458 | }) | |
459 | } | |
460 | ||
e74abb32 | 461 | #[inline(always)] |
60c5eb7d | 462 | fn instant_query_event( |
e74abb32 XL |
463 | &self, |
464 | event_kind: fn(&SelfProfiler) -> StringId, | |
dfeec247 | 465 | query_invocation_id: QueryInvocationId, |
e74abb32 | 466 | ) { |
9ffffee4 FG |
467 | let event_id = StringId::new_virtual(query_invocation_id.0); |
468 | let thread_id = get_thread_id(); | |
469 | let profiler = self.profiler.as_ref().unwrap(); | |
470 | profiler.profiler.record_instant_event( | |
471 | event_kind(profiler), | |
472 | EventId::from_virtual(event_id), | |
473 | thread_id, | |
474 | ); | |
e74abb32 | 475 | } |
60c5eb7d | 476 | |
dfeec247 | 477 | pub fn with_profiler(&self, f: impl FnOnce(&SelfProfiler)) { |
60c5eb7d | 478 | if let Some(profiler) = &self.profiler { |
487cf647 | 479 | f(profiler) |
60c5eb7d XL |
480 | } |
481 | } | |
dfeec247 | 482 | |
136023e0 XL |
483 | /// Gets a `StringId` for the given string. This method makes sure that |
484 | /// any strings going through it will only be allocated once in the | |
485 | /// profiling data. | |
486 | /// Returns `None` if the self-profiling is not enabled. | |
487 | pub fn get_or_alloc_cached_string(&self, s: &str) -> Option<StringId> { | |
488 | self.profiler.as_ref().map(|p| p.get_or_alloc_cached_string(s)) | |
489 | } | |
490 | ||
dfeec247 XL |
491 | #[inline] |
492 | pub fn enabled(&self) -> bool { | |
493 | self.profiler.is_some() | |
494 | } | |
74b04a01 XL |
495 | |
496 | #[inline] | |
497 | pub fn llvm_recording_enabled(&self) -> bool { | |
498 | self.event_filter_mask.contains(EventFilter::LLVM) | |
499 | } | |
500 | #[inline] | |
501 | pub fn get_self_profiler(&self) -> Option<Arc<SelfProfiler>> { | |
502 | self.profiler.clone() | |
503 | } | |
e74abb32 XL |
504 | } |
505 | ||
04454e1e FG |
506 | /// A helper for recording costly arguments to self-profiling events. Used with |
507 | /// `SelfProfilerRef::generic_activity_with_arg_recorder`. | |
508 | pub struct EventArgRecorder<'p> { | |
509 | /// The `SelfProfiler` used to intern the event arguments that users will ask to record. | |
510 | profiler: &'p SelfProfiler, | |
511 | ||
512 | /// The interned event arguments to be recorded in the generic activity event. | |
513 | /// | |
514 | /// The most common case, when actually recording event arguments, is to have one argument. Then | |
515 | /// followed by recording two, in a couple places. | |
516 | args: SmallVec<[StringId; 2]>, | |
517 | } | |
518 | ||
519 | impl EventArgRecorder<'_> { | |
520 | /// Records a single argument within the current generic activity being profiled. | |
521 | /// | |
522 | /// Note: when self-profiling with costly event arguments, at least one argument | |
523 | /// needs to be recorded. A panic will be triggered if that doesn't happen. | |
524 | pub fn record_arg<A>(&mut self, event_arg: A) | |
525 | where | |
526 | A: Borrow<str> + Into<String>, | |
527 | { | |
528 | let event_arg = self.profiler.get_or_alloc_cached_string(event_arg); | |
529 | self.args.push(event_arg); | |
530 | } | |
531 | } | |
532 | ||
532ac7d7 | 533 | pub struct SelfProfiler { |
48663c56 XL |
534 | profiler: Profiler, |
535 | event_filter_mask: EventFilter, | |
dfeec247 | 536 | |
74b04a01 | 537 | string_cache: RwLock<FxHashMap<String, StringId>>, |
dfeec247 | 538 | |
48663c56 XL |
539 | query_event_kind: StringId, |
540 | generic_activity_event_kind: StringId, | |
541 | incremental_load_result_event_kind: StringId, | |
136023e0 | 542 | incremental_result_hashing_event_kind: StringId, |
48663c56 XL |
543 | query_blocked_event_kind: StringId, |
544 | query_cache_hit_event_kind: StringId, | |
3c0e092e | 545 | artifact_size_event_kind: StringId, |
b7449926 XL |
546 | } |
547 | ||
548 | impl SelfProfiler { | |
dc9dc135 XL |
549 | pub fn new( |
550 | output_directory: &Path, | |
551 | crate_name: Option<&str>, | |
923072b8 FG |
552 | event_filters: Option<&[String]>, |
553 | counter_name: &str, | |
29967ef6 | 554 | ) -> Result<SelfProfiler, Box<dyn Error + Send + Sync>> { |
dc9dc135 XL |
555 | fs::create_dir_all(output_directory)?; |
556 | ||
557 | let crate_name = crate_name.unwrap_or("unknown-crate"); | |
923072b8 FG |
558 | // HACK(eddyb) we need to pad the PID, strange as it may seem, as its |
559 | // length can behave as a source of entropy for heap addresses, when | |
49aad941 | 560 | // ASLR is disabled and the heap is otherwise deterministic. |
923072b8 | 561 | let pid: u32 = process::id(); |
9c376795 | 562 | let filename = format!("{crate_name}-{pid:07}.rustc_profile"); |
dc9dc135 | 563 | let path = output_directory.join(&filename); |
923072b8 FG |
564 | let profiler = |
565 | Profiler::with_counter(&path, measureme::counters::Counter::by_name(counter_name)?)?; | |
48663c56 XL |
566 | |
567 | let query_event_kind = profiler.alloc_string("Query"); | |
568 | let generic_activity_event_kind = profiler.alloc_string("GenericActivity"); | |
569 | let incremental_load_result_event_kind = profiler.alloc_string("IncrementalLoadResult"); | |
136023e0 XL |
570 | let incremental_result_hashing_event_kind = |
571 | profiler.alloc_string("IncrementalResultHashing"); | |
48663c56 XL |
572 | let query_blocked_event_kind = profiler.alloc_string("QueryBlocked"); |
573 | let query_cache_hit_event_kind = profiler.alloc_string("QueryCacheHit"); | |
3c0e092e | 574 | let artifact_size_event_kind = profiler.alloc_string("ArtifactSize"); |
48663c56 XL |
575 | |
576 | let mut event_filter_mask = EventFilter::empty(); | |
577 | ||
923072b8 | 578 | if let Some(event_filters) = event_filters { |
48663c56 XL |
579 | let mut unknown_events = vec![]; |
580 | for item in event_filters { | |
dfeec247 XL |
581 | if let Some(&(_, mask)) = |
582 | EVENT_FILTERS_BY_NAME.iter().find(|&(name, _)| name == item) | |
583 | { | |
48663c56 XL |
584 | event_filter_mask |= mask; |
585 | } else { | |
586 | unknown_events.push(item.clone()); | |
587 | } | |
588 | } | |
589 | ||
590 | // Warn about any unknown event names | |
74b04a01 | 591 | if !unknown_events.is_empty() { |
48663c56 XL |
592 | unknown_events.sort(); |
593 | unknown_events.dedup(); | |
594 | ||
dfeec247 XL |
595 | warn!( |
596 | "Unknown self-profiler events specified: {}. Available options are: {}.", | |
48663c56 | 597 | unknown_events.join(", "), |
dfeec247 XL |
598 | EVENT_FILTERS_BY_NAME |
599 | .iter() | |
600 | .map(|&(name, _)| name.to_string()) | |
601 | .collect::<Vec<_>>() | |
602 | .join(", ") | |
603 | ); | |
48663c56 XL |
604 | } |
605 | } else { | |
606 | event_filter_mask = EventFilter::DEFAULT; | |
607 | } | |
608 | ||
609 | Ok(SelfProfiler { | |
610 | profiler, | |
611 | event_filter_mask, | |
dfeec247 | 612 | string_cache: RwLock::new(FxHashMap::default()), |
48663c56 XL |
613 | query_event_kind, |
614 | generic_activity_event_kind, | |
615 | incremental_load_result_event_kind, | |
136023e0 | 616 | incremental_result_hashing_event_kind, |
48663c56 XL |
617 | query_blocked_event_kind, |
618 | query_cache_hit_event_kind, | |
3c0e092e | 619 | artifact_size_event_kind, |
48663c56 XL |
620 | }) |
621 | } | |
622 | ||
dfeec247 XL |
623 | /// Allocates a new string in the profiling data. Does not do any caching |
624 | /// or deduplication. | |
625 | pub fn alloc_string<STR: SerializableString + ?Sized>(&self, s: &STR) -> StringId { | |
626 | self.profiler.alloc_string(s) | |
627 | } | |
628 | ||
629 | /// Gets a `StringId` for the given string. This method makes sure that | |
630 | /// any strings going through it will only be allocated once in the | |
631 | /// profiling data. | |
74b04a01 XL |
632 | pub fn get_or_alloc_cached_string<A>(&self, s: A) -> StringId |
633 | where | |
634 | A: Borrow<str> + Into<String>, | |
635 | { | |
dfeec247 XL |
636 | // Only acquire a read-lock first since we assume that the string is |
637 | // already present in the common case. | |
638 | { | |
639 | let string_cache = self.string_cache.read(); | |
640 | ||
74b04a01 | 641 | if let Some(&id) = string_cache.get(s.borrow()) { |
dfeec247 XL |
642 | return id; |
643 | } | |
644 | } | |
645 | ||
646 | let mut string_cache = self.string_cache.write(); | |
647 | // Check if the string has already been added in the small time window | |
648 | // between dropping the read lock and acquiring the write lock. | |
74b04a01 XL |
649 | match string_cache.entry(s.into()) { |
650 | Entry::Occupied(e) => *e.get(), | |
651 | Entry::Vacant(e) => { | |
652 | let string_id = self.profiler.alloc_string(&e.key()[..]); | |
653 | *e.insert(string_id) | |
654 | } | |
655 | } | |
dfeec247 XL |
656 | } |
657 | ||
658 | pub fn map_query_invocation_id_to_string(&self, from: QueryInvocationId, to: StringId) { | |
659 | let from = StringId::new_virtual(from.0); | |
660 | self.profiler.map_virtual_to_concrete_string(from, to); | |
661 | } | |
b7449926 | 662 | |
dfeec247 XL |
663 | pub fn bulk_map_query_invocation_id_to_single_string<I>(&self, from: I, to: StringId) |
664 | where | |
665 | I: Iterator<Item = QueryInvocationId> + ExactSizeIterator, | |
666 | { | |
667 | let from = from.map(|qid| StringId::new_virtual(qid.0)); | |
668 | self.profiler.bulk_map_virtual_to_single_concrete_string(from, to); | |
48663c56 XL |
669 | } |
670 | ||
dfeec247 XL |
671 | pub fn query_key_recording_enabled(&self) -> bool { |
672 | self.event_filter_mask.contains(EventFilter::QUERY_KEYS) | |
673 | } | |
674 | ||
29967ef6 | 675 | pub fn event_id_builder(&self) -> EventIdBuilder<'_> { |
dfeec247 | 676 | EventIdBuilder::new(&self.profiler) |
b7449926 | 677 | } |
e74abb32 | 678 | } |
b7449926 | 679 | |
e74abb32 | 680 | #[must_use] |
29967ef6 | 681 | pub struct TimingGuard<'a>(Option<measureme::TimingGuard<'a>>); |
9fa01778 | 682 | |
e74abb32 | 683 | impl<'a> TimingGuard<'a> { |
9fa01778 | 684 | #[inline] |
e74abb32 XL |
685 | pub fn start( |
686 | profiler: &'a SelfProfiler, | |
687 | event_kind: StringId, | |
dfeec247 | 688 | event_id: EventId, |
e74abb32 | 689 | ) -> TimingGuard<'a> { |
3c0e092e | 690 | let thread_id = get_thread_id(); |
e74abb32 | 691 | let raw_profiler = &profiler.profiler; |
dfeec247 XL |
692 | let timing_guard = |
693 | raw_profiler.start_recording_interval_event(event_kind, event_id, thread_id); | |
e74abb32 | 694 | TimingGuard(Some(timing_guard)) |
9fa01778 XL |
695 | } |
696 | ||
dfeec247 XL |
697 | #[inline] |
698 | pub fn finish_with_query_invocation_id(self, query_invocation_id: QueryInvocationId) { | |
699 | if let Some(guard) = self.0 { | |
74b04a01 XL |
700 | cold_path(|| { |
701 | let event_id = StringId::new_virtual(query_invocation_id.0); | |
702 | let event_id = EventId::from_virtual(event_id); | |
703 | guard.finish_with_override_event_id(event_id); | |
704 | }); | |
dfeec247 XL |
705 | } |
706 | } | |
707 | ||
532ac7d7 | 708 | #[inline] |
e74abb32 XL |
709 | pub fn none() -> TimingGuard<'a> { |
710 | TimingGuard(None) | |
b7449926 | 711 | } |
dfeec247 XL |
712 | |
713 | #[inline(always)] | |
714 | pub fn run<R>(self, f: impl FnOnce() -> R) -> R { | |
715 | let _timer = self; | |
716 | f() | |
717 | } | |
718 | } | |
719 | ||
353b0b11 FG |
720 | struct VerboseInfo { |
721 | start_time: Instant, | |
722 | start_rss: Option<usize>, | |
723 | message: String, | |
724 | format: TimePassesFormat, | |
725 | } | |
726 | ||
dfeec247 XL |
727 | #[must_use] |
728 | pub struct VerboseTimingGuard<'a> { | |
353b0b11 | 729 | info: Option<VerboseInfo>, |
dfeec247 XL |
730 | _guard: TimingGuard<'a>, |
731 | } | |
732 | ||
733 | impl<'a> VerboseTimingGuard<'a> { | |
353b0b11 FG |
734 | pub fn start( |
735 | message_and_format: Option<(String, TimePassesFormat)>, | |
736 | _guard: TimingGuard<'a>, | |
737 | ) -> Self { | |
5869c6ff XL |
738 | VerboseTimingGuard { |
739 | _guard, | |
353b0b11 FG |
740 | info: message_and_format.map(|(message, format)| VerboseInfo { |
741 | start_time: Instant::now(), | |
742 | start_rss: get_resident_set_size(), | |
743 | message, | |
744 | format, | |
745 | }), | |
5869c6ff | 746 | } |
dfeec247 XL |
747 | } |
748 | ||
749 | #[inline(always)] | |
750 | pub fn run<R>(self, f: impl FnOnce() -> R) -> R { | |
751 | let _timer = self; | |
752 | f() | |
753 | } | |
754 | } | |
755 | ||
756 | impl Drop for VerboseTimingGuard<'_> { | |
757 | fn drop(&mut self) { | |
353b0b11 | 758 | if let Some(info) = &self.info { |
5869c6ff | 759 | let end_rss = get_resident_set_size(); |
353b0b11 FG |
760 | let dur = info.start_time.elapsed(); |
761 | print_time_passes_entry(&info.message, dur, info.start_rss, end_rss, info.format); | |
74b04a01 | 762 | } |
dfeec247 XL |
763 | } |
764 | } | |
765 | ||
49aad941 FG |
766 | struct JsonTimePassesEntry<'a> { |
767 | pass: &'a str, | |
768 | time: f64, | |
769 | start_rss: Option<usize>, | |
770 | end_rss: Option<usize>, | |
771 | } | |
772 | ||
773 | impl Display for JsonTimePassesEntry<'_> { | |
774 | fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { | |
775 | let Self { pass: what, time, start_rss, end_rss } = self; | |
776 | write!(f, r#"{{"pass":"{what}","time":{time},"rss_start":"#).unwrap(); | |
777 | match start_rss { | |
778 | Some(rss) => write!(f, "{rss}")?, | |
779 | None => write!(f, "null")?, | |
780 | } | |
781 | write!(f, r#","rss_end":"#)?; | |
782 | match end_rss { | |
783 | Some(rss) => write!(f, "{rss}")?, | |
784 | None => write!(f, "null")?, | |
785 | } | |
786 | write!(f, "}}")?; | |
787 | Ok(()) | |
788 | } | |
789 | } | |
790 | ||
5869c6ff XL |
791 | pub fn print_time_passes_entry( |
792 | what: &str, | |
793 | dur: Duration, | |
794 | start_rss: Option<usize>, | |
795 | end_rss: Option<usize>, | |
353b0b11 | 796 | format: TimePassesFormat, |
5869c6ff | 797 | ) { |
353b0b11 FG |
798 | match format { |
799 | TimePassesFormat::Json => { | |
49aad941 FG |
800 | let entry = |
801 | JsonTimePassesEntry { pass: what, time: dur.as_secs_f64(), start_rss, end_rss }; | |
802 | ||
803 | eprintln!(r#"time: {entry}"#); | |
353b0b11 FG |
804 | return; |
805 | } | |
806 | TimePassesFormat::Text => (), | |
807 | } | |
808 | ||
2b03887a FG |
809 | // Print the pass if its duration is greater than 5 ms, or it changed the |
810 | // measured RSS. | |
811 | let is_notable = || { | |
812 | if dur.as_millis() > 5 { | |
813 | return true; | |
814 | } | |
815 | ||
816 | if let (Some(start_rss), Some(end_rss)) = (start_rss, end_rss) { | |
817 | let change_rss = end_rss.abs_diff(start_rss); | |
818 | if change_rss > 0 { | |
819 | return true; | |
820 | } | |
821 | } | |
822 | ||
823 | false | |
824 | }; | |
825 | if !is_notable() { | |
826 | return; | |
827 | } | |
828 | ||
5869c6ff XL |
829 | let rss_to_mb = |rss| (rss as f64 / 1_000_000.0).round() as usize; |
830 | let rss_change_to_mb = |rss| (rss as f64 / 1_000_000.0).round() as i128; | |
831 | ||
832 | let mem_string = match (start_rss, end_rss) { | |
833 | (Some(start_rss), Some(end_rss)) => { | |
834 | let change_rss = end_rss as i128 - start_rss as i128; | |
835 | ||
836 | format!( | |
837 | "; rss: {:>4}MB -> {:>4}MB ({:>+5}MB)", | |
838 | rss_to_mb(start_rss), | |
839 | rss_to_mb(end_rss), | |
840 | rss_change_to_mb(change_rss), | |
841 | ) | |
dfeec247 | 842 | } |
5869c6ff XL |
843 | (Some(start_rss), None) => format!("; rss start: {:>4}MB", rss_to_mb(start_rss)), |
844 | (None, Some(end_rss)) => format!("; rss end: {:>4}MB", rss_to_mb(end_rss)), | |
845 | (None, None) => String::new(), | |
dfeec247 | 846 | }; |
5869c6ff | 847 | |
6a06907d | 848 | eprintln!("time: {:>7}{}\t{}", duration_to_secs_str(dur), mem_string, what); |
dfeec247 XL |
849 | } |
850 | ||
851 | // Hack up our own formatting for the duration to make it easier for scripts | |
852 | // to parse (always use the same number of decimal places and the same unit). | |
853 | pub fn duration_to_secs_str(dur: std::time::Duration) -> String { | |
1b1a35ee | 854 | format!("{:.3}", dur.as_secs_f64()) |
dfeec247 XL |
855 | } |
856 | ||
3c0e092e XL |
857 | fn get_thread_id() -> u32 { |
858 | std::thread::current().id().as_u64().get() as u32 | |
859 | } | |
860 | ||
dfeec247 | 861 | // Memory reporting |
f9f354fc XL |
862 | cfg_if! { |
863 | if #[cfg(windows)] { | |
5869c6ff | 864 | pub fn get_resident_set_size() -> Option<usize> { |
353b0b11 FG |
865 | use std::mem; |
866 | ||
867 | use windows::{ | |
49aad941 FG |
868 | // FIXME: change back to K32GetProcessMemoryInfo when windows crate |
869 | // updated to 0.49.0+ to drop dependency on psapi.dll | |
870 | Win32::System::ProcessStatus::{GetProcessMemoryInfo, PROCESS_MEMORY_COUNTERS}, | |
353b0b11 FG |
871 | Win32::System::Threading::GetCurrentProcess, |
872 | }; | |
873 | ||
874 | let mut pmc = PROCESS_MEMORY_COUNTERS::default(); | |
875 | let pmc_size = mem::size_of_val(&pmc); | |
876 | unsafe { | |
49aad941 | 877 | GetProcessMemoryInfo( |
353b0b11 FG |
878 | GetCurrentProcess(), |
879 | &mut pmc, | |
880 | pmc_size as u32, | |
881 | ) | |
f9f354fc | 882 | } |
353b0b11 FG |
883 | .ok() |
884 | .ok()?; | |
885 | ||
886 | Some(pmc.WorkingSetSize) | |
f9f354fc | 887 | } |
064997fb FG |
888 | } else if #[cfg(target_os = "macos")] { |
889 | pub fn get_resident_set_size() -> Option<usize> { | |
890 | use libc::{c_int, c_void, getpid, proc_pidinfo, proc_taskinfo, PROC_PIDTASKINFO}; | |
891 | use std::mem; | |
892 | const PROC_TASKINFO_SIZE: c_int = mem::size_of::<proc_taskinfo>() as c_int; | |
893 | ||
894 | unsafe { | |
895 | let mut info: proc_taskinfo = mem::zeroed(); | |
896 | let info_ptr = &mut info as *mut proc_taskinfo as *mut c_void; | |
897 | let pid = getpid() as c_int; | |
898 | let ret = proc_pidinfo(pid, PROC_PIDTASKINFO, 0, info_ptr, PROC_TASKINFO_SIZE); | |
899 | if ret == PROC_TASKINFO_SIZE { | |
900 | Some(info.pti_resident_size as usize) | |
901 | } else { | |
902 | None | |
903 | } | |
904 | } | |
905 | } | |
f9f354fc | 906 | } else if #[cfg(unix)] { |
5869c6ff | 907 | pub fn get_resident_set_size() -> Option<usize> { |
f9f354fc XL |
908 | let field = 1; |
909 | let contents = fs::read("/proc/self/statm").ok()?; | |
910 | let contents = String::from_utf8(contents).ok()?; | |
911 | let s = contents.split_whitespace().nth(field)?; | |
912 | let npages = s.parse::<usize>().ok()?; | |
913 | Some(npages * 4096) | |
914 | } | |
915 | } else { | |
5869c6ff | 916 | pub fn get_resident_set_size() -> Option<usize> { |
f9f354fc | 917 | None |
dfeec247 XL |
918 | } |
919 | } | |
b7449926 | 920 | } |
49aad941 FG |
921 | |
922 | #[cfg(test)] | |
923 | mod tests; |