diff --git a/.github/CODEOWNERS b/.github/CODEOWNERS index 1237244fcf..a8de76f3fe 100644 --- a/.github/CODEOWNERS +++ b/.github/CODEOWNERS @@ -9,7 +9,7 @@ rust-toolchain.toml @MichaelMauderer @4e6 @mwu-tow @farmaazon rustfmt.toml @MichaelMauderer @4e6 @mwu-tow @farmaazon Cargo.lock @MichaelMauderer @4e6 @mwu-tow @farmaazon Cargo.toml @MichaelMauderer @4e6 @mwu-tow @farmaazon -/lib/rust/ @MichaelMauderer @4e6 @mwu-tow @farmaazon +/lib/rust/ @MichaelMauderer @4e6 @mwu-tow @farmaazon @wdanilo /lib/rust/ensogl/ @MichaelMauderer @wdanilo @farmaazon /integration-test/ @MichaelMauderer @wdanilo @farmaazon diff --git a/Cargo.lock b/Cargo.lock index 4381fad01c..85df95c0af 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1111,9 +1111,21 @@ version = "0.1.0" dependencies = [ "enso-profiler-macros", "futures 0.3.21", + "serde", + "serde_json", "wasm-bindgen", ] +[[package]] +name = "enso-profiler-data" +version = "0.1.0" +dependencies = [ + "enso-profiler", + "futures 0.3.21", + "serde", + "serde_json", +] + [[package]] name = "enso-profiler-macros" version = "0.1.0" diff --git a/Cargo.toml b/Cargo.toml index ff3f43c9a4..060dd63158 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -7,6 +7,7 @@ members = [ "app/gui", "build/rust-scripts", "lib/rust/*", + "lib/rust/profiler/data", "lib/rust/not-used/*", "integration-test" ] diff --git a/lib/rust/profiler/Cargo.toml b/lib/rust/profiler/Cargo.toml index 8c498a3da7..b9a70f1886 100644 --- a/lib/rust/profiler/Cargo.toml +++ b/lib/rust/profiler/Cargo.toml @@ -5,6 +5,8 @@ edition = "2021" authors = ["Enso Team "] [dependencies] +serde = { version = "1.0", features = ["derive"] } +serde_json = { version = "1.0.59", features = ["raw_value"] } wasm-bindgen = { version = "0.2.58", features = ["nightly"] } enso-profiler-macros = { path = "macros" } diff --git a/lib/rust/profiler/data/Cargo.toml b/lib/rust/profiler/data/Cargo.toml new file mode 100644 index 0000000000..10e8c43c57 --- /dev/null +++ b/lib/rust/profiler/data/Cargo.toml @@ -0,0 +1,13 @@ +[package] +name = "enso-profiler-data" +version = "0.1.0" +edition = "2021" +authors = ["Enso Team "] + +[dependencies] +serde = { version = "1.0", features = ["derive"] } +serde_json = "1.0" +enso-profiler = { path = "../" } + +[dev-dependencies] +futures = "0.3" diff --git a/lib/rust/profiler/data/src/lib.rs b/lib/rust/profiler/data/src/lib.rs new file mode 100644 index 0000000000..0110520a5b --- /dev/null +++ b/lib/rust/profiler/data/src/lib.rs @@ -0,0 +1,548 @@ +#![allow(rustdoc::private_intra_doc_links)] // check_no_async_tasks_active +//! Interface to profile data. +//! +//! # Overview +//! +//! Usage of this API starts with applying [`str::parse`] to JSON profiling data, returning a +//! [`Measurement`] which is the root of the hierarchy of profiler outputs. +//! +//! Parsing is robust to changes in the definitions of metadata types; if deserialization of some +//! metadata entries fails, the resulting error type provides access to the result of deserializing +//! all the data that succeeded (see [`Error::RecoverableFormatError`]). +//! +//! # Usage example: storing and retrieving metadata +//! +//! ``` +//! use enso_profiler as profiler; +//! use enso_profiler_data as profiler_data; +//! use profiler::profile; +//! +//! // Some metadata types. +//! #[derive(serde::Serialize, serde::Deserialize, PartialEq, Eq, Debug)] +//! struct MyDataA(u32); +//! +//! #[derive(serde::Serialize, serde::Deserialize, PartialEq, Eq, Debug)] +//! struct MyDataB(String); +//! +//! // An activity that produces metadata. +//! struct ActivityWithMetadata { +//! meta_logger_a: profiler::MetadataLogger, +//! meta_logger_b: profiler::MetadataLogger, +//! // ...fields for doing stuff +//! } +//! impl ActivityWithMetadata { +//! fn new() -> Self { +//! let meta_logger_a = profiler::MetadataLogger::new("MyDataA"); +//! let meta_logger_b = profiler::MetadataLogger::new("MyDataB"); +//! Self { meta_logger_a, meta_logger_b /* ... */ } +//! } +//! +//! #[profile(Objective)] +//! fn action_producing_metadata(&self) { +//! self.meta_logger_a.log(MyDataA(23)); +//! self.meta_logger_b.log(MyDataB("5".into())); +//! } +//! } +//! +//! // Run the activity that produces metadata, and profile it. +//! #[profile(Objective)] +//! fn demo() { +//! let act = ActivityWithMetadata::new(); +//! act.action_producing_metadata(); +//! } +//! +//! fn store_and_retrieve_metadata() { +//! demo(); +//! +//! // To deserialize, we define a metadata type as an enum. +//! // +//! // Each variant has a name and type that match the string-argument and type-parameter of a +//! // call to `MetadataLogger::new`. +//! #[derive(serde::Deserialize, PartialEq, Eq, Debug)] +//! enum MyMetadata { +//! MyDataA(MyDataA), +//! MyDataB(MyDataB), +//! // In this case we've handled everything. +//! // If we intended to handle some metadata and silently ignore anything else, we could +//! // include a catch-all variant like: +//! // `#[serde(other)] Other` +//! // On the other hand, if we intend to handle every type of metadata, we can omit the +//! // catch-all variant; unknown metadata will produce an +//! // [`Error::RecoverableFormatError`], which we can use to emit a warning and continue. +//! } +//! +//! // Obtain log data directly; it could also be deserialized from a file. +//! let log = profiler::internal::take_log(); +//! // Parse the log. Interpret metadata according to the enum defined above. +//! let root: profiler_data::Measurement = log.parse().unwrap(); +//! // Verify the MyData object is present and attached to the right profiler. +//! let profiler = &root.children[0].children[0]; +//! assert_eq!(&profiler.label.name, "action_producing_metadata"); +//! assert_eq!(profiler.metadata[0].data, MyMetadata::MyDataA(MyDataA(23))); +//! assert_eq!(profiler.metadata[1].data, MyMetadata::MyDataB(MyDataB("5".into()))); +//! // Marks can be used to compare the order of events. +//! assert!(profiler.metadata[0].mark < profiler.metadata[1].mark); +//! } +//! +//! store_and_retrieve_metadata(); +//! ``` +//! +//! # Limitations +//! +//! [`parse::LogVisitor::check_no_async_task_active`] checks for a type of API misuse error, but +//! currently also disallows running an async profiler during the lifetime of a non-async parent. +//! The only way that could occur is with the use of `block_on`, which is never used in the Enso +//! codebase except in tests. + +#![feature(test)] +#![deny(unconditional_recursion)] +#![warn(missing_copy_implementations)] +#![warn(missing_debug_implementations)] +#![warn(missing_docs)] +#![warn(trivial_casts)] +#![warn(trivial_numeric_casts)] +#![warn(unsafe_code)] +#![warn(unused_import_braces)] + +use enso_profiler as profiler; + +use std::error; +use std::fmt; + +pub mod parse; + + + +// ============= +// === Error === +// ============= + +/// Describes an error and where it occurred. +pub enum Error { + /// Failed to deserialize the event log at all. The file is corrupt, or in a completely + /// incompatible format. + FormatError(serde_json::Error), + /// Failed to deserialize some events; if this is caused by a change to a metadata type, the + /// core data and metadata of unaffected types will still be available. + /// + /// For an example of handling a recoverable failure, see `tests::skip_failed_metadata`. + RecoverableFormatError { + /// Deserialization errors for each Event that failed to parse. + errors: Vec>, + /// The core data. + /// + /// If the `errors` all relate to metadata events, the remaining data will be + /// available here, with one metadata object missing for each error. + /// + /// If some errors are not metadata errors (i.e. the core format has changed), the readable + /// subset of events might not form a valid log, and this will contain an error too. + with_missing_data: Result, EventError>, + }, + /// Failed to interpret the event log data. + DataError(EventError), +} + +impl fmt::Display for Error { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "{:?}", self) + } +} + +// This cannot be derived because: https://github.com/rust-lang/rust/issues/26925 +// Also, the debug output doesn't need to include the entire with_missing_data. +impl fmt::Debug for Error { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self { + Error::FormatError(e) => e.fmt(f), + Error::RecoverableFormatError { errors, .. } => errors.fmt(f), + Error::DataError(e) => e.fmt(f), + } + } +} + +impl error::Error for Error { + fn source(&self) -> Option<&(dyn error::Error + 'static)> { + Some(match self { + Error::FormatError(e) => e, + Error::RecoverableFormatError { errors, .. } => &errors[0], + Error::DataError(e) => e, + }) + } +} + +/// An error associated with a particular event in the log. +#[derive(Debug)] +pub struct EventError { + #[allow(unused)] // displayed by Debug + /// The event's index in the log. + log_pos: usize, + #[allow(unused)] // displayed by Debug + /// The error. + error: E, +} + +impl fmt::Display for EventError { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "{:?}", self) + } +} + +impl error::Error for EventError { + fn source(&self) -> Option<&(dyn error::Error + 'static)> { + self.error.source() + } +} + + + +// =================== +// === Measurement === +// =================== + +/// All the information produced by a profiler. +/// +/// This is parameterized by a type that determines how metadata is interpreted. The type must be +/// an enum, with a variant for each type of metadata that is handled. Each variant's name and type +/// should correspond to the parameters supplied to [`profiler::MetadataLogger::new`]. For an +/// example, see the docs for the [`crate`]. +#[derive(Clone, Debug)] +pub struct Measurement { + /// When the profiler was running. + pub lifetime: Lifetime, + /// Identifies the profiler's source and scope to the user. + pub label: Label, + /// Profilers started by this profiler. + pub children: Vec, + /// Metadata attached to this profiler. + pub metadata: Vec>, +} + + +// === Lifetime === + +/// Information about when a profiler was running. +#[derive(Clone, Debug)] +pub enum Lifetime { + /// Information applicable to async profilers. + Async(AsyncLifetime), + /// Information applicable to non-async profilers. + NonAsync { + /// The interval that the profiler was running. + active: Interval, + }, +} + +impl Lifetime { + /// Whether the task this profiler measures was completed. + pub fn finished(&self) -> bool { + match self { + Lifetime::Async(lifetime) => lifetime.finished, + Lifetime::NonAsync { active } => active.end.is_some(), + } + } + + /// Get a AsyncLifetime, if this Lifetime was async. + pub fn as_async(&self) -> Option<&AsyncLifetime> { + match self { + Lifetime::Async(lifetime) => Some(lifetime), + Lifetime::NonAsync { .. } => None, + } + } + + /// Whether this profiler recorded an async task. + pub fn is_async(&self) -> bool { + self.as_async().is_some() + } +} + +/// Information about when an async profiler was running. +#[derive(Clone, Debug)] +pub struct AsyncLifetime { + /// The time a profiled `async fn` was called, if known. + /// + /// This will always be before the first interval in `active`, as the function must be + /// called before it can be awaited and begin running. + pub created: Option, + /// Intervals that the profiler was running. + pub active: Vec, + /// If true: the last interval in `active` ended when the task was completed. + /// If false: the task was awaiting or running (indicated by whether the last interval in + /// `active` has an end) at the time the log was created. + pub finished: bool, +} + +impl AsyncLifetime { + /// The interval from when the async profiler was created, to when it finished. + /// + /// If creation time is not known, it will be approximated by first start-time. + /// + /// If the profiler is associated with a Future that was created but never awaited, + /// this will return None. + pub fn create_to_finish(&self) -> Option { + self.active.first().map(|first| { + let start = self.created.unwrap_or(first.start); + let end = match self.finished { + true => self.active.last().unwrap().end, + false => None, + }; + Interval { start, end } + }) + } +} + + + +// ================ +// === Metadata === +// ================ + +/// Wrapper adding a timestamp to dependency-injected contents. +#[derive(Clone, Debug)] +pub struct Metadata { + /// Time the data was logged. + pub mark: Mark, + /// The actual data. + pub data: M, +} + + + +// ============ +// === Mark === +// ============ + +/// A timestamp that can be used for distinguishing event order. +#[derive(Copy, Clone, Debug, PartialEq, Eq, PartialOrd, Ord, Default)] +pub struct Mark { + seq: Seq, + time: profiler::internal::Timestamp, +} + +impl Mark { + fn time_origin() -> Self { + Self::default() + } +} + + +// === Seq === + +/// A value that can be used to compare the order of events. +#[derive(Copy, Clone, Debug, PartialEq, Eq, PartialOrd, Ord, Default)] +pub(crate) struct Seq(u32); + +impl Seq { + fn runtime_event(event_index: u32) -> Self { + // Seq(0) is the time origin. + Seq(event_index.checked_add(1).unwrap()) + } +} + + + +// ================ +// === Interval === +// ================ + +/// A start time and an optional end time. +#[derive(Copy, Clone, Debug)] +pub struct Interval { + /// The time the interval began. + pub start: Mark, + /// The time the interval ended, or None if no end was logged. + pub end: Option, +} + +impl Interval { + /// Return whether this interval has a known end. + pub fn closed(self) -> bool { + self.end.is_some() + } +} + + + +// ============= +// === Label === +// ============= + +/// A measurement label. +#[derive(Debug, Clone)] +pub struct Label { + /// The name of the measurement, usually a function. + pub name: String, + /// Location in the code the measurement originated, if compiled with line numbers enabled. + pub pos: Option, +} + + +// === CodePos === + +/// Identifies a position within a specific file. +#[derive(Debug, Clone)] +pub struct CodePos { + /// The path to the file. + pub file: String, + /// A line number within the file. + pub line: u32, +} + + + +// ================== +// === Unit tests === +// ================== + +#[cfg(test)] +mod tests { + use crate as profiler_data; + use enso_profiler as profiler; + use profiler::profile; + + /// Black-box metadata object, for ignoring metadata contents. + #[derive(Debug, Copy, Clone, serde::Serialize, serde::Deserialize)] + pub(crate) enum OpaqueMetadata { + /// Anything. + #[serde(other)] + Unknown, + } + + #[test] + fn profile_sync() { + #[profile(Objective)] + fn parent() -> u32 { + child() + } + #[profile(Objective)] + fn child() -> u32 { + 4 + } + parent(); + let root: profiler_data::Measurement = + profiler::internal::take_log().parse().unwrap(); + let roots = &root.children; + assert_eq!(roots.len(), 1); + assert!(roots[0].lifetime.finished()); + assert!(!roots[0].lifetime.is_async(), "{:?}", &roots[0].lifetime); + assert!(roots[0].lifetime.finished()); + assert_eq!(roots[0].label.name, "parent"); + assert_eq!(roots[0].children.len(), 1); + let child = &roots[0].children[0]; + assert!(child.lifetime.finished()); + assert!(!child.lifetime.is_async()); + assert!(child.lifetime.finished()); + assert_eq!(child.label.name, "child"); + assert_eq!(child.children.len(), 0); + } + + #[test] + fn profile_async() { + #[profile(Objective)] + async fn parent() -> u32 { + child().await + } + #[profile(Objective)] + async fn child() -> u32 { + let block = async { 4 }; + block.await + } + let future = parent(); + futures::executor::block_on(future); + let root: profiler_data::Measurement = + profiler::internal::take_log().parse().unwrap(); + let roots = &root.children; + assert_eq!(roots.len(), 1); + assert!(roots[0].lifetime.finished()); + let root_intervals = &roots[0].lifetime.as_async().unwrap().active; + assert_eq!(root_intervals.len(), 2); + for interval in root_intervals { + assert!(interval.closed()); + } + assert!(roots[0].lifetime.finished()); + assert_eq!(roots[0].label.name, "parent"); + assert_eq!(roots[0].children.len(), 1); + let child = &roots[0].children[0]; + assert!(child.lifetime.finished()); + let child_intervals = &child.lifetime.as_async().unwrap().active; + assert_eq!(child_intervals.len(), 2); + for interval in child_intervals { + assert!(interval.closed()); + } + assert!(child.lifetime.finished()); + assert_eq!(child.label.name, "child"); + assert_eq!(child.children.len(), 0); + } + + #[test] + fn unfinished_never_started() { + #[profile(Objective)] + async fn func() {} + // Create a Future, but don't await it. + let _future = func(); + let root: profiler_data::Measurement = + profiler::internal::take_log().parse().unwrap(); + assert!(!root.children[0].lifetime.finished()); + } + + #[test] + fn unfinished_still_running() { + profiler::internal::EventLog.start( + profiler::internal::EventId::implicit(), + profiler::internal::Label("unfinished (?:?)"), + None, + profiler::internal::StartState::Active, + ); + let root: profiler_data::Measurement = + profiler::internal::take_log().parse().unwrap(); + assert!(!root.children[0].lifetime.finished()); + } + + #[test] + fn unfinished_paused_never_resumed() { + let id = profiler::internal::EventLog.start( + profiler::internal::EventId::implicit(), + profiler::internal::Label("unfinished (?:?)"), + None, + profiler::internal::StartState::Active, + ); + profiler::internal::EventLog.pause(id, profiler::internal::Timestamp::now()); + let root: profiler_data::Measurement = + profiler::internal::take_log().parse().unwrap(); + assert!(!root.children[0].lifetime.finished(), "{:?}", &root); + } + + /// Simulate a change to the format of a type of metadata; ensure the error is reported + /// correctly, and all other data is still readable. + #[test] + fn skip_failed_metadata() { + #[derive(serde::Serialize, serde::Deserialize, PartialEq, Eq, Debug)] + struct MyDataA(u32); + #[derive(serde::Serialize, serde::Deserialize, PartialEq, Eq, Debug)] + struct MyDataBExpected(u32); + #[derive(serde::Serialize, serde::Deserialize, PartialEq, Eq, Debug)] + struct MyDataBActual(String); + + let meta_logger_a = profiler::MetadataLogger::new("MyDataA"); + let meta_logger_b = profiler::MetadataLogger::new("MyDataB"); + meta_logger_a.log(MyDataA(23)); + meta_logger_b.log(MyDataBActual("bad".into())); + + #[derive(serde::Deserialize, PartialEq, Eq, Debug)] + enum MyMetadata { + MyDataA(MyDataA), + MyDataB(MyDataBExpected), + } + let log = profiler::internal::take_log(); + let root: Result, _> = log.parse(); + let root = match root { + Err(profiler_data::Error::RecoverableFormatError { errors, with_missing_data }) => { + assert_eq!(errors.len(), 1); + assert_eq!(errors[0].log_pos, 1); + with_missing_data.unwrap() + } + other => panic!("Expected RecoverableFormatError, found: {:?}", other), + }; + assert_eq!(root.metadata.len(), 1); + assert_eq!(root.metadata[0].data, MyMetadata::MyDataA(MyDataA(23))); + } +} diff --git a/lib/rust/profiler/data/src/parse.rs b/lib/rust/profiler/data/src/parse.rs new file mode 100644 index 0000000000..91bc500eac --- /dev/null +++ b/lib/rust/profiler/data/src/parse.rs @@ -0,0 +1,565 @@ +//! Parsing implementation. `pub` contents are low-level error details. + +use enso_profiler as profiler; + +use std::collections; +use std::error; +use std::fmt; +use std::mem; +use std::str; + + + +// =========================== +// === parse and interpret === +// =========================== + +impl str::FromStr for crate::Measurement { + type Err = crate::Error; + + fn from_str(s: &str) -> Result { + let Parse { events, errors } = parse(s).map_err(crate::Error::FormatError)?; + let result = interpret(events); + if errors.is_empty() { + result.map_err(|e| crate::Error::DataError(e)) + } else { + Err(crate::Error::RecoverableFormatError { errors, with_missing_data: result }) + } + } +} + + +// === parse === + +pub(crate) struct Parse { + pub events: Vec>, + pub errors: Vec>, +} + +/// Deserialize a log of events. +/// +/// For each entry in the log, produces either a deserialized Event or an error. +pub(crate) fn parse(s: &str) -> Result, serde_json::Error> +where M: serde::de::DeserializeOwned { + // First just decode the array structure, so we can skip any metadata events that fail. + let log: Vec<&serde_json::value::RawValue> = serde_json::from_str(s)?; + let mut errors = Vec::new(); + let mut events = Vec::with_capacity(log.len()); + for (i, entry) in log.into_iter().enumerate() { + match serde_json::from_str::>(entry.get()) { + Ok(event) => events.push(event), + Err(error) => errors.push(crate::EventError { log_pos: i, error }), + } + } + Ok(Parse { events, errors }) +} + + +// === interpret === + +/// Process a log of events, producing a hierarchy of measurements. +/// +/// Returns an error if the log cannot be interpreted. +pub(crate) fn interpret( + events: impl IntoIterator>, +) -> Result, crate::EventError> { + // Process log into data about each measurement, and data about relationships. + let LogVisitor { builders, order, root_builder, .. } = LogVisitor::visit(events)?; + // Build measurements from accumulated measurement data. + let mut measurements: collections::HashMap<_, _> = + builders.into_iter().map(|(k, v)| (k, v.build())).collect(); + // Organize measurements into trees. + let mut root = root_builder.build(); + for (id, parent) in order.into_iter().rev() { + let child = measurements.remove(&id).unwrap(); + let parent = match parent { + id::Explicit::AppLifetime => &mut root.children, + id::Explicit::Runtime(pos) => + &mut measurements + .get_mut(&pos) + .ok_or(DataError::IdNotFound) + .map_err(|e| crate::EventError { log_pos: id.0 as usize, error: e })? + .children, + }; + parent.push(child); + } + Ok(root) +} + + + +// ================= +// === DataError === +// ================= + +/// A problem with the input data. +#[derive(Debug)] +pub enum DataError { + /// A profiler was in the wrong state for a certain event to occur. + UnexpectedState(State), + /// A reference was not able to be resolved. + IdNotFound, + /// An EventId that should have been a runtime event was IMPLICIT or APP_LIFETIME. + RuntimeIdExpected(id::Event), + /// A parse error. + UnexpectedToken(Expected), + /// An event that should only occur during the lifetime of a profiler didn't find any profiler. + ActiveProfilerRequired, + /// An event expected to refer to a certain profiler referred to a different profiler. + /// This can occur for events that include a profiler ID as a consistency check, but only + /// have one valid referent (e.g. [`profiler::Event::End`] must end the current profiler.) + WrongProfiler { + /// The profiler that was referred to. + found: id::Runtime, + /// The only valid profiler for the event to refer to. + expected: id::Runtime, + }, + /// Profiler(s) were active at a time none were expected. + ExpectedEmptyStack(Vec), + /// A profiler was expected to have started before a related event occurred. + ExpectedStarted, +} + +impl fmt::Display for DataError { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "{:?}", self) + } +} + +impl error::Error for DataError {} + +impl From for DataError { + fn from(inner: Expected) -> Self { + DataError::UnexpectedToken(inner) + } +} + + +// === Expected === + +/// Parsing error: expected a different token. +#[derive(Debug, Copy, Clone)] +pub struct Expected(pub(crate) &'static str); + +impl fmt::Display for Expected { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "{:?}", self.0) + } +} + +impl error::Error for Expected {} + + + +// ========================== +// === MeasurementBuilder === +// ========================== + +/// Used while gathering information about a profiler. +struct MeasurementBuilder { + label: crate::Label, + created: crate::Mark, + created_paused: bool, + pauses: Vec, + resumes: Vec, + end: Option, + state: State, + metadata: Vec>, +} + +impl MeasurementBuilder { + fn build(self) -> crate::Measurement { + let MeasurementBuilder { + label, + pauses, + resumes, + metadata, + created, + created_paused, + end, + state: _, + } = self; + // A profiler is considered async if: + // - It was created in a non-running state (occurs when a `#[profile] async fn` is called). + // - It ever awaited. + let lifetime = if created_paused || !pauses.is_empty() { + let mut starts = resumes; + if !created_paused { + starts.insert(0, created); + } + let mut ends = pauses; + if let Some(end) = end { + ends.push(end); + } + let mut ends = ends.into_iter().fuse(); + let active: Vec<_> = starts + .into_iter() + .map(|start| crate::Interval { start, end: ends.next() }) + .collect(); + crate::Lifetime::Async(crate::AsyncLifetime { + created: if created_paused { Some(created) } else { None }, + active, + finished: end.is_some(), + }) + } else { + let active = crate::Interval { start: created, end }; + crate::Lifetime::NonAsync { active } + }; + let children = Vec::new(); + crate::Measurement { lifetime, label, children, metadata } + } +} + + +// === State === + +/// Used to validate state transitions. +#[derive(Debug, Copy, Clone)] +pub enum State { + /// Started and not paused or ended; id of most recent Start or Resume event is included. + Active(id::Runtime), + /// Paused. Id of Pause or StartPaused event is included. + Paused(id::Runtime), + /// Ended. Id of End event is included. + Ended(id::Runtime), +} + +impl State { + fn start(start_state: profiler::internal::StartState, pos: id::Runtime) -> Self { + match start_state { + profiler::internal::StartState::Active => Self::Active(pos), + profiler::internal::StartState::Paused => Self::Paused(pos), + } + } +} + + + +// ================== +// === LogVisitor === +// ================== + +/// Gathers data while visiting a series of [`profiler::internal::Event`]s. +struct LogVisitor { + /// Stack of active profilers, for keeping track of the current profiler. + active: Vec, + /// Accumulated data pertaining to each profiler. + builders: collections::HashMap>, + /// Accumulated data pertaining to the root event. + root_builder: MeasurementBuilder, + /// Ids and parents, in same order as event log. + order: Vec<(id::Runtime, id::Explicit)>, +} + +impl Default for LogVisitor { + fn default() -> Self { + let root_builder = MeasurementBuilder { + label: "APP_LIFETIME (?:?)".parse().unwrap(), + state: State::Active(id::Runtime(0)), // value doesn't matter + created: crate::Mark::time_origin(), + created_paused: Default::default(), + metadata: Default::default(), + pauses: Default::default(), + resumes: Default::default(), + end: Default::default(), + }; + Self { + active: Default::default(), + builders: Default::default(), + root_builder, + order: Default::default(), + } + } +} + +impl LogVisitor { + /// Convert the log into data about each measurement. + fn visit( + events: impl IntoIterator>, + ) -> Result> { + let mut visitor = Self::default(); + for (i, event) in events.into_iter().enumerate() { + let log_pos = id::Runtime(i as u32); + let result = match event { + profiler::internal::Event::Start(event) => + visitor.visit_start(log_pos, event, profiler::internal::StartState::Active), + profiler::internal::Event::StartPaused(event) => + visitor.visit_start(log_pos, event, profiler::internal::StartState::Paused), + profiler::internal::Event::End { id, timestamp } => + visitor.visit_end(log_pos, id, timestamp), + profiler::internal::Event::Pause { id, timestamp } => + visitor.visit_pause(log_pos, id, timestamp), + profiler::internal::Event::Resume { id, timestamp } => + visitor.visit_resume(log_pos, id, timestamp), + profiler::internal::Event::Metadata(metadata) => + visitor.visit_metadata(log_pos, metadata), + }; + result.map_err(|error| crate::EventError { log_pos: i, error })?; + } + Ok(visitor) + } +} + + +// === Handlers for each event === + +impl LogVisitor { + fn visit_start( + &mut self, + pos: id::Runtime, + event: profiler::internal::Start, + start_state: profiler::internal::StartState, + ) -> Result<(), DataError> { + let parent = match event.parent.into() { + id::Event::Explicit(parent) => parent, + id::Event::Implicit => self.current_profiler(), + }; + let start = match event.start { + Some(time) => crate::Mark { seq: pos.into(), time }, + None => self.inherit_start(parent)?, + }; + let builder = MeasurementBuilder { + label: event.label.to_string().parse()?, + created: start, + created_paused: matches!(start_state, profiler::internal::StartState::Paused), + state: State::start(start_state, pos), + pauses: Default::default(), + resumes: Default::default(), + end: Default::default(), + metadata: Default::default(), + }; + if start_state == profiler::internal::StartState::Active { + self.active.push(pos); + } + self.order.push((pos, parent)); + let old = self.builders.insert(pos, builder); + assert!(old.is_none()); + Ok(()) + } + + fn visit_end( + &mut self, + pos: id::Runtime, + id: profiler::internal::EventId, + time: profiler::internal::Timestamp, + ) -> Result<(), DataError> { + let current_profiler = self.active.pop().ok_or(DataError::ActiveProfilerRequired)?; + check_profiler(id, current_profiler)?; + let measurement = &mut self.builders.get_mut(¤t_profiler).unwrap(); + measurement.end = Some(crate::Mark { seq: pos.into(), time }); + match mem::replace(&mut measurement.state, State::Ended(pos)) { + State::Active(_) => (), + state => return Err(DataError::UnexpectedState(state)), + } + Ok(()) + } + + fn visit_pause( + &mut self, + pos: id::Runtime, + id: profiler::internal::EventId, + time: profiler::internal::Timestamp, + ) -> Result<(), DataError> { + let current_profiler = self.active.pop().ok_or(DataError::ActiveProfilerRequired)?; + check_profiler(id, current_profiler)?; + self.check_no_async_task_active()?; + let mark = crate::Mark { seq: pos.into(), time }; + let measurement = &mut self.builders.get_mut(¤t_profiler).unwrap(); + measurement.pauses.push(mark); + match mem::replace(&mut measurement.state, State::Paused(pos)) { + State::Active(_) => (), + state => return Err(DataError::UnexpectedState(state)), + } + Ok(()) + } + + fn visit_resume( + &mut self, + pos: id::Runtime, + id: profiler::internal::EventId, + time: profiler::internal::Timestamp, + ) -> Result<(), DataError> { + let start_id = match id.into() { + id::Event::Explicit(id::Explicit::Runtime(id)) => id, + id => return Err(DataError::RuntimeIdExpected(id)), + }; + self.check_no_async_task_active()?; + self.active.push(start_id); + let mark = crate::Mark { seq: pos.into(), time }; + let measurement = &mut self.builders.get_mut(&start_id).ok_or(DataError::IdNotFound)?; + measurement.resumes.push(mark); + match mem::replace(&mut measurement.state, State::Active(pos)) { + State::Paused(_) => (), + state => return Err(DataError::UnexpectedState(state)), + } + Ok(()) + } + + fn visit_metadata( + &mut self, + pos: id::Runtime, + metadata: profiler::internal::Timestamped, + ) -> Result<(), DataError> { + let builder = match self.active.last() { + Some(profiler) => self.builders.get_mut(profiler).unwrap(), + None => &mut self.root_builder, + }; + let profiler::internal::Timestamped { timestamp, data } = metadata; + let mark = crate::Mark { seq: pos.into(), time: timestamp }; + builder.metadata.push(crate::Metadata { mark, data }); + Ok(()) + } +} + + +// === Helper types, functions, and methods === + +type OwnedLabel = String; + +fn check_profiler( + found: profiler::internal::EventId, + expected: id::Runtime, +) -> Result<(), DataError> { + let found = match found.into() { + id::Event::Explicit(id::Explicit::Runtime(id)) => id, + id => return Err(DataError::RuntimeIdExpected(id)), + }; + if found != expected { + return Err(DataError::WrongProfiler { found, expected }); + } + Ok(()) +} + +impl LogVisitor { + fn current_profiler(&self) -> id::Explicit { + match self.active.last() { + Some(&pos) => pos.into(), + None => id::Explicit::AppLifetime, + } + } + + fn inherit_start(&self, parent: id::Explicit) -> Result { + Ok(match parent { + id::Explicit::AppLifetime => crate::Mark::time_origin(), + id::Explicit::Runtime(pos) => { + let measurement = self.builders.get(&pos).ok_or(DataError::IdNotFound)?; + if measurement.created_paused { + *measurement.resumes.first().ok_or(DataError::ExpectedStarted)? + } else { + measurement.created + } + } + }) + } + + fn check_empty_stack(&self) -> Result<(), DataError> { + match self.active.is_empty() { + true => Ok(()), + false => Err(DataError::ExpectedEmptyStack(self.active.clone())), + } + } + + /// Used to validate there is never more than one async task active simultaneously, which + /// would indicate that a low-level-profiled section has used an uninstrumented `.await` + /// expression. + fn check_no_async_task_active(&self) -> Result<(), DataError> { + // This simple check is conservative; it doesn't allow certain legal behavior, like an + // instrumented non-async function using block_on to run an instrumented async function, + // because support for that is unlikely to be needed. + self.check_empty_stack() + } +} + + + +// ====================== +// === String parsing === +// ====================== + +impl str::FromStr for crate::Label { + type Err = Expected; + fn from_str(s: &str) -> Result { + let (name, pos) = s.rsplit_once(' ').ok_or(Expected(" "))?; + Ok(Self { name: name.to_owned(), pos: crate::CodePos::parse(pos)? }) + } +} + +impl crate::CodePos { + fn parse(s: &str) -> Result, Expected> { + let (file, line) = s.rsplit_once(':').ok_or(Expected(":"))?; + let file = file.strip_prefix('(').ok_or(Expected("("))?; + let line = line.strip_suffix(')').ok_or(Expected(")"))?; + Ok(if file == "?" { + None + } else { + Some(Self { + file: file.to_owned(), + line: line.parse().map_err(|_| Expected("line number"))?, + }) + }) + } +} + + + +// ========== +// === id === +// ========== + +/// Facilities for classifying an event ID into subtypes. +/// +/// The [`profiler::internal::EventId`] type can be logically broken down into different subtypes, +/// but in the event log subtypes are not differentiated so that all EventIDs can be easily packed +/// into a small scalar. This module supports unpacking an EventID. +pub mod id { + use enso_profiler as profiler; + + /// An reference to an event. This type classifies [`profiler::EventId`]; they have a 1:1 + /// correspondence. + #[derive(Copy, Clone, Debug)] + pub enum Event { + /// An unspecified ID that must be inferred from context. + Implicit, + /// A specific, context-independent ID. + Explicit(Explicit), + } + + impl From for Event { + fn from(id: profiler::internal::EventId) -> Self { + if id == profiler::internal::EventId::IMPLICIT { + Event::Implicit + } else { + Event::Explicit(if id == profiler::internal::EventId::APP_LIFETIME { + Explicit::AppLifetime + } else { + Explicit::Runtime(Runtime(id.0)) + }) + } + } + } + + /// An explicit reference to an event. + #[derive(Copy, Clone, Debug)] + pub enum Explicit { + /// The parent of the real roots. + AppLifetime, + /// An event logged at runtime. + Runtime(Runtime), + } + + /// An explicit reference to an event in the log. + #[derive(Copy, Clone, Debug, Eq, PartialEq, Hash)] + pub struct Runtime(pub u32); + + impl From for Explicit { + fn from(id: Runtime) -> Self { + Explicit::Runtime(id) + } + } + + impl From for crate::Seq { + fn from(pos: Runtime) -> Self { + Self::runtime_event(pos.0) + } + } +} diff --git a/lib/rust/profiler/macros/src/lib.rs b/lib/rust/profiler/macros/src/lib.rs index ed4086423f..c17d21d8dc 100644 --- a/lib/rust/profiler/macros/src/lib.rs +++ b/lib/rust/profiler/macros/src/lib.rs @@ -60,8 +60,13 @@ fn define_profiler( // === Trait Implementations === impl Profiler for #obj_ident { - fn start(parent: EventId, label: Label, time: Option) -> Self { - #obj_ident(EventLog.start(parent, label, time)) + fn start( + parent: EventId, + label: StaticLabel, + time: Option, + start: StartState, + ) -> Self { + #obj_ident(EventLog.start(parent, label, time, start)) } fn finish(self) { EventLog.end(self.0, Timestamp::now()) @@ -82,8 +87,10 @@ fn define_profiler( macro_rules! #start { ($parent: expr, $label: expr) => {{ use profiler::Parent; - let label = concat!($label, " (", file!(), ":", line!(), ")"); - let profiler: profiler::Started = $parent.new_child(label); + let label = profiler::internal::Label( + concat!($label, " (", file!(), ":", line!(), ")")); + let profiler: profiler::internal::Started = + $parent.new_child(label); profiler }} } @@ -93,8 +100,9 @@ fn define_profiler( macro_rules! #with_same_start { ($parent: expr, $label: expr) => {{ use profiler::Parent; - let label = concat!($label, " (", file!(), ":", line!(), ")"); - let profiler: profiler::Started = + let label = profiler::internal::Label( + concat!($label, " (", file!(), ":", line!(), ")")); + let profiler: profiler::internal::Started = $parent.new_child_same_start(label); profiler }} @@ -114,7 +122,14 @@ fn define_profiler( // === Trait Implementations === impl Profiler for #obj_ident { - fn start(_: EventId, _: Label, _: Option) -> Self { Self(()) } + fn start( + _: EventId, + _: StaticLabel, + _: Option, + _: StartState, + ) -> Self { + Self(()) + } fn finish(self) {} fn pause(&self) {} fn resume(&self) { } @@ -127,14 +142,14 @@ fn define_profiler( #[macro_export] macro_rules! #start { ($parent: expr, $label: expr) => { - profiler::Started(profiler::#obj_ident(())) + profiler::internal::Started(profiler::#obj_ident(())) } } #[macro_export] #[doc = #doc_with_same_start] macro_rules! #with_same_start { ($parent: expr, $label: expr) => { - profiler::Started(profiler::#obj_ident(())) + profiler::internal::Started(profiler::#obj_ident(())) } } } @@ -150,12 +165,12 @@ fn enabled_impl_parent( ) -> proc_macro::TokenStream { let ts = quote::quote! { impl Parent<#child_ident> for #parent_ident { - fn new_child(&self, label:Label) -> Started<#child_ident> { + fn new_child(&self, label: StaticLabel) -> Started<#child_ident> { let start = Some(Timestamp::now()); - Started(#child_ident::start(self.0, label, start)) + Started(#child_ident::start(self.0, label, start, StartState::Active)) } - fn new_child_same_start(&self, label:Label) -> Started<#child_ident> { - Started(#child_ident::start(self.0, label, None)) + fn new_child_same_start(&self, label: StaticLabel) -> Started<#child_ident> { + Started(#child_ident::start(self.0, label, None, StartState::Active)) } } }; @@ -170,10 +185,10 @@ fn disabled_impl_parent( ) -> proc_macro::TokenStream { let ts = quote::quote! { impl Parent<#child_ident> for #parent_ident { - fn new_child(&self, label: Label) -> Started<#child_ident> { + fn new_child(&self, label: StaticLabel) -> Started<#child_ident> { self.new_child_same_start(label) } - fn new_child_same_start(&self, _label: Label) -> Started<#child_ident> { + fn new_child_same_start(&self, _label: StaticLabel) -> Started<#child_ident> { Started(#child_ident(())) } } @@ -262,7 +277,7 @@ fn profile_async(obj_ident: syn::Ident, label: String, func: &mut syn::ItemFn) { let body = quote::quote! {{ #start_profiler async move { - profiler::Profiler::resume(&__profiler_scope.0); + profiler::internal::Profiler::resume(&__profiler_scope.0); let result = #block; std::mem::drop(__profiler_scope); result @@ -295,18 +310,18 @@ fn start_profiler( label: String, asyncness: bool, ) -> proc_macro2::TokenStream { - let start_await = match asyncness { - true => quote::quote! { profiler.pause(); }, - false => quote::quote! {}, + let state = match asyncness { + true => quote::quote! { profiler::internal::StartState::Paused }, + false => quote::quote! { profiler::internal::StartState::Active }, }; quote::quote! { let __profiler_scope = { - use profiler::Profiler; - let parent = profiler::IMPLICIT_ID; - let now = Some(profiler::Timestamp::now()); - let profiler = profiler::#obj_ident::start(parent, #label, now); - #start_await - profiler::Started(profiler) + use profiler::internal::Profiler; + let parent = profiler::internal::EventId::implicit(); + let now = Some(profiler::internal::Timestamp::now()); + let label = profiler::internal::Label(#label); + let profiler = profiler::#obj_ident::start(parent, label, now, #state); + profiler::internal::Started(profiler) }; } } @@ -347,9 +362,9 @@ fn wrap_await(await_: &syn::ExprAwait) -> syn::Expr { let wrapped = quote::quote! { { let future = #expr; - profiler::Profiler::pause(&__profiler_scope.0); + profiler::internal::Profiler::pause(&__profiler_scope.0); let result = future.await; - profiler::Profiler::resume(&__profiler_scope.0); + profiler::internal::Profiler::resume(&__profiler_scope.0); result } }; diff --git a/lib/rust/profiler/src/internal.rs b/lib/rust/profiler/src/internal.rs new file mode 100644 index 0000000000..0f7a45c4b1 --- /dev/null +++ b/lib/rust/profiler/src/internal.rs @@ -0,0 +1,484 @@ +//! Implementation details not used directly in normal usage of the Profiling API. +//! +//! `pub` items in this module support two uses: +//! - They support profiling crates in interpreting raw profiling data. +//! - They are used by [the macros](../index.html#macros) that provide the public interface to +//! `profiler`. + +use crate::log; + +use std::fmt; +use std::num; +use std::rc; + + + +// ====================================================== +// === The global logs (EVENTS and the METADATA_LOGS) === +// ====================================================== + +thread_local! { + static EVENT_LOG: log::Log> = log::Log::new(); +} +/// Global log of [`Events`]s. +pub(crate) static EVENTS: log::ThreadLocalLog> = + log::ThreadLocalLog::new(EVENT_LOG); + +thread_local! { + static METADATA_LOG_LOG: log::Log> = log::Log::new(); +} +/// Global registry of metadata logs. +pub(crate) static METADATA_LOGS: log::ThreadLocalLog> = + log::ThreadLocalLog::new(METADATA_LOG_LOG); + +/// Produce a JSON-formatted event log from the internal event logs. +/// +/// Consumes all events that have happened up to this point; except in testing, this should only be +/// done once. +pub fn take_log() -> String { + let events = EVENTS.take_all(); + let metadatas = METADATA_LOGS.clone_all(); + let metadata_names: Vec<_> = metadatas.iter().map(|metadata| metadata.name()).collect(); + let mut metadata_entries: Vec<_> = + metadatas.into_iter().map(|metadata| metadata.take_all()).collect(); + let events: Vec<_> = events + .into_iter() + .map(|event| { + event.map_metadata(|external| { + let id = external.type_id as usize; + let name = metadata_names[id]; + let data = metadata_entries[id].next().unwrap(); + let data = serde_json::value::to_raw_value(&data).unwrap(); + Variant { name, t: data } + }) + }) + .collect(); + serde_json::to_string(&events).unwrap() +} + + +// === Variant === + +/// Wrapper for serializing an object as if it were a particular variant of some unspecified enum. +/// +/// This allows serializing instances of one variant of an enum without knowledge of the other +/// variants. +struct Variant { + name: &'static str, + t: T, +} + +impl serde::Serialize for Variant { + fn serialize(&self, serializer: S) -> Result + where S: serde::Serializer { + serializer.serialize_newtype_variant("", 0, self.name, &self.t) + } +} + + + +// =================== +// === MetadataLog === +// =================== + +pub(crate) struct MetadataLog { + pub name: &'static str, + pub entries: rc::Rc>, +} + +pub(crate) trait MetadataSource { + fn name(&self) -> &'static str; + fn take_all(&self) -> Box>>; +} + +impl MetadataSource for MetadataLog { + fn name(&self) -> &'static str { + self.name + } + fn take_all(&self) -> Box>> { + let entries = self.entries.take_all(); + let entries = + entries.into_iter().map(|data| serde_json::value::to_raw_value(&data).unwrap()); + Box::new(entries) + } +} + + + +// ================ +// === EventLog === +// ================ + +/// The log of profiling events. Data is actually stored globally. +#[derive(Copy, Clone, Debug)] +pub struct EventLog; + +impl EventLog { + /// Log the beginning of a measurement. + pub fn start( + self, + parent: EventId, + label: StaticLabel, + start: Option, + state: StartState, + ) -> EventId { + let m = Start { parent, label, start }; + let event = match state { + StartState::Active => Event::Start(m), + StartState::Paused => Event::StartPaused(m), + }; + let id = EVENTS.len() as u32; + EVENTS.append(event); + EventId(id) + } + + /// Log the end of a measurement. + pub fn end(self, id: EventId, timestamp: Timestamp) { + let event = Event::End { id, timestamp }; + EVENTS.append(event); + } + + /// Log the beginning of an interval in which the measurement is not active. + pub fn pause(self, id: EventId, timestamp: Timestamp) { + let event = Event::Pause { id, timestamp }; + EVENTS.append(event); + } + + /// Log the end of an interval in which the measurement is not active. + pub fn resume(self, id: EventId, timestamp: Timestamp) { + let event = Event::Resume { id, timestamp }; + EVENTS.append(event); + } + + /// Log metadata. + pub fn metadata(self, type_id: u32) -> EventId { + let id = EVENTS.len() as u32; + let timestamp = Timestamp::now(); + let data = ExternalMetadata { type_id }; + let event = Event::Metadata(Timestamped { timestamp, data }); + EVENTS.append(event); + EventId(id) + } +} + + +// === StartState === + +/// Specifies the initial state of a profiler. +#[derive(Debug, Copy, Clone, PartialEq, Eq)] +pub enum StartState { + /// The profiler starts in the running state. + Active, + /// The profiler starts in the paused state. + Paused, +} + + + +// ============= +// === Event === +// ============= + +/// An entry in the profiling log. +#[derive(Debug, Clone, serde::Serialize, serde::Deserialize)] +pub enum Event { + /// The beginning of a measurement. + Start(Start), + /// The beginning of a measurement that starts in the paused state. + StartPaused(Start), + /// The end of a measurement. + End { + /// Identifies the measurement by the ID of its Start event. + id: EventId, + /// When the event occurred. + timestamp: Timestamp, + }, + /// The beginning of an interruption to a measurement, e.g. an await point. + Pause { + /// Identifies the measurement by the ID of its Start event. + id: EventId, + /// When the event occurred. + timestamp: Timestamp, + }, + /// The end of an interruption to an a measurement, e.g. an await point. + Resume { + /// Identifies the measurement by the ID of its Start event. + id: EventId, + /// When the event occurred. + timestamp: Timestamp, + }, + /// Metadata: wrapper with dependency-injected contents. + Metadata(Timestamped), +} + +impl Event { + /// Produce a new event that may have a different metadata type, with metadata values + /// converted by the given function. + fn map_metadata(self, mut f: F) -> Event + where F: FnMut(Metadata) -> Metadata1 { + match self { + // metadata => f(metadata) + Event::Metadata(Timestamped { timestamp, data }) => + Event::Metadata(Timestamped { timestamp, data: f(data) }), + // event => event + Event::Start(start) => Event::Start(start), + Event::StartPaused(start) => Event::StartPaused(start), + Event::End { id, timestamp } => Event::End { id, timestamp }, + Event::Pause { id, timestamp } => Event::Pause { id, timestamp }, + Event::Resume { id, timestamp } => Event::Resume { id, timestamp }, + } + } +} + + + +// ============= +// === Start === +// ============= + +/// A measurement-start entry in the profiling log. +#[derive(Debug, Clone, serde::Serialize, serde::Deserialize)] +pub struct Start { + /// Specifies parent measurement by its [`Start`]. + pub parent: EventId, + /// Start time, or None to indicate it is the same as `parent`. + pub start: Option, + /// Identifies where in the code this measurement originates. + pub label: Label, +} + + +// === Label === + +/// The label of a profiler; this includes the name given at its creation, along with file and +/// line-number information. +#[derive(Debug, Clone, serde::Serialize, serde::Deserialize)] +pub struct Label(pub Storage); + +impl fmt::Display for Label { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + self.0.fmt(f) + } +} + +/// Static-str label, suitable for writing. +pub(crate) type StaticLabel = Label<&'static str>; + + + +// ================= +// === Timestamp === +// ================= + +/// Time elapsed since the [time origin](https://www.w3.org/TR/hr-time-2/#sec-time-origin). +/// +/// Stored in units of 100us, because that is maximum resolution of performance.now(): +/// - [in the specification](https://www.w3.org/TR/hr-time-3), 100us is the limit +/// - in practice, as observed in debug consoles: Chromium 97 (100us) and Firefox 95 (1ms) +#[derive(Copy, Clone, PartialEq, Eq, PartialOrd, Ord, Debug, serde::Serialize, serde::Deserialize)] +pub struct Timestamp(num::NonZeroU64); + +/// Offset used to encode a timestamp, which may be 0, in a [`NonZeroU64`]. +/// To maximize the supported range, this is the smallest positive integer. +const TS_OFFSET: u64 = 1; + +impl Timestamp { + /// Return the current time, relative to the time origin. + pub fn now() -> Self { + Self::from_ms(js::performance::now()) + } + + /// Return the timestamp corresponding to an offset from the time origin, in ms. + #[allow(unsafe_code)] + pub fn from_ms(ms: f64) -> Self { + let ticks = (ms * 10.0).round() as u64; + // Safety: ticks + 1 will not be 0 unless a Timestamp wraps. + // It takes (2 ** 64) * 100us = 58_455_453 years for a Timestamp to wrap. + unsafe { Self(num::NonZeroU64::new_unchecked(ticks + TS_OFFSET)) } + } + + /// Return the timestamp of the time origin. + pub fn time_origin() -> Self { + Self::from_ms(0.0) + } + + /// Convert to an offset from the time origin, in ms. + pub fn into_ms(self) -> f64 { + (self.0.get() - TS_OFFSET) as f64 / 10.0 + } +} + +impl Default for Timestamp { + fn default() -> Self { + Self::time_origin() + } +} + +// === FFI === + +#[cfg(target_arch = "wasm32")] +/// Web APIs. +mod js { + /// [The `Performance` API](https://developer.mozilla.org/en-US/docs/Web/API/Performance) + pub mod performance { + use wasm_bindgen::prelude::*; + + #[wasm_bindgen] + extern "C" { + /// The + /// [performance.now](https://developer.mozilla.org/en-US/docs/Web/API/Performance/now) + /// method returns a double-precision float, measured in milliseconds. + /// + /// The returned value represents the time elapsed since the time origin, which is when + /// the page began to load. + #[wasm_bindgen(js_namespace = performance)] + pub fn now() -> f64; + } + } +} + +#[cfg(not(target_arch = "wasm32"))] +/// Web APIs. +mod js { + /// [The `Performance` API](https://developer.mozilla.org/en-US/docs/Web/API/Performance) + pub mod performance { + /// The + /// [performance.now](https://developer.mozilla.org/en-US/docs/Web/API/Performance/now) + /// method returns a double-precision float, measured in milliseconds. + /// + /// The returned value represents the time elapsed since the time origin, which is when + /// the page began to load. + // This mock implementation returns a dummy value. + pub fn now() -> f64 { + 0.0 + } + } +} + + +// === Timestamped === + +/// Wrapper adding a timestamp to an object. +#[derive(Debug, Clone, serde::Serialize, serde::Deserialize)] +pub struct Timestamped { + /// When the event occurred. + pub timestamp: Timestamp, + /// The data. + pub data: T, +} + + + +// =============== +// === EventId === +// =============== + +/// Identifies an event in the profiling log. +#[derive(Copy, Clone, Debug, PartialEq, Eq, Hash, serde::Serialize, serde::Deserialize)] +pub struct EventId(pub u32); + +impl EventId { + /// Special value indicating that an EventId is to be inferred from context. + pub const IMPLICIT: EventId = EventId(u32::MAX); + + /// Special value indicating the root pseudo-profiler (the parent of runtime root profilers). + pub const APP_LIFETIME: EventId = EventId(u32::MAX - 1); + + /// Special value indicating that no explicit prior event is associated. + /// + /// When used to identify a parent, this indicates that the parent can be inferred to be the + /// current profiler. + pub const fn implicit() -> Self { + Self::IMPLICIT + } +} + + + +// ======================== +// === ExternalMetadata === +// ======================== + +/// Indicates where in the event log metadata from a particular external source should be inserted. +#[derive(Debug, Copy, Clone)] +pub(crate) struct ExternalMetadata { + type_id: u32, +} + + + +// ================ +// === Profiler === +// ================ + +/// The interface supported by profilers of all profiling levels. +pub trait Profiler { + /// Log the beginning of a measurement. + /// + /// Return an object that can be used to manage the measurement's lifetime. + fn start( + parent: EventId, + label: StaticLabel, + time: Option, + start: StartState, + ) -> Self; + /// Log the end of a measurement. + fn finish(self); + /// Log the beginning of an interval in which the profiler is not active. + fn pause(&self); + /// Log the end of an interval in which the profiler is not active. + fn resume(&self); +} + + + +// =============== +// === Started === +// =============== + +/// A profiler that has a start time set, and will complete its measurement when dropped. +#[derive(Debug)] +pub struct Started(pub T); + + +// === Trait Implementations === + +impl Profiler for Started { + fn start( + parent: EventId, + label: StaticLabel, + time: Option, + start: StartState, + ) -> Self { + Self(T::start(parent, label, time, start)) + } + fn finish(self) { + self.0.finish() + } + fn pause(&self) { + self.0.pause() + } + fn resume(&self) { + self.0.resume() + } +} + +impl Drop for Started { + fn drop(&mut self) { + self.0.finish(); + } +} + +impl crate::Parent for Started +where + U: crate::Parent + Profiler + Copy, + T: Profiler + Copy, +{ + fn new_child(&self, label: StaticLabel) -> Started { + self.0.new_child(label) + } + + fn new_child_same_start(&self, label: StaticLabel) -> Started { + self.0.new_child_same_start(label) + } +} diff --git a/lib/rust/profiler/src/lib.rs b/lib/rust/profiler/src/lib.rs index a2fb33f5db..3a6bed288e 100644 --- a/lib/rust/profiler/src/lib.rs +++ b/lib/rust/profiler/src/lib.rs @@ -144,328 +144,47 @@ #![warn(unsafe_code)] #![warn(unused_import_braces)] +pub mod internal; +pub mod log; + extern crate test; -use std::num; +use std::rc; use std::str; - - -// ============= -// === Label === -// ============= - -/// The label of a profiler; this includes the name given at its creation, along with file and -/// line-number information. -pub type Label = &'static str; +use internal::*; -// ================= -// === Timestamp === -// ================= +// ====================== +// === MetadataLogger === +// ====================== -/// Time elapsed since the [time origin](https://www.w3.org/TR/hr-time-2/#sec-time-origin). -/// -/// Stored in units of 100us, because that is maximum resolution of performance.now(): -/// - [in the specification](https://www.w3.org/TR/hr-time-3), 100us is the limit -/// - in practice, as observed in debug consoles: Chromium 97 (100us) and Firefox 95 (1ms) -#[derive(Copy, Clone, PartialEq, Eq, PartialOrd, Ord, Debug)] -pub struct Timestamp(num::NonZeroU64); - -/// Offset used to encode a timestamp, which may be 0, in a [`NonZeroU64`]. -/// To maximize the supported range, this is the smallest positive integer. -const TS_OFFSET: u64 = 1; - -impl Timestamp { - /// Return the current time, relative to the time origin. - pub fn now() -> Self { - Self::from_ms(js::performance::now()) - } - - /// Return the timestamp corresponding to an offset from the time origin, in ms. - #[allow(unsafe_code)] - pub fn from_ms(ms: f64) -> Self { - let ticks = (ms * 10.0).round() as u64; - // Safety: ticks + 1 will not be 0 unless a Timestamp wraps. - // It takes (2 ** 64) * 100us = 58_455_453 years for a Timestamp to wrap. - unsafe { Self(num::NonZeroU64::new_unchecked(ticks + TS_OFFSET)) } - } - - /// Convert to an offset from the time origin, in ms. - pub fn into_ms(self) -> f64 { - (self.0.get() - TS_OFFSET) as f64 / 10.0 - } +/// An object that supports writing a specific type of metadata to the profiling log. +#[derive(Debug)] +pub struct MetadataLogger { + id: u32, + entries: rc::Rc>, } -// === FFI === - -#[cfg(target_arch = "wasm32")] -/// Web APIs. -pub mod js { - /// [The `Performance` API](https://developer.mozilla.org/en-US/docs/Web/API/Performance) - pub mod performance { - use wasm_bindgen::prelude::*; - - #[wasm_bindgen] - extern "C" { - /// The - /// [performance.now](https://developer.mozilla.org/en-US/docs/Web/API/Performance/now) - /// method returns a double-precision float, measured in milliseconds. - /// - /// The returned value represents the time elapsed since the time origin, which is when - /// the page began to load. - #[wasm_bindgen(js_namespace = performance)] - pub fn now() -> f64; - } - } -} - -#[cfg(not(target_arch = "wasm32"))] -/// Web APIs. -pub mod js { - /// [The `Performance` API](https://developer.mozilla.org/en-US/docs/Web/API/Performance) - pub mod performance { - /// The - /// [performance.now](https://developer.mozilla.org/en-US/docs/Web/API/Performance/now) - /// method returns a double-precision float, measured in milliseconds. - /// - /// The returned value represents the time elapsed since the time origin, which is when - /// the page began to load. - // This mock implementation returns a dummy value. - pub fn now() -> f64 { - 0.0 - } - } -} - - - -// =============== -// === EventId === -// =============== - -/// Identifies an event in the profiling log. -#[derive(Copy, Clone, Debug, PartialEq, Eq)] -pub struct EventId(u32); - -// === Special Profilers / IDs === - -/// Special value indicating that no explicit prior event is associated. -/// -/// When used to identify a parent, this indicates that the parent can be inferred to be the -/// current profiler. -pub const IMPLICIT_ID: EventId = EventId(u32::MAX); -const APP_LIFETIME_ID: EventId = EventId(u32::MAX - 1); - -/// Pseudo-profiler serving as the root of the measurement hierarchy. -pub const APP_LIFETIME: Objective = Objective(APP_LIFETIME_ID); - - - -// ======================= -// === StartedProfiler === -// ======================= - -/// The interface supported by profiler-data objects. -pub trait StartedProfiler { - /// Log the end of a measurement, with end-time set to now. - fn finish(self); -} - - -// === Implementation for enabled profilers === - -impl StartedProfiler for EventId { - fn finish(self) { - let timestamp = Timestamp::now(); - EventLog.end(self, timestamp); - } -} - - -// === Implementation for disabled profilers === - -impl StartedProfiler for () { - fn finish(self) {} -} - - - -// ================ -// === EventLog === -// ================ - -/// The log of profiling events. Data is actually stored globally. -#[derive(Copy, Clone, Debug)] -pub struct EventLog; - -impl EventLog { - /// Log the beginning of a measurement. - pub fn start(self, parent: EventId, label: Label, start: Option) -> EventId { - let m = Start { parent, label, start }; - let id = EVENTS.with(move |log| log.len()) as u32; - EVENTS.with(move |log| log.push(Event::Start(m))); - EventId(id) - } - - /// Log the end of a measurement. - pub fn end(self, id: EventId, timestamp: Timestamp) { - EVENTS.with(move |log| log.push(Event::End { id, timestamp })); - } - - /// Log the beginning of an interval in which the measurement is not active. - pub fn pause(self, id: EventId, timestamp: Timestamp) { - EVENTS.with(move |log| log.push(Event::Pause { id, timestamp })); - } - - /// Log the end of an interval in which the measurement is not active. - pub fn resume(self, id: EventId, timestamp: Timestamp) { - EVENTS.with(move |log| log.push(Event::Resume { id, timestamp })); - } -} - -/// Internal -pub mod internal { - use crate::*; - - use std::cell; - use std::mem; - - // ======================= - // === LocalVecBuilder === - // ======================= - - /// Data structure supporting limited interior mutability, to build up a collection. - #[derive(Debug)] - pub struct LocalVecBuilder(cell::UnsafeCell>); - #[allow(unsafe_code)] - impl LocalVecBuilder { - #[allow(clippy::new_without_default)] - /// Create a new, empty vec builder. - pub fn new() -> Self { - Self(cell::UnsafeCell::new(vec![])) - } - - /// Push an element. - pub fn push(&self, element: T) { - // Note [LocalVecBuilder Safety] - unsafe { - (&mut *self.0.get()).push(element); - } - } - - /// Return (and consume) all elements pushed so far. - pub fn build(&self) -> Vec { - // Note [LocalVecBuilder Safety] - unsafe { mem::take(&mut *self.0.get()) } - } - - /// The number of elements that are currently available. - #[allow(clippy::len_without_is_empty)] - pub fn len(&self) -> usize { - // Note [LocalVecBuilder Safety] - unsafe { &*self.0.get() }.len() - } - } - // Note [LocalVecBuilder Safety] - // ============================= - // When obtaining a reference from the UnsafeCell, all accessors follow these rules: - // - There must be a scope that the reference doesn't escape. - // - There must be no other references obtained in the same scope. - // Consistently following these rules ensures the no-alias rule of mutable references is - // satisfied. - - - - // ============== - // === EVENTS === - // ============== - - thread_local! { - /// Global log of [`Events`]s. - pub static EVENTS: LocalVecBuilder = LocalVecBuilder::new(); - } -} - -#[doc(inline)] -pub use internal::EVENTS; - -/// Gather all events logged since the last time take_log() was called. -/// -/// Except in testing, this should only be done once. (Supporting incremental output would -/// require generating EventIds with a counter that isn't reset on log.build()). -pub fn take_log() -> Vec { - EVENTS.with(|log| log.build()) -} - - - -// ============= -// === Event === -// ============= - -/// An entry in the profiling log. -#[derive(Debug, Copy, Clone)] -pub enum Event { - /// The beginning of a measurement. - Start(Start), - /// The end of a measurement. - End { - /// Identifies the measurement by the ID of its Start event. - id: EventId, - /// When the event occurred. - timestamp: Timestamp, - }, - /// The beginning of an interruption to a measurement, e.g. an await point. - Pause { - /// Identifies the measurement by the ID of its Start event. - id: EventId, - /// When the event occurred. - timestamp: Timestamp, - }, - /// The end of an interruption to an a measurement, e.g. an await point. - Resume { - /// Identifies the measurement by the ID of its Start event. - id: EventId, - /// When the event occurred. - timestamp: Timestamp, - }, -} - -// ============= -// === Start === -// ============= - -/// A measurement-start entry in the profiling log. -#[derive(Debug, Copy, Clone)] -pub struct Start { - /// Specifies parent measurement by its [`Start`]. - pub parent: EventId, - /// Start time, or None to indicate it is the same as `parent`. - pub start: Option, - /// Identifies where in the code this measurement originates. - pub label: Label, -} - - - -// ================ -// === Profiler === -// ================ - -/// The interface supported by profilers of all profiling levels. -pub trait Profiler { - /// Log the beginning of a measurement. +impl MetadataLogger { + /// Create a MetadataLogger for logging a particular type. /// - /// Return an object that can be used to end the measurement. - fn start(parent: EventId, label: Label, time: Option) -> Self; - /// Log the end of a measurement. - fn finish(self); - /// Log the beginning of an interval in which the profiler is not active. - fn pause(&self); - /// Log the end of an interval in which the profiler is not active. - fn resume(&self); + /// The name given here must match the name used for deserialization. + pub fn new(name: &'static str) -> Self { + let id = METADATA_LOGS.len() as u32; + let entries = rc::Rc::new(log::Log::new()); + METADATA_LOGS.append(rc::Rc::new(MetadataLog:: { name, entries: entries.clone() })); + Self { id, entries } + } + + /// Write a metadata object to the profiling event log. + /// + /// Returns an identifier that can be used to create references between log entries. + pub fn log(&self, t: T) -> EventId { + self.entries.append(t); + EventLog.metadata(self.id) + } } @@ -477,58 +196,9 @@ pub trait Profiler { /// Any object representing a profiler that is a valid parent for a profiler of type T. pub trait Parent { /// Start a new profiler, with `self` as its parent. - fn new_child(&self, label: Label) -> Started; + fn new_child(&self, label: StaticLabel) -> Started; /// Create a new profiler, with `self` as its parent, and the same start time as `self`. - fn new_child_same_start(&self, label: Label) -> Started; -} - - - -// =============== -// === Started === -// =============== - -/// A profiler that can be used as a parent for async profilers, has a start time set, and will -/// complete its measurement when dropped. -#[derive(Debug)] -pub struct Started(pub T); - - -// === Trait Implementations === - -impl Profiler for Started { - fn start(parent: EventId, label: Label, time: Option) -> Self { - Self(T::start(parent, label, time)) - } - fn finish(self) { - self.0.finish() - } - fn pause(&self) { - self.0.pause() - } - fn resume(&self) { - self.0.resume() - } -} - -impl Drop for Started { - fn drop(&mut self) { - self.0.finish(); - } -} - -impl Parent for Started -where - U: Parent + Profiler + Copy, - T: Profiler + Copy, -{ - fn new_child(&self, label: Label) -> Started { - self.0.new_child(label) - } - - fn new_child_same_start(&self, label: Label) -> Started { - self.0.new_child_same_start(label) - } + fn new_child_same_start(&self, label: StaticLabel) -> Started; } @@ -542,13 +212,15 @@ where macro_rules! await_ { ($evaluates_to_future:expr, $profiler:ident) => {{ let future = $evaluates_to_future; - profiler::Profiler::pause(&$profiler); + profiler::internal::Profiler::pause(&$profiler); let result = future.await; - profiler::Profiler::resume(&$profiler); + profiler::internal::Profiler::resume(&$profiler); result }}; } + + // =================================== // === profiler_macros Invocations === // =================================== @@ -580,11 +252,13 @@ macro_rules! await_ { /// # use enso_profiler::profile; /// fn example(input: u32) -> u32 { /// let __profiler_scope = { -/// use profiler::Profiler; -/// let parent = profiler::IMPLICIT_ID; -/// let now = Some(profiler::Timestamp::now()); -/// let profiler = profiler::Detail::start(parent, "example (profiler/src/lib.rs:78)", now); -/// profiler::Started(profiler) +/// use profiler::internal::Profiler; +/// let parent = profiler::internal::EventId::implicit(); +/// let now = Some(profiler::internal::Timestamp::now()); +/// let label = profiler::internal::Label("example (profiler/src/lib.rs:78)"); +/// let profiler = +/// profiler::Detail::start(parent, label, now, profiler::internal::StartState::Active); +/// profiler::internal::Started(profiler) /// }; /// { /// input @@ -610,15 +284,16 @@ macro_rules! await_ { /// # use enso_profiler::profile; /// fn async_example(input: u32) -> impl std::future::Future { /// let __profiler_scope = { -/// use profiler::Profiler; -/// let parent = profiler::IMPLICIT_ID; -/// let now = Some(profiler::Timestamp::now()); -/// let profiler = profiler::Task::start(parent, "async_example (lib.rs:571)", now); -/// profiler.pause(); -/// profiler::Started(profiler) +/// use profiler::internal::Profiler; +/// let parent = profiler::internal::EventId::implicit(); +/// let now = Some(profiler::internal::Timestamp::now()); +/// let label = profiler::internal::Label("async_example (lib.rs:571)"); +/// let profiler = +/// profiler::Task::start(parent, label, now, profiler::internal::StartState::Paused); +/// profiler::internal::Started(profiler) /// }; /// async move { -/// profiler::Profiler::resume(&__profiler_scope.0); +/// profiler::internal::Profiler::resume(&__profiler_scope.0); /// let result = { input }; /// std::mem::drop(__profiler_scope); /// result @@ -646,6 +321,12 @@ pub use enso_profiler_macros::profile; enso_profiler_macros::define_hierarchy![Objective, Task, Detail, Debug]; +// === APP_LIFETIME === + +/// Pseudo-profiler serving as the root of the measurement hierarchy. +pub const APP_LIFETIME: Objective = Objective(EventId::APP_LIFETIME); + + // ============= // === Tests === @@ -656,6 +337,19 @@ mod tests { use crate as profiler; use profiler::profile; + /// Black-box metadata object, for ignoring metadata contents. + #[derive(Debug, Copy, Clone, serde::Serialize, serde::Deserialize)] + pub(crate) enum OpaqueMetadata { + /// Anything. + #[serde(other)] + Unknown, + } + + /// Take and parse the log (convenience function for tests). + fn get_log() -> Vec> { + serde_json::from_str(&profiler::take_log()).unwrap() + } + #[test] fn root() { { @@ -664,12 +358,12 @@ mod tests { // by absolute paths" (). let _profiler = start_objective!(profiler::APP_LIFETIME, "test"); } - let log = profiler::take_log(); + let log = get_log::(); match &log[..] { [profiler::Event::Start(m0), profiler::Event::End { id, timestamp: end_time }] => { assert_eq!(m0.parent, profiler::APP_LIFETIME.0); assert_eq!(id.0, 0); - assert!(m0.label.starts_with("test ")); + assert!(m0.label.0.starts_with("test ")); assert!(*end_time >= m0.start.unwrap()); } _ => panic!("log: {:?}", log), @@ -682,7 +376,7 @@ mod tests { let _profiler0 = start_objective!(profiler::APP_LIFETIME, "test0"); let _profiler1 = objective_with_same_start!(_profiler0, "test1"); } - let log = profiler::take_log(); + let log = get_log::(); use profiler::Event::*; match &log[..] { [Start(m0), Start(m1), End { id: id1, .. }, End { id: id0, .. }] => { @@ -702,11 +396,11 @@ mod tests { #[profile(Objective)] fn profiled() {} profiled(); - let log = profiler::take_log(); + let log = get_log::(); match &log[..] { [profiler::Event::Start(m0), profiler::Event::End { id: id0, .. }] => { assert!(m0.start.is_some()); - assert_eq!(m0.parent, profiler::IMPLICIT_ID); + assert_eq!(m0.parent, profiler::EventId::IMPLICIT); assert_eq!(id0.0, 0); } _ => panic!("log: {:?}", log), @@ -722,20 +416,18 @@ mod tests { } let future = profiled(); futures::executor::block_on(future); - let log = profiler::take_log(); + let log = get_log::(); #[rustfmt::skip] match &log[..] { [ - profiler::Event::Start(_), - // implicit await at start of function - profiler::Event::Pause { id: pause0, .. }, - profiler::Event::Resume { id: resume0, .. }, - // block.await - profiler::Event::Pause { id: pause1, .. }, - profiler::Event::Resume { id: resume1, .. }, - profiler::Event::End { id: end_id, .. }, + // async fn starts paused + profiler::Event::StartPaused(_), + profiler::Event::Resume { id: resume0, .. }, + // block.await + profiler::Event::Pause { id: pause1, .. }, + profiler::Event::Resume { id: resume1, .. }, + profiler::Event::End { id: end_id, .. }, ] => { - assert_eq!(pause0.0, 0); assert_eq!(resume0.0, 0); assert_eq!(pause1.0, 0); assert_eq!(resume1.0, 0); @@ -744,6 +436,75 @@ mod tests { _ => panic!("log: {:#?}", log), }; } + + #[test] + fn store_metadata() { + // A metadata type. + #[derive(serde::Serialize, serde::Deserialize)] + struct MyData(u32); + + // Attach some metadata to a profiler. + #[profile(Objective)] + fn demo() { + let meta_logger = profiler::MetadataLogger::new("MyData"); + meta_logger.log(&MyData(23)); + } + + // We can deserialize a metadata entry as an enum containing a newtype-variant for each + // type of metadata we are able to interpret; the variant name is the string given to + // MetadataLogger::register. + // + // We don't use an enum like this to *write* metadata because defining it requires + // dependencies from all over the app, but when consuming metadata we need all the datatype + // definitions anyway. + #[derive(serde::Deserialize)] + enum MyMetadata { + MyData(MyData), + } + + demo(); + let log = get_log::(); + match &log[..] { + #[rustfmt::skip] + &[ + profiler::Event::Start(_), + profiler::Event::Metadata( + profiler::Timestamped{ timestamp: _, data: MyMetadata::MyData (MyData(23)) }), + profiler::Event::End { .. }, + ] => (), + _ => panic!(), + } + } + + #[test] + fn format_stability() { + #[allow(unused)] + fn static_assert_exhaustiveness(e: profiler::Event) -> profiler::Event { + // If you define a new Event variant, this will fail to compile to remind you to: + // - Create a new test covering deserialization of the previous format, if necessary. + // - Update `TEST_LOG` in this test to cover every variant of the new Event definition. + match e { + profiler::Event::Start(_) => e, + profiler::Event::StartPaused(_) => e, + profiler::Event::End { .. } => e, + profiler::Event::Pause { .. } => e, + profiler::Event::Resume { .. } => e, + profiler::Event::Metadata(_) => e, + } + } + const TEST_LOG: &str = "[\ + {\"Start\":{\"parent\":4294967294,\"start\":null,\"label\":\"dummy label (lib.rs:23)\"}},\ + {\"StartPaused\":{\"parent\":4294967294,\"start\":1,\"label\":\"dummy label2 (lib.rs:17)\"}},\ + {\"End\":{\"id\":1,\"timestamp\":1}},\ + {\"Pause\":{\"id\":1,\"timestamp\":1}},\ + {\"Resume\":{\"id\":1,\"timestamp\":1}},\ + {\"Metadata\":{\"timestamp\":1,\"data\":\"Unknown\"}}\ + ]"; + let events: Vec> = + serde_json::from_str(TEST_LOG).unwrap(); + let reserialized = serde_json::to_string(&events).unwrap(); + assert_eq!(TEST_LOG, &reserialized[..]); + } } // Performance analysis [KW] @@ -767,9 +528,9 @@ mod bench { /// Perform a specified number of measurements, for benchmarking. fn log_measurements(count: usize) { for _ in 0..count { - let _profiler = start_objective!(profiler::APP_LIFETIME, ""); + let _profiler = start_objective!(profiler::APP_LIFETIME, "log_measurement"); } - test::black_box(profiler::take_log()); + test::black_box(crate::EVENTS.take_all()); } #[bench] @@ -783,12 +544,19 @@ mod bench { } /// For comparison with time taken by [`log_measurements`]. - fn push_vec(count: usize, log: &mut Vec) { + fn push_vec( + count: usize, + log: &mut Vec>, + ) { for _ in 0..count { - log.push(profiler::Start { - parent: profiler::APP_LIFETIME_ID, + log.push(profiler::Event::Start(profiler::Start { + parent: profiler::EventId::APP_LIFETIME, start: None, - label: "", + label: profiler::Label(""), + })); + log.push(profiler::Event::End { + id: profiler::EventId::implicit(), + timestamp: Default::default(), }); } test::black_box(&log); diff --git a/lib/rust/profiler/src/log.rs b/lib/rust/profiler/src/log.rs new file mode 100644 index 0000000000..2b3b7bf809 --- /dev/null +++ b/lib/rust/profiler/src/log.rs @@ -0,0 +1,120 @@ +//! Data structure supporting limited interior mutability, to build up a collection. +//! +//! # Implementation +//! +//! Note [Log Safety] +//! ============================= +//! When obtaining a reference from the UnsafeCell, all accessors follow these rules: +//! - There must be a scope that the reference doesn't escape. +//! - There must be no other references obtained in the same scope. +//! Consistently following these rules ensures the no-alias rule of mutable references is +//! satisfied. + +use std::cell; +use std::mem; + + + +// =========== +// === Log === +// =========== + +/// Data structure supporting limited interior mutability, to build up a collection. +#[derive(Debug)] +pub struct Log(cell::UnsafeCell>); + +#[allow(unsafe_code)] +impl Log { + #[allow(clippy::new_without_default)] + /// Create a new, empty vec builder. + pub fn new() -> Self { + Self(cell::UnsafeCell::new(vec![])) + } + + /// Push an element. + pub fn append(&self, element: T) { + // Note [Log Safety] + unsafe { + (&mut *self.0.get()).push(element); + } + } + + /// Return (and consume) all elements pushed so far. + pub fn take_all(&self) -> Vec { + // Note [Log Safety] + unsafe { mem::take(&mut *self.0.get()) } + } + + /// The number of elements that are currently available. + pub fn len(&self) -> usize { + // Note [Log Safety] + unsafe { &*self.0.get() }.len() + } + + /// Returns true if no elements are available. + pub fn is_empty(&self) -> bool { + // Note [Log Safety] + unsafe { &*self.0.get() }.is_empty() + } +} + +#[allow(unsafe_code)] +impl Log { + /// Return clones of all elements pushed so far. + pub fn clone_all(&self) -> Vec { + // Note [Log Safety] + unsafe { &*self.0.get() }.to_vec() + } +} + +// This can't be derived without requiring T: Default, which is not otherwise needed. +// See: https://github.com/rust-lang/rust/issues/26925 +impl Default for Log { + fn default() -> Self { + Self(Default::default()) + } +} + + + +// ====================== +// === ThreadLocalLog === +// ====================== + +/// Wraps a thread-local [`Log`] instance. +#[derive(Debug)] +pub struct ThreadLocalLog(std::thread::LocalKey>); + +impl ThreadLocalLog { + /// New. + pub const fn new(log: std::thread::LocalKey>) -> Self { + Self(log) + } + + /// Push an element. + pub fn append(&'static self, element: T) { + self.0.with(|log| log.append(element)) + } + + /// Return (and consume) all elements pushed so far. + pub fn take_all(&'static self) -> Vec { + self.0.with(|log| log.take_all()) + } + + /// The number of elements that are currently available. + pub fn len(&'static self) -> usize { + self.0.with(|log| log.len()) + } + + /// Returns true if no elements are available. + pub fn is_empty(&'static self) -> bool { + self.0.with(|log| log.is_empty()) + } +} + +impl ThreadLocalLog { + /// Return clones of all elements pushed so far. + pub fn clone_all(&'static self) -> Vec { + self.0.with(|log| log.clone_all()) + } +}