diff --git a/Cargo.toml b/Cargo.toml index 8433a6f4..111797ea 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,5 +1,5 @@ [workspace] -members = ["flecs_ecs", "flecs_ecs_derive", "flecs_ecs_sys", "test_crash_handler"] +members = ["flecs_ecs", "flecs_ecs_derive", "flecs_ecs_sys", "flecs_ecs_tracing", "test_crash_handler"] resolver = "2" exclude = [ diff --git a/flecs_ecs_tracing/Cargo.toml b/flecs_ecs_tracing/Cargo.toml new file mode 100644 index 00000000..ba8f8c1b --- /dev/null +++ b/flecs_ecs_tracing/Cargo.toml @@ -0,0 +1,23 @@ +[package] +name = "flecs_ecs_tracing" +version = "0.1.0" +edition.workspace = true +license.workspace = true +repository.workspace = true +rust-version.workspace = true + +[lints] +workspace = true + +[dependencies] +flecs_ecs = { version = "0.1.3", path = "../flecs_ecs" } +fxhash = "0.2.1" +tracing-core = "0.1.32" + +[dev-dependencies] +# for doctest/example +tracing = "0.1.40" +tracing-subscriber = { version = "0.3.18", features = ["env-filter"] } + +[features] +perf_trace = ["flecs_ecs/flecs_perf_trace"] diff --git a/flecs_ecs_tracing/src/lib.rs b/flecs_ecs_tracing/src/lib.rs new file mode 100644 index 00000000..92dbdad7 --- /dev/null +++ b/flecs_ecs_tracing/src/lib.rs @@ -0,0 +1,95 @@ +//! Integrates Flecs ECS logging and performance tracing into the `tracing` ecosystem. + +use flecs_ecs::prelude::*; + +mod log; +mod metadata; +#[cfg(feature = "perf_trace")] +mod perf_trace; +mod util; + +/// Send Flecs internal logging to `tracing` subscribers instead. +/// +/// Note that the application will need to set up those subscribers; by default, logs will go nowhere. +/// +/// This must be called before the first [`World`] is created anywhere in the process; +/// see [`ecs_os_api::add_init_hook`] for details on those limitations. +/// +/// # Example +/// ```no_run +/// use flecs_ecs::prelude::*; +/// use flecs_ecs_tracing::log_to_tracing; +/// use tracing_subscriber::prelude::*; +/// +/// tracing_subscriber::registry() +/// // Send logs to stdout +/// .with( +/// tracing_subscriber::fmt::layer() +/// // By default, hide anything below WARN log level from stdout +/// .with_filter( +/// tracing_subscriber::EnvFilter::builder() +/// .with_default_directive(tracing::level_filters::LevelFilter::WARN.into()) +/// .from_env_lossy(), +/// ), +/// ) +/// .init(); +/// +/// log_to_tracing(); +/// let world = World::new(); +/// ``` +pub fn log_to_tracing() { + // Ensure that the registry is initialized now + metadata::init(); + + ecs_os_api::add_init_hook(Box::new(|api| { + api.log_ = Some(log::log_to_tracing); + })); +} + +#[cfg(feature = "perf_trace")] +/// Send Flecs performance traces to `tracing` subscribers. +/// +/// This must be called before the first [`World`] is created anywhere in the process; +/// see [`ecs_os_api::add_init_hook`] for details on those limitations. +/// +/// # Example +/// ```ignore +/// use flecs_ecs::prelude::*; +/// use flecs_ecs_tracing::{log_to_tracing, perf_trace_to_tracing}; +/// use tracing_subscriber::prelude::*; +/// +/// tracing_subscriber::registry() +/// // Send logs to stdout +/// .with( +/// tracing_subscriber::fmt::layer() +/// // By default, hide anything below WARN log level from stdout +/// .with_filter( +/// tracing_subscriber::EnvFilter::builder() +/// .with_default_directive(tracing::level_filters::LevelFilter::WARN.into()) +/// .from_env_lossy(), +/// ), +/// ) +/// // Send logs and performance tracing data to the Tracy profiler +/// .with( +/// tracing_tracy::TracyLayer::default() +/// .with_filter(tracing::level_filters::LevelFilter::INFO), +/// ) +/// .init(); +/// +/// log_to_tracing(); +/// perf_trace_to_tracing(tracing::Level::INFO); +/// +/// let world = World::new(); +/// ``` +pub fn perf_trace_to_tracing(span_level: tracing_core::Level) { + // Ensure that the registry is initialized now + perf_trace::init(); + + // Set the log level of performance tracing spans + perf_trace::SPAN_LEVEL.get_or_init(|| span_level); + + ecs_os_api::add_init_hook(Box::new(|api| { + api.perf_trace_push_ = Some(perf_trace::perf_trace_push); + api.perf_trace_pop_ = Some(perf_trace::perf_trace_pop); + })); +} diff --git a/flecs_ecs_tracing/src/log.rs b/flecs_ecs_tracing/src/log.rs new file mode 100644 index 00000000..c7b55f46 --- /dev/null +++ b/flecs_ecs_tracing/src/log.rs @@ -0,0 +1,82 @@ +use std::borrow::Cow; + +use crate::{metadata, util::*}; +use tracing_core::{Dispatch, Metadata}; + +fn ensure_event_meta( + dispatch: &Dispatch, + request: metadata::MetadataRequest<'_>, +) -> &'static Metadata<'static> { + // Double-checked locking + { + let registry = metadata::REGISTRY.read().unwrap(); + if let Some(existing) = registry.metadata.get(&request) { + return existing; + } + } + + let mut registry = metadata::REGISTRY.write().unwrap(); + + if let Some(existing) = registry.metadata.get(&request) { + return existing; + } + + let (metadata, request) = request.register(dispatch); + registry.metadata.insert(request, metadata); + + metadata +} + +fn get_event_meta( + dispatch: &Dispatch, + filename: Option>, + line: i32, + level: tracing_core::metadata::Level, +) -> &'static Metadata<'static> { + let request = metadata::MetadataRequest { + kind: metadata::MetadataKind::Event, + name: Cow::Borrowed("log"), + filename, + line: line.try_into().ok(), + level, + }; + + if let Some(existing) = metadata::REGISTRY.read().unwrap().metadata.get(&request) { + // existing metadata - fast path + return existing; + } + + // new metadata - slow path + ensure_event_meta(dispatch, request) +} + +pub(crate) unsafe extern "C-unwind" fn log_to_tracing( + level: i32, + file: *const i8, + line: i32, + msg: *const i8, +) { + tracing_core::dispatcher::get_default(|dispatch| { + let file = flecs_str(file); + let msg = flecs_str(msg).unwrap_or(Cow::Borrowed("")); + let level = match level { + -4 | -3 => tracing_core::metadata::Level::ERROR, + -2 => tracing_core::metadata::Level::WARN, + 0 => tracing_core::metadata::Level::INFO, + 1..=3 => tracing_core::metadata::Level::DEBUG, + _ => tracing_core::metadata::Level::TRACE, + }; + + let meta = get_event_meta(dispatch, file, line, level); + if dispatch.enabled(meta) { + let message_field = meta.fields().iter().next().expect("FieldSet corrupted"); + tracing_core::Event::dispatch( + meta, + &meta.fields().value_set(&[( + &message_field, + Some(&(format_args!("{msg}")) as &dyn tracing_core::field::Value), + )]), + ); + } + }); +} diff --git a/flecs_ecs_tracing/src/metadata.rs b/flecs_ecs_tracing/src/metadata.rs new file mode 100644 index 00000000..d92eee69 --- /dev/null +++ b/flecs_ecs_tracing/src/metadata.rs @@ -0,0 +1,157 @@ +//! Construct [`tracing_core::Metadata`] objects in the way required by that ecosystem. +//! +//! Dynamic call site stuff based on + +use crate::util::*; +use std::{ + borrow::Cow, + collections::HashMap, + sync::{LazyLock, OnceLock, RwLock}, +}; +use tracing_core::{field::FieldSet, metadata::Level, Dispatch, Kind, Metadata}; + +/// Registry of dynamic tracing metadata generated from Flecs +pub(crate) static REGISTRY: LazyLock> = LazyLock::new(Default::default); + +/// Registry of dynamic tracing metadata generated from Flecs +pub(crate) struct Registry { + pub(crate) metadata: + HashMap, &'static Metadata<'static>, fxhash::FxBuildHasher>, +} + +impl Default for Registry { + fn default() -> Self { + Self { + // Capacity was chosen arbitrarily + metadata: HashMap::with_capacity_and_hasher(256, Default::default()), + } + } +} + +pub(crate) fn init() { + LazyLock::force(®ISTRY); +} + +#[derive(Default)] +pub(crate) struct DynamicCallsite { + /// Due to the opaque [`tracing_core::callsite::Identifier`], + /// which borrows [`tracing_core::Callsite`] for `'static`, have to use interior mutability. + /// + /// See [`MetadataRequest::register`] for details + pub(crate) metadata: OnceLock>, +} + +impl tracing_core::Callsite for DynamicCallsite { + fn set_interest(&self, _interest: tracing_core::Interest) { + // No-op + } + + fn metadata(&self) -> &Metadata<'_> { + self.metadata.get().unwrap() + } +} + +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] +pub(crate) enum MetadataKind { + // hash/eq skip filename/line since they may differ between start & stop + // only used when perf_trace is enabled + #[cfg_attr(not(feature = "perf_trace"), allow(unused))] + Span, + Event, +} + +#[derive(Clone, Debug)] +pub(crate) struct MetadataRequest<'a> { + pub(crate) kind: MetadataKind, + pub(crate) level: Level, + pub(crate) name: Cow<'a, str>, + pub(crate) filename: Option>, + pub(crate) line: Option, +} + +impl<'a> PartialEq for MetadataRequest<'a> { + fn eq(&self, other: &Self) -> bool { + self.kind == other.kind + && self.name == other.name + && self.level == other.level + && match self.kind { + MetadataKind::Span => true, + MetadataKind::Event => self.filename == other.filename && self.line == other.line, + } + } +} + +impl<'a> Eq for MetadataRequest<'a> {} + +impl<'a> std::hash::Hash for MetadataRequest<'a> { + fn hash(&self, state: &mut H) { + self.kind.hash(state); + self.name.hash(state); + self.level.hash(state); + match self.kind { + MetadataKind::Span => {} + MetadataKind::Event => { + self.filename.hash(state); + self.line.hash(state); + } + } + } +} + +impl<'a> MetadataRequest<'a> { + /// Construct a new [`Metadata`]. + /// + /// Does not interact with [`crate::REGISTRY`] by design to avoid having to deal with locking; + /// the caller should handle memoization if necessary. + pub(crate) fn register( + self, + dispatch: &Dispatch, + ) -> (&'static Metadata<'static>, MetadataRequest<'static>) { + // `Dispatch::register_callsite` demands `&'static Metadata`, this is the simplest way to get that + let callsite = Box::leak(Box::new(DynamicCallsite::default())); + + // This macro is the only 'public' way of constructing [`Identifier`] + let id = tracing_core::identify_callsite!(callsite); + + let name = leak_cowstr(self.name); + let filename: Option<&'static str> = self.filename.map(leak_cowstr); + + let metadata = Metadata::new( + name, + "flecs", + self.level, + filename, + self.line, + Some("flecs_ecs_tracing"), + match self.kind { + MetadataKind::Span { .. } => FieldSet::new(&[], id), + MetadataKind::Event { .. } => FieldSet::new(&["message"], id), + }, + match self.kind { + MetadataKind::Span { .. } => Kind::SPAN, + MetadataKind::Event { .. } => Kind::EVENT, + }, + ); + + // Store the new Metadata + callsite.metadata.set(metadata).unwrap(); + + // Since the `DynamicCallsite` is alive forever we can also use it to get + // a `&'static` to the metadata, without extra allocations + let metadata: &'static Metadata = callsite.metadata.get().unwrap(); + + // Tell `tracing` subscribers about the new callsite + dispatch.register_callsite(metadata); + + ( + metadata, + MetadataRequest { + name: Cow::Borrowed(name), + kind: self.kind, + filename: filename.map(Cow::Borrowed), + line: self.line, + level: self.level, + }, + ) + } +} diff --git a/flecs_ecs_tracing/src/perf_trace.rs b/flecs_ecs_tracing/src/perf_trace.rs new file mode 100644 index 00000000..2efc442e --- /dev/null +++ b/flecs_ecs_tracing/src/perf_trace.rs @@ -0,0 +1,130 @@ +use crate::{metadata, util::*}; +use core::ffi; +use std::{ + borrow::Cow, + collections::HashMap, + sync::{LazyLock, OnceLock, RwLock}, +}; +use tracing_core::{span, Dispatch, Level, Metadata}; + +/// Log level for performance tracing spans +pub(crate) static SPAN_LEVEL: OnceLock = OnceLock::new(); + +/// Registry of dynamic tracing spans generated from Flecs +static REGISTRY: LazyLock> = LazyLock::new(Default::default); + +/// Registry of dynamic tracing spans generated from Flecs +struct Registry { + spans: HashMap< + String, + (tracing_core::span::Id, &'static Metadata<'static>), + fxhash::FxBuildHasher, + >, +} + +impl Default for Registry { + fn default() -> Self { + Self { + spans: HashMap::with_capacity_and_hasher(256, Default::default()), + } + } +} + +pub(crate) fn init() { + LazyLock::force(®ISTRY); +} + +fn ensure_span( + dispatch: &Dispatch, + filename: Option>, + line: usize, + name: Cow<'_, str>, +) -> (span::Id, &'static Metadata<'static>, bool) { + let mut registry = REGISTRY.write().unwrap(); + + // Double-checked locking (maybe another thread added this span between read unlock and write lock) + if let Some((existing, metadata)) = registry.spans.get(name.as_ref()) { + return (existing.clone(), metadata, false); + } + + // "C++-style" names allow Tracy UI to auto-collapse names in short spans + // This conversion is done late so that the fast path can avoid allocating; + // the unmodified name is used as the hashmap key in the registry. + let meta_name = name.replace(".", "::"); + + // Don't bother caching metadata for these; there's (currently) a 1-to-1 correspondence between spans and metadata. + let (metadata, _) = metadata::MetadataRequest { + kind: metadata::MetadataKind::Span, + name: Cow::Owned(meta_name), + filename, + line: line.try_into().ok(), + level: *SPAN_LEVEL.get().unwrap_or(&Level::INFO), + } + .register(dispatch); + + // Flecs doesn't send any parameters (yet) + let values = metadata.fields().value_set(&[]); + let attributes = span::Attributes::new(metadata, &values); + + // Tell `tracing` subscribers about the new span + let span = dispatch.new_span(&attributes); + + registry + .spans + .insert(name.into_owned(), (span.clone(), metadata)); + + (span, metadata, true) +} + +fn get_span( + dispatch: &Dispatch, + filename: Option>, + line: usize, + name: Cow<'_, str>, +) -> (span::Id, &'static Metadata<'static>, bool) { + if let Some((existing, metadata)) = REGISTRY.read().unwrap().spans.get(name.as_ref()) { + // existing span - fast path + return (existing.clone(), metadata, false); + } + + // new span - slow path + ensure_span(dispatch, filename, line, name) +} + +pub(crate) unsafe extern "C-unwind" fn perf_trace_push( + filename: *const ffi::c_char, + line: usize, + name: *const ffi::c_char, +) { + tracing_core::dispatcher::get_default(|dispatch| { + let filename = flecs_str(filename); + let name = flecs_str(name).unwrap_or(Cow::Borrowed("")); + + let (span, metadata, _new) = get_span(dispatch, filename, line, name); + if dispatch.enabled(metadata) { + dispatch.enter(&span); + } + }); +} + +pub(crate) unsafe extern "C-unwind" fn perf_trace_pop( + c_filename: *const ffi::c_char, + line: usize, + c_name: *const ffi::c_char, +) { + tracing_core::dispatcher::get_default(|dispatch| { + let filename = flecs_str(c_filename); + let name = flecs_str(c_name).unwrap_or(Cow::Borrowed("")); + + let (span, metadata, new) = get_span(dispatch, filename, line, name); + debug_assert!( + !new, + "span being popped must already exist name={:?} line={line} filename={:?}", + flecs_str(c_filename), + flecs_str(c_name) + ); + if dispatch.enabled(metadata) { + dispatch.exit(&span); + } + }); +} diff --git a/flecs_ecs_tracing/src/util.rs b/flecs_ecs_tracing/src/util.rs new file mode 100644 index 00000000..0db08529 --- /dev/null +++ b/flecs_ecs_tracing/src/util.rs @@ -0,0 +1,17 @@ +use std::borrow::Cow; + +/// Convert a C string to a Rust string +pub(crate) unsafe fn flecs_str<'a>(str: *const i8) -> Option> { + match str.is_null() { + true => None, + false => Some(std::ffi::CStr::from_ptr(str).to_string_lossy()), + } +} + +pub(crate) fn leak_cowstr(f: Cow<'_, str>) -> &'static str { + match f { + // As far as I can tell, this is zero-copy if the string is already owned + Cow::Owned(s) => String::leak(s), + Cow::Borrowed(s) => String::leak(s.to_string()), + } +}