]>
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; | |
89 | use std::convert::Into; | |
48663c56 | 90 | use std::error::Error; |
dc9dc135 | 91 | use std::fs; |
dc9dc135 | 92 | use std::path::Path; |
532ac7d7 | 93 | use std::process; |
e74abb32 | 94 | use std::sync::Arc; |
dfeec247 | 95 | use std::time::{Duration, Instant}; |
b7449926 | 96 | |
136023e0 XL |
97 | pub use measureme::EventId; |
98 | use measureme::{EventIdBuilder, Profiler, SerializableString, StringId}; | |
dfeec247 | 99 | use parking_lot::RwLock; |
48663c56 | 100 | |
60c5eb7d | 101 | bitflags::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 | 125 | const 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. |
142 | pub 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)] | |
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, | |
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 | ||
164 | impl 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 | 416 | pub 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 | ||
430 | impl 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 | 555 | pub struct TimingGuard<'a>(Option<measureme::TimingGuard<'a>>); |
9fa01778 | 556 | |
e74abb32 | 557 | impl<'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] | |
595 | pub struct VerboseTimingGuard<'a> { | |
5869c6ff | 596 | start_and_message: Option<(Instant, Option<usize>, String)>, |
dfeec247 XL |
597 | _guard: TimingGuard<'a>, |
598 | } | |
599 | ||
600 | impl<'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 | ||
615 | impl 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 |
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 | ) | |
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). | |
654 | pub 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 |
659 | cfg_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 | } |