Implement a summarization tool for profile traces

Cargo.toml

@@ -3,4 +3,5 @@
 members = [
     "measureme",
     "mmview",
+    "summarize",
 ]

measureme/src/lib.rs

@@ -7,13 +7,14 @@ mod raw_event;
 mod serialization;
 mod stringtable;
 
+pub mod rustc;
 pub mod testing_common;
 
 pub use crate::event::Event;
 pub use crate::file_serialization_sink::FileSerializationSink;
 pub use crate::mmap_serialization_sink::MmapSerializationSink;
 pub use crate::profiler::{Profiler, ProfilerFiles};
-pub use crate::profiling_data::ProfilingData;
+pub use crate::profiling_data::{ProfilingData, MatchingEvent};
 pub use crate::raw_event::{RawEvent, TimestampKind};
 pub use crate::serialization::{Addr, SerializationSink};
 pub use crate::stringtable::{

measureme/src/profiling_data.rs

@@ -1,5 +1,5 @@
 use crate::event::Event;
-use crate::{ProfilerFiles, RawEvent, StringTable};
+use crate::{ProfilerFiles, RawEvent, StringTable, TimestampKind};
 use std::fs;
 use std::mem;
 use std::path::Path;
@@ -27,10 +27,11 @@ impl ProfilingData {
     }
 
     pub fn iter(&self) -> impl Iterator<Item = Event<'_>> {
-        ProfilerEventIterator {
-            data: self,
-            curr_event_idx: 0,
-        }
+        ProfilerEventIterator::new(&self)
+    }
+
+    pub fn iter_matching_events(&self) -> impl Iterator<Item = MatchingEvent<'_>> {
+        MatchingEventsIterator::new(ProfilerEventIterator::new(&self))
     }
 }
 
@@ -39,6 +40,15 @@ struct ProfilerEventIterator<'a> {
     curr_event_idx: usize,
 }
 
+impl<'a> ProfilerEventIterator<'a> {
+    pub fn new(data: &'a ProfilingData) -> ProfilerEventIterator<'a> {
+        ProfilerEventIterator {
+            data,
+            curr_event_idx: 0,
+        }
+    }
+}
+
 impl<'a> Iterator for ProfilerEventIterator<'a> {
     type Item = Event<'a>;
 
@@ -76,4 +86,61 @@ impl<'a> Iterator for ProfilerEventIterator<'a> {
             thread_id: raw_event.thread_id,
         })
     }
-}
+}
+
+#[derive(Clone, Debug, PartialEq, Eq, Hash)]
+pub enum MatchingEvent<'a> {
+    StartStop(Event<'a>, Event<'a>),
+    Instant(Event<'a>),
+}
+
+struct MatchingEventsIterator<'a> {
+    events: ProfilerEventIterator<'a>,
+    thread_stacks: Vec<Vec<Event<'a>>>,
+}
+
+impl<'a> MatchingEventsIterator<'a> {
+    pub fn new(events: ProfilerEventIterator<'a>) -> MatchingEventsIterator<'a> {
+        MatchingEventsIterator {
+            events,
+            thread_stacks: vec![],
+        }
+    }
+}
+
+impl<'a> Iterator for MatchingEventsIterator<'a> {
+    type Item = MatchingEvent<'a>;
+
+    fn next(&mut self) -> Option<MatchingEvent<'a>> {
+        while let Some(event) = self.events.next() {
+            match event.timestamp_kind {
+                TimestampKind::Start => {
+                    let thread_id = event.thread_id as usize;
+                    if thread_id >= self.thread_stacks.len() {
+                        let growth_size = (thread_id + 1) - self.thread_stacks.len();
+                        self.thread_stacks.append(
+                            &mut vec![vec![]; growth_size]
+                        )
+                    }
+
+                    self.thread_stacks[thread_id].push(event);
+                },
+                TimestampKind::Instant => {
+                    return Some(MatchingEvent::Instant(event));
+                },
+                TimestampKind::End => {
+                    let thread_id = event.thread_id as usize;
+                    let previous_event = self.thread_stacks[thread_id].pop().expect("no previous event");
+                    if previous_event.event_kind != event.event_kind ||
+                        previous_event.label != event.label {
+                        panic!("previous event on thread wasn't the start event");
+                    }
+
+                    return Some(MatchingEvent::StartStop(previous_event, event));
+                }
+            }
+        }
+
+        None
+    }
+}

measureme/src/rustc.rs

