[summarize] Move summarize functionality to a sub command and add diff

Author: wesleywiser

CHANGELOG.md

@@ -4,6 +4,10 @@
 ### Added
 - `measureme`: Added support for compiling the library under wasm/wasi ([GH-43])
 - `mmview`: Added the `-t` flag to limit output to results on the specified thread id ([GH-49])
+- `summarize`: Added the `diff` sub command to compare two profiles ([GH-50])
+
+### Changed
+- `summarize`: Moved summarization under the `summarize` sub command ([GH-50])
 
 ## [0.3.0] - 2019-05-14
 ### Added

summarize/Readme.md

@@ -43,7 +43,7 @@ You can now use the `summarize` tool we compiled in the previous section to view
 contents of these files:
 
 ```bash
-$ /path/to/measureme/target/release/summarize pid-{pid}
+$ /path/to/measureme/target/release/summarize summarize id-{pid}
 +------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
 | Item                   | Self time | % of total time | Item count | Cache hits | Blocked time | Incremental load time |
 +------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
@@ -98,7 +98,7 @@ as before: (with regex as example)
 $ git clone https://github.com/rust-lang/regex.git
 $ cd regex
 $ cargo +mytoolchain rustc -- -Z self-profile
-$ /path/to/measureme/target/release/summarize pid-{pid}
+$ /path/to/measureme/target/release/summarize summarize pid-{pid}
 +------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
 | Item                   | Self time | % of total time | Item count | Cache hits | Blocked time | Incremental load time |
 +------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
@@ -143,4 +143,31 @@ summarize the information for that event.
 
 [query]: https://rust-lang.github.io/rustc-guide/query.html
 
-The table is sorted by `Self time`.
+The table is sorted by `Self time` descending.
+
+## The `diff` sub command
+
+The `diff` sub command allows you to compare the performance of two different profiles by event.
+
+The output is a table like that of the `summarize` sub command but it instead shows the differences in each metric.
+
+```bash
+$ /path/to/measureme/target/release/summarize diff base-profile changed-profile
++---------------------------+--------------+------------+------------+--------------+-----------------------+
+| Item                      | Self Time    | Item count | Cache hits | Blocked time | Incremental load time |
++---------------------------+--------------+------------+------------+--------------+-----------------------+
+| LLVM_module_passes        | -66.626471ms | +0         | +0         | +0ns         | +0ns                  |
++---------------------------+--------------+------------+------------+--------------+-----------------------+
+| LLVM_emit_obj             | -38.700719ms | +0         | +0         | +0ns         | +0ns                  |
++---------------------------+--------------+------------+------------+--------------+-----------------------+
+| LLVM_make_bitcode         | +32.006706ms | +0         | +0         | +0ns         | +0ns                  |
++---------------------------+--------------+------------+------------+--------------+-----------------------+
+| mir_borrowck              | -12.808322ms | +0         | +0         | +0ns         | +0ns                  |
++---------------------------+--------------+------------+------------+--------------+-----------------------+
+| typeck_tables_of          | -10.325247ms | +0         | +0         | +0ns         | +0ns                  |
++---------------------------+--------------+------------+------------+--------------+-----------------------+
+(rows elided)
+Total cpu time: -155.177548ms
+```
+
+The table is sorted by the absolute value of `Self time` descending.

summarize/src/analysis.rs

@@ -3,46 +3,14 @@ use std::collections::HashMap;
 use std::time::Duration;
 use measureme::{ProfilingData, TimestampKind, Event};
 use measureme::rustc::*;
-
-use serde::{Serialize};
-
-#[derive(Serialize)]
-pub struct QueryData {
-    pub label: String,
-    pub self_time: Duration,
-    pub number_of_cache_misses: usize,
-    pub number_of_cache_hits: usize,
-    pub invocation_count: usize,
-    pub blocked_time: Duration,
-    pub incremental_load_time: Duration,
-}
-
-impl QueryData {
-    fn new(label: String) -> QueryData {
-        QueryData {
-            label,
-            self_time: Duration::from_nanos(0),
-            number_of_cache_misses: 0,
-            number_of_cache_hits: 0,
-            invocation_count: 0,
-            blocked_time: Duration::from_nanos(0),
-            incremental_load_time: Duration::from_nanos(0),
-        }
-    }
-}
-
-#[derive(Serialize)]
-pub struct Results {
-    pub query_data: Vec<QueryData>,
-    pub total_time: Duration,
-}
+use crate::query_data::{QueryData, Results};
 
 pub fn perform_analysis(data: ProfilingData) -> Results {
     let mut query_data = HashMap::<String, QueryData>::new();
     let mut threads = HashMap::<_, Vec<Event>>::new();
     let mut total_time = Duration::from_nanos(0);
 
-    let mut record_event_data = |label: &Cow<'_, str>, f: &Fn(&mut QueryData)| {
+    let mut record_event_data = |label: &Cow<'_, str>, f: &dyn Fn(&mut QueryData)| {
         if let Some(data) = query_data.get_mut(&label[..]) {
             f(data);
         } else {

summarize/src/diff.rs

@@ -0,0 +1,58 @@
+use std::collections::{HashMap, HashSet};
+use std::time::Duration;
+use serde::{Deserialize, Serialize};
+use crate::query_data::{QueryData, QueryDataDiff, Results};
+use crate::signed_duration::SignedDuration;
+
+#[derive(Serialize, Deserialize)]
+pub struct DiffResults {
+    pub query_data: Vec<QueryDataDiff>,
+    pub total_time: SignedDuration,
+}
+
+fn build_query_lookup(query_data: &[QueryData]) -> HashMap<&str, usize> {
+    let mut lookup = HashMap::with_capacity(query_data.len());
+    for i in 0..query_data.len() {
+        lookup.insert(&query_data[i].label[..], i);
+    }
+
+    lookup
+}
+
+pub fn calculate_diff(base: Results, change: Results) -> DiffResults {
+    #[inline]
+    fn sd(d: Duration) -> SignedDuration {
+        d.into()
+    }
+
+    let base_data = build_query_lookup(&base.query_data);
+    let change_data = build_query_lookup(&change.query_data);
+
+    let mut all_labels = HashSet::with_capacity(base.query_data.len() + change.query_data.len());
+    for query_data in base.query_data.iter().chain(&change.query_data) {
+        all_labels.insert(&query_data.label[..]);
+    }
+
+    let mut query_data: Vec<_> =
+        all_labels
+            .iter()
+            .map(|l| {
+                let b = base_data.get(l).map(|i| &base.query_data[*i]);
+                let c = change_data.get(l).map(|i| &change.query_data[*i]);
+
+                match (b, c) {
+                    (Some(b), Some(c)) => c.clone() - b.clone(),
+                    (Some(b), None) => b.as_query_data_diff(),
+                    (None, Some(c)) => c.invert(),
+                    (None, None) => unreachable!(),
+                }
+            })
+            .collect();
+
+    query_data.sort_by(|l, r| r.self_time.duration.cmp(&l.self_time.duration));
+
+    DiffResults {
+        query_data,
+        total_time: sd(change.total_time) - sd(base.total_time),
+    }
+}

summarize/src/main.rs

@@ -3,17 +3,35 @@ extern crate prettytable;
 
 use std::error::Error;
 use std::fs::File;
-use std::io::BufWriter;
+use std::io::{BufReader, BufWriter};
 use std::path::PathBuf;
 use measureme::ProfilingData;
 
 use prettytable::{Table};
+use serde::Serialize;
 use structopt::StructOpt;
 
 mod analysis;
+mod diff;
+mod query_data;
+mod signed_duration;
+
+use query_data::Results;
+
+#[derive(StructOpt, Debug)]
+struct DiffOpt {
+    base: PathBuf,
+    change: PathBuf,
+
+    #[structopt(short = "e", long = "exclude")]
+    exclude: Vec<String>,
+
+    #[structopt(long = "json")]
+    json: bool,
+}
 
 #[derive(StructOpt, Debug)]
-struct Opt {
+struct SummarizeOpt {
     file_prefix: PathBuf,
 
     /// Writes the analysis to a json file next to <file_prefix> instead of stdout
@@ -25,17 +43,96 @@ struct Opt {
     percent_above: f64,
 }
 
-fn main() -> Result<(), Box<dyn Error>> {
-    let opt = Opt::from_args();
+#[derive(StructOpt, Debug)]
+enum Opt {
+    #[structopt(name = "diff")]
+    Diff(DiffOpt),
+
+    /// Processes trace files and produces a summary
+    #[structopt(name = "summarize")]
+    Summarize(SummarizeOpt),
+}
+
+fn process_results(file: &PathBuf) -> Result<Results, Box<dyn Error>> {
+    if file.ends_with("json") {
+        let reader = BufReader::new(File::open(&file)?);
+
+        let results: Results = serde_json::from_reader(reader)?;
+        Ok(results)
+    } else {
+        let data = ProfilingData::new(&file)?;
+
+        Ok(analysis::perform_analysis(data))
+    }
+}
+
+fn write_results_json(file: &PathBuf, results: impl Serialize) -> Result<(), Box<dyn Error>> {
+    let file = BufWriter::new(File::create(file.with_extension("json"))?);
+    serde_json::to_writer(file, &results)?;
+    Ok(())
+}
+
+fn diff(opt: DiffOpt) -> Result<(), Box<dyn Error>> {
+    let base = process_results(&opt.base)?;
+    let change = process_results(&opt.change)?;
+
+    let results = diff::calculate_diff(base, change);
+
+    if opt.json {
+        write_results_json(&opt.change, results)?;
+        return Ok(());
+    }
+
+    let mut table = Table::new();
 
+    table.add_row(row!(
+        "Item",
+        "Self Time",
+        "Item count",
+        "Cache hits",
+        "Blocked time",
+        "Incremental load time"
+    ));
+
+    for query_data in results.query_data {
+        let exclude = opt.exclude.iter().any(|e| query_data.label.contains(e));
+        if exclude {
+            continue;
+        }
+
+        fn print_i64(i: i64) -> String {
+            if i >= 0 {
+                format!("+{}", i)
+            } else {
+                format!("{}", i)
+            }
+        }
+
+        table.add_row(row![
+            query_data.label,
+            format!("{:.2?}", query_data.self_time),
+            print_i64(query_data.invocation_count),
+            print_i64(query_data.number_of_cache_hits),
+            format!("{:.2?}", query_data.blocked_time),
+            format!("{:.2?}", query_data.incremental_load_time),
+        ]);
+    }
+
+    table.printstd();
+
+    println!("Total cpu time: {:?}", results.total_time);
+
+    Ok(())
+}
+
+fn summarize(opt: SummarizeOpt) -> Result<(), Box<dyn Error>> {
     let data = ProfilingData::new(&opt.file_prefix)?;
 
     let mut results = analysis::perform_analysis(data);
 
     //just output the results into a json file
     if opt.json {
-        let file = BufWriter::new(File::create(opt.file_prefix.with_extension("json"))?);
-        serde_json::to_writer(file, &results)?;
+        write_results_json(&opt.file_prefix, &results)?;
         return Ok(());
     }
 
@@ -68,7 +165,6 @@ fn main() -> Result<(), Box<dyn Error>> {
     let mut percent_total_time: f64 = 0.0;
 
     for query_data in results.query_data {
-
         let curr_percent = (query_data.self_time.as_nanos() as f64) / total_time * 100.0;
         if curr_percent < percent_above { break } //no need to run entire loop if filtering by % time
 
@@ -95,3 +191,12 @@ fn main() -> Result<(), Box<dyn Error>> {
 
     Ok(())
 }
+
+fn main() -> Result<(), Box<dyn Error>> {
+    let opt = Opt::from_args();
+
+    match opt {
+        Opt::Summarize(opt) => summarize(opt),
+        Opt::Diff(opt) => diff(opt),
+    }
+}