Move crates under a sub folder to clean up the code

crates/tracing-trace/Cargo.toml

@@ -0,0 +1,24 @@
+[package]
+name = "tracing-trace"
+version = "0.1.0"
+edition = "2021"
+
+# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
+
+[dependencies]
+color-spantrace = "0.2.1"
+fxprof-processed-profile = "0.7.0"
+serde = { version = "1.0.204", features = ["derive"] }
+serde_json = "1.0.120"
+tracing = "0.1.40"
+tracing-error = "0.2.0"
+tracing-subscriber = "0.3.18"
+byte-unit = { version = "5.1.4", default-features = false, features = [
+    "std",
+    "byte",
+    "serde",
+] }
+tokio = { version = "1.38.0", features = ["sync"] }
+
+[target.'cfg(any(target_os = "linux", target_os = "macos"))'.dependencies]
+libproc = "0.14.8"

crates/tracing-trace/src/bin/trace-to-callstats.rs

@@ -0,0 +1,21 @@
+use std::ffi::OsString;
+use std::io::Write;
+
+use serde_json::json;
+
+fn main() {
+    let input_file = std::env::args_os().nth(1).expect("missing <INPUT> file");
+    let input =
+        std::io::BufReader::new(std::fs::File::open(&input_file).expect("could not open <INPUT>"));
+    let trace = tracing_trace::TraceReader::new(input);
+    let profile = tracing_trace::processor::span_stats::to_call_stats(trace).unwrap();
+    let mut output_file = OsString::new();
+    output_file.push("callstats-");
+    output_file.push(input_file);
+    let mut output_file = std::io::BufWriter::new(std::fs::File::create(output_file).unwrap());
+    for (key, value) in profile {
+        serde_json::to_writer(&mut output_file, &json!({key: value})).unwrap();
+        writeln!(&mut output_file).unwrap();
+    }
+    output_file.flush().unwrap();
+}

crates/tracing-trace/src/bin/trace-to-firefox.rs

@@ -0,0 +1,18 @@
+use std::ffi::OsString;
+use std::io::Write;
+
+fn main() {
+    let input_file = std::env::args_os().nth(1).expect("missing <INPUT> file");
+    let input =
+        std::io::BufReader::new(std::fs::File::open(&input_file).expect("could not open <INPUT>"));
+    let trace = tracing_trace::TraceReader::new(input);
+    let profile =
+        tracing_trace::processor::firefox_profiler::to_firefox_profile(trace, "Meilisearch")
+            .unwrap();
+    let mut output_file = OsString::new();
+    output_file.push("firefox-");
+    output_file.push(input_file);
+    let mut output_file = std::io::BufWriter::new(std::fs::File::create(output_file).unwrap());
+    serde_json::to_writer(&mut output_file, &profile).unwrap();
+    output_file.flush().unwrap();
+}

crates/tracing-trace/src/entry.rs

@@ -0,0 +1,141 @@
+use std::borrow::Cow;
+
+use serde::{Deserialize, Serialize};
+use tracing::span::Id as TracingId;
+
+#[derive(Debug, Serialize, Deserialize)]
+pub enum Entry {
+    /// A code location was accessed for the first time
+    NewCallsite(NewCallsite),
+
+    /// A new thread was accessed
+    NewThread(NewThread),
+
+    /// A new call started
+    NewSpan(NewSpan),
+
+    /// An already in-flight call started doing work.
+    ///
+    /// For synchronous functions, open should always be followed immediately by enter, exit and close,
+    /// but for asynchronous functions, work can suspend (exiting the span without closing it), and then
+    /// later resume (entering the span again without opening it).
+    ///
+    /// The timer for a span only starts when the span is entered.
+    SpanEnter(SpanEnter),
+
+    /// An in-flight call suspended and paused work.
+    ///
+    /// For synchronous functions, exit should always be followed immediately by close,
+    /// but for asynchronous functions, work can suspend and then later resume.
+    ///
+    /// The timer for a span pauses when the span is exited.
+    SpanExit(SpanExit),
+
+    /// A call ended
+    SpanClose(SpanClose),
+
+    /// An event occurred
+    Event(Event),
+}
+
+#[derive(Clone, Copy, Debug, Serialize, Deserialize, PartialEq, Eq, Hash)]
+pub struct SpanId(u64);
+
+impl From<&TracingId> for SpanId {
+    fn from(value: &TracingId) -> Self {
+        Self(value.into_u64())
+    }
+}
+
+#[derive(Debug, Serialize, Deserialize)]
+pub struct NewCallsite {
+    pub call_id: ResourceId,
+    pub name: Cow<'static, str>,
+    pub module_path: Option<Cow<'static, str>>,
+    pub file: Option<Cow<'static, str>>,
+    pub line: Option<u32>,
+    pub target: Cow<'static, str>,
+}
+
+#[derive(Debug, Serialize, Deserialize)]
+pub struct NewThread {
+    pub thread_id: ResourceId,
+    pub name: Option<String>,
+}
+
+#[derive(Clone, Copy, Debug, Serialize, Deserialize)]
+pub struct SpanEnter {
+    pub id: SpanId,
+    pub time: std::time::Duration,
+    pub memory: Option<MemoryStats>,
+}
+
+#[derive(Clone, Copy, Debug, Serialize, Deserialize)]
+pub struct SpanExit {
+    pub id: SpanId,
+    pub time: std::time::Duration,
+    pub memory: Option<MemoryStats>,
+}
+
+#[derive(Clone, Copy, Debug, Serialize, Deserialize)]
+pub struct Event {
+    pub call_id: ResourceId,
+    pub thread_id: ResourceId,
+    pub parent_id: Option<SpanId>,
+    pub time: std::time::Duration,
+    pub memory: Option<MemoryStats>,
+}
+
+#[derive(Clone, Copy, Debug, Serialize, Deserialize)]
+pub struct NewSpan {
+    pub id: SpanId,
+    pub call_id: ResourceId,
+    pub parent_id: Option<SpanId>,
+    pub thread_id: ResourceId,
+}
+
+#[derive(Clone, Copy, Debug, Serialize, Deserialize)]
+pub struct SpanClose {
+    pub id: SpanId,
+    pub time: std::time::Duration,
+}
+
+/// A struct with a memory allocation stat.
+#[derive(Debug, Default, Clone, Copy, Serialize, Deserialize)]
+pub struct MemoryStats {
+    /// Resident set size, measured in bytes.
+    /// (same as VmRSS in /proc/<pid>/status).
+    pub resident: u64,
+}
+
+impl MemoryStats {
+    #[cfg(any(target_os = "linux", target_os = "macos"))]
+    pub fn fetch() -> Option<Self> {
+        use libproc::libproc::pid_rusage::{pidrusage, RUsageInfoV0};
+
+        match pidrusage(std::process::id() as i32) {
+            Ok(RUsageInfoV0 { ri_resident_size, .. }) => {
+                Some(MemoryStats { resident: ri_resident_size })
+            }
+            Err(_) => None, /* ignoring error to avoid spamming */
+        }
+    }
+
+    #[cfg(not(any(target_os = "linux", target_os = "macos")))]
+    pub fn fetch() -> Option<Self> {
+        None
+    }
+
+    pub fn checked_sub(self, other: Self) -> Option<Self> {
+        Some(Self { resident: self.resident.checked_sub(other.resident)? })
+    }
+}
+
+#[derive(Debug, Clone, Copy, Serialize, Deserialize, PartialEq, Eq, Hash)]
+pub struct ResourceId(pub(crate) usize);
+
+impl ResourceId {
+    pub fn to_usize(self) -> usize {
+        self.0
+    }
+}

