enso-org/enso
1
1
Fork 0
mirror of https://github.com/enso-org/enso.git synced 2024-11-22 22:10:15 +03:00
Code Issues Projects Releases Wiki Activity

API for storing metadata (#3291)

Browse Source 
API for storing metadata.

See: https://www.pivotaltracker.com/story/show/181149277

# Important Notes
**New APIs**:
- Storing metadata is implemented with `profiler::MetadataLogger`.
- A full metadata storage/retrieval example is in [the top-level doctests](https://github.com/enso-org/enso/blob/wip/kw/profiling-metadata-api/lib/rust/profiler/data/src/lib.rs) for profiler::data, a crate which implements an API for profiling data consumers (it abstracts away the low-level details of the event log, and checks its invariants in the process) [after review of this new API here I'll open a PR to add it to the design doc].

**Implementation**:
- `profiler::Event` is parameterized by a metadata type, so that different types of metadata can be dependency-injected into it.
- A data consumer defines its metadata type as an enum of all the kinds of metadata it is interested in.
- Producing the metadata enum is accomplished without defining its type (which would require dependencies from around the app): A `MetadataLogger` internally use a serialization helper `Variant` to serialize its variant of the metadata enum without knowledge of the other possible variants.

**Performance impact**: still in the low ns/measurement range, comparable to pushing to a vec.

*Note*: `LocalVecBuilder` is currently present under the name `Log`, which is accurate but probably too overloaded. I'd like to find the right name for it, document it with examples, and move it to its own crate under data-structures, but I don't want doing that to hold up this PR.
This commit is contained in:
Kaz Wesley 2022-02-28 01:55:56 -08:00 committed by GitHub
parent b03416f907
commit a3914f33c1
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
11 changed files with 1953 additions and 425 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
.github/CODEOWNERS vendored
View File

@ -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

12
Cargo.lock generated
View File

@ -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"

1
Cargo.toml
View File

@ -7,6 +7,7 @@ members = [
"app/gui",
"build/rust-scripts",
"lib/rust/*",
"lib/rust/profiler/data",
"lib/rust/not-used/*",
"integration-test"
]

2
lib/rust/profiler/Cargo.toml
View File

@ -5,6 +5,8 @@ edition = "2021"
authors = ["Enso Team <contact@enso.org>"]
[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" }

13
lib/rust/profiler/data/Cargo.toml Normal file
View File

@ -0,0 +1,13 @@
[package]
name = "enso-profiler-data"
version = "0.1.0"
edition = "2021"
authors = ["Enso Team <contact@enso.org>"]
[dependencies]
serde = { version = "1.0", features = ["derive"] }
serde_json = "1.0"
enso-profiler = { path = "../" }
[dev-dependencies]
futures = "0.3"

548
lib/rust/profiler/data/src/lib.rs Normal file
View File

@ -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<MyDataA>,
//! meta_logger_b: profiler::MetadataLogger<MyDataB>,
//! // ...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<MyMetadata> = 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<M> {
/// 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<EventError<serde_json::Error>>,
/// 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<Measurement<M>, EventError<parse::DataError>>,
},
/// Failed to interpret the event log data.
DataError(EventError<parse::DataError>),
}
impl<M> fmt::Display for Error<M> {
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<M> fmt::Debug for Error<M> {
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<M> error::Error for Error<M> {
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<E> {
#[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<E: fmt::Debug> fmt::Display for EventError<E> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(f, "{:?}", self)
}
}
impl<E: error::Error> error::Error for EventError<E> {
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<M> {
/// 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<Self>,
/// Metadata attached to this profiler.
pub metadata: Vec<Metadata<M>>,
}
// === 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<Mark>,
/// Intervals that the profiler was running.
pub active: Vec<Interval>,
/// 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<Interval> {
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<M> {
/// 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<Mark>,
}
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>,
}
// === 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<OpaqueMetadata> =
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<OpaqueMetadata> =
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<OpaqueMetadata> =
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<OpaqueMetadata> =
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<OpaqueMetadata> =
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<profiler_data::Measurement<MyMetadata>, _> = 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)));
}
}

565
lib/rust/profiler/data/src/parse.rs Normal file
View File

