Add model tracing spans + tracing feature flag

asynchronix/Cargo.toml

@@ -3,6 +3,7 @@ name = "asynchronix"
 # When incrementing version and releasing to crates.io:
 # - Update crate version in this Cargo.toml
 # - Update crate version in README.md
+# - Update crate version in the lib.rs documentation of feature flags
 # - Update CHANGELOG.md
 # - Update if necessary copyright notice in LICENSE-MIT
 # - Create a "vX.Y.Z" git tag
@@ -23,6 +24,7 @@ autotests = false
 [features]
 # gRPC service.
 grpc = ["dep:bytes", "dep:ciborium", "dep:prost", "dep:prost-types", "dep:serde", "dep:tonic", "dep:tokio", "dep:tonic"]
+tracing = ["dep:tracing"]
 
 # DEVELOPMENT ONLY: API-unstable public exports meant for external test/benchmarking.
 dev-hooks = []
@@ -44,20 +46,23 @@ spin_sleep = "1"
 st3 = "0.4"
 tai-time = "0.3.3"
 
-# gRPC service dependencies.
+# Optional dependencies.
 bytes = { version = "1", default-features = false, optional = true }
+ciborium = { version = "0.2.2", optional = true }
 prost = { version = "0.13", optional = true }
 prost-types = { version = "0.13", optional = true }
-ciborium = { version = "0.2.2", optional = true }
 serde = { version = "1", optional = true }
 tokio = { version = "1.0", features=["net", "rt-multi-thread"], optional = true }
 tonic = { version = "0.12", default-features = false, features=["codegen", "prost", "server"], optional = true }
+tracing = { version= "0.1.40", default-features = false, features=["std"], optional = true }
 
 [dev-dependencies]
 atomic-wait = "1.1"
 futures-util = "0.3"
 futures-executor = "0.3"
 mio = { version = "1.0", features = ["os-poll", "net"] }
+tracing = "0.1"
+tracing-subscriber = { version = "0.3", features = ["env-filter"] }
 
 [target.'cfg(asynchronix_loom)'.dev-dependencies]
 loom = "0.5"

asynchronix/src/lib.rs

@@ -379,6 +379,61 @@
 //! [pony]: https://www.ponylang.io/
 //!
 //!
+//! # Feature flags
+//!
+//! ## Tracing support
+//!
+//! The `tracing` feature flag provides support for the
+//! [`tracing`](https://docs.rs/tracing/latest/tracing/) crate and can be
+//! activated in `Cargo.toml` with:
+//!
+//! ```toml
+//! [dependencies]
+//! asynchronix = { version = "0.3", features = ["tracing"] }
+//! ```
+//!
+//! Each tracing event or span emitted by a model is then wrapped in a span
+//! named `model` with a target `asynchronix` and an attribute `name`. The value
+//! of the attribute is the name provided to
+//! [`SimInit::add_model`](simulation::SimInit::add_model).
+//!
+//! Note that model spans are always emitted at
+//! [`Level::INFO`](tracing::Level::INFO) .
+//!
+//! ### Tracing examples
+//!
+//! The examples below assume that the `tracing` feature flag is activated, the
+//! `tracing_subscriber` crate is used with the `env-filter` feature flag
+//! activated and the default subscriber is set up, e.g. with:
+//!
+//! ```ignore
+//! tracing_subscriber::fmt::init();
+//! ```
+//!
+//! In order to let only warnings and errors pass through but still see model
+//! span information (which is emitted as info), you may run the bench with:
+//!
+//! ```{.bash}
+//! $ RUST_LOG="warn,[model]=info" cargo run --release my_bench
+//! 2024-09-09T21:05:47.891984Z  WARN model{name="kettle"}: my_bench: water is boiling
+//! 2024-09-09T21:08:13.284753Z  WARN model{name="timer"}: my_bench: ring ring
+//! 2024-09-09T21:08:13.284753Z  WARN model{name="kettle"}: my_bench: water is hot
+//! ```
+//!
+//! In order to see warnings or errors for the `kettle` model only, you may
+//! instead run the bench with:
+//!
+//! ```{.bash}
+//! $ RUST_LOG="[model{name=kettle}]=warn" cargo run --release my_bench
+//! 2024-09-09T21:05:47.891984Z  WARN model{name="kettle"}: my_bench: water is boiling
+//! 2024-09-09T21:08:13.284753Z  WARN model{name="kettle"}: my_bench: water is hot
+//! ```
+//!
+//! If the `model` span name collides with that of spans defined outside
+//! `asynchronix`, the above filters can be made more specific using
+//! `asynchronix[model]` instead of just `[model]`.
+//!
+//!
 //! # Other resources
 //!
 //! ## Other examples

asynchronix/src/simulation.rs

@@ -257,7 +257,7 @@ impl Simulation {
         Ok(())
     }
 
-    /// Returns scheduler.
+    /// Returns a scheduler handle.
     pub fn scheduler(&self) -> Scheduler {
         Scheduler::new(self.scheduler_queue.clone(), self.time.reader())
     }
@@ -488,14 +488,22 @@ pub(crate) fn add_model<M: Model>(
     scheduler: Scheduler,
     executor: &Executor,
 ) {
+    #[cfg(feature = "tracing")]
+    let span = tracing::span!(target: env!("CARGO_PKG_NAME"), tracing::Level::INFO, "model", name);
+
     let context = Context::new(name, LocalScheduler::new(scheduler, mailbox.address()));
     let setup_context = SetupContext::new(&mailbox, &context, executor);
 
     model.setup(&setup_context);
 
     let mut receiver = mailbox.0;
-    executor.spawn_and_forget(async move {
+    let fut = async move {
         let mut model = model.init(&context).await.0;
         while receiver.recv(&mut model, &context).await.is_ok() {}
-    });
+    };
+
+    #[cfg(feature = "tracing")]
+    let fut = tracing::Instrument::instrument(fut, span);
+
+    executor.spawn_and_forget(fut);
 }

asynchronix/src/simulation/sim_init.rs

@@ -16,6 +16,8 @@ pub struct SimInit {
     scheduler_queue: Arc<Mutex<SchedulerQueue>>,
     time: SyncCell<TearableAtomicTime>,
     clock: Box<dyn Clock + 'static>,
+    #[cfg(feature = "tracing")]
+    log_level: tracing::Level,
 }
 
 impl SimInit {
@@ -44,6 +46,8 @@ impl SimInit {
             scheduler_queue: Arc::new(Mutex::new(PriorityQueue::new())),
             time: SyncCell::new(TearableAtomicTime::new(MonotonicTime::EPOCH)),
             clock: Box::new(NoClock::new()),
+            #[cfg(feature = "tracing")]
+            log_level: tracing::Level::INFO,
         }
     }
 
@@ -74,6 +78,16 @@ impl SimInit {
         self
     }
 
+    /// Set the level of verbosity for model spans.
+    ///
+    /// By default, model spans use [`Level::INFO`](tracing::Level::INFO).
+    #[cfg(feature = "tracing")]
+    pub fn with_log_level(mut self, level: tracing::Level) -> Self {
+        self.log_level = level;
+
+        self
+    }
+
     /// Builds a simulation initialized at the specified simulation time,
     /// executing the [`Model::init()`](crate::model::Model::init) method on all
     /// model initializers.