crates/tracing-trace/src/error.rs

@@ -0,0 +1,21 @@
+#[derive(Debug)]
+pub enum Error {
+    Json(serde_json::Error),
+}
+
+impl std::error::Error for Error {}
+
+impl std::fmt::Display for Error {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.write_str("error de/serializing trace entry:")?;
+        match self {
+            Error::Json(error) => std::fmt::Display::fmt(&error, f),
+        }
+    }
+}
+
+impl From<serde_json::Error> for Error {
+    fn from(value: serde_json::Error) -> Self {
+        Self::Json(value)
+    }
+}

crates/tracing-trace/src/layer.rs

@@ -0,0 +1,208 @@
+use std::borrow::Cow;
+use std::collections::HashMap;
+use std::io::Write;
+use std::ops::ControlFlow;
+use std::sync::RwLock;
+
+use tracing::span::{Attributes, Id as TracingId};
+use tracing::{Metadata, Subscriber};
+use tracing_subscriber::layer::Context;
+use tracing_subscriber::Layer;
+
+use crate::entry::{
+    Entry, Event, MemoryStats, NewCallsite, NewSpan, NewThread, ResourceId, SpanClose, SpanEnter,
+    SpanExit, SpanId,
+};
+use crate::{Error, Trace, TraceWriter};
+
+/// Layer that measures the time spent in spans.
+pub struct TraceLayer {
+    sender: tokio::sync::mpsc::UnboundedSender<Entry>,
+    callsites: RwLock<HashMap<OpaqueIdentifier, ResourceId>>,
+    start_time: std::time::Instant,
+    profile_memory: bool,
+}
+
+impl Trace {
+    pub fn new(profile_memory: bool) -> (Self, TraceLayer) {
+        let (sender, receiver) = tokio::sync::mpsc::unbounded_channel();
+        let trace = Trace { receiver };
+        let layer = TraceLayer {
+            sender,
+            callsites: Default::default(),
+            start_time: std::time::Instant::now(),
+            profile_memory,
+        };
+        (trace, layer)
+    }
+}
+
+impl<W: Write> TraceWriter<W> {
+    pub fn new(writer: W, profile_memory: bool) -> (Self, TraceLayer) {
+        let (trace, layer) = Trace::new(profile_memory);
+        (trace.into_writer(writer), layer)
+    }
+
+    pub async fn receive(&mut self) -> Result<ControlFlow<(), ()>, Error> {
+        let Some(entry) = self.receiver.recv().await else {
+            return Ok(ControlFlow::Break(()));
+        };
+        self.write(entry)?;
+        Ok(ControlFlow::Continue(()))
+    }
+
+    /// Panics if called from an asynchronous context
+    pub fn blocking_receive(&mut self) -> Result<ControlFlow<(), ()>, Error> {
+        let Some(entry) = self.receiver.blocking_recv() else {
+            return Ok(ControlFlow::Break(()));
+        };
+        self.write(entry)?;
+        Ok(ControlFlow::Continue(()))
+    }
+
+    pub fn write(&mut self, entry: Entry) -> Result<(), Error> {
+        Ok(serde_json::ser::to_writer(&mut self.writer, &entry)?)
+    }
+
+    pub fn try_receive(&mut self) -> Result<ControlFlow<(), ()>, Error> {
+        let Ok(entry) = self.receiver.try_recv() else {
+            return Ok(ControlFlow::Break(()));
+        };
+        self.write(entry)?;
+        Ok(ControlFlow::Continue(()))
+    }
+
+    pub fn flush(&mut self) -> Result<(), std::io::Error> {
+        self.writer.flush()
+    }
+}
+
+#[derive(PartialEq, Eq, Hash)]
+enum OpaqueIdentifier {
+    Thread(std::thread::ThreadId),
+    Call(tracing::callsite::Identifier),
+}
+
+impl TraceLayer {
+    fn resource_id(&self, opaque: OpaqueIdentifier) -> Option<ResourceId> {
+        self.callsites.read().unwrap().get(&opaque).copied()
+    }
+
+    fn register_resource_id(&self, opaque: OpaqueIdentifier) -> ResourceId {
+        let mut map = self.callsites.write().unwrap();
+        let len = map.len();
+        *map.entry(opaque).or_insert(ResourceId(len))
+    }
+
+    fn elapsed(&self) -> std::time::Duration {
+        self.start_time.elapsed()
+    }
+
+    fn memory_stats(&self) -> Option<MemoryStats> {
+        if self.profile_memory {
+            MemoryStats::fetch()
+        } else {
+            None
+        }
+    }
+
+    fn send(&self, entry: Entry) {
+        // we never care that the other end hanged on us
+        let _ = self.sender.send(entry);
+    }
+
+    fn register_callsite(&self, metadata: &'static Metadata<'static>) -> ResourceId {
+        let call_id = self.register_resource_id(OpaqueIdentifier::Call(metadata.callsite()));
+
+        let module_path = metadata.module_path();
+        let file = metadata.file();
+        let line = metadata.line();
+        let name = metadata.name();
+        let target = metadata.target();
+
+        self.send(Entry::NewCallsite(NewCallsite {
+            call_id,
+            module_path: module_path.map(Cow::Borrowed),
+            file: file.map(Cow::Borrowed),
+            line,
+            name: Cow::Borrowed(name),
+            target: Cow::Borrowed(target),
+        }));
+        call_id
+    }
+
+    fn register_thread(&self) -> ResourceId {
+        let thread_id = std::thread::current().id();
+        let name = std::thread::current().name().map(ToOwned::to_owned);
+        let thread_id = self.register_resource_id(OpaqueIdentifier::Thread(thread_id));
+        self.send(Entry::NewThread(NewThread { thread_id, name }));
+        thread_id
+    }
+}
+
+impl<S> Layer<S> for TraceLayer
+where
+    S: Subscriber,
+{
+    fn on_new_span(&self, attrs: &Attributes<'_>, id: &TracingId, _ctx: Context<'_, S>) {
+        let call_id = self
+            .resource_id(OpaqueIdentifier::Call(attrs.metadata().callsite()))
+            .unwrap_or_else(|| self.register_callsite(attrs.metadata()));
+
+        let thread_id = self
+            .resource_id(OpaqueIdentifier::Thread(std::thread::current().id()))
+            .unwrap_or_else(|| self.register_thread());
+
+        let parent_id = attrs
+            .parent()
+            .cloned()
+            .or_else(|| tracing::Span::current().id())
+            .map(|id| SpanId::from(&id));
+
+        self.send(Entry::NewSpan(NewSpan { id: id.into(), call_id, parent_id, thread_id }));
+    }
+
+    fn on_enter(&self, id: &TracingId, _ctx: Context<'_, S>) {
+        self.send(Entry::SpanEnter(SpanEnter {
+            id: id.into(),
+            time: self.elapsed(),
+            memory: self.memory_stats(),
+        }))
+    }
+
+    fn on_exit(&self, id: &TracingId, _ctx: Context<'_, S>) {
+        self.send(Entry::SpanExit(SpanExit {
+            id: id.into(),
+            time: self.elapsed(),
+            memory: self.memory_stats(),
+        }))
+    }
+
+    fn on_event(&self, event: &tracing::Event<'_>, _ctx: Context<'_, S>) {
+        let call_id = self
+            .resource_id(OpaqueIdentifier::Call(event.metadata().callsite()))
+            .unwrap_or_else(|| self.register_callsite(event.metadata()));
+
+        let thread_id = self
+            .resource_id(OpaqueIdentifier::Thread(std::thread::current().id()))
+            .unwrap_or_else(|| self.register_thread());
+
+        let parent_id = event
+            .parent()
+            .cloned()
+            .or_else(|| tracing::Span::current().id())
+            .map(|id| SpanId::from(&id));
+
+        self.send(Entry::Event(Event {
+            call_id,
+            thread_id,
+            parent_id,
+            time: self.elapsed(),
+            memory: self.memory_stats(),
+        }))
+    }
+
+    fn on_close(&self, id: TracingId, _ctx: Context<'_, S>) {
+        self.send(Entry::SpanClose(SpanClose { id: Into::into(&id), time: self.elapsed() }))
+    }
+}

