From 5bb96edbb29fb579cfe42d3da77f63630f43106f Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Sun, 27 Jan 2019 13:52:17 -0500 Subject: [PATCH 1/3] Implement more detailed self profiling Timing data and cache hits/misses are now recorded at the query level. This allows us to show detailed per query information such as total time for each query. To see detailed query information in the summary pass the `-Z verbose` flag. For example: ``` rustc -Z self-profile -Z verbose hello_world.rs ``` --- src/librustc/ty/query/plumbing.rs | 19 +- src/librustc/util/profiling.rs | 508 ++++++++++++++++++++---------- 2 files changed, 345 insertions(+), 182 deletions(-) diff --git a/src/librustc/ty/query/plumbing.rs b/src/librustc/ty/query/plumbing.rs index a26b21a1059fe..8e80f95aba102 100644 --- a/src/librustc/ty/query/plumbing.rs +++ b/src/librustc/ty/query/plumbing.rs @@ -113,7 +113,7 @@ impl<'a, 'tcx, Q: QueryDescription<'tcx>> JobOwner<'a, 'tcx, Q> { let mut lock = cache.borrow_mut(); if let Some(value) = lock.results.get(key) { profq_msg!(tcx, ProfileQueriesMsg::CacheHit); - tcx.sess.profiler(|p| p.record_query_hit(Q::CATEGORY)); + tcx.sess.profiler(|p| p.record_query_hit(Q::NAME, Q::CATEGORY)); let result = Ok((value.value.clone(), value.index)); #[cfg(debug_assertions)] { @@ -375,7 +375,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { if dep_node.kind.is_anon() { profq_msg!(self, ProfileQueriesMsg::ProviderBegin); - self.sess.profiler(|p| p.start_activity(Q::CATEGORY)); + self.sess.profiler(|p| p.start_query(Q::NAME, Q::CATEGORY)); let ((result, dep_node_index), diagnostics) = with_diagnostics(|diagnostics| { job.start(self, diagnostics, |tcx| { @@ -385,7 +385,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { }) }); - self.sess.profiler(|p| p.end_activity(Q::CATEGORY)); + self.sess.profiler(|p| p.end_query(Q::NAME, Q::CATEGORY)); profq_msg!(self, ProfileQueriesMsg::ProviderEnd); self.dep_graph.read_index(dep_node_index); @@ -452,14 +452,14 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { let result = if let Some(result) = result { profq_msg!(self, ProfileQueriesMsg::CacheHit); - self.sess.profiler(|p| p.record_query_hit(Q::CATEGORY)); + self.sess.profiler(|p| p.record_query_hit(Q::NAME, Q::CATEGORY)); result } else { // We could not load a result from the on-disk cache, so // recompute. - self.sess.profiler(|p| p.start_activity(Q::CATEGORY)); + self.sess.profiler(|p| p.start_query(Q::NAME, Q::CATEGORY)); // The diagnostics for this query have already been // promoted to the current session during @@ -472,7 +472,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { }) }); - self.sess.profiler(|p| p.end_activity(Q::CATEGORY)); + self.sess.profiler(|p| p.end_query(Q::NAME, Q::CATEGORY)); result }; @@ -541,7 +541,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { key, dep_node); profq_msg!(self, ProfileQueriesMsg::ProviderBegin); - self.sess.profiler(|p| p.start_activity(Q::CATEGORY)); + self.sess.profiler(|p| p.start_query(Q::NAME, Q::CATEGORY)); let ((result, dep_node_index), diagnostics) = with_diagnostics(|diagnostics| { job.start(self, diagnostics, |tcx| { @@ -559,7 +559,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { }) }); - self.sess.profiler(|p| p.end_activity(Q::CATEGORY)); + self.sess.profiler(|p| p.end_query(Q::NAME, Q::CATEGORY)); profq_msg!(self, ProfileQueriesMsg::ProviderEnd); if unlikely!(self.sess.opts.debugging_opts.query_dep_graph) { @@ -602,7 +602,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { let _ = self.get_query::(DUMMY_SP, key); } else { profq_msg!(self, ProfileQueriesMsg::CacheHit); - self.sess.profiler(|p| p.record_query_hit(Q::CATEGORY)); + self.sess.profiler(|p| p.record_query_hit(Q::NAME, Q::CATEGORY)); } } @@ -729,6 +729,7 @@ macro_rules! define_queries_inner { sess.profiler(|p| { $( p.record_computed_queries( + as QueryConfig<'_>>::NAME, as QueryConfig<'_>>::CATEGORY, self.$name.lock().results.len() ); diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index 0e03946f82a5c..2cec7ec65afc6 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -1,146 +1,167 @@ -use crate::session::config::Options; - +use std::collections::{BTreeMap, HashMap}; use std::fs; -use std::io::{self, StderrLock, Write}; +use std::io::{self, Write}; +use std::thread::ThreadId; use std::time::Instant; -macro_rules! define_categories { - ($($name:ident,)*) => { - #[derive(Clone, Copy, Debug, PartialEq, Eq)] - pub enum ProfileCategory { - $($name),* +use crate::session::config::{Options, OptLevel}; + +#[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)] +pub enum ProfileCategory { + Parsing, + Expansion, + TypeChecking, + BorrowChecking, + Codegen, + Linking, + Other, +} + +#[derive(Clone, Copy, Debug, Eq, PartialEq)] +pub enum ProfilerEvent { + QueryStart { query_name: &'static str, category: ProfileCategory, time: Instant }, + QueryEnd { query_name: &'static str, category: ProfileCategory, time: Instant }, + GenericActivityStart { category: ProfileCategory, time: Instant }, + GenericActivityEnd { category: ProfileCategory, time: Instant }, + QueryCacheHit { query_name: &'static str, category: ProfileCategory }, + QueryCount { query_name: &'static str, category: ProfileCategory, count: usize }, +} + +impl ProfilerEvent { + fn is_start_event(&self) -> bool { + use self::ProfilerEvent::*; + + match self { + QueryStart { .. } | GenericActivityStart { .. } => true, + QueryEnd { .. } | GenericActivityEnd { .. } | + QueryCacheHit { .. } | QueryCount { .. } => false, } + } +} - #[allow(nonstandard_style)] - struct Categories { - $($name: T),* +pub struct SelfProfiler { + events: HashMap>, +} + +struct CategoryResultData { + query_times: BTreeMap<&'static str, u64>, + query_cache_stats: BTreeMap<&'static str, (u64, u64)>, //(hits, total) +} + +impl CategoryResultData { + fn new() -> CategoryResultData { + CategoryResultData { + query_times: BTreeMap::new(), + query_cache_stats: BTreeMap::new(), } + } - impl Categories { - fn new() -> Categories { - Categories { - $($name: T::default()),* - } - } + fn total_time(&self) -> u64 { + let mut total = 0; + for (_, time) in &self.query_times { + total += time; } - impl Categories { - fn get(&self, category: ProfileCategory) -> &T { - match category { - $(ProfileCategory::$name => &self.$name),* - } - } + total + } - fn set(&mut self, category: ProfileCategory, value: T) { - match category { - $(ProfileCategory::$name => self.$name = value),* - } - } - } + fn total_cache_data(&self) -> (u64, u64) { + let (mut hits, mut total) = (0, 0); - struct CategoryData { - times: Categories, - query_counts: Categories<(u64, u64)>, + for (_, (h, t)) in &self.query_cache_stats { + hits += h; + total += t; } - impl CategoryData { - fn new() -> CategoryData { - CategoryData { - times: Categories::new(), - query_counts: Categories::new(), - } - } + (hits, total) + } +} - fn print(&self, lock: &mut StderrLock<'_>) { - writeln!(lock, "| Phase | Time (ms) \ - | Time (%) | Queries | Hits (%)") - .unwrap(); - writeln!(lock, "| ---------------- | -------------- \ - | -------- | -------------- | --------") - .unwrap(); - - let total_time = ($(self.times.$name + )* 0) as f32; - - $( - let (hits, computed) = self.query_counts.$name; - let total = hits + computed; - let (hits, total) = if total > 0 { - (format!("{:.2}", - (((hits as f32) / (total as f32)) * 100.0)), total.to_string()) - } else { - (String::new(), String::new()) - }; +impl Default for CategoryResultData { + fn default() -> CategoryResultData { + CategoryResultData::new() + } +} - writeln!( - lock, - "| {0: <16} | {1: <14} | {2: <8.2} | {3: <14} | {4: <8}", - stringify!($name), - self.times.$name / 1_000_000, - ((self.times.$name as f32) / total_time) * 100.0, - total, - hits, - ).unwrap(); - )* - } +struct CalculatedResults { + categories: BTreeMap, + crate_name: Option, + optimization_level: OptLevel, + incremental: bool, + verbose: bool, +} - fn json(&self) -> String { - let mut json = String::from("["); - - $( - let (hits, computed) = self.query_counts.$name; - let total = hits + computed; - - //normalize hits to 0% - let hit_percent = - if total > 0 { - ((hits as f32) / (total as f32)) * 100.0 - } else { - 0.0 - }; - - json.push_str(&format!( - "{{ \"category\": \"{}\", \"time_ms\": {},\ - \"query_count\": {}, \"query_hits\": {} }},", - stringify!($name), - self.times.$name / 1_000_000, - total, - format!("{:.2}", hit_percent) - )); - )* +impl CalculatedResults { + fn new() -> CalculatedResults { + CalculatedResults { + categories: BTreeMap::new(), + crate_name: None, + optimization_level: OptLevel::No, + incremental: false, + verbose: false, + } + } - //remove the trailing ',' character - json.pop(); + fn consolidate(mut cr1: CalculatedResults, cr2: CalculatedResults) -> CalculatedResults { + for (category, data) in cr2.categories { + let cr1_data = cr1.categories.entry(category).or_default(); - json.push(']'); + for (query, time) in data.query_times { + *cr1_data.query_times.entry(query).or_default() += time; + } - json + for (query, (hits, total)) in data.query_cache_stats { + let (h, t) = cr1_data.query_cache_stats.entry(query).or_insert((0, 0)); + *h += hits; + *t += total; } } + + cr1 + } + + fn total_time(&self) -> u64 { + let mut total = 0; + + for (_, data) in &self.categories { + total += data.total_time(); + } + + total + } + + fn with_options(mut self, opts: &Options) -> CalculatedResults { + self.crate_name = opts.crate_name.clone(); + self.optimization_level = opts.optimize; + self.incremental = opts.incremental.is_some(); + self.verbose = opts.debugging_opts.verbose; + + self } } -define_categories! { - Parsing, - Expansion, - TypeChecking, - BorrowChecking, - Codegen, - Linking, - Other, +fn time_between_ns(start: Instant, end: Instant) -> u64 { + if start < end { + let time = end - start; + (time.as_secs() * 1_000_000_000) + (time.subsec_nanos() as u64) + } else { + debug!("time_between_ns: ignorning instance of end < start"); + 0 + } } -pub struct SelfProfiler { - timer_stack: Vec, - data: CategoryData, - current_timer: Instant, +fn calculate_percent(numerator: u64, denominator: u64) -> f32 { + if denominator > 0 { + ((numerator as f32) / (denominator as f32)) * 100.0 + } else { + 0.0 + } } impl SelfProfiler { pub fn new() -> SelfProfiler { let mut profiler = SelfProfiler { - timer_stack: Vec::new(), - data: CategoryData::new(), - current_timer: Instant::now(), + events: HashMap::new(), }; profiler.start_activity(ProfileCategory::Other); @@ -149,103 +170,244 @@ impl SelfProfiler { } pub fn start_activity(&mut self, category: ProfileCategory) { - match self.timer_stack.last().cloned() { - None => { - self.current_timer = Instant::now(); - }, - Some(current_category) if current_category == category => { - //since the current category is the same as the new activity's category, - //we don't need to do anything with the timer, we just need to push it on the stack - } - Some(current_category) => { - let elapsed = self.stop_timer(); + self.record(ProfilerEvent::GenericActivityStart { + category, + time: Instant::now(), + }) + } - //record the current category's time - let new_time = self.data.times.get(current_category) + elapsed; - self.data.times.set(current_category, new_time); - } - } + pub fn end_activity(&mut self, category: ProfileCategory) { + self.record(ProfilerEvent::GenericActivityEnd { + category, + time: Instant::now(), + }) + } - //push the new category - self.timer_stack.push(category); + pub fn record_computed_queries( + &mut self, + query_name: &'static str, + category: ProfileCategory, + count: usize) + { + self.record(ProfilerEvent::QueryCount { + query_name, + category, + count, + }) } - pub fn record_computed_queries(&mut self, category: ProfileCategory, count: usize) { - let (hits, computed) = *self.data.query_counts.get(category); - self.data.query_counts.set(category, (hits, computed + count as u64)); + pub fn record_query_hit(&mut self, query_name: &'static str, category: ProfileCategory) { + self.record(ProfilerEvent::QueryCacheHit { + query_name, + category, + }) } - pub fn record_query_hit(&mut self, category: ProfileCategory) { - let (hits, computed) = *self.data.query_counts.get(category); - self.data.query_counts.set(category, (hits + 1, computed)); + pub fn start_query(&mut self, query_name: &'static str, category: ProfileCategory) { + self.record(ProfilerEvent::QueryStart { + query_name, + category, + time: Instant::now(), + }); } - pub fn end_activity(&mut self, category: ProfileCategory) { - match self.timer_stack.pop() { - None => bug!("end_activity() was called but there was no running activity"), - Some(c) => - assert!( - c == category, - "end_activity() was called but a different activity was running"), + pub fn end_query(&mut self, query_name: &'static str, category: ProfileCategory) { + self.record(ProfilerEvent::QueryEnd { + query_name, + category, + time: Instant::now(), + }) + } + + fn record(&mut self, event: ProfilerEvent) { + let thread_id = std::thread::current().id(); + let events = self.events.entry(thread_id).or_default(); + + events.push(event); + } + + fn calculate_thread_results(events: &Vec) -> CalculatedResults { + use self::ProfilerEvent::*; + + assert!( + events.last().map(|e| !e.is_start_event()).unwrap_or(true), + "there was an event running when calculate_reslts() was called" + ); + + let mut results = CalculatedResults::new(); + + let mut query_stack = Vec::new(); + + for event in events { + match event { + QueryStart { .. } | GenericActivityStart { .. } => { + query_stack.push(event); + }, + QueryEnd { query_name, category, time: end_time } => { + let previous_query = query_stack.pop(); + if let Some(QueryStart { + query_name: p_query_name, + time: start_time, + category: _ }) = previous_query { + assert_eq!( + p_query_name, + query_name, + "Saw a query end but the previous query wasn't the corresponding start" + ); + + let time_ns = time_between_ns(*start_time, *end_time); + let result_data = results.categories.entry(*category).or_default(); + + *result_data.query_times.entry(query_name).or_default() += time_ns; + } else { + bug!("Saw a query end but the previous event wasn't a query start"); + } + } + GenericActivityEnd { category, time: end_time } => { + let previous_event = query_stack.pop(); + if let Some(GenericActivityStart { + category: previous_category, + time: start_time }) = previous_event { + assert_eq!( + previous_category, + category, + "Saw an end but the previous event wasn't the corresponding start" + ); + + let time_ns = time_between_ns(*start_time, *end_time); + let result_data = results.categories.entry(*category).or_default(); + + *result_data.query_times + .entry("{time spent not running queries}") + .or_default() += time_ns; + } else { + bug!("Saw an activity end but the previous event wasn't an activity start"); + } + }, + QueryCacheHit { category, query_name } => { + let result_data = results.categories.entry(*category).or_default(); + + let (hits, total) = + result_data.query_cache_stats.entry(query_name).or_insert((0, 0)); + *hits += 1; + *total += 1; + }, + QueryCount { category, query_name, count } => { + let result_data = results.categories.entry(*category).or_default(); + + let (_, totals) = + result_data.query_cache_stats.entry(query_name).or_insert((0, 0)); + *totals += *count as u64; + }, + } } - //check if the new running timer is in the same category as this one - //if it is, we don't need to do anything - if let Some(c) = self.timer_stack.last() { - if *c == category { - return; + //normalize the times to ms + for (_, data) in &mut results.categories { + for (_, time) in &mut data.query_times { + *time = *time / 1_000_000; } } - //the new timer is different than the previous, - //so record the elapsed time and start a new timer - let elapsed = self.stop_timer(); - let new_time = self.data.times.get(category) + elapsed; - self.data.times.set(category, new_time); + results } - fn stop_timer(&mut self) -> u64 { - let elapsed = self.current_timer.elapsed(); - - self.current_timer = Instant::now(); - - (elapsed.as_secs() * 1_000_000_000) + (elapsed.subsec_nanos() as u64) + fn get_results(&self, opts: &Options) -> CalculatedResults { + self.events + .iter() + .map(|(_, r)| SelfProfiler::calculate_thread_results(r)) + .fold(CalculatedResults::new(), CalculatedResults::consolidate) + .with_options(opts) } pub fn print_results(&mut self, opts: &Options) { self.end_activity(ProfileCategory::Other); - assert!( - self.timer_stack.is_empty(), - "there were timers running when print_results() was called"); + let results = self.get_results(opts); + + let total_time = results.total_time() as f32; let out = io::stderr(); let mut lock = out.lock(); - let crate_name = - opts.crate_name - .as_ref() - .map(|n| format!(" for {}", n)) - .unwrap_or_default(); + let crate_name = results.crate_name.map(|n| format!(" for {}", n)).unwrap_or_default(); writeln!(lock, "Self profiling results{}:", crate_name).unwrap(); writeln!(lock).unwrap(); - self.data.print(&mut lock); + writeln!(lock, "| Phase | Time (ms) \ + | Time (%) | Queries | Hits (%)") + .unwrap(); + writeln!(lock, "| ----------------------------------------- | -------------- \ + | -------- | -------------- | --------") + .unwrap(); + + let mut categories: Vec<_> = results.categories.iter().collect(); + categories.sort_by(|(_, data1), (_, data2)| data2.total_time().cmp(&data1.total_time())); + + for (category, data) in categories { + let (category_hits, category_total) = data.total_cache_data(); + let category_hit_percent = calculate_percent(category_hits, category_total); + + writeln!( + lock, + "| {0: <41} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}", + format!("{:?}", category), + data.total_time(), + ((data.total_time() as f32) / total_time) * 100.0, + category_total, + format!("{:.2}", category_hit_percent), + ).unwrap(); + + //in verbose mode, show individual query data + if results.verbose { + //don't show queries that took less than 1ms + let mut times: Vec<_> = data.query_times.iter().filter(|(_, t)| **t > 0).collect(); + times.sort_by(|(_, time1), (_, time2)| time2.cmp(time1)); + + for (query, time) in times { + let (hits, total) = data.query_cache_stats.get(query).unwrap_or(&(0, 0)); + let hit_percent = calculate_percent(*hits, *total); + + writeln!( + lock, + "| - {0: <39} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}", + query, + time, + ((*time as f32) / total_time) * 100.0, + total, + format!("{:.2}", hit_percent), + ).unwrap(); + } + } + } writeln!(lock).unwrap(); writeln!(lock, "Optimization level: {:?}", opts.optimize).unwrap(); - - let incremental = if opts.incremental.is_some() { "on" } else { "off" }; - writeln!(lock, "Incremental: {}", incremental).unwrap(); + writeln!(lock, "Incremental: {}", if results.incremental { "on" } else { "off" }).unwrap(); } pub fn save_results(&self, opts: &Options) { - let category_data = self.data.json(); + let results = self.get_results(opts); + let compilation_options = format!("{{ \"optimization_level\": \"{:?}\", \"incremental\": {} }}", - opts.optimize, - if opts.incremental.is_some() { "true" } else { "false" }); + results.optimization_level, + if results.incremental { "true" } else { "false" }); + + let mut category_data = String::new(); + + for (category, data) in &results.categories { + let (hits, total) = data.total_cache_data(); + let hit_percent = calculate_percent(hits, total); + + category_data.push_str(&format!("{{ \"category\": \"{:?}\", \"time_ms\": {}, \ + \"query_count\": {}, \"query_hits\": {} }}", + category, + data.total_time(), + total, + format!("{:.2}", hit_percent))); + } let json = format!("{{ \"category_data\": {}, \"compilation_options\": {} }}", category_data, From a568e7e47b400d34ba598784f0367064d8e7f317 Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Tue, 5 Feb 2019 17:59:41 +0100 Subject: [PATCH 2/3] Add #[inline] annotations --- src/librustc/util/profiling.rs | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index 2cec7ec65afc6..92a952f85bb15 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -169,6 +169,7 @@ impl SelfProfiler { profiler } + #[inline] pub fn start_activity(&mut self, category: ProfileCategory) { self.record(ProfilerEvent::GenericActivityStart { category, @@ -176,6 +177,7 @@ impl SelfProfiler { }) } + #[inline] pub fn end_activity(&mut self, category: ProfileCategory) { self.record(ProfilerEvent::GenericActivityEnd { category, @@ -183,6 +185,7 @@ impl SelfProfiler { }) } + #[inline] pub fn record_computed_queries( &mut self, query_name: &'static str, @@ -196,6 +199,7 @@ impl SelfProfiler { }) } + #[inline] pub fn record_query_hit(&mut self, query_name: &'static str, category: ProfileCategory) { self.record(ProfilerEvent::QueryCacheHit { query_name, @@ -203,6 +207,7 @@ impl SelfProfiler { }) } + #[inline] pub fn start_query(&mut self, query_name: &'static str, category: ProfileCategory) { self.record(ProfilerEvent::QueryStart { query_name, @@ -211,6 +216,7 @@ impl SelfProfiler { }); } + #[inline] pub fn end_query(&mut self, query_name: &'static str, category: ProfileCategory) { self.record(ProfilerEvent::QueryEnd { query_name, @@ -219,6 +225,7 @@ impl SelfProfiler { }) } + #[inline] fn record(&mut self, event: ProfilerEvent) { let thread_id = std::thread::current().id(); let events = self.events.entry(thread_id).or_default(); From 584081af4a386e9ef2e03684f1f3f1466b3996d1 Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Tue, 5 Feb 2019 18:35:41 +0100 Subject: [PATCH 3/3] Calculate self-times not total times --- src/librustc/util/profiling.rs | 25 ++++++++++++++++++------- 1 file changed, 18 insertions(+), 7 deletions(-) diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index 92a952f85bb15..f8fa01b639500 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -243,19 +243,20 @@ impl SelfProfiler { let mut results = CalculatedResults::new(); + //(event, child time to subtract) let mut query_stack = Vec::new(); for event in events { match event { QueryStart { .. } | GenericActivityStart { .. } => { - query_stack.push(event); + query_stack.push((event, 0)); }, QueryEnd { query_name, category, time: end_time } => { let previous_query = query_stack.pop(); - if let Some(QueryStart { + if let Some((QueryStart { query_name: p_query_name, time: start_time, - category: _ }) = previous_query { + category: _ }, child_time_to_subtract)) = previous_query { assert_eq!( p_query_name, query_name, @@ -263,18 +264,23 @@ impl SelfProfiler { ); let time_ns = time_between_ns(*start_time, *end_time); + let self_time_ns = time_ns - child_time_to_subtract; let result_data = results.categories.entry(*category).or_default(); - *result_data.query_times.entry(query_name).or_default() += time_ns; + *result_data.query_times.entry(query_name).or_default() += self_time_ns; + + if let Some((_, child_time_to_subtract)) = query_stack.last_mut() { + *child_time_to_subtract += time_ns; + } } else { bug!("Saw a query end but the previous event wasn't a query start"); } } GenericActivityEnd { category, time: end_time } => { let previous_event = query_stack.pop(); - if let Some(GenericActivityStart { + if let Some((GenericActivityStart { category: previous_category, - time: start_time }) = previous_event { + time: start_time }, child_time_to_subtract)) = previous_event { assert_eq!( previous_category, category, @@ -282,11 +288,16 @@ impl SelfProfiler { ); let time_ns = time_between_ns(*start_time, *end_time); + let self_time_ns = time_ns - child_time_to_subtract; let result_data = results.categories.entry(*category).or_default(); *result_data.query_times .entry("{time spent not running queries}") - .or_default() += time_ns; + .or_default() += self_time_ns; + + if let Some((_, child_time_to_subtract)) = query_stack.last_mut() { + *child_time_to_subtract += time_ns; + } } else { bug!("Saw an activity end but the previous event wasn't an activity start"); }