From 6e33dce9c2d549f0c32f7940ffccd0f0de8af74e Mon Sep 17 00:00:00 2001 From: Ryan Levick Date: Fri, 25 Jun 2021 13:17:52 +0200 Subject: [PATCH 1/2] Profile incremental hashing --- .../rustc_data_structures/src/profiling.rs | 56 +++++++++++++++---- .../rustc_query_system/src/dep_graph/graph.rs | 27 ++++++++- compiler/rustc_session/src/options.rs | 2 +- 3 files changed, 70 insertions(+), 15 deletions(-) diff --git a/compiler/rustc_data_structures/src/profiling.rs b/compiler/rustc_data_structures/src/profiling.rs index 51f851dc9469f..531214bc40e64 100644 --- a/compiler/rustc_data_structures/src/profiling.rs +++ b/compiler/rustc_data_structures/src/profiling.rs @@ -94,31 +94,34 @@ use std::process; use std::sync::Arc; use std::time::{Duration, Instant}; -use measureme::{EventId, EventIdBuilder, Profiler, SerializableString, StringId}; +pub use measureme::EventId; +use measureme::{EventIdBuilder, Profiler, SerializableString, StringId}; use parking_lot::RwLock; bitflags::bitflags! { struct EventFilter: u32 { - const GENERIC_ACTIVITIES = 1 << 0; - const QUERY_PROVIDERS = 1 << 1; - const QUERY_CACHE_HITS = 1 << 2; - const QUERY_BLOCKED = 1 << 3; - const INCR_CACHE_LOADS = 1 << 4; + const GENERIC_ACTIVITIES = 1 << 0; + const QUERY_PROVIDERS = 1 << 1; + const QUERY_CACHE_HITS = 1 << 2; + const QUERY_BLOCKED = 1 << 3; + const INCR_CACHE_LOADS = 1 << 4; - const QUERY_KEYS = 1 << 5; - const FUNCTION_ARGS = 1 << 6; - const LLVM = 1 << 7; + const QUERY_KEYS = 1 << 5; + const FUNCTION_ARGS = 1 << 6; + const LLVM = 1 << 7; + const INCR_RESULT_HASHING = 1 << 8; const DEFAULT = Self::GENERIC_ACTIVITIES.bits | Self::QUERY_PROVIDERS.bits | Self::QUERY_BLOCKED.bits | - Self::INCR_CACHE_LOADS.bits; + Self::INCR_CACHE_LOADS.bits | + Self::INCR_RESULT_HASHING.bits; const ARGS = Self::QUERY_KEYS.bits | Self::FUNCTION_ARGS.bits; } } -// keep this in sync with the `-Z self-profile-events` help message in librustc_session/options.rs +// keep this in sync with the `-Z self-profile-events` help message in rustc_session/options.rs const EVENT_FILTERS_BY_NAME: &[(&str, EventFilter)] = &[ ("none", EventFilter::empty()), ("all", EventFilter::all()), @@ -132,6 +135,7 @@ const EVENT_FILTERS_BY_NAME: &[(&str, EventFilter)] = &[ ("function-args", EventFilter::FUNCTION_ARGS), ("args", EventFilter::ARGS), ("llvm", EventFilter::LLVM), + ("incr-result-hashing", EventFilter::INCR_RESULT_HASHING), ]; /// Something that uniquely identifies a query invocation. @@ -248,6 +252,15 @@ impl SelfProfilerRef { }) } + /// Start profiling with some event filter for a given event. Profiling continues until the + /// TimingGuard returned from this call is dropped. + #[inline(always)] + pub fn generic_activity_with_event(&self, event_id: EventId) -> TimingGuard<'_> { + self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| { + TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id) + }) + } + /// Start profiling a generic activity. Profiling continues until the /// TimingGuard returned from this call is dropped. #[inline(always)] @@ -337,6 +350,19 @@ impl SelfProfilerRef { }) } + /// Start profiling how long it takes to hash query results for incremental compilation. + /// Profiling continues until the TimingGuard returned from this call is dropped. + #[inline(always)] + pub fn incr_result_hashing(&self) -> TimingGuard<'_> { + self.exec(EventFilter::INCR_RESULT_HASHING, |profiler| { + TimingGuard::start( + profiler, + profiler.incremental_result_hashing_event_kind, + EventId::INVALID, + ) + }) + } + #[inline(always)] fn instant_query_event( &self, @@ -364,6 +390,10 @@ impl SelfProfilerRef { } } + pub fn get_or_alloc_cached_string(&self, s: &'static str) -> Option { + self.profiler.as_ref().map(|p| p.get_or_alloc_cached_string(s)) + } + #[inline] pub fn enabled(&self) -> bool { self.profiler.is_some() @@ -388,6 +418,7 @@ pub struct SelfProfiler { query_event_kind: StringId, generic_activity_event_kind: StringId, incremental_load_result_event_kind: StringId, + incremental_result_hashing_event_kind: StringId, query_blocked_event_kind: StringId, query_cache_hit_event_kind: StringId, } @@ -408,6 +439,8 @@ impl SelfProfiler { let query_event_kind = profiler.alloc_string("Query"); let generic_activity_event_kind = profiler.alloc_string("GenericActivity"); let incremental_load_result_event_kind = profiler.alloc_string("IncrementalLoadResult"); + let incremental_result_hashing_event_kind = + profiler.alloc_string("IncrementalResultHashing"); let query_blocked_event_kind = profiler.alloc_string("QueryBlocked"); let query_cache_hit_event_kind = profiler.alloc_string("QueryCacheHit"); @@ -451,6 +484,7 @@ impl SelfProfiler { query_event_kind, generic_activity_event_kind, incremental_load_result_event_kind, + incremental_result_hashing_event_kind, query_blocked_event_kind, query_cache_hit_event_kind, }) diff --git a/compiler/rustc_query_system/src/dep_graph/graph.rs b/compiler/rustc_query_system/src/dep_graph/graph.rs index 71e67dfee538b..d629fc2aa81d1 100644 --- a/compiler/rustc_query_system/src/dep_graph/graph.rs +++ b/compiler/rustc_query_system/src/dep_graph/graph.rs @@ -1,7 +1,6 @@ use rustc_data_structures::fingerprint::Fingerprint; use rustc_data_structures::fx::{FxHashMap, FxHashSet}; -use rustc_data_structures::profiling::QueryInvocationId; -use rustc_data_structures::profiling::SelfProfilerRef; +use rustc_data_structures::profiling::{EventId, QueryInvocationId, SelfProfilerRef}; use rustc_data_structures::sharded::{self, Sharded}; use rustc_data_structures::stable_hasher::{HashStable, StableHasher}; use rustc_data_structures::steal::Steal; @@ -36,6 +35,11 @@ pub struct DepGraph { /// each task has a `DepNodeIndex` that uniquely identifies it. This unique /// ID is used for self-profiling. virtual_dep_node_index: Lrc, + + /// The cached event id for profiling node interning. This saves us + /// from having to look up the event id every time we intern a node + /// which may incur too much overhead. + node_intern_event_id: Option, } rustc_index::newtype_index! { @@ -130,6 +134,10 @@ impl DepGraph { ); debug_assert_eq!(_green_node_index, DepNodeIndex::SINGLETON_DEPENDENCYLESS_ANON_NODE); + let node_intern_event_id = profiler + .get_or_alloc_cached_string("incr_comp_intern_dep_graph_node") + .map(EventId::from_label); + DepGraph { data: Some(Lrc::new(DepGraphData { previous_work_products: prev_work_products, @@ -141,11 +149,16 @@ impl DepGraph { colors: DepNodeColorMap::new(prev_graph_node_count), })), virtual_dep_node_index: Lrc::new(AtomicU32::new(0)), + node_intern_event_id, } } pub fn new_disabled() -> DepGraph { - DepGraph { data: None, virtual_dep_node_index: Lrc::new(AtomicU32::new(0)) } + DepGraph { + data: None, + virtual_dep_node_index: Lrc::new(AtomicU32::new(0)), + node_intern_event_id: None, + } } /// Returns `true` if we are actually building the full dep-graph, and `false` otherwise. @@ -244,10 +257,15 @@ impl DepGraph { let edges = task_deps.map_or_else(|| smallvec![], |lock| lock.into_inner().reads); let mut hcx = dcx.create_stable_hashing_context(); + let hashing_timer = dcx.profiler().incr_result_hashing(); let current_fingerprint = hash_result(&mut hcx, &result); let print_status = cfg!(debug_assertions) && dcx.sess().opts.debugging_opts.dep_tasks; + // Get timer for profiling `DepNode` interning + let node_intern_timer = self + .node_intern_event_id + .map(|eid| dcx.profiler().generic_activity_with_event(eid)); // Intern the new `DepNode`. let (dep_node_index, prev_and_color) = data.current.intern_node( dcx.profiler(), @@ -257,6 +275,9 @@ impl DepGraph { current_fingerprint, print_status, ); + drop(node_intern_timer); + + hashing_timer.finish_with_query_invocation_id(dep_node_index.into()); if let Some((prev_index, color)) = prev_and_color { debug_assert!( diff --git a/compiler/rustc_session/src/options.rs b/compiler/rustc_session/src/options.rs index 4c40d0c367eca..a95b7ff96ee5c 100644 --- a/compiler/rustc_session/src/options.rs +++ b/compiler/rustc_session/src/options.rs @@ -1249,7 +1249,7 @@ options! { "specify the events recorded by the self profiler; for example: `-Z self-profile-events=default,query-keys` all options: none, all, default, generic-activity, query-provider, query-cache-hit - query-blocked, incr-cache-load, query-keys, function-args, args, llvm"), + query-blocked, incr-cache-load, incr-result-hashing, query-keys, function-args, args, llvm"), share_generics: Option = (None, parse_opt_bool, [TRACKED], "make the current crate share its generic instantiations"), show_span: Option = (None, parse_opt_string, [TRACKED], From b5bec171841ef35d9f29a58ec567c734348118d0 Mon Sep 17 00:00:00 2001 From: Ryan Levick Date: Wed, 7 Jul 2021 11:13:46 +0200 Subject: [PATCH 2/2] Add docs to new methods --- compiler/rustc_data_structures/src/profiling.rs | 8 ++++++-- compiler/rustc_query_system/src/dep_graph/graph.rs | 3 ++- 2 files changed, 8 insertions(+), 3 deletions(-) diff --git a/compiler/rustc_data_structures/src/profiling.rs b/compiler/rustc_data_structures/src/profiling.rs index 531214bc40e64..ef101c56ab578 100644 --- a/compiler/rustc_data_structures/src/profiling.rs +++ b/compiler/rustc_data_structures/src/profiling.rs @@ -255,7 +255,7 @@ impl SelfProfilerRef { /// Start profiling with some event filter for a given event. Profiling continues until the /// TimingGuard returned from this call is dropped. #[inline(always)] - pub fn generic_activity_with_event(&self, event_id: EventId) -> TimingGuard<'_> { + pub fn generic_activity_with_event_id(&self, event_id: EventId) -> TimingGuard<'_> { self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| { TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id) }) @@ -390,7 +390,11 @@ impl SelfProfilerRef { } } - pub fn get_or_alloc_cached_string(&self, s: &'static str) -> Option { + /// Gets a `StringId` for the given string. This method makes sure that + /// any strings going through it will only be allocated once in the + /// profiling data. + /// Returns `None` if the self-profiling is not enabled. + pub fn get_or_alloc_cached_string(&self, s: &str) -> Option { self.profiler.as_ref().map(|p| p.get_or_alloc_cached_string(s)) } diff --git a/compiler/rustc_query_system/src/dep_graph/graph.rs b/compiler/rustc_query_system/src/dep_graph/graph.rs index d629fc2aa81d1..c8a46e974f305 100644 --- a/compiler/rustc_query_system/src/dep_graph/graph.rs +++ b/compiler/rustc_query_system/src/dep_graph/graph.rs @@ -39,6 +39,7 @@ pub struct DepGraph { /// The cached event id for profiling node interning. This saves us /// from having to look up the event id every time we intern a node /// which may incur too much overhead. + /// This will be None if self-profiling is disabled. node_intern_event_id: Option, } @@ -265,7 +266,7 @@ impl DepGraph { // Get timer for profiling `DepNode` interning let node_intern_timer = self .node_intern_event_id - .map(|eid| dcx.profiler().generic_activity_with_event(eid)); + .map(|eid| dcx.profiler().generic_activity_with_event_id(eid)); // Intern the new `DepNode`. let (dep_node_index, prev_and_color) = data.current.intern_node( dcx.profiler(),