crates/tracing-trace/src/lib.rs

@@ -0,0 +1,54 @@
+use std::io::{Read, Write};
+
+use entry::Entry;
+
+pub mod entry;
+mod error;
+pub mod layer;
+pub mod processor;
+
+pub use error::Error;
+
+pub struct TraceWriter<W: Write> {
+    writer: W,
+    receiver: tokio::sync::mpsc::UnboundedReceiver<Entry>,
+}
+
+pub struct Trace {
+    receiver: tokio::sync::mpsc::UnboundedReceiver<Entry>,
+}
+
+impl Trace {
+    pub fn into_receiver(self) -> tokio::sync::mpsc::UnboundedReceiver<Entry> {
+        self.receiver
+    }
+
+    pub fn into_writer<W: Write>(self, writer: W) -> TraceWriter<W> {
+        TraceWriter { writer, receiver: self.receiver }
+    }
+}
+
+pub struct TraceReader<R: Read> {
+    reader: R,
+}
+
+impl<R: Read> TraceReader<R> {
+    pub fn new(reader: R) -> Self {
+        Self { reader }
+    }
+
+    fn read(&mut self) -> Option<Result<Entry, Error>> {
+        serde_json::Deserializer::from_reader(&mut self.reader)
+            .into_iter()
+            .next()
+            .map(|res| res.map_err(Into::into))
+    }
+}
+
+impl<R: Read> Iterator for TraceReader<R> {
+    type Item = Result<Entry, Error>;
+
+    fn next(&mut self) -> Option<Self::Item> {
+        self.read()
+    }
+}

crates/tracing-trace/src/main.rs