@@ -0,0 +1,11 @@
+//! This module contains functionality specific to to the measureme integration with rustc
+
+pub const QUERY_EVENT_KIND: &str = "Query";
+
+pub const GENERIC_ACTIVITY_EVENT_KIND: &str = "GenericActivity";
+
+pub const INCREMENTAL_LOAD_RESULT_EVENT_KIND: &str = "IncrementalLoadResult";
+
+pub const QUERY_BLOCKED_EVENT_KIND: &str = "QueryBlocked";
+
+pub const QUERY_CACHE_HIT_EVENT_KIND: &str = "QueryCacheHit";

summarize/Cargo.toml

@@ -0,0 +1,13 @@
+[package]
+name = "summarize"
+version = "0.1.0"
+authors = ["Wesley Wiser <[email protected]>", "Michael Woerister <michaelwoerister@posteo>"]
+edition = "2018"
+license = "MIT OR Apache-2.0"
+
+[dependencies]
+measureme = { path = "../measureme" }
+prettytable-rs = "0.8"
+serde = { version = "1.0", features = [ "derive" ] }
+serde_json = "1.0"
+structopt = "0.2"

summarize/Readme.md

@@ -0,0 +1,46 @@
+# summarize
+
+Summarize is a tool to produce a human readable summary of `mesaurme` profiling data.
+
+## Example
+
+```bash
+$ git clone https://github.com/rust-lang/regex.git
+
+$ cd regex
+
+$ cargo rustc -- -Z self-profile
+
+$ summarize pid-{pid}
+
++------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
+| Item                   | Self time | % of total time | Item count | Cache hits | Blocked time | Incremental load time |
++------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
+| LLVM_emit_obj          | 4.51s     | 41.432          | 141        | 0          | 0.00ns       | 0.00ns                |
++------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
+| LLVM_module_passes     | 1.05s     | 9.626           | 140        | 0          | 0.00ns       | 0.00ns                |
++------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
+| LLVM_make_bitcode      | 712.94ms  | 6.543           | 140        | 0          | 0.00ns       | 0.00ns                |
++------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
+| typeck_tables_of       | 542.23ms  | 4.976           | 17470      | 16520      | 0.00ns       | 0.00ns                |
++------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
+| codegen                | 366.82ms  | 3.366           | 141        | 0          | 0.00ns       | 0.00ns                |
++------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
+| optimized_mir          | 188.22ms  | 1.727           | 11668      | 9114       | 0.00ns       | 0.00ns                |
++------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
+| mir_built              | 156.30ms  | 1.434           | 2040       | 1020       | 0.00ns       | 0.00ns                |
++------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
+| evaluate_obligation    | 151.95ms  | 1.394           | 33134      | 23817      | 0.00ns       | 0.00ns                |
++------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
+| LLVM_compress_bitcode  | 126.55ms  | 1.161           | 140        | 0          | 0.00ns       | 0.00ns                |
++------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
+| codegen crate          | 119.08ms  | 1.093           | 1          | 0          | 0.00ns       | 0.00ns                |
++------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
+| mir_const              | 117.82ms  | 1.081           | 1050       | 30         | 0.00ns       | 0.00ns                |
++------------------------+-----------+-----------------+------------+------------+--------------+-----------------------+
+
+(many more rows elided)
+
+Total cpu time: 10.896488447s
+
+```

summarize/src/analysis.rs

