use metadata for more info about events

deserialize metadata and store it in ProfilingData.
use the start_time as base for all event times.

to be able to use merge multiple crox logs:
use the porcess_id for the crox events.
use duration from epoch as timestamp in the crox events.

Author: andjo403

analyzeme/Cargo.toml

@@ -8,3 +8,5 @@ license = "MIT OR Apache-2.0"
 [dependencies]
 measureme = { path = "../measureme" }
 rustc-hash = "1.0.1"
+serde = { version = "1.0", features = [ "derive" ] }
+serde_json = "1.0"

analyzeme/src/profiling_data.rs

@@ -5,18 +5,38 @@ use measureme::file_header::{
 };
 use measureme::ByteVecSink;
 use measureme::{ProfilerFiles, RawEvent, SerializationSink, StringTable, StringTableBuilder};
+use serde::{Deserialize, Deserializer};
 use std::error::Error;
 use std::fs;
 use std::mem;
 use std::path::Path;
 use std::sync::Arc;
-use std::time::SystemTime;
+use std::time::{Duration, SystemTime, UNIX_EPOCH};
 
 const RAW_EVENT_SIZE: usize = mem::size_of::<RawEvent>();
 
+fn system_time_from_nanos<'de, D>(deserializer: D) -> Result<SystemTime, D::Error>
+where
+    D: Deserializer<'de>,
+{
+    let duration_from_epoch = Duration::from_nanos(u64::deserialize(deserializer)?);
+    Ok(UNIX_EPOCH
+        .checked_add(duration_from_epoch)
+        .expect("a time that can be represented as SystemTime"))
+}
+
+#[derive(Deserialize)]
+pub struct MetaData {
+    #[serde(deserialize_with = "system_time_from_nanos")]
+    pub start_time: SystemTime,
+    pub process_id: u32,
+    pub cmd: String,
+}
+
 pub struct ProfilingData {
     event_data: Vec<u8>,
     string_table: StringTable,
+    pub meta_data: MetaData,
 }
 
 impl ProfilingData {
@@ -39,9 +59,13 @@ impl ProfilingData {
 
         let string_table = StringTable::new(string_data, index_data)?;
 
+        let meta_data = string_table.get_metadata().to_string();
+        let meta_data: MetaData = serde_json::from_str(&meta_data)?;
+
         Ok(ProfilingData {
             string_table,
             event_data,
+            meta_data,
         })
     }
 
@@ -88,8 +112,7 @@ impl<'a> ProfilerEventIterator<'a> {
 
         let string_table = &self.data.string_table;
 
-        // FIXME: Lots of Rust code compiled in the seventies apparently.
-        let timestamp = Timestamp::from_raw_event(&raw_event, SystemTime::UNIX_EPOCH);
+        let timestamp = Timestamp::from_raw_event(&raw_event, self.data.meta_data.start_time);
 
         Event {
             event_kind: string_table.get(raw_event.event_kind).to_string(),
@@ -240,10 +263,16 @@ impl ProfilingDataBuilder {
             CURRENT_FILE_FORMAT_VERSION
         );
         let string_table = StringTable::new(data_bytes, index_bytes).unwrap();
+        let meta_data = MetaData {
+            start_time: UNIX_EPOCH,
+            process_id: 0,
+            cmd: "test cmd".to_string(),
+        };
 
         ProfilingData {
             event_data,
             string_table,
+            meta_data,
         }
     }
 

crox/src/main.rs

@@ -2,8 +2,7 @@ use rustc_hash::FxHashMap;
 use std::fs;
 use std::io::BufWriter;
 use std::path::PathBuf;
-use std::time::Duration;
-use std::time::SystemTime;
+use std::time::{Duration, SystemTime, UNIX_EPOCH};
 
 use analyzeme::{ProfilingData, Timestamp};
 
@@ -118,10 +117,6 @@ fn main() -> Result<(), Box<dyn std::error::Error>> {
 
     let chrome_file = BufWriter::new(fs::File::create("chrome_profiler.json")?);
 
-    //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 = 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();
@@ -142,9 +137,9 @@ fn main() -> Result<(), Box<dyn std::error::Error>> {
                     name: event.label.clone().into_owned(),
                     category: event.event_kind.clone().into_owned(),
                     event_type: EventType::Complete,
-                    timestamp: start.duration_since(first_event_timestamp).unwrap(),
+                    timestamp: start.duration_since(UNIX_EPOCH).unwrap(),
                     duration,
-                    process_id: 0,
+                    process_id: data.meta_data.process_id,
                     thread_id: *thread_to_collapsed_thread
                         .get(&event.thread_id)
                         .unwrap_or(&event.thread_id),
@@ -171,22 +166,3 @@ fn timestamp_to_min_max(timestamp: Timestamp) -> (SystemTime, SystemTime) {
         }
     }
 }
-
-// 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)
-}

measureme/src/stringtable.rs

@@ -295,6 +295,10 @@ impl StringTable {
     pub fn get<'a>(&'a self, id: StringId) -> StringRef<'a> {
         StringRef { id, table: self }
     }
+    pub fn get_metadata<'a>(&'a self) -> StringRef<'a> {
+        let id = StringId(METADATA_STRING_ID);
+        self.get(id)
+    }
 }
 
 #[cfg(test)]