Skip to content

Commit 4118fcd

Browse files
wesleywiserwesleywiser
committed
Calculate time blocked
1 parent 1334160 commit 4118fcd

File tree

2 files changed

+53
-33
lines changed

2 files changed

+53
-33
lines changed

‎summarize/src/analysis.rs

Lines changed: 49 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@ pub struct QueryData {
77
pub self_time: Duration,
88
pub number_of_cache_misses: usize,
99
pub number_of_cache_hits: usize,
10+
pub blocked_time: Duration,
1011
}
1112

1213
impl QueryData {
@@ -16,6 +17,7 @@ impl QueryData {
1617
self_time: Duration::from_nanos(0),
1718
number_of_cache_misses: 0,
1819
number_of_cache_hits: 0,
20+
blocked_time: Duration::from_nanos(0),
1921
}
2022
}
2123
}
@@ -35,25 +37,30 @@ pub fn perform_analysis(data: ProfilingData) -> Results {
3537
TimestampKind::Start => {
3638
let thread_stack = threads.entry(event.thread_id).or_default();
3739

38-
if let Some(prev_event) = thread_stack.last() {
39-
//count the time run so far for this event
40-
let duration =
41-
event.timestamp.duration_since(prev_event.timestamp)
42-
.unwrap_or(Duration::from_nanos(0));
40+
if &event.event_kind[..] == "Query" || &event.event_kind[..] == "GenericActivity" {
41+
if let Some(prev_event) = thread_stack.last() {
42+
//count the time run so far for this event
43+
let duration =
44+
event.timestamp.duration_since(prev_event.timestamp)
45+
.unwrap_or(Duration::from_nanos(0));
4346

44-
if let Some(data) = query_data.get_mut(&prev_event.label[..]) {
45-
data.self_time += duration;
46-
} else {
47-
let mut data = QueryData::new(prev_event.label.clone().into_owned());
48-
data.self_time = duration;
49-
query_data.insert(prev_event.label.clone().into_owned(), data);
47+
if let Some(data) = query_data.get_mut(&prev_event.label[..]) {
48+
data.self_time += duration;
49+
} else {
50+
let mut data = QueryData::new(prev_event.label.clone().into_owned());
51+
data.self_time = duration;
52+
query_data.insert(prev_event.label.clone().into_owned(), data);
53+
}
54+
55+
//record the total time
56+
total_time += duration;
5057
}
5158

52-
//record the total time
53-
total_time += duration;
59+
thread_stack.push(event);
60+
} else if &event.event_kind[..] == "QueryBlocked" ||
61+
&event.event_kind[..] == "IncrementalLoadResult" {
62+
thread_stack.push(event);
5463
}
55-
56-
thread_stack.push(event);
5764
},
5865
TimestampKind::Instant => {
5966
if &event.event_kind[..] == "QueryCacheHit" {
@@ -69,6 +76,7 @@ pub fn perform_analysis(data: ProfilingData) -> Results {
6976
TimestampKind::End => {
7077
let thread_stack = threads.get_mut(&event.thread_id).unwrap();
7178
let start_event = thread_stack.pop().unwrap();
79+
7280
assert_eq!(start_event.event_kind, event.event_kind);
7381
assert_eq!(start_event.label, event.label);
7482
assert_eq!(start_event.timestamp_kind, TimestampKind::Start);
@@ -79,24 +87,34 @@ pub fn perform_analysis(data: ProfilingData) -> Results {
7987
.duration_since(start_event.timestamp)
8088
.unwrap_or(Duration::from_nanos(0));
8189

82-
if let Some(data) = query_data.get_mut(&start_event.label[..]) {
83-
data.self_time += duration;
84-
data.number_of_cache_misses += 1;
85-
} else {
86-
let mut data = QueryData::new(start_event.label.clone().into_owned());
87-
data.self_time = duration;
88-
data.number_of_cache_misses = 1;
89-
query_data.insert(start_event.label.into_owned(), data);
90-
}
90+
if &event.event_kind[..] == "Query" || &event.event_kind[..] == "GenericActivity" {
91+
if let Some(data) = query_data.get_mut(&start_event.label[..]) {
92+
data.self_time += duration;
93+
data.number_of_cache_misses += 1;
94+
} else {
95+
let mut data = QueryData::new(start_event.label.clone().into_owned());
96+
data.self_time = duration;
97+
data.number_of_cache_misses = 1;
98+
query_data.insert(start_event.label.clone().into_owned(), data);
99+
}
91100

92-
//now adjust the previous event's start time so that it "started" right now
93-
if let Some(previous_event) = thread_stack.last_mut() {
94-
assert_eq!(TimestampKind::Start, previous_event.timestamp_kind);
95-
previous_event.timestamp = event.timestamp;
96-
}
101+
//now adjust the previous event's start time so that it "started" right now
102+
if let Some(previous_event) = thread_stack.last_mut() {
103+
assert_eq!(TimestampKind::Start, previous_event.timestamp_kind);
104+
previous_event.timestamp = event.timestamp;
105+
}
97106

98-
//record the total time
99-
total_time += duration;
107+
//record the total time
108+
total_time += duration;
109+
} else if &event.event_kind[..] == "QueryBlocked" {
110+
if let Some(data) = query_data.get_mut(&start_event.label[..]) {
111+
data.blocked_time += duration;
112+
} else {
113+
let mut data = QueryData::new(start_event.label.clone().into_owned());
114+
data.blocked_time = duration;
115+
query_data.insert(start_event.label.clone().into_owned(), data);
116+
}
117+
}
100118
}
101119
}
102120
}

‎summarize/src/main.rs

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -20,15 +20,17 @@ fn main() {
2020
//order the results by descending self time
2121
results.query_data.sort_by(|l, r| r.self_time.cmp(&l.self_time));
2222

23-
println!("| Item | Self Time | % of total time | Number of invocations | Cache hits |");
23+
println!("| Item | Self Time | % of total time | Number of invocations \
24+
| Cache hits | Blocked time |");
2425

2526
for query_data in results.query_data {
2627
println!(
27-
"{} | {:?} | {} | {} |",
28+
"{} | {:?} | {} | {} | {:?} |",
2829
query_data.label,
2930
query_data.self_time,
3031
query_data.number_of_cache_hits + query_data.number_of_cache_misses,
3132
query_data.number_of_cache_hits,
33+
query_data.blocked_time,
3234
);
3335
}
3436

0 commit comments

Comments
 (0)