Auto merge of #86619 - rylev:incr-hashing-profiling, r=wesleywiser

Profile incremental compilation hashing fingerprints

Adds profiling instrumentation for the hashing of incremental compilation fingerprints per query.

This will eventually feed into the `measureme` and `rustc-perf` infrastructure for tracking if computing hashes changes over time.

TODOs:
* [x] Address the FIXME where we are including node interning in the hash timing.
* [ ] Update measureme/summarize to handle this new data: rust-lang/measureme#166
* [ ] ~Update rustc-perf to handle the new data from measureme~ (will be done at a later time)

r? `@ghost`

cc `@michaelwoerister`

Author: bors

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_id(&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,14 @@ impl SelfProfilerRef {
         }
     }
 
+    /// 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<StringId> {
+        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 +422,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 +443,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 +488,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,
         })

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,12 @@ pub struct DepGraph<K: DepKind> {
     /// each task has a `DepNodeIndex` that uniquely identifies it. This unique
     /// ID is used for self-profiling.
     virtual_dep_node_index: Lrc<AtomicU32>,
+
+    /// 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<EventId>,
 }
 
 rustc_index::newtype_index! {
@@ -130,6 +135,10 @@ impl<K: DepKind> DepGraph<K> {
         );
         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 +150,16 @@ impl<K: DepKind> DepGraph<K> {
                 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<K> {
-        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 +258,15 @@ impl<K: DepKind> DepGraph<K> {
             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_id(eid));
             // Intern the new `DepNode`.
             let (dep_node_index, prev_and_color) = data.current.intern_node(
                 dcx.profiler(),
@@ -257,6 +276,9 @@ impl<K: DepKind> DepGraph<K> {
                 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!(

compiler/rustc_session/src/options.rs

@@ -1250,7 +1250,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<bool> = (None, parse_opt_bool, [TRACKED],
         "make the current crate share its generic instantiations"),
     show_span: Option<String> = (None, parse_opt_string, [TRACKED],