@@ -0,0 +1,122 @@
+use tracing::{instrument, Span};
+use tracing_error::{ErrorLayer, InstrumentResult, SpanTrace, TracedError};
+
+#[instrument(level = "trace", target = "profile::indexing")]
+fn foo() -> Result<(), TracedError<Error>> {
+    let _ = bar(40, 2);
+    bar(40, 2)
+}
+
+#[derive(Debug)]
+pub enum Error {
+    XTooBig,
+}
+
+impl std::fmt::Display for Error {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.write_str("x too big")
+    }
+}
+
+impl std::error::Error for Error {}
+
+#[instrument(level = "trace", target = "profile::indexing")]
+fn bar(x: u32, y: u32) -> Result<(), TracedError<Error>> {
+    let handle_ok = spawn_in_current_scope(move || baz(y));
+    let handle = spawn_in_current_scope(move || baz(x + y));
+    handle_ok.join().unwrap().and(handle.join().unwrap())
+}
+
+pub fn spawn_in_current_scope<F, T>(f: F) -> std::thread::JoinHandle<T>
+where
+    F: FnOnce() -> T + Send + 'static,
+    T: Send + 'static,
+{
+    let current = Span::current();
+    std::thread::spawn(move || {
+        let span = tracing::trace_span!(parent: &current, "thread_spawn", id = ?std::thread::current().id(), name = tracing::field::Empty);
+        if let Some(name) = std::thread::current().name() {
+            span.record("name", name);
+        }
+        span.in_scope(f)
+    })
+}
+
+#[instrument(level = "trace", target = "profile::indexing")]
+fn baz(x: u32) -> Result<(), TracedError<Error>> {
+    if x > 10 {
+        fibo_recursive(10);
+        return Err(Error::XTooBig).in_current_span();
+    }
+    Ok(())
+}
+
+#[instrument(level = "trace", target = "profile::indexing")]
+fn fibo_recursive(n: u32) -> u32 {
+    if n == 0 {
+        return 1;
+    }
+    if n == 1 {
+        return 2;
+    }
+    return fibo_recursive(n - 1) - fibo_recursive(n - 2);
+}
+
+use tracing_error::ExtractSpanTrace as _;
+use tracing_subscriber::layer::SubscriberExt as _;
+use tracing_trace::processor;
+
+fn on_panic(info: &std::panic::PanicInfo) {
+    let info = info.to_string();
+    let trace = SpanTrace::capture();
+    tracing::error!(%info, %trace);
+}
+
+fn main() {
+    let (mut trace, profiling_layer) =
+        tracing_trace::TraceWriter::new(std::fs::File::create("trace.json").unwrap(), true);
+
+    let subscriber = tracing_subscriber::registry()
+        // any number of other subscriber layers may be added before or
+        // after the `ErrorLayer`...
+        .with(ErrorLayer::default())
+        .with(profiling_layer);
+
+    // set the subscriber as the default for the application
+    tracing::subscriber::set_global_default(subscriber).unwrap();
+
+    std::panic::set_hook(Box::new(on_panic));
+
+    let res = foo();
+
+    if let Err(error) = res {
+        print_extracted_spantraces(&error)
+    }
+
+    while trace.try_receive().unwrap().is_continue() {}
+
+    trace.flush().unwrap();
+
+    let trace = tracing_trace::TraceReader::new(std::fs::File::open("trace.json").unwrap());
+
+    let profile = processor::firefox_profiler::to_firefox_profile(trace, "test").unwrap();
+    serde_json::to_writer(std::fs::File::create("processed.json").unwrap(), &profile).unwrap();
+}
+
+fn print_extracted_spantraces(error: &(dyn std::error::Error + 'static)) {
+    let mut error = Some(error);
+    let mut ind = 0;
+
+    eprintln!("Error:");
+
+    while let Some(err) = error {
+        if let Some(spantrace) = err.span_trace() {
+            eprintln!("found a spantrace:\n{}", color_spantrace::colorize(spantrace));
+        } else {
+            eprintln!("{:>4}: {}", ind, err);
+        }
+
+        error = err.source();
+        ind += 1;
+    }
+}

crates/tracing-trace/src/processor/firefox_profiler.rs

@@ -0,0 +1,451 @@
+use std::collections::HashMap;
+
+use fxprof_processed_profile::{
+    CategoryHandle, CategoryPairHandle, CounterHandle, CpuDelta, Frame, FrameFlags, FrameInfo,
+    MarkerDynamicField, MarkerFieldFormat, MarkerLocation, MarkerSchema, MarkerSchemaField,
+    ProcessHandle, Profile, ProfilerMarker, ReferenceTimestamp, SamplingInterval, StringHandle,
+    Timestamp,
+};
+use serde_json::json;
+
+use crate::entry::{
+    Entry, Event, MemoryStats, NewCallsite, NewSpan, ResourceId, SpanClose, SpanEnter, SpanExit,
+    SpanId,
+};
+use crate::{Error, TraceReader};
+
+pub fn to_firefox_profile<R: std::io::Read>(
+    trace: TraceReader<R>,
+    app: &str,
+) -> Result<Profile, Error> {
+    let mut profile = Profile::new(
+        app,
+        ReferenceTimestamp::from_millis_since_unix_epoch(0.0),
+        SamplingInterval::from_nanos(15),
+    );
+
+    let mut last_timestamp = Timestamp::from_nanos_since_reference(0);
+    let main = profile.add_process(app, 0, last_timestamp);
+
+    let mut calls = HashMap::new();
+    let mut threads = HashMap::new();
+    let mut spans = HashMap::new();
+
+    let category = profile.add_category("general", fxprof_processed_profile::CategoryColor::Blue);
+    let subcategory = profile.add_subcategory(category, "subcategory");
+
+    let mut last_memory = MemoryStats::default();
+
+    let mut memory_counters = None;
+
+    for entry in trace {
+        let entry = entry?;
+        match entry {
+            Entry::NewCallsite(callsite) => {
+                let string_handle = profile.intern_string(callsite.name.as_ref());
+                calls.insert(callsite.call_id, (callsite, string_handle));
+            }
+            Entry::NewThread(thread) => {
+                let thread_handle = profile.add_thread(
+                    main,
+                    thread.thread_id.to_usize() as u32,
+                    last_timestamp,
+                    threads.is_empty(),
+                );
+                if let Some(name) = &thread.name {
+                    profile.set_thread_name(thread_handle, name)
+                }
+                threads.insert(thread.thread_id, thread_handle);
+            }
+            Entry::NewSpan(span) => {
+                spans.insert(span.id, (span, SpanStatus::Outside));
+            }
+            Entry::SpanEnter(SpanEnter { id, time, memory }) => {
+                let (_span, status) = spans.get_mut(&id).unwrap();
+
+                let SpanStatus::Outside = status else {
+                    continue;
+                };
+
+                *status = SpanStatus::Inside { time, memory };
+
+                last_timestamp = Timestamp::from_nanos_since_reference(time.as_nanos() as u64);
+
+                add_memory_samples(
+                    &mut profile,
+                    main,
+                    memory,
+                    last_timestamp,
+                    &mut memory_counters,
+                    &mut last_memory,
+                );
+            }
+            Entry::SpanExit(SpanExit { id, time, memory }) => {
+                let (span, status) = spans.get_mut(&id).unwrap();
+
+                let SpanStatus::Inside { time: begin, memory: begin_memory } = status else {
+                    continue;
+                };
+                last_timestamp = Timestamp::from_nanos_since_reference(time.as_nanos() as u64);
+
+                let begin = *begin;
+                let begin_memory = *begin_memory;
+
+                *status = SpanStatus::Outside;
+
+                let span = *span;
+                let thread_handle = threads.get(&span.thread_id).unwrap();
+
+                let frames = make_frames(span, &spans, &calls, subcategory);
+
+                profile.add_sample(
+                    *thread_handle,
+                    to_timestamp(begin),
+                    frames.iter().rev().cloned(),
+                    CpuDelta::ZERO,
+                    1,
+                );
+                profile.add_sample(
+                    *thread_handle,
+                    to_timestamp(time),
+                    frames.iter().rev().cloned(),
+                    CpuDelta::from_nanos((time - begin).as_nanos() as u64),
+                    1,
+                );
+
+                add_memory_samples(
+                    &mut profile,
+                    main,
+                    memory,
+                    last_timestamp,
+                    &mut memory_counters,
+                    &mut last_memory,
+                );
+
+                let (callsite, _) = calls.get(&span.call_id).unwrap();
+
+                let memory_delta =
+                    begin_memory.zip(memory).and_then(|(begin, end)| end.checked_sub(begin));
+                let marker = SpanMarker { callsite, span: &span, memory_delta };
+
+                profile.add_marker_with_stack(
+                    *thread_handle,
+                    CategoryHandle::OTHER,
+                    &callsite.name,
+                    marker,
+                    fxprof_processed_profile::MarkerTiming::Interval(
+                        to_timestamp(begin),
+                        to_timestamp(time),
+                    ),
+                    frames.iter().rev().cloned(),
+                )
+            }
+            Entry::Event(event) => {
+                let span = event
+                    .parent_id
+                    .as_ref()
+                    .and_then(|parent_id| spans.get(parent_id))
+                    .and_then(|(span, status)| match status {
+                        SpanStatus::Outside => None,
+                        SpanStatus::Inside { .. } => Some(span),
+                    })
+                    .copied();
+                let timestamp = to_timestamp(event.time);
+
+                let thread_handle = threads.get(&event.thread_id).unwrap();
+
+                let frames = span
+                    .map(|span| make_frames(span, &spans, &calls, subcategory))
+                    .unwrap_or_default();
+
+                profile.add_sample(
+                    *thread_handle,
+                    timestamp,
+                    frames.iter().rev().cloned(),
+                    CpuDelta::ZERO,
+                    1,
+                );
+
+                let memory_delta = add_memory_samples(
+                    &mut profile,
+                    main,
+                    event.memory,
+                    last_timestamp,
+                    &mut memory_counters,
+                    &mut last_memory,
+                );
+
+                let (callsite, _) = calls.get(&event.call_id).unwrap();
+
+                let marker = EventMarker { callsite, event: &event, memory_delta };
+
+                profile.add_marker_with_stack(
+                    *thread_handle,
+                    CategoryHandle::OTHER,
+                    &callsite.name,
+                    marker,
+                    fxprof_processed_profile::MarkerTiming::Instant(timestamp),
+                    frames.iter().rev().cloned(),
+                );
+
+                last_timestamp = timestamp;
+            }
+            Entry::SpanClose(SpanClose { id, time }) => {
+                spans.remove(&id);
+                last_timestamp = to_timestamp(time);
+            }
+        }
+    }
+
+    Ok(profile)
+}
+
+struct MemoryCounterHandles {
+    usage: CounterHandle,
+}
+
+impl MemoryCounterHandles {
+    fn new(profile: &mut Profile, main: ProcessHandle) -> Self {
+        let usage =
+            profile.add_counter(main, "mimmalloc", "Memory", "Amount of memory currently in use");
+        Self { usage }
+    }
+}
+
+fn add_memory_samples(
+    profile: &mut Profile,
+    main: ProcessHandle,
+    memory: Option<MemoryStats>,
+    last_timestamp: Timestamp,
+    memory_counters: &mut Option<MemoryCounterHandles>,
+    last_memory: &mut MemoryStats,
+) -> Option<MemoryStats> {
+    let stats = memory?;
+
+    let memory_counters =
+        memory_counters.get_or_insert_with(|| MemoryCounterHandles::new(profile, main));
+
+    profile.add_counter_sample(
+        memory_counters.usage,
+        last_timestamp,
+        stats.resident as f64 - last_memory.resident as f64,
+        0,
+    );
+
+    let delta = stats.checked_sub(*last_memory);
+    *last_memory = stats;
+    delta
+}
+
+fn to_timestamp(time: std::time::Duration) -> Timestamp {
+    Timestamp::from_nanos_since_reference(time.as_nanos() as u64)
+}
+
+fn make_frames(
+    span: NewSpan,
+    spans: &HashMap<SpanId, (NewSpan, SpanStatus)>,
+    calls: &HashMap<ResourceId, (NewCallsite, StringHandle)>,
+    subcategory: CategoryPairHandle,
+) -> Vec<FrameInfo> {
+    let mut frames = Vec::new();
+    let mut current_span = span;
+    loop {
+        let frame = make_frame(current_span, calls, subcategory);
+        frames.push(frame);
+        if let Some(parent) = current_span.parent_id {
+            current_span = spans.get(&parent).unwrap().0;
+        } else {
+            break;
+        }
+    }
+    frames
+}
+
+fn make_frame(
+    span: NewSpan,
+    calls: &HashMap<ResourceId, (NewCallsite, StringHandle)>,
+    subcategory: CategoryPairHandle,
+) -> FrameInfo {
+    let (_, call) = calls.get(&span.call_id).unwrap();
+    FrameInfo { frame: Frame::Label(*call), category_pair: subcategory, flags: FrameFlags::empty() }
+}
+
+#[derive(Debug, Clone, Copy)]
+enum SpanStatus {
+    Outside,
+    Inside { time: std::time::Duration, memory: Option<MemoryStats> },
+}
+
+struct SpanMarker<'a> {
+    span: &'a NewSpan,
+    callsite: &'a NewCallsite,
+    memory_delta: Option<MemoryStats>,
+}
+
+impl<'a> ProfilerMarker for SpanMarker<'a> {
+    const MARKER_TYPE_NAME: &'static str = "span";
+
+    fn schema() -> MarkerSchema {
+        let fields = vec![
+            MarkerSchemaField::Dynamic(MarkerDynamicField {
+                key: "filename",
+                label: "File name",
+                format: MarkerFieldFormat::FilePath,
+                searchable: true,
+            }),
+            MarkerSchemaField::Dynamic(MarkerDynamicField {
+                key: "line",
+                label: "Line",
+                format: MarkerFieldFormat::Integer,
+                searchable: true,
+            }),
+            MarkerSchemaField::Dynamic(MarkerDynamicField {
+                key: "module_path",
+                label: "Module path",
+                format: MarkerFieldFormat::String,
+                searchable: true,
+            }),
+            MarkerSchemaField::Dynamic(MarkerDynamicField {
+                key: "span_id",
+                label: "Span ID",
+                format: MarkerFieldFormat::Integer,
+                searchable: true,
+            }),
+            MarkerSchemaField::Dynamic(MarkerDynamicField {
+                key: "thread_id",
+                label: "Thread ID",
+                format: MarkerFieldFormat::Integer,
+                searchable: true,
+            }),
+            MarkerSchemaField::Dynamic(MarkerDynamicField {
+                key: "resident",
+                label: "Resident set size, measured in bytes while this function was executing",
+                format: MarkerFieldFormat::Bytes,
+                searchable: false,
+            }),
+        ];
+
+        MarkerSchema {
+            type_name: Self::MARKER_TYPE_NAME,
+            locations: vec![
+                MarkerLocation::MarkerTable,
+                MarkerLocation::MarkerChart,
+                MarkerLocation::TimelineOverview,
+            ],
+            chart_label: None,
+            tooltip_label: Some("{marker.name} - {marker.data.filename}:{marker.data.line}"),
+            table_label: Some("{marker.data.filename}:{marker.data.line}"),
+            fields,
+        }
+    }
+
+    fn json_marker_data(&self) -> serde_json::Value {
+        let filename = self.callsite.file.as_deref();
+        let line = self.callsite.line;
+        let module_path = self.callsite.module_path.as_deref();
+        let span_id = self.span.id;
+        let thread_id = self.span.thread_id;
+
+        let mut value = json!({
+            "type": Self::MARKER_TYPE_NAME,
+            "filename": filename,
+            "line": line,
+            "module_path": module_path,
+            "span_id": span_id,
+            "thread_id": thread_id,
+        });
+
+        if let Some(MemoryStats { resident }) = self.memory_delta {
+            value["resident"] = json!(resident);
+        }
+
+        value
+    }
+}
+
+struct EventMarker<'a> {
+    event: &'a Event,
+    callsite: &'a NewCallsite,
+    memory_delta: Option<MemoryStats>,
+}
+
+impl<'a> ProfilerMarker for EventMarker<'a> {
+    const MARKER_TYPE_NAME: &'static str = "tracing-event";
+
+    fn schema() -> MarkerSchema {
+        let fields = vec![
+            MarkerSchemaField::Dynamic(MarkerDynamicField {
+                key: "filename",
+                label: "File name",
+                format: MarkerFieldFormat::FilePath,
+                searchable: true,
+            }),
+            MarkerSchemaField::Dynamic(MarkerDynamicField {
+                key: "line",
+                label: "Line",
+                format: MarkerFieldFormat::Integer,
+                searchable: true,
+            }),
+            MarkerSchemaField::Dynamic(MarkerDynamicField {
+                key: "module_path",
+                label: "Module path",
+                format: MarkerFieldFormat::String,
+                searchable: true,
+            }),
+            MarkerSchemaField::Dynamic(MarkerDynamicField {
+                key: "parent_span_id",
+                label: "Parent Span ID",
+                format: MarkerFieldFormat::Integer,
+                searchable: true,
+            }),
+            MarkerSchemaField::Dynamic(MarkerDynamicField {
+                key: "thread_id",
+                label: "Thread ID",
+                format: MarkerFieldFormat::Integer,
+                searchable: true,
+            }),
+            MarkerSchemaField::Dynamic(MarkerDynamicField {
+                key: "resident",
+                label: "Resident set size, measured in bytes while this function was executing",
+                format: MarkerFieldFormat::Bytes,
+                searchable: false,
+            }),
+        ];
+
+        MarkerSchema {
+            type_name: Self::MARKER_TYPE_NAME,
+            locations: vec![
+                MarkerLocation::MarkerTable,
+                MarkerLocation::MarkerChart,
+                MarkerLocation::TimelineOverview,
+            ],
+            chart_label: None,
+            tooltip_label: Some("{marker.name} - {marker.data.filename}:{marker.data.line}"),
+            table_label: Some("{marker.data.filename}:{marker.data.line}"),
+            fields,
+        }
+    }
+
+    fn json_marker_data(&self) -> serde_json::Value {
+        let filename = self.callsite.file.as_deref();
+        let line = self.callsite.line;
+        let module_path = self.callsite.module_path.as_deref();
+        let span_id = self.event.parent_id;
+        let thread_id = self.event.thread_id;
+
+        let mut value = json!({
+            "type": Self::MARKER_TYPE_NAME,
+            "filename": filename,
+            "line": line,
+            "module_path": module_path,
+            "parent_span_id": span_id,
+            "thread_id": thread_id,
+        });
+
+        if let Some(MemoryStats { resident }) = self.memory_delta {
+            value["resident"] = json!(resident);
+        }
+
+        value
+    }
+}

