Replace (start, stop) event pairs with interval events.

This reduces the number of events that need to be recorded.

Author: michaelwoerister

CHANGELOG.md

@@ -4,6 +4,10 @@
 ### Added
 - `flamegraph`: new tool that uses the `inferno` crate to generate flamegraph svg files ([GH-73])
 
+### Changed
+- `measureme`: Events are recorded in a more compact format ([GH-76])
+- `stack_collapse`: Removed the `--interval` commandline option ([GH-76])
+
 ## [0.4.0] - 2019-10-24
 ### Added
 - `measureme`: Added RAII-based API for recording events ([GH-70])
@@ -42,3 +46,4 @@
 [GH-60]: https://github.com/rust-lang/measureme/pull/60
 [GH-70]: https://github.com/rust-lang/measureme/pull/70
 [GH-73]: https://github.com/rust-lang/measureme/pull/73
+[GH-76]: https://github.com/rust-lang/measureme/pull/76

crox/src/main.rs

@@ -5,9 +5,10 @@ use std::path::PathBuf;
 use std::time::Duration;
 use std::time::SystemTime;
 
-use measureme::{MatchingEvent, ProfilingData};
+use measureme::{ProfilingData, Timestamp};
 
 use serde::{Serialize, Serializer};
+use std::cmp;
 use structopt::StructOpt;
 
 fn as_micros<S: Serializer>(d: &Duration, s: S) -> Result<S::Ok, S::Error> {
@@ -64,14 +65,12 @@ fn generate_thread_to_collapsed_thread_mapping(
         for event in data.iter() {
             thread_start_and_end
                 .entry(event.thread_id)
-                .and_modify(|(start, end)| {
-                    if *start > event.timestamp {
-                        *start = event.timestamp;
-                    } else if *end < event.timestamp {
-                        *end = event.timestamp;
-                    }
+                .and_modify(|(thread_start, thread_end)| {
+                    let (event_min, event_max) = timestamp_to_min_max(event.timestamp);
+                    *thread_start = cmp::min(*thread_start, event_min);
+                    *thread_end = cmp::max(*thread_end, event_max);
                 })
-                .or_insert_with(|| (event.timestamp, event.timestamp));
+                .or_insert_with(|| timestamp_to_min_max(event.timestamp));
         }
         // collect the the threads in order of the end time
         let mut end_and_thread = thread_start_and_end
@@ -120,37 +119,34 @@ fn main() -> Result<(), Box<dyn std::error::Error>> {
 
     //find the earlier timestamp (it should be the first event)
     //subtract one tick so that the start of the event shows in Chrome
-    let first_event_timestamp = data.iter().next().unwrap().timestamp - Duration::from_micros(1);
+    let first_event_timestamp = make_start_timestamp(&data);
 
     let mut serializer = serde_json::Serializer::new(chrome_file);
     let thread_to_collapsed_thread = generate_thread_to_collapsed_thread_mapping(&opt, &data);
-    let mut event_iterator = data.iter_matching_events();
+    let mut event_iterator = data.iter();
 
     //create an iterator so we can avoid allocating a Vec with every Event for serialization
     let json_event_iterator = std::iter::from_fn(|| {
         while let Some(event) = event_iterator.next() {
             // Chrome does not seem to like how many QueryCacheHit events we generate
             // only handle startStop events for now
-            if let MatchingEvent::StartStop(start, stop) = event {
-                let duration = stop.timestamp.duration_since(start.timestamp).unwrap();
+            if let Timestamp::Interval { start, end } = event.timestamp {
+                let duration = end.duration_since(start).unwrap();
                 if let Some(minimum_duration) = opt.minimum_duration {
                     if duration.as_micros() < minimum_duration {
                         continue;
                     }
                 }
                 return Some(Event {
-                    name: start.label.clone().into_owned(),
-                    category: start.event_kind.clone().into_owned(),
+                    name: event.label.clone().into_owned(),
+                    category: event.event_kind.clone().into_owned(),
                     event_type: EventType::Complete,
-                    timestamp: start
-                        .timestamp
-                        .duration_since(first_event_timestamp)
-                        .unwrap(),
+                    timestamp: start.duration_since(first_event_timestamp).unwrap(),
                     duration,
                     process_id: 0,
                     thread_id: *thread_to_collapsed_thread
-                        .get(&start.thread_id)
-                        .unwrap_or(&start.thread_id),
+                        .get(&event.thread_id)
+                        .unwrap_or(&event.thread_id),
                     args: None,
                 });
             }
@@ -163,3 +159,33 @@ fn main() -> Result<(), Box<dyn std::error::Error>> {
 
     Ok(())
 }
+
+fn timestamp_to_min_max(timestamp: Timestamp) -> (SystemTime, SystemTime) {
+    match timestamp {
+        Timestamp::Instant(t) => (t, t),
+        Timestamp::Interval { start, end } => {
+            // Usually start should always be greater than end, but let's not
+            // choke on invalid data here.
+            (cmp::min(start, end), cmp::max(start, end))
+        }
+    }
+}
+
+// FIXME: Move this to `ProfilingData` and base it on the `start_time` field
+//        from metadata.
+fn make_start_timestamp(data: &ProfilingData) -> SystemTime {
+    // We cannot assume the first event in the stream actually is the first
+    // event because interval events are emitted at their end. So in theory it
+    // is possible that the event with the earliest starting time is the last
+    // event in the stream (i.e. if there is an interval event that spans the
+    // entire execution of the profile).
+    //
+    // Let's be on the safe side and iterate the whole stream.
+    let min = data
+        .iter()
+        .map(|e| timestamp_to_min_max(e.timestamp).0)
+        .min()
+        .unwrap();
+
+    min - Duration::from_micros(1)
+}

flamegraph/src/main.rs

@@ -14,18 +14,14 @@ use inferno::flamegraph::{from_lines, Options as FlamegraphOptions};
 #[derive(StructOpt, Debug)]
 struct Opt {
     file_prefix: PathBuf,
-
-    /// The sampling interval in milliseconds
-    #[structopt(short = "i", long = "interval", default_value = "1")]
-    interval: u64,
 }
 
 fn main() -> Result<(), Box<dyn Error>> {
     let opt = Opt::from_args();
 
     let profiling_data = ProfilingData::new(&opt.file_prefix)?;
 
-    let recorded_stacks = collapse_stacks(profiling_data.iter(), opt.interval)
+    let recorded_stacks = collapse_stacks(&profiling_data)
         .iter()
         .map(|(unique_stack, count)| format!("{} {}", unique_stack, count))
         .collect::<Vec<_>>();

measureme/src/event.rs

@@ -1,13 +1,86 @@
-use crate::raw_event::TimestampKind;
+use crate::raw_event::RawEvent;
 use std::borrow::Cow;
-use std::time::SystemTime;
+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: &'a [Cow<'a, str>],
-    pub timestamp: SystemTime,
-    pub timestamp_kind: TimestampKind,
+    pub timestamp: Timestamp,
     pub thread_id: u64,
 }
+
+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,
+        }
+    }
+
+    pub fn duration(&self) -> Option<Duration> {
+        match self.timestamp {
+            Timestamp::Interval { start, end } => end.duration_since(start).ok(),
+            Timestamp::Instant(_) => 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) -> Timestamp {
+        if raw_event.end_ns == std::u64::MAX {
+            let t = start_time + Duration::from_nanos(raw_event.start_ns);
+            Timestamp::Instant(t)
+        } else {
+            let start = start_time + Duration::from_nanos(raw_event.start_ns);
+            let end = start_time + Duration::from_nanos(raw_event.end_ns);
+            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,
+        }
+    }
+}

measureme/src/file_header.rs

@@ -6,7 +6,7 @@ use crate::serialization::SerializationSink;
 use byteorder::{ByteOrder, LittleEndian};
 use std::error::Error;
 
-pub const CURRENT_FILE_FORMAT_VERSION: u32 = 0;
+pub const CURRENT_FILE_FORMAT_VERSION: u32 = 1;
 pub const FILE_MAGIC_EVENT_STREAM: &[u8; 4] = b"MMES";
 pub const FILE_MAGIC_STRINGTABLE_DATA: &[u8; 4] = b"MMSD";
 pub const FILE_MAGIC_STRINGTABLE_INDEX: &[u8; 4] = b"MMSI";

measureme/src/lib.rs

@@ -50,7 +50,6 @@
 //! [`ProfilingData::iter()`]: struct.ProfilingData.html#method.iter
 //! [`ProfilingData::iter_matching_events()`]: struct.ProfilingData.html#method.iter_matching_events
 //! [`StringId`]: struct.StringId.html
-//! [`TimestampKind`]: enum.TimestampKind.html
 
 #![deny(warnings)]
 
@@ -69,14 +68,14 @@ mod stringtable;
 pub mod rustc;
 pub mod testing_common;
 
-pub use crate::event::Event;
+pub use crate::event::{Event, Timestamp};
 #[cfg(any(not(target_arch = "wasm32"), target_os = "wasi"))]
 pub use crate::file_serialization_sink::FileSerializationSink;
 #[cfg(not(target_arch = "wasm32"))]
 pub use crate::mmap_serialization_sink::MmapSerializationSink;
 pub use crate::profiler::{Profiler, ProfilerFiles, TimingGuard};
-pub use crate::profiling_data::{MatchingEvent, ProfilingData, ProfilingDataBuilder};
-pub use crate::raw_event::{RawEvent, Timestamp, TimestampKind};
+pub use crate::profiling_data::{ProfilingData, ProfilingDataBuilder};
+pub use crate::raw_event::RawEvent;
 pub use crate::serialization::{Addr, ByteVecSink, SerializationSink};
 pub use crate::stringtable::{
     SerializableString, StringId, StringRef, StringTable, StringTableBuilder,

measureme/src/profiler.rs

@@ -1,5 +1,5 @@
 use crate::file_header::{write_file_header, FILE_MAGIC_EVENT_STREAM};
-use crate::raw_event::{RawEvent, Timestamp, TimestampKind};
+use crate::raw_event::RawEvent;
 use crate::serialization::SerializationSink;
 use crate::stringtable::{SerializableString, StringId, StringTableBuilder};
 use std::error::Error;
@@ -83,32 +83,38 @@ impl<S: SerializationSink> Profiler<S> {
 
     /// Records an event with the given parameters. The event time is computed
     /// automatically.
-    pub fn record_event(
-        &self,
+    pub fn record_instant_event(&self, event_kind: StringId, event_id: StringId, thread_id: u64) {
+        let raw_event =
+            RawEvent::new_instant(event_kind, event_id, thread_id, self.nanos_since_start());
+
+        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.
+    pub fn start_recording_interval_event<'a>(
+        &'a self,
         event_kind: StringId,
         event_id: StringId,
         thread_id: u64,
-        timestamp_kind: TimestampKind,
-    ) {
-        let duration_since_start = self.start_time.elapsed();
-        let nanos_since_start = duration_since_start.as_secs() * 1_000_000_000
-            + duration_since_start.subsec_nanos() as u64;
-        let timestamp = Timestamp::new(nanos_since_start, timestamp_kind);
-
-        let raw_event = RawEvent {
+    ) -> TimingGuard<'a, S> {
+        TimingGuard {
+            profiler: self,
+            event_id,
             event_kind,
-            id: event_id,
             thread_id,
-            timestamp,
-        };
+            start_ns: self.nanos_since_start(),
+        }
+    }
 
+    fn record_raw_event(&self, raw_event: &RawEvent) {
         self.event_sink
             .write_atomic(std::mem::size_of::<RawEvent>(), |bytes| {
                 debug_assert_eq!(bytes.len(), std::mem::size_of::<RawEvent>());
 
                 let raw_event_bytes: &[u8] = unsafe {
                     std::slice::from_raw_parts(
-                        &raw_event as *const _ as *const u8,
+                        raw_event as *const _ as *const u8,
                         std::mem::size_of::<RawEvent>(),
                     )
                 };
@@ -117,22 +123,9 @@ impl<S: SerializationSink> Profiler<S> {
             });
     }
 
-    /// Creates a "start" event and returns a `TimingGuard` that will create
-    /// the corresponding "end" event when it is dropped.
-    pub fn start_recording_interval_event<'a>(
-        &'a self,
-        event_kind: StringId,
-        event_id: StringId,
-        thread_id: u64,
-    ) -> TimingGuard<'a, S> {
-        self.record_event(event_kind, event_id, thread_id, TimestampKind::Start);
-
-        TimingGuard {
-            profiler: self,
-            event_id,
-            event_kind,
-            thread_id,
-        }
+    fn nanos_since_start(&self) -> u64 {
+        let duration_since_start = self.start_time.elapsed();
+        duration_since_start.as_secs() * 1_000_000_000 + duration_since_start.subsec_nanos() as u64
     }
 }
 
@@ -144,16 +137,20 @@ pub struct TimingGuard<'a, S: SerializationSink> {
     event_id: StringId,
     event_kind: StringId,
     thread_id: u64,
+    start_ns: u64,
 }
 
 impl<'a, S: SerializationSink> Drop for TimingGuard<'a, S> {
     #[inline]
     fn drop(&mut self) {
-        self.profiler.record_event(
+        let raw_event = RawEvent::new_interval(
             self.event_kind,
             self.event_id,
             self.thread_id,
-            TimestampKind::End,
+            self.start_ns,
+            self.profiler.nanos_since_start(),
         );
+
+        self.profiler.record_raw_event(&raw_event);
     }
 }