From ae3adb74e3d6cb4f283610265e40f095103c4a58 Mon Sep 17 00:00:00 2001 From: Andreas Jonson Date: Mon, 13 Jan 2020 21:33:00 +0100 Subject: [PATCH] add event time column to summarize results --- summarize/src/analysis.rs | 6 ++++++ summarize/src/main.rs | 6 ++++++ summarize/src/query_data.rs | 14 ++++++++++++-- 3 files changed, 24 insertions(+), 2 deletions(-) diff --git a/summarize/src/analysis.rs b/summarize/src/analysis.rs index e499550..53a557b 100644 --- a/summarize/src/analysis.rs +++ b/summarize/src/analysis.rs @@ -194,6 +194,7 @@ pub fn perform_analysis(data: ProfilingData) -> Results { QUERY_EVENT_KIND | GENERIC_ACTIVITY_EVENT_KIND => { record_event_data(¤t_event.label, &|data| { data.self_time += current_event_duration; + data.time += current_event_duration; data.number_of_cache_misses += 1; data.invocation_count += 1; }); @@ -202,6 +203,7 @@ pub fn perform_analysis(data: ProfilingData) -> Results { QUERY_BLOCKED_EVENT_KIND => { record_event_data(¤t_event.label, &|data| { data.self_time += current_event_duration; + data.time += current_event_duration; data.blocked_time += current_event_duration; }); } @@ -209,6 +211,7 @@ pub fn perform_analysis(data: ProfilingData) -> Results { INCREMENTAL_LOAD_RESULT_EVENT_KIND => { record_event_data(¤t_event.label, &|data| { data.self_time += current_event_duration; + data.time += current_event_duration; data.incremental_load_time += current_event_duration; }); } @@ -493,6 +496,7 @@ mod tests { assert_eq!(results.query_data_by_label("e1").self_time, Duration::from_nanos(100)); assert_eq!(results.query_data_by_label("e1").invocation_count, 3); + assert_eq!(results.query_data_by_label("e1").time, Duration::from_nanos(180)); } #[test] @@ -514,6 +518,7 @@ mod tests { assert_eq!(results.query_data_by_label("q1").self_time, Duration::from_nanos(230)); assert_eq!(results.query_data_by_label("q1").blocked_time, Duration::from_nanos(130)); + assert_eq!(results.query_data_by_label("q1").time, Duration::from_nanos(230)); } #[test] @@ -535,5 +540,6 @@ mod tests { assert_eq!(results.query_data_by_label("q1").self_time, Duration::from_nanos(230)); assert_eq!(results.query_data_by_label("q1").incremental_load_time, Duration::from_nanos(230)); + assert_eq!(results.query_data_by_label("q1").time, Duration::from_nanos(230)); } } diff --git a/summarize/src/main.rs b/summarize/src/main.rs index de7ff4a..5adb0ab 100644 --- a/summarize/src/main.rs +++ b/summarize/src/main.rs @@ -89,6 +89,8 @@ fn diff(opt: DiffOpt) -> Result<(), Box> { "Item", "Self Time", "Self Time Change", + "Time", + "Time Change", "Item count", "Cache hits", "Blocked time", @@ -105,6 +107,8 @@ fn diff(opt: DiffOpt) -> Result<(), Box> { query_data.label, format!("{:.2?}", query_data.self_time), format!("{:+.2}%", query_data.self_time_change), + format!("{:.2?}", query_data.time), + format!("{:+.2}%", query_data.time_change), format!("{:+}", query_data.invocation_count), format!("{:+}", query_data.number_of_cache_hits), format!("{:.2?}", query_data.blocked_time), @@ -151,6 +155,7 @@ fn summarize(opt: SummarizeOpt) -> Result<(), Box> { "Item", "Self time", "% of total time", + "Time", "Item count", "Cache hits", "Blocked time", @@ -172,6 +177,7 @@ fn summarize(opt: SummarizeOpt) -> Result<(), Box> { query_data.label, format!("{:.2?}", query_data.self_time), format!("{:.3}", curr_percent), + format!("{:.2?}", query_data.time), format!("{}", query_data.invocation_count), format!("{}", query_data.number_of_cache_hits), format!("{:.2?}", query_data.blocked_time), diff --git a/summarize/src/query_data.rs b/summarize/src/query_data.rs index 355484b..a98a0ba 100644 --- a/summarize/src/query_data.rs +++ b/summarize/src/query_data.rs @@ -6,6 +6,7 @@ use std::time::Duration; #[derive(Serialize, Deserialize, Clone, Debug)] pub struct QueryData { pub label: String, + pub time: Duration, pub self_time: Duration, pub number_of_cache_misses: usize, pub number_of_cache_hits: usize, @@ -18,6 +19,7 @@ impl QueryData { pub fn new(label: String) -> QueryData { QueryData { label, + time: Duration::from_nanos(0), self_time: Duration::from_nanos(0), number_of_cache_misses: 0, number_of_cache_hits: 0, @@ -37,6 +39,8 @@ impl QueryData { QueryDataDiff { label: self.label.clone(), + time: invert(self.time), + time_change: -100.0, self_time: invert(self.self_time), self_time_change: -100.0, number_of_cache_misses: -(self.number_of_cache_misses as i64), @@ -50,6 +54,8 @@ impl QueryData { pub fn as_query_data_diff(&self) -> QueryDataDiff { QueryDataDiff { label: self.label.clone(), + time: self.time.into(), + time_change: std::f64::INFINITY, self_time: self.self_time.into(), self_time_change: std::f64::INFINITY, number_of_cache_misses: self.number_of_cache_misses as i64, @@ -64,6 +70,8 @@ impl QueryData { #[derive(Serialize, Deserialize)] pub struct QueryDataDiff { pub label: String, + pub time: SignedDuration, + pub time_change: f64, pub self_time: SignedDuration, pub self_time_change: f64, pub number_of_cache_misses: i64, @@ -89,6 +97,8 @@ impl Sub for QueryData { QueryDataDiff { label: self.label, + time: sd(self.time) - sd(rhs.time), + time_change: percentage_change(rhs.time, self.time), self_time: sd(self.self_time) - sd(rhs.self_time), self_time_change: percentage_change(rhs.self_time, self.self_time), number_of_cache_misses: i(self.number_of_cache_misses) - i(rhs.number_of_cache_misses), @@ -101,8 +111,8 @@ impl Sub for QueryData { } fn percentage_change(base: Duration, change: Duration) -> f64 { - let self_time_nanos = change.as_nanos() as i128 - base.as_nanos() as i128; - self_time_nanos as f64 / base.as_nanos() as f64 * 100.0 + let nanos = change.as_nanos() as i128 - base.as_nanos() as i128; + nanos as f64 / base.as_nanos() as f64 * 100.0 } #[derive(Serialize, Deserialize)]