From 5209fe098f60de1e874035f20c5cdec669f2e0fe Mon Sep 17 00:00:00 2001
From: Ibraheem Ahmed <ibraheem@ibraheem.ca>
Date: Sun, 20 Jul 2025 18:16:35 -0400
Subject: [PATCH 1/2] outline all tracing events

---
 src/database_impl.rs                |  2 +-
 src/function/backdate.rs            |  2 +-
 src/function/execute.rs             | 14 ++++----
 src/function/fetch.rs               |  7 ++--
 src/function/maybe_changed_after.rs | 18 +++++-----
 src/function/memo.rs                | 12 +++----
 src/function/specify.rs             |  2 +-
 src/lib.rs                          |  1 +
 src/runtime.rs                      |  8 ++---
 src/tracing.rs                      | 54 +++++++++++++++++++++++++++++
 src/tracked_struct.rs               |  8 ++---
 src/zalsa.rs                        |  4 +--
 src/zalsa_local.rs                  | 15 +++++---
 13 files changed, 106 insertions(+), 41 deletions(-)
 create mode 100644 src/tracing.rs

diff --git a/src/database_impl.rs b/src/database_impl.rs
index c1eda125a..8b8c9bd25 100644
--- a/src/database_impl.rs
+++ b/src/database_impl.rs
@@ -16,7 +16,7 @@ impl Default for DatabaseImpl {
             // Default behavior: tracing debug log the event.
             storage: Storage::new(if tracing::enabled!(Level::DEBUG) {
                 Some(Box::new(|event| {
-                    tracing::debug!("salsa_event({:?})", event)
+                    crate::tracing::debug!("salsa_event({:?})", event)
                 }))
             } else {
                 None
diff --git a/src/function/backdate.rs b/src/function/backdate.rs
index 873041597..f735f577b 100644
--- a/src/function/backdate.rs
+++ b/src/function/backdate.rs
@@ -34,7 +34,7 @@ where
             if revisions.durability >= old_memo.revisions.durability
                 && C::values_equal(old_value, value)
             {
-                tracing::debug!(
+                crate::tracing::debug!(
                     "{index:?} value is equal, back-dating to {:?}",
                     old_memo.revisions.changed_at,
                 );
diff --git a/src/function/execute.rs b/src/function/execute.rs
index 13ecca561..9013ee7fe 100644
--- a/src/function/execute.rs
+++ b/src/function/execute.rs
@@ -29,7 +29,7 @@ where
         let database_key_index = active_query.database_key_index;
         let id = database_key_index.key_index();
 
-        tracing::info!("{:?}: executing query", database_key_index);
+        crate::tracing::info!("{:?}: executing query", database_key_index);
         let zalsa = db.zalsa();
 
         zalsa.event(&|| {
@@ -169,7 +169,7 @@ where
                 };
                 // SAFETY: The `LRU` does not run mid-execution, so the value remains filled
                 let last_provisional_value = unsafe { last_provisional_value.unwrap_unchecked() };
-                tracing::debug!(
+                crate::tracing::debug!(
                     "{database_key_index:?}: execute: \
                         I am a cycle head, comparing last provisional value with new value"
                 );
@@ -196,7 +196,7 @@ where
                     ) {
                         crate::CycleRecoveryAction::Iterate => {}
                         crate::CycleRecoveryAction::Fallback(fallback_value) => {
-                            tracing::debug!(
+                            crate::tracing::debug!(
                                 "{database_key_index:?}: execute: user cycle_fn says to fall back"
                             );
                             new_value = fallback_value;
@@ -220,7 +220,7 @@ where
                     });
                     cycle_heads.update_iteration_count(database_key_index, iteration_count);
                     revisions.update_iteration_count(iteration_count);
-                    tracing::debug!(
+                    crate::tracing::debug!(
                         "{database_key_index:?}: execute: iterate again, revisions: {revisions:#?}"
                     );
                     opt_last_provisional = Some(self.insert_memo(
@@ -236,7 +236,7 @@ where
 
                     continue;
                 }
-                tracing::debug!(
+                crate::tracing::debug!(
                     "{database_key_index:?}: execute: fixpoint iteration has a final value"
                 );
                 cycle_heads.remove(&database_key_index);
@@ -247,7 +247,9 @@ where
                 }
             }
 
-            tracing::debug!("{database_key_index:?}: execute: result.revisions = {revisions:#?}");
+            crate::tracing::debug!(
+                "{database_key_index:?}: execute: result.revisions = {revisions:#?}"
+            );
 
             break (new_value, revisions);
         }
diff --git a/src/function/fetch.rs b/src/function/fetch.rs
index 6c7819f81..252bba124 100644
--- a/src/function/fetch.rs
+++ b/src/function/fetch.rs
@@ -15,8 +15,9 @@ where
         zalsa.unwind_if_revision_cancelled(zalsa_local);
 
         let database_key_index = self.database_key_index(id);
+
         #[cfg(debug_assertions)]
-        let _span = tracing::debug_span!("fetch", query = ?database_key_index).entered();
+        let _span = crate::tracing::debug_span!("fetch", query = ?database_key_index).entered();
 
         let memo = self.refresh_memo(db, zalsa, zalsa_local, id);
         // SAFETY: We just refreshed the memo so it is guaranteed to contain a value now.
@@ -169,7 +170,7 @@ where
                         );
                     }),
                     CycleRecoveryStrategy::Fixpoint => {
-                        tracing::debug!(
+                        crate::tracing::debug!(
                             "hit cycle at {database_key_index:#?}, \
                             inserting and returning fixpoint initial value"
                         );
@@ -183,7 +184,7 @@ where
                         ))
                     }
                     CycleRecoveryStrategy::FallbackImmediate => {
-                        tracing::debug!(
+                        crate::tracing::debug!(
                             "hit a `FallbackImmediate` cycle at {database_key_index:#?}"
                         );
                         let active_query =
diff --git a/src/function/maybe_changed_after.rs b/src/function/maybe_changed_after.rs
index 9d0ca4c44..7df0a41fe 100644
--- a/src/function/maybe_changed_after.rs
+++ b/src/function/maybe_changed_after.rs
@@ -53,7 +53,9 @@ where
         loop {
             let database_key_index = self.database_key_index(id);
 
-            tracing::debug!("{database_key_index:?}: maybe_changed_after(revision = {revision:?})");
+            crate::tracing::debug!(
+                "{database_key_index:?}: maybe_changed_after(revision = {revision:?})"
+            );
 
             // Check if we have a verified version: this is the hot path.
             let memo_guard = self.get_memo_from_table_for(zalsa, id, memo_ingredient_index);
@@ -117,7 +119,7 @@ where
                     return Some(VerifyResult::unchanged());
                 }
                 CycleRecoveryStrategy::Fixpoint => {
-                    tracing::debug!(
+                    crate::tracing::debug!(
                         "hit cycle at {database_key_index:?} in `maybe_changed_after`,  returning fixpoint initial value",
                     );
                     cycle_heads.push_initial(database_key_index);
@@ -132,7 +134,7 @@ where
             return Some(VerifyResult::Changed);
         };
 
-        tracing::debug!(
+        crate::tracing::debug!(
             "{database_key_index:?}: maybe_changed_after_cold, successful claim, \
                 revision = {revision:?}, old_memo = {old_memo:#?}",
             old_memo = old_memo.tracing_debug()
@@ -194,7 +196,7 @@ where
         database_key_index: DatabaseKeyIndex,
         memo: &Memo<'_, C>,
     ) -> ShallowUpdate {
-        tracing::debug!(
+        crate::tracing::debug!(
             "{database_key_index:?}: shallow_verify_memo(memo = {memo:#?})",
             memo = memo.tracing_debug()
         );
@@ -207,7 +209,7 @@ where
         }
 
         let last_changed = zalsa.last_changed_revision(memo.revisions.durability);
-        tracing::debug!(
+        crate::tracing::debug!(
             "{database_key_index:?}: check_durability(memo = {memo:#?}, last_changed={:?} <= verified_at={:?}) = {:?}",
             last_changed,
             verified_at,
@@ -263,7 +265,7 @@ where
         database_key_index: DatabaseKeyIndex,
         memo: &Memo<'_, C>,
     ) -> bool {
-        tracing::trace!(
+        crate::tracing::trace!(
             "{database_key_index:?}: validate_provisional(memo = {memo:#?})",
             memo = memo.tracing_debug()
         );
@@ -324,7 +326,7 @@ where
         database_key_index: DatabaseKeyIndex,
         memo: &Memo<'_, C>,
     ) -> bool {
-        tracing::trace!(
+        crate::tracing::trace!(
             "{database_key_index:?}: validate_same_iteration(memo = {memo:#?})",
             memo = memo.tracing_debug()
         );
@@ -377,7 +379,7 @@ where
         database_key_index: DatabaseKeyIndex,
         cycle_heads: &mut CycleHeads,
     ) -> VerifyResult {
-        tracing::debug!(
+        crate::tracing::debug!(
             "{database_key_index:?}: deep_verify_memo(old_memo = {old_memo:#?})",
             old_memo = old_memo.tracing_debug()
         );
diff --git a/src/function/memo.rs b/src/function/memo.rs
index 8f8393fc6..f61077329 100644
--- a/src/function/memo.rs
+++ b/src/function/memo.rs
@@ -151,7 +151,7 @@ impl<'db, C: Configuration> Memo<'db, C> {
         } else {
             // all our cycle heads are complete; re-fetch
             // and we should get a non-provisional memo.
-            tracing::debug!(
+            crate::tracing::debug!(
                 "Retrying provisional memo {database_key_index:?} after awaiting cycle heads."
             );
             true
@@ -178,7 +178,7 @@ impl<'db, C: Configuration> Memo<'db, C> {
 
         #[inline(never)]
         fn block_on_heads_cold(zalsa: &Zalsa, heads: &CycleHeads) -> bool {
-            let _entered = tracing::debug_span!("block_on_heads").entered();
+            let _entered = crate::tracing::debug_span!("block_on_heads").entered();
             let mut cycle_heads = TryClaimCycleHeadsIter::new(zalsa, heads);
             let mut all_cycles = true;
 
@@ -207,7 +207,7 @@ impl<'db, C: Configuration> Memo<'db, C> {
     /// Unlike `block_on_heads`, this code does not block on any cycle head. Instead it returns `false` if
     /// claiming all cycle heads failed because one of them is running on another thread.
     pub(super) fn try_claim_heads(&self, zalsa: &Zalsa, zalsa_local: &ZalsaLocal) -> bool {
-        let _entered = tracing::debug_span!("try_claim_heads").entered();
+        let _entered = crate::tracing::debug_span!("try_claim_heads").entered();
         if self.all_cycles_on_stack(zalsa_local) {
             return true;
         }
@@ -417,7 +417,7 @@ impl<'me> Iterator for TryClaimCycleHeadsIter<'me> {
             ProvisionalStatus::Final { .. } | ProvisionalStatus::FallbackImmediate => {
                 // This cycle is already finalized, so we don't need to wait on it;
                 // keep looping through cycle heads.
-                tracing::trace!("Dependent cycle head {head:?} has been finalized.");
+                crate::tracing::trace!("Dependent cycle head {head:?} has been finalized.");
                 Some(TryClaimHeadsResult::Finalized)
             }
             ProvisionalStatus::Provisional { .. } => {
@@ -425,11 +425,11 @@ impl<'me> Iterator for TryClaimCycleHeadsIter<'me> {
                     WaitForResult::Cycle { .. } => {
                         // We hit a cycle blocking on the cycle head; this means this query actively
                         // participates in the cycle and some other query is blocked on this thread.
-                        tracing::debug!("Waiting for {head:?} results in a cycle");
+                        crate::tracing::debug!("Waiting for {head:?} results in a cycle");
                         Some(TryClaimHeadsResult::Cycle)
                     }
                     WaitForResult::Running(running) => {
-                        tracing::debug!("Ingredient {head:?} is running: {running:?}");
+                        crate::tracing::debug!("Ingredient {head:?} is running: {running:?}");
 
                         Some(TryClaimHeadsResult::Running(RunningCycleHead {
                             inner: running,
diff --git a/src/function/specify.rs b/src/function/specify.rs
index 10a85b513..3bc71c565 100644
--- a/src/function/specify.rs
+++ b/src/function/specify.rs
@@ -83,7 +83,7 @@ where
             revisions,
         };
 
-        tracing::debug!(
+        crate::tracing::debug!(
             "specify: about to add memo {:#?} for key {:?}",
             memo.tracing_debug(),
             key
diff --git a/src/lib.rs b/src/lib.rs
index 171452250..9b1355856 100644
--- a/src/lib.rs
+++ b/src/lib.rs
@@ -26,6 +26,7 @@ mod salsa_struct;
 mod storage;
 mod sync;
 mod table;
+mod tracing;
 mod tracked_struct;
 mod update;
 mod views;
diff --git a/src/runtime.rs b/src/runtime.rs
index 8366e16f1..bc2859a7e 100644
--- a/src/runtime.rs
+++ b/src/runtime.rs
@@ -86,7 +86,7 @@ impl Running<'_> {
             })
         });
 
-        tracing::debug!(
+        crate::tracing::debug!(
             "block_on: thread {thread_id:?} is blocking on {database_key:?} in thread {other_id:?}",
         );
 
@@ -180,7 +180,7 @@ impl Runtime {
     }
 
     pub(crate) fn set_cancellation_flag(&self) {
-        tracing::trace!("set_cancellation_flag");
+        crate::tracing::trace!("set_cancellation_flag");
         self.revision_canceled.store(true, Ordering::Release);
     }
 
@@ -206,7 +206,7 @@ impl Runtime {
         let r_old = self.current_revision();
         let r_new = r_old.next();
         self.revisions[0] = r_new;
-        tracing::debug!("new_revision: {r_old:?} -> {r_new:?}");
+        crate::tracing::debug!("new_revision: {r_old:?} -> {r_new:?}");
         r_new
     }
 
@@ -236,7 +236,7 @@ impl Runtime {
         let dg = self.dependency_graph.lock();
 
         if dg.depends_on(other_id, thread_id) {
-            tracing::debug!("block_on: cycle detected for {database_key:?} in thread {thread_id:?} on {other_id:?}");
+            crate::tracing::debug!("block_on: cycle detected for {database_key:?} in thread {thread_id:?} on {other_id:?}");
             return BlockResult::Cycle { same_thread: false };
         }
 
diff --git a/src/tracing.rs b/src/tracing.rs
new file mode 100644
index 000000000..47f95d00e
--- /dev/null
+++ b/src/tracing.rs
@@ -0,0 +1,54 @@
+//! Wrappers around `tracing` macros that avoid inlining debug machinery into the hot path,
+//! as tracing events are typically only enabled for debugging purposes.
+
+macro_rules! trace {
+    ($($x:tt)*) => {
+        crate::tracing::event!(TRACE, $($x)*)
+    };
+}
+
+macro_rules! info {
+    ($($x:tt)*) => {
+        crate::tracing::event!(INFO, $($x)*)
+    };
+}
+
+macro_rules! debug {
+    ($($x:tt)*) => {
+        crate::tracing::event!(DEBUG, $($x)*)
+    };
+}
+
+macro_rules! debug_span {
+    ($($x:tt)*) => {
+        crate::tracing::span!(DEBUG, $($x)*)
+    };
+}
+
+macro_rules! event {
+    ($level:ident, $($x:tt)*) => {{
+        let event = {
+            #[cold] #[inline(never)] || { ::tracing::event!(::tracing::Level::$level, $($x)*) }
+        };
+
+        if ::tracing::enabled!(::tracing::Level::$level) {
+            event();
+        }
+    }};
+}
+
+macro_rules! span {
+    ($level:ident, $($x:tt)*) => {{
+        let span = {
+            #[cold] #[inline(never)] || { ::tracing::span!(::tracing::Level::$level, $($x)*) }
+        };
+
+        if ::tracing::enabled!(::tracing::Level::$level) {
+            span()
+        } else {
+            ::tracing::Span::none()
+        }
+    }};
+}
+
+pub(crate) use {debug, debug_span, event, info, span, trace};
diff --git a/src/tracked_struct.rs b/src/tracked_struct.rs
index fd93250aa..c9d51837e 100644
--- a/src/tracked_struct.rs
+++ b/src/tracked_struct.rs
@@ -397,7 +397,7 @@ where
         if let Some(id) = zalsa_local.tracked_struct_id(&identity) {
             // The struct already exists in the intern map.
             let index = self.database_key_index(id);
-            tracing::trace!("Reuse tracked struct {id:?}", id = index);
+            crate::tracing::trace!("Reuse tracked struct {id:?}", id = index);
             zalsa_local.add_output(index);
 
             // SAFETY: The `id` was present in the interned map, so the value must be initialized.
@@ -423,7 +423,7 @@ where
         // in the struct map.
         let id = self.allocate(zalsa, zalsa_local, current_revision, &current_deps, fields);
         let key = self.database_key_index(id);
-        tracing::trace!("Allocated new tracked struct {key:?}");
+        crate::tracing::trace!("Allocated new tracked struct {key:?}");
         zalsa_local.add_output(key);
         zalsa_local.store_tracked_struct_id(identity, id);
         FromId::from_id(id)
@@ -453,7 +453,7 @@ where
             // If the generation would overflow, we are forced to leak the slot. Note that this
             // shouldn't be a problem in general as sufficient bits are reserved for the generation.
             let Some(id) = id.next_generation() else {
-                tracing::info!(
+                crate::tracing::info!(
                     "leaking tracked struct {:?} due to generation overflow",
                     self.database_key_index(id)
                 );
@@ -553,7 +553,7 @@ where
             // the unlikely case that the ID is already at its maximum generation, we are forced to leak
             // the previous slot and allocate a new value.
             if id.generation() == u32::MAX {
-                tracing::info!(
+                crate::tracing::info!(
                     "leaking tracked struct {:?} due to generation overflow",
                     self.database_key_index(id)
                 );
diff --git a/src/zalsa.rs b/src/zalsa.rs
index c1c46296d..8173aa11f 100644
--- a/src/zalsa.rs
+++ b/src/zalsa.rs
@@ -396,7 +396,7 @@ impl Zalsa {
     #[doc(hidden)]
     pub fn new_revision(&mut self) -> Revision {
         let new_revision = self.runtime.new_revision();
-        let _span = tracing::debug_span!("new_revision", ?new_revision).entered();
+        let _span = crate::tracing::debug_span!("new_revision", ?new_revision).entered();
 
         for (_, index) in self.ingredients_requiring_reset.iter() {
             let index = index.as_u32() as usize;
@@ -414,7 +414,7 @@ impl Zalsa {
     /// **NOT SEMVER STABLE**
     #[doc(hidden)]
     pub fn evict_lru(&mut self) {
-        let _span = tracing::debug_span!("evict_lru").entered();
+        let _span = crate::tracing::debug_span!("evict_lru").entered();
         for (_, index) in self.ingredients_requiring_reset.iter() {
             let index = index.as_u32() as usize;
             self.ingredients_vec
diff --git a/src/zalsa_local.rs b/src/zalsa_local.rs
index 51c28c9c5..a9f20912f 100644
--- a/src/zalsa_local.rs
+++ b/src/zalsa_local.rs
@@ -4,7 +4,6 @@ use std::ptr::{self, NonNull};
 
 use rustc_hash::FxHashMap;
 use thin_vec::ThinVec;
-use tracing::debug;
 
 use crate::accumulator::accumulated_map::{AccumulatedMap, AtomicInputAccumulatedValues};
 use crate::active_query::QueryStack;
@@ -197,10 +196,13 @@ impl ZalsaLocal {
         accumulated_inputs: &AtomicInputAccumulatedValues,
         cycle_heads: &CycleHeads,
     ) {
-        debug!(
+        crate::tracing::debug!(
             "report_tracked_read(input={:?}, durability={:?}, changed_at={:?})",
-            input, durability, changed_at
+            input,
+            durability,
+            changed_at
         );
+
         self.with_query_stack_mut(|stack| {
             if let Some(top_query) = stack.last_mut() {
                 top_query.add_read(
@@ -223,10 +225,13 @@ impl ZalsaLocal {
         durability: Durability,
         changed_at: Revision,
     ) {
-        debug!(
+        crate::tracing::debug!(
             "report_tracked_read(input={:?}, durability={:?}, changed_at={:?})",
-            input, durability, changed_at
+            input,
+            durability,
+            changed_at
         );
+
         self.with_query_stack_mut(|stack| {
             if let Some(top_query) = stack.last_mut() {
                 top_query.add_read_simple(input, durability, changed_at);

From e982eb88c3f9c1ae3e7134b29f797c8253119567 Mon Sep 17 00:00:00 2001
From: Ibraheem Ahmed <ibraheem@ibraheem.ca>
Date: Mon, 21 Jul 2025 00:43:24 -0400
Subject: [PATCH 2/2] outline log events

---
 src/zalsa.rs | 12 ++++++++++--
 1 file changed, 10 insertions(+), 2 deletions(-)

diff --git a/src/zalsa.rs b/src/zalsa.rs
index 8173aa11f..f7a492f0a 100644
--- a/src/zalsa.rs
+++ b/src/zalsa.rs
@@ -431,10 +431,18 @@ impl Zalsa {
 
     #[inline(always)]
     pub fn event(&self, event: &dyn Fn() -> crate::Event) {
-        if let Some(event_callback) = &self.event_callback {
-            event_callback(event());
+        if self.event_callback.is_some() {
+            self.event_cold(event);
         }
     }
+
+    // Avoid inlining, as events are typically only enabled for debugging purposes.
+    #[cold]
+    #[inline(never)]
+    pub fn event_cold(&self, event: &dyn Fn() -> crate::Event) {
+        let event_callback = self.event_callback.as_ref().unwrap();
+        event_callback(event());
+    }
 }
 
 /// A type-erased `Jar`, used for ingredient registration.