crates/tracing-trace/src/processor/fmt.rs

@@ -0,0 +1,197 @@
+use std::collections::HashMap;
+use std::io::Read;
+
+use byte_unit::UnitType;
+
+use crate::entry::{
+    Entry, Event, MemoryStats, NewCallsite, NewSpan, NewThread, ResourceId, SpanClose, SpanEnter,
+    SpanExit, SpanId,
+};
+use crate::{Error, TraceReader};
+
+#[derive(Debug, Clone, Copy)]
+enum SpanStatus {
+    Outside,
+    Inside(std::time::Duration),
+}
+
+pub fn print_trace<R: Read>(trace: TraceReader<R>) -> Result<(), Error> {
+    let mut calls = HashMap::new();
+    let mut threads = HashMap::new();
+    let mut spans = HashMap::new();
+    for entry in trace {
+        let entry = entry?;
+        match entry {
+            Entry::NewCallsite(callsite) => {
+                calls.insert(callsite.call_id, callsite);
+            }
+            Entry::NewThread(NewThread { thread_id, name }) => {
+                threads.insert(thread_id, name);
+            }
+            Entry::NewSpan(span) => {
+                spans.insert(span.id, (span, SpanStatus::Outside));
+            }
+            Entry::SpanEnter(SpanEnter { id, time, memory }) => {
+                let (span, status) = spans.get_mut(&id).unwrap();
+
+                let SpanStatus::Outside = status else {
+                    continue;
+                };
+
+                *status = SpanStatus::Inside(time);
+
+                let span = *span;
+
+                match memory {
+                    Some(stats) => println!(
+                        "[{}]{}::{} ({}) <-",
+                        print_thread(&threads, span.thread_id),
+                        print_backtrace(&spans, &calls, &span),
+                        print_span(&calls, &span),
+                        print_memory(stats),
+                    ),
+                    None => println!(
+                        "[{}]{}::{} <-",
+                        print_thread(&threads, span.thread_id),
+                        print_backtrace(&spans, &calls, &span),
+                        print_span(&calls, &span),
+                    ),
+                }
+            }
+            Entry::SpanExit(SpanExit { id, time, memory }) => {
+                let (span, status) = spans.get_mut(&id).unwrap();
+
+                let SpanStatus::Inside(begin) = status else {
+                    continue;
+                };
+                let begin = *begin;
+
+                *status = SpanStatus::Outside;
+
+                let span = *span;
+
+                match memory {
+                    Some(stats) => println!(
+                        "[{}]{}::{} ({}) -> {}",
+                        print_thread(&threads, span.thread_id),
+                        print_backtrace(&spans, &calls, &span),
+                        print_span(&calls, &span),
+                        print_memory(stats),
+                        print_duration(time - begin),
+                    ),
+                    None => println!(
+                        "[{}]{}::{} -> {}",
+                        print_thread(&threads, span.thread_id),
+                        print_backtrace(&spans, &calls, &span),
+                        print_span(&calls, &span),
+                        print_duration(time - begin),
+                    ),
+                }
+            }
+            Entry::SpanClose(SpanClose { id, time: _ }) => {
+                spans.remove(&id);
+            }
+            Entry::Event(Event { call_id, thread_id, parent_id, time: _, memory }) => {
+                let parent_span = parent_id.and_then(|parent_id| spans.get(&parent_id)).and_then(
+                    |(span, status)| match status {
+                        SpanStatus::Outside => None,
+                        SpanStatus::Inside(_) => Some(span),
+                    },
+                );
+                match (parent_span, memory) {
+                    (Some(parent_span), Some(stats)) => println!(
+                        "[{}]{}::{} ({}) event: {}",
+                        print_thread(&threads, thread_id),
+                        print_backtrace(&spans, &calls, parent_span),
+                        print_span(&calls, parent_span),
+                        print_memory(stats),
+                        print_call(&calls, call_id)
+                    ),
+                    (Some(parent_span), None) => println!(
+                        "[{}]{}::{} event: {}",
+                        print_thread(&threads, thread_id),
+                        print_backtrace(&spans, &calls, parent_span),
+                        print_span(&calls, parent_span),
+                        print_call(&calls, call_id)
+                    ),
+                    (None, None) => println!(
+                        "[{}] event: {}",
+                        print_thread(&threads, thread_id),
+                        print_call(&calls, call_id)
+                    ),
+                    (None, Some(stats)) => println!(
+                        "[{}] ({}) event: {}",
+                        print_thread(&threads, thread_id),
+                        print_memory(stats),
+                        print_call(&calls, call_id)
+                    ),
+                }
+            }
+        }
+    }
+    Ok(())
+}
+
+fn print_thread(threads: &HashMap<ResourceId, Option<String>>, thread_id: ResourceId) -> String {
+    let thread = threads.get(&thread_id).unwrap();
+    let thread =
+        thread.as_ref().cloned().unwrap_or_else(|| format!("ThreadId({})", thread_id.to_usize()));
+    thread
+}
+
+fn print_backtrace(
+    spans: &HashMap<SpanId, (NewSpan, SpanStatus)>,
+    calls: &HashMap<ResourceId, NewCallsite>,
+    span: &NewSpan,
+) -> String {
+    let mut parents = Vec::new();
+    let mut current = span.parent_id;
+    while let Some(current_id) = &current {
+        let (span, _) = spans.get(current_id).unwrap();
+        let callsite = calls.get(&span.call_id).unwrap();
+        parents.push(callsite.name.clone());
+
+        current = span.parent_id;
+    }
+
+    let x: Vec<String> = parents.into_iter().rev().map(|x| x.to_string()).collect();
+    x.join("::")
+}
+
+fn print_span(calls: &HashMap<ResourceId, NewCallsite>, span: &NewSpan) -> String {
+    print_call(calls, span.call_id)
+}
+
+fn print_call(calls: &HashMap<ResourceId, NewCallsite>, call_id: ResourceId) -> String {
+    let callsite = calls.get(&call_id).unwrap();
+    match (callsite.file.clone(), callsite.line) {
+        (Some(file), None) => format!("{} ({})", callsite.name, file),
+        (Some(file), Some(line)) => format!("{} ({}:{})", callsite.name, file, line),
+        _ => callsite.name.to_string(),
+    }
+}
+
+fn print_duration(duration: std::time::Duration) -> String {
+    if duration.as_nanos() < 1000 {
+        format!("{}ns", duration.as_nanos())
+    } else if duration.as_micros() < 1000 {
+        format!("{}μs", duration.as_micros())
+    } else if duration.as_millis() < 1000 {
+        format!("{}ms", duration.as_millis())
+    } else if duration.as_secs() < 120 {
+        format!("{}s", duration.as_secs())
+    } else if duration.as_secs_f64() / 60.0 < 60.0 {
+        format!("{}min", duration.as_secs_f64() / 60.0)
+    } else if duration.as_secs_f64() / 3600.0 < 8.0 {
+        format!("{}h", duration.as_secs_f64() / 3600.0)
+    } else {
+        format!("{}d", duration.as_secs_f64() / 3600.0 / 24.0)
+    }
+}
+
+/// Format only the allocated bytes, deallocated bytes and reallocated bytes in GiB, MiB, KiB, Bytes.
+fn print_memory(MemoryStats { resident }: MemoryStats) -> String {
+    use byte_unit::Byte;
+    let rss_bytes = Byte::from_u64(resident).get_appropriate_unit(UnitType::Binary);
+    format!("RSS {rss_bytes:.2}")
+}

