Capture time spent blocked waiting on queries

This captures time spent blocked when a query is waiting for another
query to finish executing in another thread.
This commit is contained in:
Wesley Wiser 2019-02-08 17:17:58 +01:00
parent ae044ee893
commit 8170828cb9
2 changed files with 39 additions and 4 deletions

View File

@ -124,7 +124,15 @@ pub(super) fn try_get(
let job = match lock.active.entry((*key).clone()) {
Entry::Occupied(entry) => {
match *entry.get() {
QueryResult::Started(ref job) => job.clone(),
QueryResult::Started(ref job) => {
//For parallel queries, we'll block and wait until the query running
//in another thread has completed. Record how long we wait in the
//self-profiler
#[cfg(parallel_compiler)]
tcx.sess.profiler(|p| p.query_blocked_start(Q::NAME, Q::CATEGORY));
job.clone()
},
QueryResult::Poisoned => FatalError.raise(),
}
}
@ -160,7 +168,10 @@ pub(super) fn try_get(
// thread
#[cfg(parallel_compiler)]
{
if let Err(cycle) = job.r#await(tcx, span) {
let result = job.r#await(tcx, span);
tcx.sess.profiler(|p| p.query_blocked_end(Q::NAME, Q::CATEGORY));
if let Err(cycle) = result {
return TryGetJob::JobCompleted(Err(cycle));
}
}

View File

@ -27,6 +27,8 @@ pub enum ProfilerEvent {
QueryCount { query_name: &'static str, category: ProfileCategory, count: usize },
IncrementalLoadResultStart { query_name: &'static str, time: Instant },
IncrementalLoadResultEnd { query_name: &'static str, time: Instant },
QueryBlockedStart { query_name: &'static str, category: ProfileCategory, time: Instant },
QueryBlockedEnd { query_name: &'static str, category: ProfileCategory, time: Instant },
}
impl ProfilerEvent {
@ -36,13 +38,15 @@ fn is_start_event(&self) -> bool {
match self {
QueryStart { .. } |
GenericActivityStart { .. } |
IncrementalLoadResultStart { .. } => true,
IncrementalLoadResultStart { .. } |
QueryBlockedStart { .. } => true,
QueryEnd { .. } |
GenericActivityEnd { .. } |
QueryCacheHit { .. } |
QueryCount { .. } |
IncrementalLoadResultEnd { .. } => false,
IncrementalLoadResultEnd { .. } |
QueryBlockedEnd { .. } => false,
}
}
}
@ -249,6 +253,24 @@ pub fn incremental_load_result_end(&mut self, query_name: &'static str) {
})
}
#[inline]
pub fn query_blocked_start(&mut self, query_name: &'static str, category: ProfileCategory) {
self.record(ProfilerEvent::QueryBlockedStart {
query_name,
category,
time: Instant::now(),
})
}
#[inline]
pub fn query_blocked_end(&mut self, query_name: &'static str, category: ProfileCategory) {
self.record(ProfilerEvent::QueryBlockedEnd {
query_name,
category,
time: Instant::now(),
})
}
#[inline]
fn record(&mut self, event: ProfilerEvent) {
let thread_id = std::thread::current().id();
@ -343,6 +365,8 @@ fn calculate_thread_results(events: &Vec<ProfilerEvent>) -> CalculatedResults {
},
//we don't summarize incremental load result events in the simple output mode
IncrementalLoadResultStart { .. } | IncrementalLoadResultEnd { .. } => { },
//we don't summarize parallel query blocking in the simple output mode
QueryBlockedStart { .. } | QueryBlockedEnd { .. } => { },
}
}