@ -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<M: serde::de::DeserializeOwned> str::FromStr for crate::Measurement<M> {
type Err = crate::Error<M>;
fn from_str(s: &str) -> Result<Self, Self::Err> {
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<M> {
pub events: Vec<profiler::internal::Event<M, OwnedLabel>>,
pub errors: Vec<crate::EventError<serde_json::Error>>,
}
/// Deserialize a log of events.
///
/// For each entry in the log, produces either a deserialized Event or an error.
pub(crate) fn parse<M>(s: &str) -> Result<Parse<M>, 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::<profiler::internal::Event<M, String>>(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<M>(
events: impl IntoIterator<Item = profiler::internal::Event<M, OwnedLabel>>,
) -> Result<crate::Measurement<M>, crate::EventError<DataError>> {
// 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<id::Runtime>),
/// 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<Expected> 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<M> {
label: crate::Label,
created: crate::Mark,
created_paused: bool,
pauses: Vec<crate::Mark>,
resumes: Vec<crate::Mark>,
end: Option<crate::Mark>,
state: State,
metadata: Vec<crate::Metadata<M>>,
}
impl<M> MeasurementBuilder<M> {
fn build(self) -> crate::Measurement<M> {
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<M> {
/// Stack of active profilers, for keeping track of the current profiler.
active: Vec<id::Runtime>,
/// Accumulated data pertaining to each profiler.
builders: collections::HashMap<id::Runtime, MeasurementBuilder<M>>,
/// Accumulated data pertaining to the root event.
root_builder: MeasurementBuilder<M>,
/// Ids and parents, in same order as event log.
order: Vec<(id::Runtime, id::Explicit)>,
}
impl<M> Default for LogVisitor<M> {
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<M> LogVisitor<M> {
/// Convert the log into data about each measurement.
fn visit(
events: impl IntoIterator<Item = profiler::internal::Event<M, OwnedLabel>>,
) -> Result<Self, crate::EventError<DataError>> {
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<M> LogVisitor<M> {
fn visit_start(
&mut self,
pos: id::Runtime,
event: profiler::internal::Start<OwnedLabel>,
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(&current_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(&current_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<M>,
) -> 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<M> LogVisitor<M> {
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<crate::Mark, DataError> {
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<Self, Self::Err> {
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<Option<Self>, 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<profiler::internal::EventId> 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<Runtime> for Explicit {
fn from(id: Runtime) -> Self {
Explicit::Runtime(id)
}
}
impl From<Runtime> for crate::Seq {
fn from(pos: Runtime) -> Self {
Self::runtime_event(pos.0)
}
}
}

69
lib/rust/profiler/macros/src/lib.rs
View File

@ -60,8 +60,13 @@ fn define_profiler(
// === Trait Implementations ===
impl Profiler for #obj_ident {
fn start(parent: EventId, label: Label, time: Option<Timestamp>) -> Self {
#obj_ident(EventLog.start(parent, label, time))
fn start(
parent: EventId,
label: StaticLabel,
time: Option<Timestamp>,
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<profiler::#obj_ident> = $parent.new_child(label);
let label = profiler::internal::Label(
concat!($label, " (", file!(), ":", line!(), ")"));
let profiler: profiler::internal::Started<profiler::#obj_ident> =
$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<profiler::#obj_ident> =
let label = profiler::internal::Label(
concat!($label, " (", file!(), ":", line!(), ")"));
let profiler: profiler::internal::Started<profiler::#obj_ident> =
$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<Timestamp>) -> Self { Self(()) }
fn start(
_: EventId,
_: StaticLabel,
_: Option<Timestamp>,
_: 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
}
};

484
lib/rust/profiler/src/internal.rs Normal file
View File

@ -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<Event<ExternalMetadata, &'static str>> = log::Log::new();
}
/// Global log of [`Events`]s.
pub(crate) static EVENTS: log::ThreadLocalLog<Event<ExternalMetadata, &'static str>> =
log::ThreadLocalLog::new(EVENT_LOG);
thread_local! {
static METADATA_LOG_LOG: log::Log<rc::Rc<dyn MetadataSource>> = log::Log::new();
}
/// Global registry of metadata logs.
pub(crate) static METADATA_LOGS: log::ThreadLocalLog<rc::Rc<dyn MetadataSource>> =
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<T> {
name: &'static str,
t: T,
}
impl<T: serde::Serialize> serde::Serialize for Variant<T> {
fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
where S: serde::Serializer {
serializer.serialize_newtype_variant("", 0, self.name, &self.t)
}
}
// ===================
// === MetadataLog ===
// ===================
pub(crate) struct MetadataLog<T> {
pub name: &'static str,
pub entries: rc::Rc<log::Log<T>>,
}
pub(crate) trait MetadataSource {
fn name(&self) -> &'static str;
fn take_all(&self) -> Box<dyn Iterator<Item = Box<serde_json::value::RawValue>>>;
}
impl<T: 'static + serde::Serialize> MetadataSource for MetadataLog<T> {
fn name(&self) -> &'static str {
self.name
}
fn take_all(&self) -> Box<dyn Iterator<Item = Box<serde_json::value::RawValue>>> {
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<Timestamp>,
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<Metadata, LabelStorage> {
/// The beginning of a measurement.
Start(Start<LabelStorage>),
/// The beginning of a measurement that starts in the paused state.
StartPaused(Start<LabelStorage>),
/// 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<Metadata>),
}
impl<Metadata, LabelStorage> Event<Metadata, LabelStorage> {
/// Produce a new event that may have a different metadata type, with metadata values
/// converted by the given function.
fn map_metadata<F, Metadata1>(self, mut f: F) -> Event<Metadata1, LabelStorage>
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<LabelStorage> {
/// Specifies parent measurement by its [`Start`].
pub parent: EventId,
/// Start time, or None to indicate it is the same as `parent`.
pub start: Option<Timestamp>,
/// Identifies where in the code this measurement originates.
pub label: Label<LabelStorage>,
}
// === 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<Storage>(pub Storage);
impl<Storage: fmt::Display> fmt::Display for Label<Storage> {
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<T> {
/// 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<Timestamp>,
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<T: Profiler + Copy>(pub T);
// === Trait Implementations ===
impl<T: Profiler + Copy> Profiler for Started<T> {
fn start(
parent: EventId,
label: StaticLabel,
time: Option<Timestamp>,
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<T: Profiler + Copy> Drop for Started<T> {
fn drop(&mut self) {
self.0.finish();
}
}
impl<T, U> crate::Parent<T> for Started<U>
where
U: crate::Parent<T> + Profiler + Copy,
T: Profiler + Copy,
{
fn new_child(&self, label: StaticLabel) -> Started<T> {
self.0.new_child(label)
}
fn new_child_same_start(&self, label: StaticLabel) -> Started<T> {
self.0.new_child_same_start(label)
}
}

562
lib/rust/profiler/src/lib.rs
View File

@ -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<T> {
id: u32,
entries: rc::Rc<log::Log<T>>,
}
// === 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<Timestamp>) -> 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<T>(cell::UnsafeCell<Vec<T>>);
#[allow(unsafe_code)]
impl<T> LocalVecBuilder<T> {
#[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<T> {
// 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<Event> = 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<Event> {
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<Timestamp>,
/// 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<T: 'static + serde::Serialize> MetadataLogger<T> {
/// 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<Timestamp>) -> 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::<T> { 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<T: Profiler + Copy> {
/// Start a new profiler, with `self` as its parent.
fn new_child(&self, label: Label) -> Started<T>;
fn new_child(&self, label: StaticLabel) -> Started<T>;
/// 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<T>;
}
// ===============
// === 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<T: Profiler + Copy>(pub T);
// === Trait Implementations ===
impl<T: Profiler + Copy> Profiler for Started<T> {
fn start(parent: EventId, label: Label, time: Option<Timestamp>) -> 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<T: Profiler + Copy> Drop for Started<T> {
fn drop(&mut self) {
self.0.finish();
}
}
impl<T, U> Parent<T> for Started<U>
where
U: Parent<T> + Profiler + Copy,
T: Profiler + Copy,
{
fn new_child(&self, label: Label) -> Started<T> {
self.0.new_child(label)
}
fn new_child_same_start(&self, label: Label) -> Started<T> {
self.0.new_child_same_start(label)
}
fn new_child_same_start(&self, label: StaticLabel) -> Started<T>;
}
@ -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<Output = u32> {
/// 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<M: serde::de::DeserializeOwned>() -> Vec<profiler::Event<M, String>> {
serde_json::from_str(&profiler::take_log()).unwrap()
}
#[test]
fn root() {
{
@ -664,12 +358,12 @@ mod tests {
// by absolute paths" (<https://github.com/rust-lang/rust/issues/52234>).
let _profiler = start_objective!(profiler::APP_LIFETIME, "test");
}
let log = profiler::take_log();
let log = get_log::<OpaqueMetadata>();
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::<OpaqueMetadata>();
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::<OpaqueMetadata>();
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::<OpaqueMetadata>();
#[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::<MyMetadata>();
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<M, L>(e: profiler::Event<M, L>) -> profiler::Event<M, L> {
// 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<profiler::Event<OpaqueMetadata, String>> =
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<profiler::Start>) {
fn push_vec(
count: usize,
log: &mut Vec<profiler::Event<crate::tests::OpaqueMetadata, &'static str>>,
) {
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);

120
lib/rust/profiler/src/log.rs Normal file
View File

@ -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<T>(cell::UnsafeCell<Vec<T>>);
#[allow(unsafe_code)]
impl<T> Log<T> {
#[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<T> {
// 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<T: Clone> Log<T> {
/// Return clones of all elements pushed so far.
pub fn clone_all(&self) -> Vec<T> {
// 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<T> Default for Log<T> {
fn default() -> Self {
Self(Default::default())
}
}
// ======================
// === ThreadLocalLog ===
// ======================
/// Wraps a thread-local [`Log`] instance.
#[derive(Debug)]
pub struct ThreadLocalLog<T: 'static>(std::thread::LocalKey<Log<T>>);
impl<T: 'static> ThreadLocalLog<T> {
/// New.
pub const fn new(log: std::thread::LocalKey<Log<T>>) -> 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<T> {
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<T: Clone> ThreadLocalLog<T> {
/// Return clones of all elements pushed so far.
pub fn clone_all(&'static self) -> Vec<T> {
self.0.with(|log| log.clone_all())
}
}