crates/tracing-trace/src/processor/mod.rs

@@ -0,0 +1,3 @@
+pub mod firefox_profiler;
+pub mod fmt;
+pub mod span_stats;

crates/tracing-trace/src/processor/span_stats.rs

@@ -0,0 +1,157 @@
+use std::collections::{BTreeMap, HashMap};
+use std::ops::Range;
+use std::time::Duration;
+
+use serde::{Deserialize, Serialize};
+
+use crate::entry::{Entry, NewCallsite, SpanClose, SpanEnter, SpanExit};
+use crate::{Error, TraceReader};
+
+#[derive(Debug, Clone, Copy)]
+enum SpanStatus {
+    Outside,
+    Inside(std::time::Duration),
+}
+
+#[derive(Serialize, Deserialize)]
+pub struct CallStats {
+    pub call_count: usize,
+    pub time: u64,
+    pub self_time: u64,
+}
+
+#[derive(Debug, Default)]
+pub struct SelfTime {
+    child_ranges: Vec<Range<Duration>>,
+}
+
+impl SelfTime {
+    pub fn new() -> Self {
+        Default::default()
+    }
+
+    pub fn add_child_range(&mut self, child_range: Range<Duration>) {
+        self.child_ranges.push(child_range)
+    }
+
+    pub fn self_duration(&mut self, self_range: Range<Duration>) -> Duration {
+        if self.child_ranges.is_empty() {
+            return self_range.end - self_range.start;
+        }
+
+        // by sorting child ranges by their start time,
+        // we make sure that no child will start before the last one we visited.
+        self.child_ranges
+            .sort_by(|left, right| left.start.cmp(&right.start).then(left.end.cmp(&right.end)));
+        // self duration computed by adding all the segments where the span is not executing a child
+        let mut self_duration = Duration::from_nanos(0);
+
+        // last point in time where we are certain that this span was not executing a child.
+        let mut committed_point = self_range.start;
+
+        for child_range in &self.child_ranges {
+            if child_range.start > committed_point {
+                // we add to the self duration the point between the end of the latest span and the beginning of the next span
+                self_duration += child_range.start - committed_point;
+            }
+            if committed_point < child_range.end {
+                // then we set ourselves to the end of the latest span
+                committed_point = child_range.end;
+            }
+        }
+
+        self_duration
+    }
+}
+
+pub fn to_call_stats<R: std::io::Read>(
+    trace: TraceReader<R>,
+) -> Result<BTreeMap<String, CallStats>, Error> {
+    let mut calls = HashMap::new();
+    let mut spans = HashMap::new();
+    let mut last_point = Duration::from_nanos(0);
+    let mut first_point = None;
+    let mut total_self_time = SelfTime::new();
+    for entry in trace {
+        let entry = entry?;
+        match entry {
+            Entry::NewCallsite(callsite) => {
+                calls.insert(callsite.call_id, (callsite, vec![]));
+            }
+            Entry::NewThread(_) => {}
+            Entry::NewSpan(span) => {
+                spans.insert(span.id, (span, SpanStatus::Outside, SelfTime::new()));
+            }
+            Entry::SpanEnter(SpanEnter { id, time, memory: _ }) => {
+                first_point.get_or_insert(time);
+                let (_, status, _) = spans.get_mut(&id).unwrap();
+
+                let SpanStatus::Outside = status else {
+                    continue;
+                };
+
+                *status = SpanStatus::Inside(time);
+            }
+            Entry::SpanExit(SpanExit { id, time: end, memory: _ }) => {
+                let (span, status, self_time) = spans.get_mut(&id).unwrap();
+
+                let SpanStatus::Inside(begin) = status else {
+                    continue;
+                };
+                let begin = *begin;
+
+                if last_point < end {
+                    last_point = end;
+                }
+
+                *status = SpanStatus::Outside;
+
+                let self_range = begin..end;
+
+                let self_duration = self_time.self_duration(self_range.clone());
+                *self_time = SelfTime::new();
+
+                let span = *span;
+                if let Some(parent_id) = span.parent_id {
+                    let (_, _, parent_self_time) = spans.get_mut(&parent_id).unwrap();
+                    parent_self_time.add_child_range(self_range.clone())
+                }
+                total_self_time.add_child_range(self_range);
+                let (_, call_list) = calls.get_mut(&span.call_id).unwrap();
+                call_list.push((end - begin, self_duration));
+            }
+            Entry::SpanClose(SpanClose { id, time: _ }) => {
+                spans.remove(&id);
+            }
+            Entry::Event(_) => {}
+        }
+    }
+
+    let total_self_time = first_point
+        .map(|first_point| (first_point, total_self_time.self_duration(first_point..last_point)));
+
+    Ok(calls
+        .into_iter()
+        .map(|(_, (call_site, calls))| (site_to_string(call_site), calls_to_stats(calls)))
+        .chain(total_self_time.map(|(first_point, total_self_time)| {
+            (
+                "::meta::total".to_string(),
+                CallStats {
+                    call_count: 1,
+                    time: (last_point - first_point).as_nanos() as u64,
+                    self_time: total_self_time.as_nanos() as u64,
+                },
+            )
+        }))
+        .collect())
+}
+
+fn site_to_string(call_site: NewCallsite) -> String {
+    format!("{}::{}", call_site.target, call_site.name)
+}
+fn calls_to_stats(calls: Vec<(Duration, Duration)>) -> CallStats {
+    let nb = calls.len();
+    let sum: Duration = calls.iter().map(|(total, _)| total).sum();
+    let self_sum: Duration = calls.iter().map(|(_, self_duration)| self_duration).sum();
+    CallStats { call_count: nb, time: sum.as_nanos() as u64, self_time: self_sum.as_nanos() as u64 }
+}