add event time column to summarize results

Author: andjo403

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(&current_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,13 +203,15 @@ pub fn perform_analysis(data: ProfilingData) -> Results {
                     QUERY_BLOCKED_EVENT_KIND => {
                         record_event_data(&current_event.label, &|data| {
                             data.self_time += current_event_duration;
+                            data.time += current_event_duration;
                             data.blocked_time += current_event_duration;
                         });
                     }
 
                     INCREMENTAL_LOAD_RESULT_EVENT_KIND => {
                         record_event_data(&current_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));
     }
 }

summarize/src/main.rs

@@ -89,6 +89,8 @@ fn diff(opt: DiffOpt) -> Result<(), Box<dyn Error>> {
         "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<dyn Error>> {
             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<dyn Error>> {
         "Item",
         "Self time",
         "% of total time",
+        "Time",
         "Item count",
         "Cache hits",
         "Blocked time",
@@ -172,6 +177,7 @@ fn summarize(opt: SummarizeOpt) -> Result<(), Box<dyn Error>> {
             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),

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)]