Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion src/database_impl.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
2 changes: 1 addition & 1 deletion src/function/backdate.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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,
);
Expand Down
14 changes: 8 additions & 6 deletions src/function/execute.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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(&|| {
Expand Down Expand Up @@ -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"
);
Expand All @@ -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;
Expand All @@ -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(
Expand All @@ -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);
Expand All @@ -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);
}
Expand Down
7 changes: 4 additions & 3 deletions src/function/fetch.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -169,7 +170,7 @@ where
);
}),
CycleRecoveryStrategy::Fixpoint => {
tracing::debug!(
crate::tracing::debug!(
"hit cycle at {database_key_index:#?}, \
inserting and returning fixpoint initial value"
);
Expand All @@ -183,7 +184,7 @@ where
))
}
CycleRecoveryStrategy::FallbackImmediate => {
tracing::debug!(
crate::tracing::debug!(
"hit a `FallbackImmediate` cycle at {database_key_index:#?}"
);
let active_query =
Expand Down
18 changes: 10 additions & 8 deletions src/function/maybe_changed_after.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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);
Expand All @@ -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()
Expand Down Expand Up @@ -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()
);
Expand All @@ -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,
Expand Down Expand Up @@ -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()
);
Expand Down Expand Up @@ -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()
);
Expand Down Expand Up @@ -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()
);
Expand Down
12 changes: 6 additions & 6 deletions src/function/memo.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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;

Expand Down Expand Up @@ -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;
}
Expand Down Expand Up @@ -417,19 +417,19 @@ 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 { .. } => {
match ingredient.wait_for(self.zalsa, head_key_index) {
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,
Expand Down
2 changes: 1 addition & 1 deletion src/function/specify.rs
Original file line number Diff line number Diff line change
Expand Up @@ -83,7 +83,7 @@ where
revisions,
};

tracing::debug!(
crate::tracing::debug!(
"specify: about to add memo {:#?} for key {:?}",
memo.tracing_debug(),
key
Expand Down
1 change: 1 addition & 0 deletions src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@ mod salsa_struct;
mod storage;
mod sync;
mod table;
mod tracing;
mod tracked_struct;
mod update;
mod views;
Expand Down
8 changes: 4 additions & 4 deletions src/runtime.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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:?}",
);

Expand Down Expand Up @@ -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);
}

Expand All @@ -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
}

Expand Down Expand Up @@ -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 };
}

Expand Down
54 changes: 54 additions & 0 deletions src/tracing.rs
Original file line number Diff line number Diff line change
@@ -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};
8 changes: 4 additions & 4 deletions src/tracked_struct.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -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)
Expand Down Expand Up @@ -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)
);
Expand Down Expand Up @@ -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)
);
Expand Down
Loading