Change implementation of query cache hit counts

Author: Kobzol

compiler/rustc_data_structures/src/profiling.rs

@@ -88,12 +88,14 @@ use std::fmt::Display;
 use std::intrinsics::unlikely;
 use std::path::Path;
 use std::sync::Arc;
+use std::sync::atomic::{AtomicU64, Ordering};
 use std::time::{Duration, Instant};
 use std::{fs, process};
 
 pub use measureme::EventId;
 use measureme::{EventIdBuilder, Profiler, SerializableString, StringId};
 use parking_lot::RwLock;
+use rustc_index::Idx;
 use smallvec::SmallVec;
 use tracing::warn;
 
@@ -117,6 +119,7 @@ bitflags::bitflags! {
 
         const DEFAULT = Self::GENERIC_ACTIVITIES.bits() |
                         Self::QUERY_PROVIDERS.bits() |
+                        Self::QUERY_CACHE_HITS.bits() |
                         Self::QUERY_BLOCKED.bits() |
                         Self::INCR_CACHE_LOADS.bits() |
                         Self::INCR_RESULT_HASHING.bits() |
@@ -145,8 +148,20 @@ const EVENT_FILTERS_BY_NAME: &[(&str, EventFilter)] = &[
 ];
 
 /// Something that uniquely identifies a query invocation.
+#[derive(PartialEq, Eq, Hash, Copy, Clone, Debug)]
 pub struct QueryInvocationId(pub u32);
 
+impl Idx for QueryInvocationId {
+    #[inline]
+    fn new(idx: usize) -> Self {
+        Self(idx as u32)
+    }
+    #[inline]
+    fn index(self) -> usize {
+        self.0 as usize
+    }
+}
+
 /// Which format to use for `-Z time-passes`
 #[derive(Clone, Copy, PartialEq, Hash, Debug)]
 pub enum TimePassesFormat {
@@ -411,10 +426,7 @@ impl SelfProfilerRef {
         #[inline(never)]
         #[cold]
         fn cold_call(profiler_ref: &SelfProfilerRef, query_invocation_id: QueryInvocationId) {
-            profiler_ref.instant_query_event(
-                |profiler| profiler.query_cache_hit_event_kind,
-                query_invocation_id,
-            );
+            profiler_ref.profiler.as_ref().unwrap().increment_query_cache_hit(query_invocation_id);
         }
 
         if unlikely(self.event_filter_mask.contains(EventFilter::QUERY_CACHE_HITS)) {
@@ -459,22 +471,6 @@ impl SelfProfilerRef {
         })
     }
 
-    #[inline(always)]
-    fn instant_query_event(
-        &self,
-        event_kind: fn(&SelfProfiler) -> StringId,
-        query_invocation_id: QueryInvocationId,
-    ) {
-        let event_id = StringId::new_virtual(query_invocation_id.0);
-        let thread_id = get_thread_id();
-        let profiler = self.profiler.as_ref().unwrap();
-        profiler.profiler.record_instant_event(
-            event_kind(profiler),
-            EventId::from_virtual(event_id),
-            thread_id,
-        );
-    }
-
     pub fn with_profiler(&self, f: impl FnOnce(&SelfProfiler)) {
         if let Some(profiler) = &self.profiler {
             f(profiler)
@@ -489,6 +485,30 @@ impl SelfProfilerRef {
         self.profiler.as_ref().map(|p| p.get_or_alloc_cached_string(s))
     }
 
+    /// Store query cache hits to the self-profile log.
+    /// Should be called once at the end of the compilation session.
+    ///
+    /// The cache hits are stored per **query invocation**, not **per query kind/type**.
+    /// `analyzeme` can later deduplicate individual query labels from the QueryInvocationId event
+    /// IDs.
+    pub fn store_query_cache_hits(&self) {
+        if self.event_filter_mask.contains(EventFilter::QUERY_CACHE_HITS) {
+            let profiler = self.profiler.as_ref().unwrap();
+            let query_hits = profiler.query_hits.read();
+            let builder = EventIdBuilder::new(&profiler.profiler);
+            let thread_id = get_thread_id();
+            for (query_invocation, hit_count) in query_hits.iter().enumerate() {
+                let event_id = builder.from_label(StringId::new_virtual(query_invocation as u64));
+                profiler.profiler.record_integer_event(
+                    profiler.query_cache_hit_count_event_kind,
+                    event_id,
+                    thread_id,
+                    hit_count.load(Ordering::Relaxed),
+                );
+            }
+        }
+    }
+
     #[inline]
     pub fn enabled(&self) -> bool {
         self.profiler.is_some()
@@ -537,13 +557,27 @@ pub struct SelfProfiler {
 
     string_cache: RwLock<FxHashMap<String, StringId>>,
 
+    /// Recording individual query cache hits as "instant" measureme events
+    /// is incredibly expensive. Instead of doing that, we simply aggregate
+    /// cache hit *counts* per query invocation, and then store the final count
+    /// of cache hits per invocation at the end of the compilation session.
+    ///
+    /// With this approach, we don't know the individual thread IDs and timestamps
+    /// of cache hits, but it has very little overhead on top of `-Zself-profile`.
+    /// Recording the cache hits as individual events made compilation 3-5x slower.
+    ///
+    /// Query invocation IDs should be monotonic integers, so we can store them in a vec,
+    /// rather than using a hashmap.
+    query_hits: RwLock<Vec<AtomicU64>>,
+
     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,
     artifact_size_event_kind: StringId,
+    /// Total cache hits per query invocation
+    query_cache_hit_count_event_kind: StringId,
 }
 
 impl SelfProfiler {
@@ -571,8 +605,8 @@ impl SelfProfiler {
         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");
         let artifact_size_event_kind = profiler.alloc_string("ArtifactSize");
+        let query_cache_hit_count_event_kind = profiler.alloc_string("QueryCacheHitCount");
 
         let mut event_filter_mask = EventFilter::empty();
 
@@ -616,8 +650,9 @@ impl SelfProfiler {
             incremental_load_result_event_kind,
             incremental_result_hashing_event_kind,
             query_blocked_event_kind,
-            query_cache_hit_event_kind,
             artifact_size_event_kind,
+            query_cache_hit_count_event_kind,
+            query_hits: Default::default(),
         })
     }
 
@@ -627,6 +662,25 @@ impl SelfProfiler {
         self.profiler.alloc_string(s)
     }
 
+    /// Store a cache hit of a query invocation
+    pub fn increment_query_cache_hit(&self, id: QueryInvocationId) {
+        // Fast path: assume that the query was already encountered before, and just record
+        // a cache hit.
+        let mut guard = self.query_hits.upgradable_read();
+        let query_hits = &guard;
+        let index = id.0 as usize;
+        if index < query_hits.len() {
+            // We only want to increment the count, no other synchronization is required
+            query_hits[index].fetch_add(1, Ordering::Relaxed);
+        } else {
+            // If not, we need to extend the query hit map to the highest observed ID
+            guard.with_upgraded(|vec| {
+                vec.resize_with(index + 1, || AtomicU64::new(0));
+                vec[index] = AtomicU64::from(1);
+            });
+        }
+    }
+
     /// 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.

compiler/rustc_query_impl/src/profiling_support.rs

@@ -259,4 +259,5 @@ pub fn alloc_self_profile_query_strings(tcx: TyCtxt<'_>) {
     for alloc in super::ALLOC_SELF_PROFILE_QUERY_STRINGS.iter() {
         alloc(tcx, &mut string_cache)
     }
+    tcx.sess.prof.store_query_cache_hits();
 }