From 5e13ee3d8cb9f7e3173894cafb9517d47023ef60 Mon Sep 17 00:00:00 2001
From: Jonathan Johnson <jon@khonsulabs.com>
Date: Wed, 7 Aug 2024 07:16:27 -0700
Subject: [PATCH] Optional tracing

---
 Cargo.lock                       |   5 ++
 Cargo.toml                       |   4 +
 muse-lang/Cargo.toml             |   5 ++
 muse-lang/src/lib.rs             |   7 ++
 muse-lang/src/mock_tracing.rs    | 135 +++++++++++++++++++++++++++++++
 muse-lang/src/tests.rs           |  13 +++
 muse-lang/src/vm.rs              |   2 +-
 muse-reactor/Cargo.toml          |   7 ++
 muse-reactor/src/lib.rs          |  17 +++-
 muse-reactor/src/mock_tracing.rs | 135 +++++++++++++++++++++++++++++++
 muse-reactor/src/tests.rs        |   8 ++
 tests/harness.rs                 |   3 +
 tests/hosted.rs                  |   3 +
 13 files changed, 341 insertions(+), 3 deletions(-)
 create mode 100644 muse-lang/src/mock_tracing.rs
 create mode 100644 muse-reactor/src/mock_tracing.rs

diff --git a/Cargo.lock b/Cargo.lock
index 7c40755..b82c033 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -1586,6 +1586,7 @@ dependencies = [
  "rsn",
  "rustyline",
  "serde",
+ "tracing-subscriber",
 ]
 
 [[package]]
@@ -1601,6 +1602,8 @@ dependencies = [
  "refuse-pool",
  "regex",
  "serde",
+ "tracing",
+ "tracing-subscriber",
  "unicode-ident",
 ]
 
@@ -1615,6 +1618,8 @@ dependencies = [
  "muse-lang",
  "parking_lot",
  "refuse",
+ "tracing",
+ "tracing-subscriber",
 ]
 
 [[package]]
diff --git a/Cargo.toml b/Cargo.toml
index d501e89..9ff9110 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -14,6 +14,8 @@ parking_lot = "0.12.1"
 refuse = "0.0.4"
 refuse-pool = "0.0.4"
 serde = { version = "1.0.195", features = ["derive", "rc"] }
+tracing = "0.1.40"
+tracing-subscriber = "0.3.18"
 
 [package]
 name = "muse"
@@ -28,6 +30,7 @@ reactor = ["dep:muse-reactor"]
 ui = ["dep:muse-ui"]
 dispatched = ["muse-lang/dispatched"]
 repl = ["dep:rustyline", "dep:ariadne", "dep:dirs"]
+tracing = ["muse-reactor/tracing", "muse-lang/tracing"]
 
 [[bin]]
 name = "muse"
@@ -49,6 +52,7 @@ rsn = "0.1"
 pollster = "0.3.0"
 flume = "0.11.0"
 serde = { workspace = true }
+tracing-subscriber = { workspace = true }
 
 [lints.clippy]
 pedantic = { level = "warn", priority = -1 }
diff --git a/muse-lang/Cargo.toml b/muse-lang/Cargo.toml
index 9448a5b..3976df4 100644
--- a/muse-lang/Cargo.toml
+++ b/muse-lang/Cargo.toml
@@ -7,6 +7,7 @@ license = "MIT OR Apache-2.0"
 
 [features]
 dispatched = []
+tracing = ["dep:tracing"]
 
 [dependencies]
 serde = { workspace = true }
@@ -19,3 +20,7 @@ parking_lot = { workspace = true }
 ahash = "0.8.7"
 regex = "1.10.3"
 unicode-ident = "1.0.12"
+tracing = { workspace = true, optional = true }
+
+[dev-dependencies]
+tracing-subscriber = { workspace = true }
diff --git a/muse-lang/src/lib.rs b/muse-lang/src/lib.rs
index 0ba11df..184fe79 100644
--- a/muse-lang/src/lib.rs
+++ b/muse-lang/src/lib.rs
@@ -10,6 +10,13 @@ macro_rules! impl_from {
     };
 }
 
+#[cfg(feature = "tracing")]
+#[macro_use]
+extern crate tracing;
+#[cfg(not(feature = "tracing"))]
+#[macro_use]
+mod mock_tracing;
+
 pub mod compiler;
 pub mod vm;
 
