From e6b27c0dc01e43eb6da36060a0e4b74d65d4e514 Mon Sep 17 00:00:00 2001 From: Ryan Levick Date: Fri, 23 Jul 2021 13:45:37 +0200 Subject: [PATCH 1/5] Add support for integer events --- analyzeme/src/event.rs | 33 ++-- analyzeme/src/event_payload.rs | 126 ++++++++++++++ analyzeme/src/lib.rs | 4 +- analyzeme/src/lightweight_event.rs | 47 +++--- analyzeme/src/profiling_data.rs | 101 ++++++++--- analyzeme/src/stack_collapse.rs | 8 +- analyzeme/src/testing_common.rs | 12 +- analyzeme/src/timestamp.rs | 49 ------ crox/src/main.rs | 15 +- measureme/src/lib.rs | 4 +- measureme/src/profiler.rs | 20 ++- measureme/src/raw_event.rs | 258 ++++++++++++++++++----------- mmview/src/main.rs | 15 +- summarize/src/aggregate.rs | 38 +++-- summarize/src/analysis.rs | 9 +- 15 files changed, 472 insertions(+), 267 deletions(-) create mode 100644 analyzeme/src/event_payload.rs delete mode 100644 analyzeme/src/timestamp.rs diff --git a/analyzeme/src/event.rs b/analyzeme/src/event.rs index 2c548c0..d51c3a8 100644 --- a/analyzeme/src/event.rs +++ b/analyzeme/src/event.rs @@ -1,14 +1,14 @@ -use crate::timestamp::Timestamp; +use crate::event_payload::EventPayload; use memchr::memchr; use std::borrow::Cow; -use std::time::Duration; +use std::time::{Duration, SystemTime}; #[derive(Clone, Eq, PartialEq, Hash, Debug)] pub struct Event<'a> { pub event_kind: Cow<'a, str>, pub label: Cow<'a, str>, pub additional_data: Vec>, - pub timestamp: Timestamp, + pub payload: EventPayload, pub thread_id: u32, } @@ -16,26 +16,19 @@ impl<'a> Event<'a> { /// Returns true if the time interval of `self` completely contains the /// time interval of `other`. pub fn contains(&self, other: &Event<'_>) -> bool { - match self.timestamp { - Timestamp::Interval { - start: self_start, - end: self_end, - } => match other.timestamp { - Timestamp::Interval { - start: other_start, - end: other_end, - } => self_start <= other_start && other_end <= self_end, - Timestamp::Instant(other_t) => self_start <= other_t && other_t <= self_end, - }, - Timestamp::Instant(_) => false, - } + self.payload.contains(&other.payload) } pub fn duration(&self) -> Option { - match self.timestamp { - Timestamp::Interval { start, end } => end.duration_since(start).ok(), - Timestamp::Instant(_) => None, - } + self.payload.duration() + } + + pub fn start(&self) -> SystemTime { + self.payload.start() + } + + pub fn end(&self) -> SystemTime { + self.payload.end() } pub(crate) fn parse_event_id(event_id: Cow<'a, str>) -> (Cow<'a, str>, Vec>) { diff --git a/analyzeme/src/event_payload.rs b/analyzeme/src/event_payload.rs new file mode 100644 index 0000000..2671caa --- /dev/null +++ b/analyzeme/src/event_payload.rs @@ -0,0 +1,126 @@ +use measureme::RawEvent; +use std::time::{Duration, SystemTime}; + +#[derive(Copy, Clone, Eq, PartialEq, Hash, Debug)] +pub enum EventPayload { + Timestamp(Timestamp), + Integer(u64), +} + +impl EventPayload { + pub fn from_raw_event(raw_event: &RawEvent, start_time: SystemTime) -> Self { + if raw_event.is_integer() { + Self::Integer(raw_event.value()) + } else { + Self::Timestamp(Timestamp::from_raw_event(raw_event, start_time)) + } + } + + /// Returns true if the time interval of `self` completely contains the + /// time interval of `other`. + pub fn contains(&self, other: &Self) -> bool { + match self { + EventPayload::Timestamp(Timestamp::Interval { + start: self_start, + end: self_end, + }) => match other { + EventPayload::Timestamp(Timestamp::Interval { + start: other_start, + end: other_end, + }) => self_start <= other_start && other_end <= self_end, + EventPayload::Timestamp(Timestamp::Instant(other_t)) => { + self_start <= other_t && other_t <= self_end + } + EventPayload::Integer(_) => false, + }, + _ => false, + } + } + + pub fn duration(&self) -> Option { + match *self { + EventPayload::Timestamp(Timestamp::Interval { start, end }) => { + end.duration_since(start).ok() + } + _ => None, + } + } + + pub fn is_interval(&self) -> bool { + matches!(self, &Self::Timestamp(Timestamp::Interval { .. })) + } + + pub fn is_instant(&self) -> bool { + matches!(self, &Self::Timestamp(Timestamp::Instant(_))) + } + + pub fn is_integer(&self) -> bool { + matches!(self, &Self::Integer(_)) + } + + pub fn start(&self) -> SystemTime { + match *self { + Self::Timestamp(t) => t.start(), + _ => unreachable!(), + } + } + + pub fn end(&self) -> SystemTime { + match *self { + Self::Timestamp(t) => t.end(), + _ => unreachable!(), + } + } + + pub fn timestamp(&self) -> Option { + match self { + Self::Timestamp(t) => Some(*t), + Self::Integer(_) => None, + } + } +} + +#[derive(Copy, Clone, Eq, PartialEq, Hash, Debug)] +pub enum Timestamp { + Interval { start: SystemTime, end: SystemTime }, + Instant(SystemTime), +} + +impl Timestamp { + pub fn from_raw_event(raw_event: &RawEvent, start_time: SystemTime) -> Self { + debug_assert!(!raw_event.is_integer()); + if raw_event.is_instant() { + let t = start_time + Duration::from_nanos(raw_event.start_value()); + Self::Instant(t) + } else { + let start = start_time + Duration::from_nanos(raw_event.start_value()); + let end = start_time + Duration::from_nanos(raw_event.end_value()); + Timestamp::Interval { start, end } + } + } + + pub fn contains(&self, t: SystemTime) -> bool { + match *self { + Timestamp::Interval { start, end } => t >= start && t < end, + Timestamp::Instant(_) => false, + } + } + + pub fn is_instant(&self) -> bool { + matches!(self, &Timestamp::Instant(_)) + } + + pub fn start(&self) -> SystemTime { + match *self { + Timestamp::Interval { start, .. } => start, + Timestamp::Instant(t) => t, + } + } + + pub fn end(&self) -> SystemTime { + match *self { + Timestamp::Interval { end, .. } => end, + Timestamp::Instant(t) => t, + } + } +} diff --git a/analyzeme/src/lib.rs b/analyzeme/src/lib.rs index b9a324b..9f26b4c 100644 --- a/analyzeme/src/lib.rs +++ b/analyzeme/src/lib.rs @@ -11,16 +11,16 @@ //! call the [`ProfilingData::iter()`] method. mod event; +mod event_payload; mod lightweight_event; mod profiling_data; mod stack_collapse; mod stringtable; pub mod testing_common; -mod timestamp; pub use crate::event::Event; +pub use crate::event_payload::{EventPayload, Timestamp}; pub use crate::lightweight_event::LightweightEvent; pub use crate::profiling_data::{ProfilingData, ProfilingDataBuilder}; pub use crate::stack_collapse::collapse_stacks; pub use crate::stringtable::{StringRef, StringTable}; -pub use crate::timestamp::Timestamp; diff --git a/analyzeme/src/lightweight_event.rs b/analyzeme/src/lightweight_event.rs index ee51f38..781e854 100644 --- a/analyzeme/src/lightweight_event.rs +++ b/analyzeme/src/lightweight_event.rs @@ -1,15 +1,15 @@ use crate::event::Event; +use crate::event_payload::{EventPayload, Timestamp}; use crate::profiling_data::ProfilingData; -use crate::timestamp::Timestamp; use std::hash::{Hash, Hasher}; -use std::time::Duration; +use std::time::{Duration, SystemTime}; #[derive(Clone, Debug)] pub struct LightweightEvent<'a> { pub data: &'a ProfilingData, pub event_index: usize, pub thread_id: u32, - pub timestamp: Timestamp, + pub payload: EventPayload, } impl<'a> LightweightEvent<'a> { @@ -20,26 +20,23 @@ impl<'a> LightweightEvent<'a> { /// Returns true if the time interval of `self` completely contains the /// time interval of `other`. pub fn contains(&self, other: &LightweightEvent) -> bool { - match self.timestamp { - Timestamp::Interval { - start: self_start, - end: self_end, - } => match other.timestamp { - Timestamp::Interval { - start: other_start, - end: other_end, - } => self_start <= other_start && other_end <= self_end, - Timestamp::Instant(other_t) => self_start <= other_t && other_t <= self_end, - }, - Timestamp::Instant(_) => false, - } + self.payload.contains(&other.payload) } pub fn duration(&self) -> Option { - match self.timestamp { - Timestamp::Interval { start, end } => end.duration_since(start).ok(), - Timestamp::Instant(_) => None, - } + self.payload.duration() + } + + pub fn start(&self) -> SystemTime { + self.payload.start() + } + + pub fn end(&self) -> SystemTime { + self.payload.end() + } + + pub fn timestamp(&self) -> Option { + self.payload.timestamp() } } @@ -49,20 +46,20 @@ impl<'a> PartialEq for LightweightEvent<'a> { data, event_index, thread_id, - timestamp, + payload, } = *self; let LightweightEvent { data: other_data, event_index: other_event_index, thread_id: other_thread_id, - timestamp: other_timestamp, + payload: other_payload, } = *other; std::ptr::eq(data, other_data) && event_index == other_event_index && thread_id == other_thread_id - && timestamp == other_timestamp + && payload == other_payload } } @@ -74,12 +71,12 @@ impl<'a> Hash for LightweightEvent<'a> { data, event_index, thread_id, - timestamp, + payload, } = *self; std::ptr::hash(data, state); event_index.hash(state); thread_id.hash(state); - timestamp.hash(state); + payload.hash(state); } } diff --git a/analyzeme/src/profiling_data.rs b/analyzeme/src/profiling_data.rs index 5b280c3..5b93833 100644 --- a/analyzeme/src/profiling_data.rs +++ b/analyzeme/src/profiling_data.rs @@ -1,6 +1,6 @@ use crate::event::Event; +use crate::event_payload::EventPayload; use crate::lightweight_event::LightweightEvent; -use crate::timestamp::Timestamp; use crate::StringTable; use measureme::file_header::{ verify_file_header, write_file_header, FILE_EXTENSION, FILE_HEADER_SIZE, @@ -141,7 +141,7 @@ impl ProfilingData { let string_table = &self.string_table; - let timestamp = Timestamp::from_raw_event(&raw_event, self.metadata.start_time); + let payload = EventPayload::from_raw_event(&raw_event, self.metadata.start_time); let event_id = string_table .get(raw_event.event_id.to_string_id()) @@ -153,7 +153,7 @@ impl ProfilingData { event_kind: string_table.get(raw_event.event_kind).to_string(), label, additional_data, - timestamp, + payload, thread_id: raw_event.thread_id, } } @@ -165,12 +165,12 @@ impl ProfilingData { let raw_event_bytes = &self.event_data[event_start_addr..event_end_addr]; let raw_event = RawEvent::deserialize(raw_event_bytes); - let timestamp = Timestamp::from_raw_event(&raw_event, self.metadata.start_time); + let payload = EventPayload::from_raw_event(&raw_event, self.metadata.start_time); LightweightEvent { data: self, event_index, - timestamp, + payload, thread_id: raw_event.thread_id, } } @@ -306,7 +306,6 @@ impl ProfilingDataBuilder { ) -> &mut Self { let event_kind = self.string_table.alloc(event_kind); let event_id = EventId::from_label(self.string_table.alloc(event_id)); - let raw_event = RawEvent::new_instant(event_kind, event_id, thread_id, timestamp_nanos); self.write_raw_event(&raw_event); @@ -314,6 +313,23 @@ impl ProfilingDataBuilder { self } + /// Record and instant event with the given data. + pub fn integer( + &mut self, + event_kind: &str, + event_id: &str, + thread_id: u32, + value: u64, + ) -> &mut Self { + let event_kind = self.string_table.alloc(event_kind); + let event_id = EventId::from_label(self.string_table.alloc(event_id)); + let raw_event = RawEvent::new_integer(event_kind, event_id, thread_id, value); + + self.write_raw_event(&raw_event); + + self + } + /// Convert this builder into a `ProfilingData` object that can be iterated. pub fn into_profiling_data(self) -> ProfilingData { // Drop the string table, so that the `string_table_data_sink` and @@ -383,6 +399,7 @@ impl ProfilerFiles { mod tests { use super::*; use std::borrow::Cow; + use crate::event_payload::Timestamp; use std::time::Duration; fn full_interval( @@ -396,10 +413,10 @@ mod tests { event_kind: Cow::from(event_kind), label: Cow::from(label), additional_data: Vec::new(), - timestamp: Timestamp::Interval { + payload: EventPayload::Timestamp(Timestamp::Interval { start: SystemTime::UNIX_EPOCH + Duration::from_nanos(start_nanos), end: SystemTime::UNIX_EPOCH + Duration::from_nanos(end_nanos), - }, + }), thread_id, } } @@ -414,9 +431,24 @@ mod tests { event_kind: Cow::from(event_kind), label: Cow::from(label), additional_data: Vec::new(), - timestamp: Timestamp::Instant( + payload: EventPayload::Timestamp(Timestamp::Instant( SystemTime::UNIX_EPOCH + Duration::from_nanos(timestamp_nanos), - ), + )), + thread_id, + } + } + + fn full_integer( + event_kind: &'static str, + label: &'static str, + thread_id: u32, + value: u64, + ) -> Event<'static> { + Event { + event_kind: Cow::from(event_kind), + label: Cow::from(label), + additional_data: Vec::new(), + payload: EventPayload::Integer(value), thread_id, } } @@ -432,10 +464,10 @@ mod tests { data, event_index, thread_id, - timestamp: Timestamp::Interval { + payload: EventPayload::Timestamp(Timestamp::Interval { start: SystemTime::UNIX_EPOCH + Duration::from_nanos(start_nanos), end: SystemTime::UNIX_EPOCH + Duration::from_nanos(end_nanos), - }, + }), } } @@ -449,9 +481,23 @@ mod tests { data, event_index, thread_id, - timestamp: Timestamp::Instant( + payload: EventPayload::Timestamp(Timestamp::Instant( SystemTime::UNIX_EPOCH + Duration::from_nanos(timestamp_nanos), - ), + )), + } + } + + fn lightweight_integer<'a>( + data: &'a ProfilingData, + event_index: usize, + thread_id: u32, + value: u64, + ) -> LightweightEvent<'a> { + LightweightEvent { + data, + event_index, + thread_id, + payload: EventPayload::Integer(value), } } @@ -508,10 +554,11 @@ mod tests { b.interval("k2", "id2", 0, 20, 92, |b| { b.interval("k3", "id3", 0, 30, 90, |b| { b.instant("k4", "id4", 0, 70); - b.instant("k5", "id5", 0, 75); + b.integer("k5", "id5", 0, 42); + b.instant("k6", "id6", 0, 75); }); }); - b.instant("k6", "id6", 0, 95); + b.instant("k7", "id7", 0, 95); }); let profiling_data = b.into_profiling_data(); @@ -519,17 +566,19 @@ mod tests { let events: Vec> = profiling_data.iter().collect(); assert_eq!(events[0], lightweight_instant(&profiling_data, 0, 0, 70)); - assert_eq!(events[1], lightweight_instant(&profiling_data, 1, 0, 75)); - assert_eq!(events[2], lightweight_interval(&profiling_data, 2, 0, 30, 90)); - assert_eq!(events[3], lightweight_interval(&profiling_data, 3, 0, 20, 92)); - assert_eq!(events[4], lightweight_instant(&profiling_data, 4, 0, 95)); - assert_eq!(events[5], lightweight_interval(&profiling_data, 5, 0, 10, 100)); + assert_eq!(events[1], lightweight_integer(&profiling_data, 1, 0, 42)); + assert_eq!(events[2], lightweight_instant(&profiling_data, 2, 0, 75)); + assert_eq!(events[3], lightweight_interval(&profiling_data, 3, 0, 30, 90)); + assert_eq!(events[4], lightweight_interval(&profiling_data, 4, 0, 20, 92)); + assert_eq!(events[5], lightweight_instant(&profiling_data, 5, 0, 95)); + assert_eq!(events[6], lightweight_interval(&profiling_data, 6, 0, 10, 100)); assert_eq!(events[0].to_event(), full_instant("k4", "id4", 0, 70)); - assert_eq!(events[1].to_event(), full_instant("k5", "id5", 0, 75)); - assert_eq!(events[2].to_event(), full_interval("k3", "id3", 0, 30, 90)); - assert_eq!(events[3].to_event(), full_interval("k2", "id2", 0, 20, 92)); - assert_eq!(events[4].to_event(), full_instant("k6", "id6", 0, 95)); - assert_eq!(events[5].to_event(), full_interval("k1", "id1", 0, 10, 100)); + assert_eq!(events[1].to_event(), full_integer("k5", "id5", 0, 42)); + assert_eq!(events[2].to_event(), full_instant("k6", "id6", 0, 75)); + assert_eq!(events[3].to_event(), full_interval("k3", "id3", 0, 30, 90)); + assert_eq!(events[4].to_event(), full_interval("k2", "id2", 0, 20, 92)); + assert_eq!(events[5].to_event(), full_instant("k7", "id7", 0, 95)); + assert_eq!(events[6].to_event(), full_interval("k1", "id1", 0, 10, 100)); } } diff --git a/analyzeme/src/stack_collapse.rs b/analyzeme/src/stack_collapse.rs index bdac92a..8b86262 100644 --- a/analyzeme/src/stack_collapse.rs +++ b/analyzeme/src/stack_collapse.rs @@ -24,19 +24,19 @@ pub fn collapse_stacks<'a>(profiling_data: &ProfilingData) -> FxHashMap PathBuf { let mut path = PathBuf::new(); @@ -163,8 +162,8 @@ fn check_profiling_data( assert_eq!(actual_event.label, expected_event.label); assert_eq!(actual_event.additional_data, expected_event.additional_data); assert_eq!( - actual_event.timestamp.is_instant(), - expected_event.timestamp.is_instant() + actual_event.payload.is_instant(), + expected_event.payload.is_instant() ); count += 1; @@ -235,9 +234,6 @@ fn pseudo_invocation( additional_data: expected_events_templates[random_event_index].args.clone(), thread_id, // We can't test this anyway: - timestamp: Timestamp::Interval { - start: SystemTime::UNIX_EPOCH, - end: SystemTime::UNIX_EPOCH, - }, + payload: EventPayload::Integer(0), }); } diff --git a/analyzeme/src/timestamp.rs b/analyzeme/src/timestamp.rs deleted file mode 100644 index 3eb6696..0000000 --- a/analyzeme/src/timestamp.rs +++ /dev/null @@ -1,49 +0,0 @@ -use measureme::RawEvent; -use std::time::{Duration, SystemTime}; - -#[derive(Copy, Clone, Eq, PartialEq, Hash, Debug)] -pub enum Timestamp { - Interval { start: SystemTime, end: SystemTime }, - Instant(SystemTime), -} - -impl Timestamp { - pub fn from_raw_event(raw_event: &RawEvent, start_time: SystemTime) -> Timestamp { - if raw_event.is_instant() { - let t = start_time + Duration::from_nanos(raw_event.start_nanos()); - Timestamp::Instant(t) - } else { - let start = start_time + Duration::from_nanos(raw_event.start_nanos()); - let end = start_time + Duration::from_nanos(raw_event.end_nanos()); - Timestamp::Interval { start, end } - } - } - - pub fn contains(&self, t: SystemTime) -> bool { - match *self { - Timestamp::Interval { start, end } => t >= start && t < end, - Timestamp::Instant(_) => false, - } - } - - pub fn is_instant(&self) -> bool { - match *self { - Timestamp::Interval { .. } => false, - Timestamp::Instant(_) => true, - } - } - - pub fn start(&self) -> SystemTime { - match *self { - Timestamp::Interval { start, .. } => start, - Timestamp::Instant(t) => t, - } - } - - pub fn end(&self) -> SystemTime { - match *self { - Timestamp::Interval { end, .. } => end, - Timestamp::Instant(t) => t, - } - } -} diff --git a/crox/src/main.rs b/crox/src/main.rs index fee72c2..5745a55 100644 --- a/crox/src/main.rs +++ b/crox/src/main.rs @@ -69,15 +69,18 @@ fn generate_thread_to_collapsed_thread_mapping( // collect start and end times for all threads let mut thread_start_and_end: FxHashMap = FxHashMap::default(); - for event in data.iter() { + for (thread_id, timestamp) in data + .iter() + .filter_map(|e| e.timestamp().map(|t| (e.thread_id, t))) + { thread_start_and_end - .entry(event.thread_id) + .entry(thread_id) .and_modify(|(thread_start, thread_end)| { - let (event_min, event_max) = timestamp_to_min_max(event.timestamp); + let (event_min, event_max) = timestamp_to_min_max(timestamp); *thread_start = cmp::min(*thread_start, event_min); *thread_end = cmp::max(*thread_end, event_max); }) - .or_insert_with(|| timestamp_to_min_max(event.timestamp)); + .or_insert_with(|| timestamp_to_min_max(timestamp)); } // collect the the threads in order of the end time let mut end_and_thread = thread_start_and_end @@ -149,7 +152,7 @@ fn main() -> Result<(), Box> { // Chrome does not seem to like how many QueryCacheHit events we generate // only handle Interval events for now - for event in data.iter().filter(|e| !e.timestamp.is_instant()) { + for event in data.iter().filter(|e| !e.payload.is_instant()) { let duration = event.duration().unwrap(); if let Some(minimum_duration) = opt.minimum_duration { if duration.as_micros() < minimum_duration { @@ -161,7 +164,7 @@ fn main() -> Result<(), Box> { name: full_event.label.clone().into_owned(), category: full_event.event_kind.clone().into_owned(), event_type: EventType::Complete, - timestamp: event.timestamp.start().duration_since(UNIX_EPOCH).unwrap(), + timestamp: event.payload.start().duration_since(UNIX_EPOCH).unwrap(), duration, process_id: data.metadata.process_id, thread_id: *thread_to_collapsed_thread diff --git a/measureme/src/lib.rs b/measureme/src/lib.rs index aabaeea..39516c2 100644 --- a/measureme/src/lib.rs +++ b/measureme/src/lib.rs @@ -50,8 +50,8 @@ pub mod stringtable; pub mod rustc; pub use crate::event_id::{EventId, EventIdBuilder}; -pub use crate::profiler::{Profiler, TimingGuard, DetachedTiming}; -pub use crate::raw_event::{RawEvent, MAX_INSTANT_TIMESTAMP, MAX_INTERVAL_TIMESTAMP}; +pub use crate::profiler::{DetachedTiming, Profiler, TimingGuard}; +pub use crate::raw_event::{RawEvent, MAX_INTERVAL_VALUE, MAX_SINGLE_VALUE}; pub use crate::serialization::{ split_streams, Addr, PageTag, SerializationSink, SerializationSinkBuilder, }; diff --git a/measureme/src/profiler.rs b/measureme/src/profiler.rs index d243d0f..0fdf417 100644 --- a/measureme/src/profiler.rs +++ b/measureme/src/profiler.rs @@ -104,6 +104,19 @@ impl Profiler { self.record_raw_event(&raw_event); } + /// Records an event with the given parameters. The event time is computed + /// automatically. + pub fn record_integer_event( + &self, + event_kind: StringId, + event_id: EventId, + thread_id: u32, + value: u64, + ) { + let raw_event = RawEvent::new_integer(event_kind, event_id, thread_id, value); + self.record_raw_event(&raw_event); + } + /// Creates a "start" event and returns a `TimingGuard` that will create /// the corresponding "end" event when it is dropped. #[inline] @@ -135,7 +148,7 @@ impl Profiler { &self, event_kind: StringId, event_id: EventId, - thread_id: u32 + thread_id: u32, ) -> DetachedTiming { DetachedTiming { event_id, @@ -148,10 +161,7 @@ impl Profiler { /// Creates the corresponding "end" event for /// the "start" event represented by `timing`. You /// must have obtained `timing` from the same `Profiler` - pub fn finish_recording_interval_event( - &self, - timing: DetachedTiming - ) { + pub fn finish_recording_interval_event(&self, timing: DetachedTiming) { drop(TimingGuard { profiler: self, event_id: timing.event_id, diff --git a/measureme/src/raw_event.rs b/measureme/src/raw_event.rs index d2a8d20..f181fb5 100644 --- a/measureme/src/raw_event.rs +++ b/measureme/src/raw_event.rs @@ -12,26 +12,36 @@ pub struct RawEvent { pub event_id: EventId, pub thread_id: u32, - // The following 96 bits store the start and the end counter value, using + // The following 96 bits store the payload values, using // 48 bits for each. - // FIXME(eddyb) s/time/count/ - pub start_time_lower: u32, - // FIXME(eddyb) s/time/count/ - pub end_time_lower: u32, - pub start_and_end_upper: u32, + // Interval: + // Payload 1 is start value and payload 2 is end value + // SSSSSSSSSSSSSSSSEEEEEEEEEEEEEEEESSSSSSSEEEEEEEEE + // [payload1_lower][payload2_lower][payloads_upper] + // Instant: + // Payload2 is 0xFFFF_FFFF_FFFF + // VVVVVVVVVVVVVVVV1111111111111111VVVVVVV11111111 + // [payload1_lower][payload2_lower][payloads_upper] + // Integer: + // Payload2 is 0xFFFF_FFFF_FFFE + // VVVVVVVVVVVVVVVV1111111111111111VVVVVVV11111110 + // [payload1_lower][payload2_lower][payloads_upper] + pub payload1_lower: u32, + pub payload2_lower: u32, + pub payloads_upper: u32, } -/// `RawEvents` that have an end counter value with this value are instant events. -const INSTANT_COUNT_MARKER: u64 = 0xFFFF_FFFF_FFFF; +/// `RawEvents` that have a payload 2 value with this value are instant events. +const INSTANT_MARKER: u64 = 0xFFFF_FFFF_FFFF; +/// `RawEvents` that have a payload 2 value with this value are integer events. +const INTEGER_MARKER: u64 = INSTANT_MARKER - 1; -/// The max instant counter value we can represent with the 48 bits available. -// FIXME(eddyb) s/TIMESTAMP/COUNT/ -pub const MAX_INSTANT_TIMESTAMP: u64 = 0xFFFF_FFFF_FFFF; +/// The max value we can represent with the 48 bits available. +pub const MAX_SINGLE_VALUE: u64 = 0xFFFF_FFFF_FFFF; -/// The max interval counter value we can represent with the 48 bits available. -/// The highest value is reserved for the `INSTANT_COUNT_MARKER`. -// FIXME(eddyb) s/TIMESTAMP/COUNT/ -pub const MAX_INTERVAL_TIMESTAMP: u64 = INSTANT_COUNT_MARKER - 1; +/// The max value we can represent with the 48 bits available. +/// The highest two values are reserved for the `INSTANT_MARKER` and `INTEGER_MARKER`. +pub const MAX_INTERVAL_VALUE: u64 = INTEGER_MARKER - 1; impl RawEvent { #[inline] @@ -39,70 +49,89 @@ impl RawEvent { event_kind: StringId, event_id: EventId, thread_id: u32, - start_count: u64, - end_count: u64, - ) -> RawEvent { - assert!(start_count <= end_count); - assert!(end_count <= MAX_INTERVAL_TIMESTAMP); + start: u64, + end: u64, + ) -> Self { + assert!(start <= end); + assert!(end <= MAX_INTERVAL_VALUE); - let start_time_lower = start_count as u32; - let end_time_lower = end_count as u32; - - let start_time_upper = (start_count >> 16) as u32 & 0xFFFF_0000; - let end_time_upper = (end_count >> 32) as u32; + Self::pack_values(event_kind, event_id, thread_id, start, end) + } - let start_and_end_upper = start_time_upper | end_time_upper; + #[inline] + pub fn new_instant( + event_kind: StringId, + event_id: EventId, + thread_id: u32, + instant: u64, + ) -> Self { + assert!(instant <= MAX_SINGLE_VALUE); + Self::pack_values(event_kind, event_id, thread_id, instant, INSTANT_MARKER) + } - RawEvent { - event_kind, - event_id, - thread_id, - start_time_lower, - end_time_lower, - start_and_end_upper, - } + #[inline] + pub fn new_integer( + event_kind: StringId, + event_id: EventId, + thread_id: u32, + value: u64, + ) -> Self { + assert!(value <= MAX_SINGLE_VALUE); + Self::pack_values(event_kind, event_id, thread_id, value, INTEGER_MARKER) } #[inline] - pub fn new_instant( + fn pack_values( event_kind: StringId, event_id: EventId, thread_id: u32, - count: u64, - ) -> RawEvent { - assert!(count <= MAX_INSTANT_TIMESTAMP); + value1: u64, + value2: u64, + ) -> Self { + let payload1_lower = value1 as u32; + let payload2_lower = value2 as u32; - let start_time_lower = count as u32; - let end_time_lower = 0xFFFF_FFFF; + let value1_upper = (value1 >> 16) as u32 & 0xFFFF_0000; + let value2_upper = (value2 >> 32) as u32; - let start_time_upper = (count >> 16) as u32; - let start_and_end_upper = start_time_upper | 0x0000_FFFF; + let payloads_upper = value1_upper | value2_upper; - RawEvent { + Self { event_kind, event_id, thread_id, - start_time_lower, - end_time_lower, - start_and_end_upper, + payload1_lower, + payload2_lower, + payloads_upper, } } + /// The start value assuming self is an interval + #[inline] + pub fn start_value(&self) -> u64 { + self.payload1_lower as u64 | (((self.payloads_upper & 0xFFFF_0000) as u64) << 16) + } + + /// The end value assuming self is an interval #[inline] - // FIXME(eddyb) s/nanos/count/ - pub fn start_nanos(&self) -> u64 { - self.start_time_lower as u64 | (((self.start_and_end_upper & 0xFFFF_0000) as u64) << 16) + pub fn end_value(&self) -> u64 { + self.payload2_lower as u64 | (((self.payloads_upper & 0x0000_FFFF) as u64) << 32) } + /// The value assuming self is an interval or integer. #[inline] - // FIXME(eddyb) s/nanos/count/ - pub fn end_nanos(&self) -> u64 { - self.end_time_lower as u64 | (((self.start_and_end_upper & 0x0000_FFFF) as u64) << 32) + pub fn value(&self) -> u64 { + self.payload1_lower as u64 | (((self.payloads_upper & 0xFFFF_0000) as u64) << 16) } #[inline] pub fn is_instant(&self) -> bool { - self.end_nanos() == INSTANT_COUNT_MARKER + self.end_value() == INSTANT_MARKER + } + + #[inline] + pub fn is_integer(&self) -> bool { + self.end_value() == INTEGER_MARKER } #[inline] @@ -128,9 +157,9 @@ impl RawEvent { bytes[0..4].copy_from_slice(&self.event_kind.as_u32().to_le_bytes()); bytes[4..8].copy_from_slice(&self.event_id.as_u32().to_le_bytes()); bytes[8..12].copy_from_slice(&self.thread_id.to_le_bytes()); - bytes[12..16].copy_from_slice(&self.start_time_lower.to_le_bytes()); - bytes[16..20].copy_from_slice(&self.end_time_lower.to_le_bytes()); - bytes[20..24].copy_from_slice(&self.start_and_end_upper.to_le_bytes()); + bytes[12..16].copy_from_slice(&self.payload1_lower.to_le_bytes()); + bytes[16..20].copy_from_slice(&self.payload2_lower.to_le_bytes()); + bytes[20..24].copy_from_slice(&self.payloads_upper.to_le_bytes()); } } @@ -157,9 +186,9 @@ impl RawEvent { event_kind: StringId::new(u32::from_le_bytes(bytes[0..4].try_into().unwrap())), event_id: EventId::from_u32(u32::from_le_bytes(bytes[4..8].try_into().unwrap())), thread_id: u32::from_le_bytes(bytes[8..12].try_into().unwrap()), - start_time_lower: u32::from_le_bytes(bytes[12..16].try_into().unwrap()), - end_time_lower: u32::from_le_bytes(bytes[16..20].try_into().unwrap()), - start_and_end_upper: u32::from_le_bytes(bytes[20..24].try_into().unwrap()), + payload1_lower: u32::from_le_bytes(bytes[12..16].try_into().unwrap()), + payload2_lower: u32::from_le_bytes(bytes[16..20].try_into().unwrap()), + payloads_upper: u32::from_le_bytes(bytes[20..24].try_into().unwrap()), } } } @@ -171,9 +200,9 @@ impl Default for RawEvent { event_kind: StringId::INVALID, event_id: EventId::INVALID, thread_id: 0, - start_time_lower: 0, - end_time_lower: 0, - start_and_end_upper: 0, + payload1_lower: 0, + payload2_lower: 0, + payloads_upper: 0, } } } @@ -192,22 +221,44 @@ mod tests { fn is_instant() { assert!(RawEvent::new_instant(StringId::INVALID, EventId::INVALID, 987, 0,).is_instant()); - assert!(RawEvent::new_instant( + assert!( + RawEvent::new_instant(StringId::INVALID, EventId::INVALID, 987, MAX_SINGLE_VALUE,) + .is_instant() + ); + + assert!(!RawEvent::new_interval( StringId::INVALID, EventId::INVALID, 987, - MAX_INSTANT_TIMESTAMP, + 0, + MAX_INTERVAL_VALUE, ) .is_instant()); + } + + #[test] + fn is_integer() { + let integer = RawEvent::new_integer(StringId::INVALID, EventId::INVALID, 987, 0); + assert!(integer.is_integer()); + assert_eq!(integer.value(), 0); + + let integer = RawEvent::new_integer(StringId::INVALID, EventId::INVALID, 987, 8769); + assert!(integer.is_integer()); + assert_eq!(integer.value(), 8769); + + assert!( + RawEvent::new_integer(StringId::INVALID, EventId::INVALID, 987, MAX_SINGLE_VALUE,) + .is_integer() + ); assert!(!RawEvent::new_interval( StringId::INVALID, EventId::INVALID, 987, 0, - MAX_INTERVAL_TIMESTAMP, + MAX_INTERVAL_VALUE, ) - .is_instant()); + .is_integer()); } #[test] @@ -218,7 +269,7 @@ mod tests { EventId::INVALID, 123, // count too large - MAX_INSTANT_TIMESTAMP + 1, + MAX_SINGLE_VALUE + 1, ); } @@ -230,8 +281,8 @@ mod tests { EventId::INVALID, 123, // start count too large - MAX_INTERVAL_TIMESTAMP + 1, - MAX_INTERVAL_TIMESTAMP + 1, + MAX_INTERVAL_VALUE + 1, + MAX_INTERVAL_VALUE + 1, ); } @@ -244,20 +295,14 @@ mod tests { 123, 0, // end count too large - MAX_INTERVAL_TIMESTAMP + 3, + MAX_INTERVAL_VALUE + 3, ); } #[test] #[should_panic] fn invalid_end_count2() { - let _ = RawEvent::new_interval( - StringId::INVALID, - EventId::INVALID, - 123, - 0, - INSTANT_COUNT_MARKER, - ); + let _ = RawEvent::new_interval(StringId::INVALID, EventId::INVALID, 123, 0, INTEGER_MARKER); } #[test] @@ -286,18 +331,18 @@ mod tests { StringId::INVALID, EventId::INVALID, 1234, - MAX_INTERVAL_TIMESTAMP, - MAX_INTERVAL_TIMESTAMP, + MAX_INTERVAL_VALUE, + MAX_INTERVAL_VALUE, ); - assert_eq!(e.start_nanos(), MAX_INTERVAL_TIMESTAMP); - assert_eq!(e.end_nanos(), MAX_INTERVAL_TIMESTAMP); + assert_eq!(e.start_value(), MAX_INTERVAL_VALUE); + assert_eq!(e.end_value(), MAX_INTERVAL_VALUE); // Check the lower limits let e = RawEvent::new_interval(StringId::INVALID, EventId::INVALID, 1234, 0, 0); - assert_eq!(e.start_nanos(), 0); - assert_eq!(e.end_nanos(), 0); + assert_eq!(e.start_value(), 0); + assert_eq!(e.end_value(), 0); // Check that end does not bleed into start let e = RawEvent::new_interval( @@ -305,11 +350,11 @@ mod tests { EventId::INVALID, 1234, 0, - MAX_INTERVAL_TIMESTAMP, + MAX_INTERVAL_VALUE, ); - assert_eq!(e.start_nanos(), 0); - assert_eq!(e.end_nanos(), MAX_INTERVAL_TIMESTAMP); + assert_eq!(e.start_value(), 0); + assert_eq!(e.end_value(), MAX_INTERVAL_VALUE); // Test some random values let e = RawEvent::new_interval( @@ -320,26 +365,45 @@ mod tests { 0x1234567890A, ); - assert_eq!(e.start_nanos(), 0x1234567890); - assert_eq!(e.end_nanos(), 0x1234567890A); + assert_eq!(e.start_value(), 0x1234567890); + assert_eq!(e.end_value(), 0x1234567890A); } #[test] fn instant_count_decoding() { assert_eq!( - RawEvent::new_instant(StringId::INVALID, EventId::INVALID, 987, 0,).start_nanos(), + RawEvent::new_instant(StringId::INVALID, EventId::INVALID, 987, 0,).start_value(), 0 ); assert_eq!( - RawEvent::new_instant( - StringId::INVALID, - EventId::INVALID, - 987, - MAX_INSTANT_TIMESTAMP, - ) - .start_nanos(), - MAX_INSTANT_TIMESTAMP + RawEvent::new_instant(StringId::INVALID, EventId::INVALID, 987, 42,).start_value(), + 42 + ); + + assert_eq!( + RawEvent::new_instant(StringId::INVALID, EventId::INVALID, 987, MAX_SINGLE_VALUE,) + .start_value(), + MAX_SINGLE_VALUE + ); + } + + #[test] + fn integer_decoding() { + assert_eq!( + RawEvent::new_integer(StringId::INVALID, EventId::INVALID, 987, 0,).start_value(), + 0 + ); + + assert_eq!( + RawEvent::new_integer(StringId::INVALID, EventId::INVALID, 987, 42,).start_value(), + 42 + ); + + assert_eq!( + RawEvent::new_integer(StringId::INVALID, EventId::INVALID, 987, MAX_SINGLE_VALUE,) + .start_value(), + MAX_SINGLE_VALUE ); } } diff --git a/mmview/src/main.rs b/mmview/src/main.rs index 45f7041..c3881a1 100644 --- a/mmview/src/main.rs +++ b/mmview/src/main.rs @@ -1,4 +1,4 @@ -use analyzeme::{Event, ProfilingData, Timestamp}; +use analyzeme::{Event, EventPayload, ProfilingData, Timestamp}; use std::error::Error; use std::path::PathBuf; use std::time::{Duration, SystemTime}; @@ -18,7 +18,7 @@ fn main() -> Result<(), Box> { let data = ProfilingData::new(&opt.file_prefix)?; - if let Some(global_start_time) = data.iter().map(|e| e.timestamp.start()).min() { + if let Some(global_start_time) = data.iter().map(|e| e.payload.start()).min() { for event in data.iter() { if let Some(thread_id) = opt.thread_id { if event.thread_id != thread_id { @@ -43,15 +43,16 @@ fn system_time_to_micros_since(t: SystemTime, since: SystemTime) -> u128 { fn print_event(event: &Event<'_>, global_start_time: SystemTime) { let additional_data = event.additional_data.join(","); - let timestamp = match event.timestamp { - Timestamp::Instant(t) => { + let payload = match event.payload { + EventPayload::Timestamp(Timestamp::Instant(t)) => { format!("{} μs", system_time_to_micros_since(t, global_start_time)) } - Timestamp::Interval { start, end } => format!( + EventPayload::Timestamp(Timestamp::Interval { start, end }) => format!( "{} μs - {} μs", system_time_to_micros_since(start, global_start_time), system_time_to_micros_since(end, global_start_time) ), + EventPayload::Integer(i) => format!("{}", i), }; println!( @@ -59,9 +60,9 @@ fn print_event(event: &Event<'_>, global_start_time: SystemTime) { kind: {}, label: {}, additional_data: [{}], - timestamp: {}, + payload: {}, thread_id: {}, }}"#, - event.event_kind, event.label, additional_data, timestamp, event.thread_id + event.event_kind, event.label, additional_data, payload, event.thread_id ); } diff --git a/summarize/src/aggregate.rs b/summarize/src/aggregate.rs index 21b4bbe..eda6ae0 100644 --- a/summarize/src/aggregate.rs +++ b/summarize/src/aggregate.rs @@ -29,7 +29,7 @@ mod backwards_iter { } use self::backwards_iter::{BackwardsIterator, BackwardsIteratorExt as _}; -use analyzeme::{Event, ProfilingData, Timestamp}; +use analyzeme::{Event, EventPayload, ProfilingData, Timestamp}; use measureme::rustc::*; use std::borrow::Cow; use std::collections::BTreeMap; @@ -115,7 +115,12 @@ impl SamplePoint { impl SamplePoint>> { fn timestamp(&self) -> SystemTime { - match (self, self.event().this.timestamp) { + let timestamp = match self.event().this.payload { + EventPayload::Timestamp(t) => t, + _ => unreachable!(), + }; + + match (self, timestamp) { (SamplePoint::Start(_), Timestamp::Interval { start, .. }) => start, (SamplePoint::End(_), Timestamp::Interval { end, .. }) => end, (SamplePoint::Instant(_), Timestamp::Instant(time)) => time, @@ -128,18 +133,20 @@ impl SamplePoint>> { } } -struct SamplePoints<'a, I: DoubleEndedIterator>> { +struct SamplePoints<'a> { /// This analysis only works with deterministic runs, which precludes parallelism, /// so we just have to find the *only* thread's ID and require there is no other. expected_thread_id: u32, - rev_events: std::iter::Peekable>, + rev_events: std::iter::Peekable> + 'a>>, stack: Vec>, } -impl<'a, I: DoubleEndedIterator>> SamplePoints<'a, I> { - fn new(events: I) -> Self { - let mut rev_events = events.rev().peekable(); +impl<'a> SamplePoints<'a> { + fn new<'b: 'a, I: Iterator> + DoubleEndedIterator + 'b>(events: I) -> Self { + let mut rev_events = (Box::new(events.rev().filter(|e| !e.payload.is_integer())) + as Box>>) + .peekable(); SamplePoints { // The `0` default doesn't matter, if there are no events. expected_thread_id: rev_events.peek().map_or(0, |event| event.thread_id), @@ -154,11 +161,11 @@ impl<'a, I: DoubleEndedIterator>> SamplePoints<'a, I> { } } -impl<'a, I: DoubleEndedIterator>> BackwardsIterator for SamplePoints<'a, I> { +impl<'a> BackwardsIterator for SamplePoints<'a> { type Item = SamplePoint>>; fn next_back(&mut self) -> Option { let sample_point = match self.rev_events.peek() { - Some(peeked_event) => { + Some(peeked_event) if !peeked_event.payload.is_integer() => { assert_eq!( peeked_event.thread_id, self.expected_thread_id, "more than one thread is not supported in `summarize aggregate`" @@ -170,21 +177,28 @@ impl<'a, I: DoubleEndedIterator>> BackwardsIterator for SampleP Some(top_event) if !top_event.contains(peeked_event) => { SamplePoint::Start(self.stack.pop().unwrap()) } + Some(_) => unreachable!(), _ => { let event = self.rev_events.next().unwrap(); - match event.timestamp { - Timestamp::Interval { .. } => { + match event.payload { + EventPayload::Timestamp(Timestamp::Interval { .. }) => { // Now entering this new event. self.stack.push(event.clone()); SamplePoint::End(event) } - Timestamp::Instant(_) => SamplePoint::Instant(event), + EventPayload::Timestamp(Timestamp::Instant(_)) => { + SamplePoint::Instant(event) + } + EventPayload::Integer(_) => { + unreachable!() + } } } } } + Some(_) => unreachable!(), // Ran out of events, but we might still have stack entries to leave. None => SamplePoint::Start(self.stack.pop()?), diff --git a/summarize/src/analysis.rs b/summarize/src/analysis.rs index 56c5f45..687af25 100644 --- a/summarize/src/analysis.rs +++ b/summarize/src/analysis.rs @@ -1,5 +1,5 @@ use crate::query_data::{QueryData, Results}; -use analyzeme::{Event, ProfilingData, Timestamp}; +use analyzeme::{Event, EventPayload, ProfilingData, Timestamp}; use measureme::rustc::*; use rustc_hash::FxHashMap; use std::borrow::Cow; @@ -133,8 +133,8 @@ pub fn perform_analysis(data: ProfilingData) -> Results { .rev() .map(|lightweight_event| lightweight_event.to_event()) { - match current_event.timestamp { - Timestamp::Instant(_) => { + match current_event.payload { + EventPayload::Timestamp(Timestamp::Instant(_)) => { if ¤t_event.event_kind[..] == QUERY_CACHE_HIT_EVENT_KIND { record_event_data(¤t_event.label, &|data| { data.number_of_cache_hits += 1; @@ -142,7 +142,7 @@ pub fn perform_analysis(data: ProfilingData) -> Results { }); } } - Timestamp::Interval { start, end } => { + EventPayload::Timestamp(Timestamp::Interval { start, end }) => { // This is an interval event let thread = threads @@ -252,6 +252,7 @@ pub fn perform_analysis(data: ProfilingData) -> Results { // Bring the stack up-to-date thread.stack.push(current_event) } + EventPayload::Integer(_) => todo!("Handle integers"), } } From 1cfe8bcdfd2324165d54fe2ab2a554dfd0544ca2 Mon Sep 17 00:00:00 2001 From: Ryan Levick Date: Fri, 23 Jul 2021 16:23:52 +0200 Subject: [PATCH 2/5] Handle artifact sizes --- summarize/src/analysis.rs | 8 +++++-- summarize/src/diff.rs | 42 ++++++++++++++++++++++++++++++++++--- summarize/src/main.rs | 31 +++++++++++++++++++++++++++ summarize/src/query_data.rs | 30 ++++++++++++++++++++++++++ 4 files changed, 106 insertions(+), 5 deletions(-) diff --git a/summarize/src/analysis.rs b/summarize/src/analysis.rs index 687af25..d4edc32 100644 --- a/summarize/src/analysis.rs +++ b/summarize/src/analysis.rs @@ -1,4 +1,4 @@ -use crate::query_data::{QueryData, Results}; +use crate::query_data::{ArtifactSize, QueryData, Results}; use analyzeme::{Event, EventPayload, ProfilingData, Timestamp}; use measureme::rustc::*; use rustc_hash::FxHashMap; @@ -116,6 +116,7 @@ pub fn perform_analysis(data: ProfilingData) -> Results { } let mut query_data = FxHashMap::::default(); + let mut artifact_sizes = Vec::::default(); let mut threads = FxHashMap::<_, PerThreadState>::default(); let mut record_event_data = |label: &Cow<'_, str>, f: &dyn Fn(&mut QueryData)| { @@ -252,7 +253,9 @@ pub fn perform_analysis(data: ProfilingData) -> Results { // Bring the stack up-to-date thread.stack.push(current_event) } - EventPayload::Integer(_) => todo!("Handle integers"), + EventPayload::Integer(value) => { + artifact_sizes.push(ArtifactSize::new(current_event.label.into_owned(), value)) + } } } @@ -263,6 +266,7 @@ pub fn perform_analysis(data: ProfilingData) -> Results { Results { query_data: query_data.drain().map(|(_, value)| value).collect(), + artifact_sizes, total_time, } } diff --git a/summarize/src/diff.rs b/summarize/src/diff.rs index ce846c3..3bcad3c 100644 --- a/summarize/src/diff.rs +++ b/summarize/src/diff.rs @@ -1,19 +1,30 @@ -use crate::query_data::{QueryData, QueryDataDiff, Results}; +use crate::query_data::{ArtifactSize, ArtifactSizeDiff, QueryData, QueryDataDiff, Results}; use crate::signed_duration::SignedDuration; use rustc_hash::{FxHashMap, FxHashSet}; use serde::{Deserialize, Serialize}; +use std::collections::HashSet; use std::time::Duration; #[derive(Serialize, Deserialize)] pub struct DiffResults { pub query_data: Vec, + pub artifact_sizes: Vec, pub total_time: SignedDuration, } fn build_query_lookup(query_data: &[QueryData]) -> FxHashMap<&str, usize> { let mut lookup = FxHashMap::with_capacity_and_hasher(query_data.len(), Default::default()); - for i in 0..query_data.len() { - lookup.insert(&query_data[i].label[..], i); + for (i, data) in query_data.iter().enumerate() { + lookup.insert(&data.label[..], i); + } + + lookup +} + +fn build_artifact_lookup(artifact_sizes: &[ArtifactSize]) -> FxHashMap<&str, usize> { + let mut lookup = FxHashMap::with_capacity_and_hasher(artifact_sizes.len(), Default::default()); + for (i, data) in artifact_sizes.iter().enumerate() { + lookup.insert(&data.label[..], i); } lookup @@ -53,8 +64,33 @@ pub fn calculate_diff(base: Results, change: Results) -> DiffResults { query_data.sort_by(|l, r| r.self_time.duration.cmp(&l.self_time.duration)); + let base_data = build_artifact_lookup(&base.artifact_sizes); + let change_data = build_artifact_lookup(&change.artifact_sizes); + let all_labels = base + .artifact_sizes + .iter() + .chain(&change.artifact_sizes) + .map(|a| a.label.as_str()) + .collect::>(); + let mut artifact_sizes: Vec<_> = all_labels + .iter() + .map(|l| { + let b = base_data.get(l).map(|i| &base.artifact_sizes[*i]); + let c = change_data.get(l).map(|i| &change.artifact_sizes[*i]); + + match (b, c) { + (Some(b), Some(c)) => c.clone() - b.clone(), + (Some(_b), None) => todo!(), + (None, Some(_c)) => todo!(), + (None, None) => unreachable!(), + } + }) + .collect(); + artifact_sizes.sort_by(|l, r| r.size_change.cmp(&l.size_change)); + DiffResults { query_data, + artifact_sizes, total_time: sd(change.total_time) - sd(base.total_time), } } diff --git a/summarize/src/main.rs b/summarize/src/main.rs index 075cc73..435acdb 100644 --- a/summarize/src/main.rs +++ b/summarize/src/main.rs @@ -148,6 +148,24 @@ fn diff(opt: DiffOpt) -> Result<(), Box> { println!("Total cpu time: {:?}", results.total_time); + let mut table = Table::new(); + + table.add_row(row!("Item", "Artifact Size Change",)); + + for artifact_size in results.artifact_sizes { + let exclude = opt.exclude.iter().any(|e| artifact_size.label.contains(e)); + if exclude { + continue; + } + + table.add_row(row![ + artifact_size.label, + format!("{:.2?} bytes", artifact_size.size_change), + ]); + } + + table.printstd(); + Ok(()) } @@ -281,6 +299,19 @@ fn summarize(opt: SummarizeOpt) -> Result<(), Box> { ); } + let mut table = Table::new(); + + table.add_row(row!("Item", "Artifact Size",)); + + for artifact_size in results.artifact_sizes { + table.add_row(row![ + artifact_size.label, + format!("{:.2?} bytes", artifact_size.value), + ]); + } + + table.printstd(); + Ok(()) } diff --git a/summarize/src/query_data.rs b/summarize/src/query_data.rs index ab7156f..18b6679 100644 --- a/summarize/src/query_data.rs +++ b/summarize/src/query_data.rs @@ -125,6 +125,7 @@ fn percentage_change(base: Duration, change: Duration) -> f64 { #[derive(Serialize, Deserialize)] pub struct Results { pub query_data: Vec, + pub artifact_sizes: Vec, pub total_time: Duration, } @@ -135,3 +136,32 @@ impl Results { self.query_data.iter().find(|qd| qd.label == label).unwrap() } } + +#[derive(Serialize, Deserialize, Debug, Clone)] +pub struct ArtifactSize { + pub label: String, + pub value: u64, +} + +impl ArtifactSize { + pub fn new(label: String, value: u64) -> Self { + Self { label, value } + } +} + +#[derive(Serialize, Deserialize, Debug)] +pub struct ArtifactSizeDiff { + pub label: String, + pub size_change: i64, +} + +impl Sub for ArtifactSize { + type Output = ArtifactSizeDiff; + + fn sub(self, rhs: ArtifactSize) -> ArtifactSizeDiff { + ArtifactSizeDiff { + label: self.label, + size_change: self.value as i64 - rhs.value as i64, + } + } +} From e5d5cecf381e9362f0ca461221a840bf36cc4ce0 Mon Sep 17 00:00:00 2001 From: Ryan Levick Date: Mon, 26 Jul 2021 11:19:44 +0200 Subject: [PATCH 3/5] Clean up handling of intervals --- analyzeme/src/event.rs | 10 +--------- analyzeme/src/event_payload.rs | 25 ++++++++----------------- analyzeme/src/lightweight_event.rs | 10 ++++++---- analyzeme/src/stack_collapse.rs | 8 +++++--- crox/src/main.rs | 4 ++-- mmview/src/main.rs | 2 +- 6 files changed, 23 insertions(+), 36 deletions(-) diff --git a/analyzeme/src/event.rs b/analyzeme/src/event.rs index d51c3a8..110fa26 100644 --- a/analyzeme/src/event.rs +++ b/analyzeme/src/event.rs @@ -1,7 +1,7 @@ use crate::event_payload::EventPayload; use memchr::memchr; use std::borrow::Cow; -use std::time::{Duration, SystemTime}; +use std::time::Duration; #[derive(Clone, Eq, PartialEq, Hash, Debug)] pub struct Event<'a> { @@ -23,14 +23,6 @@ impl<'a> Event<'a> { self.payload.duration() } - pub fn start(&self) -> SystemTime { - self.payload.start() - } - - pub fn end(&self) -> SystemTime { - self.payload.end() - } - pub(crate) fn parse_event_id(event_id: Cow<'a, str>) -> (Cow<'a, str>, Vec>) { let event_id = match event_id { Cow::Owned(s) => Cow::Owned(s.into_bytes()), diff --git a/analyzeme/src/event_payload.rs b/analyzeme/src/event_payload.rs index 2671caa..e4f9be0 100644 --- a/analyzeme/src/event_payload.rs +++ b/analyzeme/src/event_payload.rs @@ -39,9 +39,7 @@ impl EventPayload { pub fn duration(&self) -> Option { match *self { - EventPayload::Timestamp(Timestamp::Interval { start, end }) => { - end.duration_since(start).ok() - } + EventPayload::Timestamp(t) => t.duration(), _ => None, } } @@ -58,20 +56,6 @@ impl EventPayload { matches!(self, &Self::Integer(_)) } - pub fn start(&self) -> SystemTime { - match *self { - Self::Timestamp(t) => t.start(), - _ => unreachable!(), - } - } - - pub fn end(&self) -> SystemTime { - match *self { - Self::Timestamp(t) => t.end(), - _ => unreachable!(), - } - } - pub fn timestamp(&self) -> Option { match self { Self::Timestamp(t) => Some(*t), @@ -123,4 +107,11 @@ impl Timestamp { Timestamp::Instant(t) => t, } } + + pub fn duration(&self) -> Option { + match *self { + Timestamp::Interval { start, end } => end.duration_since(start).ok(), + _ => None, + } + } } diff --git a/analyzeme/src/lightweight_event.rs b/analyzeme/src/lightweight_event.rs index 781e854..0c89507 100644 --- a/analyzeme/src/lightweight_event.rs +++ b/analyzeme/src/lightweight_event.rs @@ -27,12 +27,14 @@ impl<'a> LightweightEvent<'a> { self.payload.duration() } - pub fn start(&self) -> SystemTime { - self.payload.start() + // Returns start time if event is a timestamp + pub fn start(&self) -> Option { + self.payload.timestamp().map(|t| t.start()) } - pub fn end(&self) -> SystemTime { - self.payload.end() + // Returns end time if event is a timestamp + pub fn end(&self) -> Option { + self.payload.timestamp().map(|t| t.end()) } pub fn timestamp(&self) -> Option { diff --git a/analyzeme/src/stack_collapse.rs b/analyzeme/src/stack_collapse.rs index 8b86262..fc47607 100644 --- a/analyzeme/src/stack_collapse.rs +++ b/analyzeme/src/stack_collapse.rs @@ -26,17 +26,19 @@ pub fn collapse_stacks<'a>(profiling_data: &ProfilingData) -> FxHashMap Result<(), Box> { // Chrome does not seem to like how many QueryCacheHit events we generate // only handle Interval events for now - for event in data.iter().filter(|e| !e.payload.is_instant()) { + for event in data.iter().filter(|e| e.payload.is_interval()) { let duration = event.duration().unwrap(); if let Some(minimum_duration) = opt.minimum_duration { if duration.as_micros() < minimum_duration { @@ -164,7 +164,7 @@ fn main() -> Result<(), Box> { name: full_event.label.clone().into_owned(), category: full_event.event_kind.clone().into_owned(), event_type: EventType::Complete, - timestamp: event.payload.start().duration_since(UNIX_EPOCH).unwrap(), + timestamp: event.start().unwrap().duration_since(UNIX_EPOCH).unwrap(), duration, process_id: data.metadata.process_id, thread_id: *thread_to_collapsed_thread diff --git a/mmview/src/main.rs b/mmview/src/main.rs index c3881a1..6606873 100644 --- a/mmview/src/main.rs +++ b/mmview/src/main.rs @@ -18,7 +18,7 @@ fn main() -> Result<(), Box> { let data = ProfilingData::new(&opt.file_prefix)?; - if let Some(global_start_time) = data.iter().map(|e| e.payload.start()).min() { + if let Some(global_start_time) = data.iter().filter_map(|e| e.start()).min() { for event in data.iter() { if let Some(thread_id) = opt.thread_id { if event.thread_id != thread_id { From 0f767ae8dcd4a9b2da29252c2a3350feee005e9b Mon Sep 17 00:00:00 2001 From: Ryan Levick Date: Mon, 26 Jul 2021 11:34:33 +0200 Subject: [PATCH 4/5] Clean up --- analyzeme/src/stack_collapse.rs | 6 +++++- summarize/src/diff.rs | 4 ++-- summarize/src/query_data.rs | 14 ++++++++++++++ 3 files changed, 21 insertions(+), 3 deletions(-) diff --git a/analyzeme/src/stack_collapse.rs b/analyzeme/src/stack_collapse.rs index fc47607..7850c62 100644 --- a/analyzeme/src/stack_collapse.rs +++ b/analyzeme/src/stack_collapse.rs @@ -121,6 +121,7 @@ mod test { b.interval("Query", "e2", 0, 3, 9, |b| { b.interval("Query", "e1", 0, 4, 8, |b| { b.interval("Query", "e3", 0, 5, 7, |_| {}); + b.integer("ArtifactSize", "e3", 0, 100); }); }); @@ -156,9 +157,12 @@ mod test { b.interval("Query", "e1", 1, 1, 2, |_| {}); b.interval("Query", "e1", 1, 3, 4, |_| {}); - b.interval("Query", "e1", 2, 1, 2, |_| {}); + b.interval("Query", "e1", 2, 1, 2, |b| { + b.instant("Instant", "e4", 2, 100); + }); b.interval("Query", "e2", 2, 2, 5, |b| { b.interval("Query", "e3", 2, 3, 4, |_| {}); + b.integer("ArtifactSize", "e4", 2, 1); }); let profiling_data = b.into_profiling_data(); diff --git a/summarize/src/diff.rs b/summarize/src/diff.rs index 3bcad3c..f207016 100644 --- a/summarize/src/diff.rs +++ b/summarize/src/diff.rs @@ -80,8 +80,8 @@ pub fn calculate_diff(base: Results, change: Results) -> DiffResults { match (b, c) { (Some(b), Some(c)) => c.clone() - b.clone(), - (Some(_b), None) => todo!(), - (None, Some(_c)) => todo!(), + (Some(b), None) => b.invert(), + (None, Some(c)) => c.as_artifact_size_diff(), (None, None) => unreachable!(), } }) diff --git a/summarize/src/query_data.rs b/summarize/src/query_data.rs index 18b6679..cf9d17d 100644 --- a/summarize/src/query_data.rs +++ b/summarize/src/query_data.rs @@ -147,6 +147,20 @@ impl ArtifactSize { pub fn new(label: String, value: u64) -> Self { Self { label, value } } + + pub fn invert(&self) -> ArtifactSizeDiff { + ArtifactSizeDiff { + label: self.label.clone(), + size_change: -(self.value as i64), + } + } + + pub fn as_artifact_size_diff(&self) -> ArtifactSizeDiff { + ArtifactSizeDiff { + label: self.label.clone(), + size_change: self.value as i64, + } + } } #[derive(Serialize, Deserialize, Debug)] From be738296ab40df6cff34eb8bd1dda4c5229d9b90 Mon Sep 17 00:00:00 2001 From: Ryan Levick Date: Mon, 2 Aug 2021 18:24:43 +0200 Subject: [PATCH 5/5] Address PR nits --- analyzeme/src/event_payload.rs | 16 +++++++++------- analyzeme/src/profiling_data.rs | 2 +- 2 files changed, 10 insertions(+), 8 deletions(-) diff --git a/analyzeme/src/event_payload.rs b/analyzeme/src/event_payload.rs index e4f9be0..128400b 100644 --- a/analyzeme/src/event_payload.rs +++ b/analyzeme/src/event_payload.rs @@ -33,14 +33,15 @@ impl EventPayload { } EventPayload::Integer(_) => false, }, - _ => false, + EventPayload::Timestamp(Timestamp::Instant(_)) | EventPayload::Integer(_) => false, } } pub fn duration(&self) -> Option { - match *self { - EventPayload::Timestamp(t) => t.duration(), - _ => None, + if let EventPayload::Timestamp(t) = *self { + t.duration() + } else { + None } } @@ -109,9 +110,10 @@ impl Timestamp { } pub fn duration(&self) -> Option { - match *self { - Timestamp::Interval { start, end } => end.duration_since(start).ok(), - _ => None, + if let Timestamp::Interval { start, end } = *self { + end.duration_since(start).ok() + } else { + None } } } diff --git a/analyzeme/src/profiling_data.rs b/analyzeme/src/profiling_data.rs index 5b93833..17fbbd7 100644 --- a/analyzeme/src/profiling_data.rs +++ b/analyzeme/src/profiling_data.rs @@ -269,7 +269,7 @@ impl ProfilingDataBuilder { } } - /// Record and interval event. Provide an `inner` function for recording + /// Record an interval event. Provide an `inner` function for recording /// nested events. pub fn interval( &mut self,