diff --git a/Cargo.toml b/Cargo.toml index d30c453..803aef9 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -3,4 +3,5 @@ members = [ "measureme", "mmview", + "summarize", ] diff --git a/measureme/src/lib.rs b/measureme/src/lib.rs index a709d97..775ac2c 100644 --- a/measureme/src/lib.rs +++ b/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::{ diff --git a/measureme/src/profiling_data.rs b/measureme/src/profiling_data.rs index c7b8a5c..2df29a9 100644 --- a/measureme/src/profiling_data.rs +++ b/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> { - ProfilerEventIterator { - data: self, - curr_event_idx: 0, - } + ProfilerEventIterator::new(&self) + } + + pub fn iter_matching_events(&self) -> impl Iterator> { + 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, }) } -} \ No newline at end of file +} + +#[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>>, +} + +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> { + 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 + } +} diff --git a/measureme/src/rustc.rs b/measureme/src/rustc.rs new file mode 100644 index 0000000..033c146 --- /dev/null +++ b/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"; diff --git a/summarize/Cargo.toml b/summarize/Cargo.toml new file mode 100644 index 0000000..dfd419f --- /dev/null +++ b/summarize/Cargo.toml @@ -0,0 +1,13 @@ +[package] +name = "summarize" +version = "0.1.0" +authors = ["Wesley Wiser ", "Michael Woerister "] +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" diff --git a/summarize/Readme.md b/summarize/Readme.md new file mode 100644 index 0000000..42acb69 --- /dev/null +++ b/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 + +``` diff --git a/summarize/src/analysis.rs b/summarize/src/analysis.rs new file mode 100644 index 0000000..3363d35 --- /dev/null +++ b/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, + pub total_time: Duration, +} + +pub fn perform_analysis(data: ProfilingData) -> Results { + let mut query_data = HashMap::::new(); + let mut threads = HashMap::<_, Vec>::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, + } +} diff --git a/summarize/src/main.rs b/summarize/src/main.rs new file mode 100644 index 0000000..ab5768a --- /dev/null +++ b/summarize/src/main.rs @@ -0,0 +1,71 @@ +#[macro_use] +extern crate prettytable; + +use std::fs::File; +use std::io::BufWriter; +use std::path::PathBuf; +use measureme::ProfilingData; + +use prettytable::{Table}; +use structopt::StructOpt; + +mod analysis; + +#[derive(StructOpt, Debug)] +struct Opt { + file_prefix: PathBuf, + + /// Writes the analysis to a json file next to instead of stdout + #[structopt(long = "json")] + json: bool, +} + +fn main() -> Result<(), Box> { + let opt = Opt::from_args(); + + 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)?; + return Ok(()); + } + + //order the results by descending self time + results.query_data.sort_by(|l, r| r.self_time.cmp(&l.self_time)); + + let mut table = Table::new(); + + table.add_row(row![ + "Item", + "Self time", + "% of total time", + "Item count", + "Cache hits", + "Blocked time", + "Incremental load time", + ]); + + let total_time = results.total_time.as_nanos() as f64; + + for query_data in results.query_data { + table.add_row(row![ + query_data.label, + format!("{:.2?}", query_data.self_time), + format!("{:.3}", ((query_data.self_time.as_nanos() as f64) / total_time) * 100.0), + format!("{}", query_data.invocation_count), + format!("{}", 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(()) +}