diff --git a/muse-lang/src/mock_tracing.rs b/muse-lang/src/mock_tracing.rs
new file mode 100644
index 0000000..5748b62
--- /dev/null
+++ b/muse-lang/src/mock_tracing.rs
@@ -0,0 +1,135 @@
+#[allow(unused_macros)]
+macro_rules! info {
+    // Name / target / parent.
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, $($arg:tt)+ ) => {};
+
+    // Name / target.
+    (name: $name:expr, target: $target:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, target: $target:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, $($arg:tt)+ ) => {};
+
+    // Target / parent.
+    (target: $target:expr, parent: $parent:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (target: $target:expr, parent: $parent:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (target: $target:expr, parent: $parent:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (target: $target:expr, parent: $parent:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (target: $target:expr, parent: $parent:expr, $($arg:tt)+ ) => {};
+
+    // Name / parent.
+    (name: $name:expr, parent: $parent:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, parent: $parent:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, parent: $parent:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, parent: $parent:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, parent: $parent:expr, $($arg:tt)+ ) => {};
+
+    // Name.
+    (name: $name:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, $($k:ident).+ $($field:tt)* ) => {};
+    (name: $name:expr, ?$($k:ident).+ $($field:tt)* ) => {};
+    (name: $name:expr, %$($k:ident).+ $($field:tt)* ) => {};
+    (name: $name:expr, $($arg:tt)+ ) => {};
+
+    // Target.
+    (target: $target:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (target: $target:expr, $($k:ident).+ $($field:tt)* ) => {};
+    (target: $target:expr, ?$($k:ident).+ $($field:tt)* ) => {};
+    (target: $target:expr, %$($k:ident).+ $($field:tt)* ) => {};
+    (target: $target:expr, $($arg:tt)+ ) => {};
+
+    // Parent.
+    (parent: $parent:expr, { $($field:tt)+ }, $($arg:tt)+ ) => {};
+    (parent: $parent:expr, $($k:ident).+ = $($field:tt)*) => {};
+    (parent: $parent:expr, ?$($k:ident).+ = $($field:tt)*) => {};
+    (parent: $parent:expr, %$($k:ident).+ = $($field:tt)*) => {};
+    (parent: $parent:expr, $($k:ident).+, $($field:tt)*) => {};
+    (parent: $parent:expr, ?$($k:ident).+, $($field:tt)*) => {};
+    (parent: $parent:expr, %$($k:ident).+, $($field:tt)*) => {};
+    (parent: $parent:expr, $($arg:tt)+) => {};
+
+    // ...
+    ({ $($field:tt)+ }, $($arg:tt)+ ) => {};
+    ($($k:ident).+ = $($field:tt)*) => {};
+    (?$($k:ident).+ = $($field:tt)*) => {};
+    (%$($k:ident).+ = $($field:tt)*) => {};
+    ($($k:ident).+, $($field:tt)*) => {};
+    (?$($k:ident).+, $($field:tt)*) => {};
+    (%$($k:ident).+, $($field:tt)*) => {};
+    (?$($k:ident).+) => {};
+    (%$($k:ident).+) => {};
+    ($($k:ident).+) => {};
+    ($($arg:tt)+) => {};
+}
+
+#[allow(unused_macros)]
+macro_rules! trace {
+    // Name / target / parent.
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, $($arg:tt)+ ) => {};
+
+    // Name / target.
+    (name: $name:expr, target: $target:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, target: $target:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, $($arg:tt)+ ) => {};
+
+    // Target / parent.
+    (target: $target:expr, parent: $parent:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (target: $target:expr, parent: $parent:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (target: $target:expr, parent: $parent:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (target: $target:expr, parent: $parent:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (target: $target:expr, parent: $parent:expr, $($arg:tt)+ ) => {};
+
+    // Name / parent.
+    (name: $name:expr, parent: $parent:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, parent: $parent:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, parent: $parent:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, parent: $parent:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, parent: $parent:expr, $($arg:tt)+ ) => {};
+
+    // Name.
+    (name: $name:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, $($k:ident).+ $($field:tt)* ) => {};
+    (name: $name:expr, ?$($k:ident).+ $($field:tt)* ) => {};
+    (name: $name:expr, %$($k:ident).+ $($field:tt)* ) => {};
+    (name: $name:expr, $($arg:tt)+ ) => {};
+
+    // Target.
+    (target: $target:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (target: $target:expr, $($k:ident).+ $($field:tt)* ) => {};
+    (target: $target:expr, ?$($k:ident).+ $($field:tt)* ) => {};
+    (target: $target:expr, %$($k:ident).+ $($field:tt)* ) => {};
+    (target: $target:expr, $($arg:tt)+ ) => {};
+
+    // Parent.
+    (parent: $parent:expr, { $($field:tt)+ }, $($arg:tt)+ ) => {};
+    (parent: $parent:expr, $($k:ident).+ = $($field:tt)*) => {};
+    (parent: $parent:expr, ?$($k:ident).+ = $($field:tt)*) => {};
+    (parent: $parent:expr, %$($k:ident).+ = $($field:tt)*) => {};
+    (parent: $parent:expr, $($k:ident).+, $($field:tt)*) => {};
+    (parent: $parent:expr, ?$($k:ident).+, $($field:tt)*) => {};
+    (parent: $parent:expr, %$($k:ident).+, $($field:tt)*) => {};
+    (parent: $parent:expr, $($arg:tt)+) => {};
+
+    // ...
+    ({ $($field:tt)+ }, $($arg:tt)+ ) => {};
+    ($($k:ident).+ = $($field:tt)*) => {};
+    (?$($k:ident).+ = $($field:tt)*) => {};
+    (%$($k:ident).+ = $($field:tt)*) => {};
+    ($($k:ident).+, $($field:tt)*) => {};
+    (?$($k:ident).+, $($field:tt)*) => {};
+    (%$($k:ident).+, $($field:tt)*) => {};
+    (?$($k:ident).+) => {};
+    (%$($k:ident).+) => {};
+    ($($k:ident).+) => {};
+    ($($arg:tt)+) => {};
+}
diff --git a/muse-lang/src/tests.rs b/muse-lang/src/tests.rs
index 9538b80..d6d957b 100644
--- a/muse-lang/src/tests.rs
+++ b/muse-lang/src/tests.rs
@@ -1,6 +1,7 @@
 use std::collections::VecDeque;
 
 use refuse::CollectionGuard;
+use tracing_subscriber::filter::LevelFilter;
 
 use crate::compiler::syntax::token::{Paired, Token};
 use crate::compiler::syntax::{Expression, Ranged, SourceRange, TokenizeInto};
@@ -11,9 +12,16 @@ use crate::runtime::value::{Primitive, Value};
 use crate::vm::bitcode::BitcodeBlock;
 use crate::vm::{ExecutionError, Register, Vm};
 
+fn initialize_tracing() {
+    let _ = tracing_subscriber::fmt()
+        .with_max_level(LevelFilter::TRACE)
+        .try_init();
+}
+
 #[test]
 fn budgeting() {
     const COUNT_TO: i64 = 42;
+    initialize_tracing();
 
     let mut guard = CollectionGuard::acquire();
     let mut code = BitcodeBlock::default();
@@ -42,6 +50,7 @@ fn budgeting() {
 #[test]
 fn module_budgeting() {
     const MAX_OPS: usize = 24;
+    initialize_tracing();
     let mut guard = CollectionGuard::acquire();
     let code = Compiler::compile(
         r"
@@ -86,6 +95,7 @@ fn module_budgeting() {
 
 #[test]
 fn invoke() {
+    initialize_tracing();
     let mut guard = CollectionGuard::acquire();
     let code = Compiler::compile(
         r"
@@ -124,6 +134,7 @@ fn invoke() {
 
 #[test]
 fn macros() {
+    initialize_tracing();
     let mut guard = CollectionGuard::acquire();
     let code = Compiler::default()
         .with_macro("$test", |mut tokens: VecDeque<Ranged<Token>>| {
@@ -148,6 +159,7 @@ fn macros() {
 
 #[test]
 fn recursive_macros() {
+    initialize_tracing();
     let mut guard = CollectionGuard::acquire();
     let code = Compiler::default()
         .with_macro("$inner", |mut tokens: VecDeque<Ranged<Token>>| {
@@ -179,6 +191,7 @@ fn recursive_macros() {
 
 #[test]
 fn infix_macros() {
+    initialize_tracing();
     let mut guard = CollectionGuard::acquire();
     let code = Compiler::default()
         .with_infix_macro(
diff --git a/muse-lang/src/vm.rs b/muse-lang/src/vm.rs
index 4edbca9..5e0f91d 100644
--- a/muse-lang/src/vm.rs
+++ b/muse-lang/src/vm.rs
@@ -1416,7 +1416,7 @@ impl VmContext<'_, '_> {
             Ordering::Equal => return Ok(StepResult::Complete),
             Ordering::Greater => return Err(Fault::InvalidInstructionAddress),
         };
-        println!("Executing {instruction:?}");
+        trace!("Executing {instruction:?}");
         let next_instruction = StepResult::from(address.checked_add(1));
         let result = match instruction {
             LoadedOp::Return => return Ok(StepResult::Complete),
diff --git a/muse-reactor/Cargo.toml b/muse-reactor/Cargo.toml
index 4cae9a1..5f3f4af 100644
--- a/muse-reactor/Cargo.toml
+++ b/muse-reactor/Cargo.toml
@@ -5,6 +5,9 @@ edition = "2021"
 repository = "https://github.com/khonsulabs/muse"
 license = "MIT OR Apache-2.0"
 
+[features]
+tracing = ["dep:tracing", "muse-lang/tracing"]
+
 [dependencies]
 muse-lang = { workspace = true }
 alot = { workspace = true }
@@ -13,3 +16,7 @@ crossbeam-utils = { workspace = true }
 kempt = { workspace = true }
 parking_lot = { workspace = true }
 refuse = { workspace = true }
+tracing = { workspace = true, optional = true }
+
+[dev-dependencies]
+tracing-subscriber = { workspace = true }
diff --git a/muse-reactor/src/lib.rs b/muse-reactor/src/lib.rs
index e620a78..fb0f6e1 100644
--- a/muse-reactor/src/lib.rs
+++ b/muse-reactor/src/lib.rs
@@ -97,6 +97,13 @@ use muse_lang::vm::{
 use parking_lot::{Condvar, Mutex, MutexGuard};
 use refuse::{CollectionGuard, ContainsNoRefs, Trace};
 
+#[cfg(feature = "tracing")]
+#[macro_use]
+extern crate tracing;
+#[cfg(not(feature = "tracing"))]
+#[macro_use]
+mod mock_tracing;
+
 pub struct Builder<Work> {
     vm_source: Option<Arc<dyn NewVm<Work>>>,
     threads: usize,
@@ -184,7 +191,7 @@ where
         for id in 0..self.threads {
             let (spawn_send, spawn_recv) = flume::unbounded();
             let parker = Parker::new();
-            let data = Arc::new(PerThreadData::new(parker.unparker().clone()));
+            let data = Arc::new(PerThreadData::new(id, parker.unparker().clone()));
             let reactor = Reactor {
                 id,
                 receiver: spawn_recv,
@@ -224,6 +231,8 @@ enum ThreadCommand<Work> {
 }
 
 struct DispatcherThread<Work> {
+    #[cfg_attr(not(feature = "tracing"), allow(dead_code))]
+    num: usize,
     spawner: Sender<ThreadCommand<Work>>,
     load: usize,
     unparker: Unparker,
@@ -266,6 +275,7 @@ impl<Work> Dispatcher<Work> {
         self.threads.clear();
         for t in &*threads {
             self.threads.push_back(DispatcherThread {
+                num: t.data.num,
                 spawner: t.spawner.clone(),
                 load: t.spawner.len() * 2
                     + t.data.executing.load(Ordering::Relaxed)
@@ -344,6 +354,7 @@ impl<Work> Dispatcher<Work> {
                         return;
                     };
 
+                    trace!(task = spawn.id, thread = thread.num, "spawn");
                     match thread.spawner.send(ThreadCommand::Spawn(spawn)) {
                         Ok(()) => {
                             thread.unparker.unpark();
@@ -1272,14 +1283,16 @@ struct PerThread<Work> {
 
 #[derive(Debug)]
 struct PerThreadData {
+    num: usize,
     unparker: Unparker,
     executing: AtomicUsize,
     total: AtomicUsize,
 }
 
 impl PerThreadData {
-    fn new(unparker: Unparker) -> Self {
+    fn new(num: usize, unparker: Unparker) -> Self {
         Self {
+            num,
             unparker,
             executing: AtomicUsize::new(0),
             total: AtomicUsize::new(0),
diff --git a/muse-reactor/src/mock_tracing.rs b/muse-reactor/src/mock_tracing.rs
new file mode 100644
index 0000000..5748b62
--- /dev/null
+++ b/muse-reactor/src/mock_tracing.rs
@@ -0,0 +1,135 @@
+#[allow(unused_macros)]
+macro_rules! info {
+    // Name / target / parent.
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, $($arg:tt)+ ) => {};
+
+    // Name / target.
+    (name: $name:expr, target: $target:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, target: $target:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, $($arg:tt)+ ) => {};
+
+    // Target / parent.
+    (target: $target:expr, parent: $parent:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (target: $target:expr, parent: $parent:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (target: $target:expr, parent: $parent:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (target: $target:expr, parent: $parent:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (target: $target:expr, parent: $parent:expr, $($arg:tt)+ ) => {};
+
+    // Name / parent.
+    (name: $name:expr, parent: $parent:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, parent: $parent:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, parent: $parent:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, parent: $parent:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, parent: $parent:expr, $($arg:tt)+ ) => {};
+
+    // Name.
+    (name: $name:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, $($k:ident).+ $($field:tt)* ) => {};
+    (name: $name:expr, ?$($k:ident).+ $($field:tt)* ) => {};
+    (name: $name:expr, %$($k:ident).+ $($field:tt)* ) => {};
+    (name: $name:expr, $($arg:tt)+ ) => {};
+
+    // Target.
+    (target: $target:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (target: $target:expr, $($k:ident).+ $($field:tt)* ) => {};
+    (target: $target:expr, ?$($k:ident).+ $($field:tt)* ) => {};
+    (target: $target:expr, %$($k:ident).+ $($field:tt)* ) => {};
+    (target: $target:expr, $($arg:tt)+ ) => {};
+
+    // Parent.
+    (parent: $parent:expr, { $($field:tt)+ }, $($arg:tt)+ ) => {};
+    (parent: $parent:expr, $($k:ident).+ = $($field:tt)*) => {};
+    (parent: $parent:expr, ?$($k:ident).+ = $($field:tt)*) => {};
+    (parent: $parent:expr, %$($k:ident).+ = $($field:tt)*) => {};
+    (parent: $parent:expr, $($k:ident).+, $($field:tt)*) => {};
+    (parent: $parent:expr, ?$($k:ident).+, $($field:tt)*) => {};
+    (parent: $parent:expr, %$($k:ident).+, $($field:tt)*) => {};
+    (parent: $parent:expr, $($arg:tt)+) => {};
+
+    // ...
+    ({ $($field:tt)+ }, $($arg:tt)+ ) => {};
+    ($($k:ident).+ = $($field:tt)*) => {};
+    (?$($k:ident).+ = $($field:tt)*) => {};
+    (%$($k:ident).+ = $($field:tt)*) => {};
+    ($($k:ident).+, $($field:tt)*) => {};
+    (?$($k:ident).+, $($field:tt)*) => {};
+    (%$($k:ident).+, $($field:tt)*) => {};
+    (?$($k:ident).+) => {};
+    (%$($k:ident).+) => {};
+    ($($k:ident).+) => {};
+    ($($arg:tt)+) => {};
+}
+
+#[allow(unused_macros)]
+macro_rules! trace {
+    // Name / target / parent.
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, parent: $parent:expr, $($arg:tt)+ ) => {};
+
+    // Name / target.
+    (name: $name:expr, target: $target:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, target: $target:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, target: $target:expr, $($arg:tt)+ ) => {};
+
+    // Target / parent.
+    (target: $target:expr, parent: $parent:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (target: $target:expr, parent: $parent:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (target: $target:expr, parent: $parent:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (target: $target:expr, parent: $parent:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (target: $target:expr, parent: $parent:expr, $($arg:tt)+ ) => {};
+
+    // Name / parent.
+    (name: $name:expr, parent: $parent:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, parent: $parent:expr, $($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, parent: $parent:expr, ?$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, parent: $parent:expr, %$($k:ident).+ $($field:tt)+ ) => {};
+    (name: $name:expr, parent: $parent:expr, $($arg:tt)+ ) => {};
+
+    // Name.
+    (name: $name:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (name: $name:expr, $($k:ident).+ $($field:tt)* ) => {};
+    (name: $name:expr, ?$($k:ident).+ $($field:tt)* ) => {};
+    (name: $name:expr, %$($k:ident).+ $($field:tt)* ) => {};
+    (name: $name:expr, $($arg:tt)+ ) => {};
+
+    // Target.
+    (target: $target:expr, { $($field:tt)* }, $($arg:tt)* ) => {};
+    (target: $target:expr, $($k:ident).+ $($field:tt)* ) => {};
+    (target: $target:expr, ?$($k:ident).+ $($field:tt)* ) => {};
+    (target: $target:expr, %$($k:ident).+ $($field:tt)* ) => {};
+    (target: $target:expr, $($arg:tt)+ ) => {};
+
+    // Parent.
+    (parent: $parent:expr, { $($field:tt)+ }, $($arg:tt)+ ) => {};
+    (parent: $parent:expr, $($k:ident).+ = $($field:tt)*) => {};
+    (parent: $parent:expr, ?$($k:ident).+ = $($field:tt)*) => {};
+    (parent: $parent:expr, %$($k:ident).+ = $($field:tt)*) => {};
+    (parent: $parent:expr, $($k:ident).+, $($field:tt)*) => {};
+    (parent: $parent:expr, ?$($k:ident).+, $($field:tt)*) => {};
+    (parent: $parent:expr, %$($k:ident).+, $($field:tt)*) => {};
+    (parent: $parent:expr, $($arg:tt)+) => {};
+
+    // ...
+    ({ $($field:tt)+ }, $($arg:tt)+ ) => {};
+    ($($k:ident).+ = $($field:tt)*) => {};
+    (?$($k:ident).+ = $($field:tt)*) => {};
+    (%$($k:ident).+ = $($field:tt)*) => {};
+    ($($k:ident).+, $($field:tt)*) => {};
+    (?$($k:ident).+, $($field:tt)*) => {};
+    (%$($k:ident).+, $($field:tt)*) => {};
+    (?$($k:ident).+) => {};
+    (%$($k:ident).+) => {};
+    ($($k:ident).+) => {};
+    ($($arg:tt)+) => {};
+}
diff --git a/muse-reactor/src/tests.rs b/muse-reactor/src/tests.rs
index 105c8ab..652e38a 100644
--- a/muse-reactor/src/tests.rs
+++ b/muse-reactor/src/tests.rs
@@ -6,11 +6,19 @@ use muse_lang::compiler::{self};
 use muse_lang::runtime::value::{Primitive, RootedValue};
 use muse_lang::vm::Vm;
 use refuse::CollectionGuard;
+use tracing_subscriber::filter::LevelFilter;
 
 use crate::{BudgetPoolConfig, NoWork, Reactor, ReactorHandle, TaskError};
 
+fn initialize_tracing() {
+    let _ = tracing_subscriber::fmt()
+        .with_max_level(LevelFilter::TRACE)
+        .try_init();
+}
+
 #[test]
 fn works() {
+    initialize_tracing();
     let reactor = Reactor::new();
     let task = reactor.spawn_source("1 + 2").unwrap();
     assert_eq!(
diff --git a/tests/harness.rs b/tests/harness.rs
index 437552d..75cb259 100644
--- a/tests/harness.rs
+++ b/tests/harness.rs
@@ -20,6 +20,9 @@ use serde::de::Visitor;
 use serde::Deserialize;
 
 fn main() {
+    let _ = tracing_subscriber::fmt()
+        .with_max_level(tracing_subscriber::filter::LevelFilter::TRACE)
+        .try_init();
     let filter = std::env::args().nth(1).unwrap_or_default();
     // let filter = String::from("mod_multi");
     for entry in std::fs::read_dir("tests/cases").unwrap() {
diff --git a/tests/hosted.rs b/tests/hosted.rs
index 588f1cf..64529fe 100644
--- a/tests/hosted.rs
+++ b/tests/hosted.rs
@@ -15,6 +15,9 @@ use muse::vm::{ExecutionError, Fault, Register, Vm, VmContext};
 use muse::Error;
 
 fn main() {
+    let _ = tracing_subscriber::fmt()
+        .with_max_level(tracing_subscriber::filter::LevelFilter::TRACE)
+        .try_init();
     let filter = std::env::args().nth(1).unwrap_or_default();
     // let filter = String::from("basic_struct");
     for entry in std::fs::read_dir("tests/cases").unwrap() {