@@ -0,0 +1,194 @@
+use std::borrow::Cow;
+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,
+}
+
+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)| {
+        if let Some(data) = query_data.get_mut(&label[..]) {
+            f(data);
+        } else {
+            let mut data = QueryData::new(label.clone().into_owned());
+            f(&mut data);
+            query_data.insert(label.clone().into_owned(), data);
+        }
+    };
+
+    /*
+        The basic idea is to iterate over all of the events in the profile data file, with some
+        special handling for Start and Stop events.
+
+        When calculating timing data, the core thing we're interested in is self-time.
+        In order to calculate that correctly, we need to track when an event is running and when
+        it has been interrupted by another event.
+
+        Let's look at a simple example with two events:
+
+        Event 1:
+        - Started at 0ms
+        - Ended at 10ms
+
+        Event 2:
+        - Started at 4ms
+        - Ended at 6ms
+
+          0  1  2  3  4  5  6  7  8  9  10
+          ================================
+        1 |------------------------------|
+        2             |-----|
+
+        When processing this, we see the events like this:
+
+        - Start Event 1
+        - Start Event 2
+        - End Event 2
+        - End Event 1
+
+        Now, I'll add some annotation to these events to show what's happening in the code:
+
+        - Start Event 1
+            - Since there is no other event is running, there is no additional bookkeeping to do
+            - We push Event 1 onto the thread stack.
+        - Start Event 2
+            - Since there is another event on the stack running, record the time from that event's
+              start time to this event's start time. (In this case, that's the time from 0ms - 4ms)
+            - We push Event 2 onto the thread stack.
+        - End Event 2
+            - We pop Event 2's start event from the thread stack and record the time from its start
+              time to the current time (In this case, that's 4ms - 6ms)
+            - Since there's another event on the stack, we mutate its start time to be the current
+              time. This effectively "restarts" that event's timer.
+        - End Event 1
+            - We pop Event 1's start event from the thread stack and record the time from its start
+              time to the current time (In this case, that's 6ms - 10ms because we mutated the start
+              time when we processed End Event 2)
+            - Since there's no other events on the stack, there is no additional bookkeeping to do
+
+        As a result:
+        Event 1's self-time is `(4-0)ms + (10-6)ms = 8ms`
+
+        Event 2's self-time is `(6-2)ms = 2ms`
+    */
+
+    for event in data.iter() {
+        match event.timestamp_kind {
+            TimestampKind::Start => {
+                let thread_stack = threads.entry(event.thread_id).or_default();
+
+                if &event.event_kind[..] == QUERY_EVENT_KIND ||
+                    &event.event_kind[..] == GENERIC_ACTIVITY_EVENT_KIND {
+                    if let Some(prev_event) = thread_stack.last() {
+                        //count the time run so far for this event
+                        let duration =
+                            event.timestamp.duration_since(prev_event.timestamp)
+                                .unwrap_or(Duration::from_nanos(0));
+
+                        record_event_data(&prev_event.label, &|data| {
+                            data.self_time += duration;
+                        });
+
+                        //record the total time
+                        total_time += duration;
+                    }
+
+                    thread_stack.push(event);
+                } else if &event.event_kind[..] == QUERY_BLOCKED_EVENT_KIND ||
+                          &event.event_kind[..] == INCREMENTAL_LOAD_RESULT_EVENT_KIND {
+                    thread_stack.push(event);
+                }
+            },
+            TimestampKind::Instant => {
+                if &event.event_kind[..] == QUERY_CACHE_HIT_EVENT_KIND {
+                    record_event_data(&event.label, &|data| {
+                        data.number_of_cache_hits += 1;
+                        data.invocation_count += 1;
+                    });
+                }
+            },
+            TimestampKind::End => {
+                let thread_stack = threads.get_mut(&event.thread_id).unwrap();
+                let start_event = thread_stack.pop().unwrap();
+
+                assert_eq!(start_event.event_kind, event.event_kind);
+                assert_eq!(start_event.label, event.label);
+                assert_eq!(start_event.timestamp_kind, TimestampKind::Start);
+
+                //track the time for this event
+                let duration =
+                    event.timestamp
+                        .duration_since(start_event.timestamp)
+                        .unwrap_or(Duration::from_nanos(0));
+
+                if &event.event_kind[..] == QUERY_EVENT_KIND ||
+                    &event.event_kind[..] == GENERIC_ACTIVITY_EVENT_KIND {
+                    record_event_data(&event.label, &|data| {
+                        data.self_time += duration;
+                        data.number_of_cache_misses += 1;
+                        data.invocation_count += 1;
+                    });
+
+                    //this is the critical bit to correctly calculating self-time:
+                    //adjust the previous event's start time so that it "started" right now
+                    if let Some(previous_event) = thread_stack.last_mut() {
+                        assert_eq!(TimestampKind::Start, previous_event.timestamp_kind);
+                        previous_event.timestamp = event.timestamp;
+                    }
+
+                    //record the total time
+                    total_time += duration;
+                } else if &event.event_kind[..] == QUERY_BLOCKED_EVENT_KIND {
+                    record_event_data(&event.label, &|data| {
+                        data.blocked_time += duration;
+                    });
+                } else if &event.event_kind[..] == INCREMENTAL_LOAD_RESULT_EVENT_KIND {
+                    record_event_data(&event.label, &|data| {
+                        data.incremental_load_time += duration;
+                    });
+                }
+            }
+        }
+    }
+
+    Results {
+        query_data: query_data.drain().map(|(_, value)| value).collect(),
+        total_time,
+    }
+}