Skip to content

Commit bb0831a

Browse files
ibraheemdevibraheemdev
authored
Outline all tracing events (#942)
* outline all tracing events * outline log events
1 parent 53cd6b1 commit bb0831a

File tree

13 files changed

+116
-43
lines changed

13 files changed

+116
-43
lines changed

‎src/database_impl.rs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -16,7 +16,7 @@ impl Default for DatabaseImpl {
1616
// Default behavior: tracing debug log the event.
1717
storage: Storage::new(if tracing::enabled!(Level::DEBUG) {
1818
Some(Box::new(|event| {
19-
tracing::debug!("salsa_event({:?})", event)
19+
crate::tracing::debug!("salsa_event({:?})", event)
2020
}))
2121
} else {
2222
None

‎src/function/backdate.rs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -34,7 +34,7 @@ where
3434
if revisions.durability >= old_memo.revisions.durability
3535
&& C::values_equal(old_value, value)
3636
{
37-
tracing::debug!(
37+
crate::tracing::debug!(
3838
"{index:?} value is equal, back-dating to {:?}",
3939
old_memo.revisions.changed_at,
4040
);

‎src/function/execute.rs‎

Lines changed: 8 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,7 @@ where
2929
let database_key_index = active_query.database_key_index;
3030
let id = database_key_index.key_index();
3131

32-
tracing::info!("{:?}: executing query", database_key_index);
32+
crate::tracing::info!("{:?}: executing query", database_key_index);
3333
let zalsa = db.zalsa();
3434

3535
zalsa.event(&|| {
@@ -169,7 +169,7 @@ where
169169
};
170170
// SAFETY: The `LRU` does not run mid-execution, so the value remains filled
171171
let last_provisional_value = unsafe { last_provisional_value.unwrap_unchecked() };
172-
tracing::debug!(
172+
crate::tracing::debug!(
173173
"{database_key_index:?}: execute: \
174174
I am a cycle head, comparing last provisional value with new value"
175175
);
@@ -196,7 +196,7 @@ where
196196
) {
197197
crate::CycleRecoveryAction::Iterate => {}
198198
crate::CycleRecoveryAction::Fallback(fallback_value) => {
199-
tracing::debug!(
199+
crate::tracing::debug!(
200200
"{database_key_index:?}: execute: user cycle_fn says to fall back"
201201
);
202202
new_value = fallback_value;
@@ -220,7 +220,7 @@ where
220220
});
221221
cycle_heads.update_iteration_count(database_key_index, iteration_count);
222222
revisions.update_iteration_count(iteration_count);
223-
tracing::debug!(
223+
crate::tracing::debug!(
224224
"{database_key_index:?}: execute: iterate again, revisions: {revisions:#?}"
225225
);
226226
opt_last_provisional = Some(self.insert_memo(
@@ -236,7 +236,7 @@ where
236236

237237
continue;
238238
}
239-
tracing::debug!(
239+
crate::tracing::debug!(
240240
"{database_key_index:?}: execute: fixpoint iteration has a final value"
241241
);
242242
cycle_heads.remove(&database_key_index);
@@ -247,7 +247,9 @@ where
247247
}
248248
}
249249

250-
tracing::debug!("{database_key_index:?}: execute: result.revisions = {revisions:#?}");
250+
crate::tracing::debug!(
251+
"{database_key_index:?}: execute: result.revisions = {revisions:#?}"
252+
);
251253

252254
break (new_value, revisions);
253255
}

‎src/function/fetch.rs‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -15,8 +15,9 @@ where
1515
zalsa.unwind_if_revision_cancelled(zalsa_local);
1616

1717
let database_key_index = self.database_key_index(id);
18+
1819
#[cfg(debug_assertions)]
19-
let _span = tracing::debug_span!("fetch", query = ?database_key_index).entered();
20+
let _span = crate::tracing::debug_span!("fetch", query = ?database_key_index).entered();
2021

2122
let memo = self.refresh_memo(db, zalsa, zalsa_local, id);
2223
// SAFETY: We just refreshed the memo so it is guaranteed to contain a value now.
@@ -169,7 +170,7 @@ where
169170
);
170171
}),
171172
CycleRecoveryStrategy::Fixpoint => {
172-
tracing::debug!(
173+
crate::tracing::debug!(
173174
"hit cycle at {database_key_index:#?}, \
174175
inserting and returning fixpoint initial value"
175176
);
@@ -183,7 +184,7 @@ where
183184
))
184185
}
185186
CycleRecoveryStrategy::FallbackImmediate => {
186-
tracing::debug!(
187+
crate::tracing::debug!(
187188
"hit a `FallbackImmediate` cycle at {database_key_index:#?}"
188189
);
189190
let active_query =

‎src/function/maybe_changed_after.rs‎

Lines changed: 10 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -53,7 +53,9 @@ where
5353
loop {
5454
let database_key_index = self.database_key_index(id);
5555

56-
tracing::debug!("{database_key_index:?}: maybe_changed_after(revision = {revision:?})");
56+
crate::tracing::debug!(
57+
"{database_key_index:?}: maybe_changed_after(revision = {revision:?})"
58+
);
5759

5860
// Check if we have a verified version: this is the hot path.
5961
let memo_guard = self.get_memo_from_table_for(zalsa, id, memo_ingredient_index);
@@ -117,7 +119,7 @@ where
117119
return Some(VerifyResult::unchanged());
118120
}
119121
CycleRecoveryStrategy::Fixpoint => {
120-
tracing::debug!(
122+
crate::tracing::debug!(
121123
"hit cycle at {database_key_index:?} in `maybe_changed_after`, returning fixpoint initial value",
122124
);
123125
cycle_heads.push_initial(database_key_index);
@@ -132,7 +134,7 @@ where
132134
return Some(VerifyResult::Changed);
133135
};
134136

135-
tracing::debug!(
137+
crate::tracing::debug!(
136138
"{database_key_index:?}: maybe_changed_after_cold, successful claim, \
137139
revision = {revision:?}, old_memo = {old_memo:#?}",
138140
old_memo = old_memo.tracing_debug()
@@ -194,7 +196,7 @@ where
194196
database_key_index: DatabaseKeyIndex,
195197
memo: &Memo<'_, C>,
196198
) -> ShallowUpdate {
197-
tracing::debug!(
199+
crate::tracing::debug!(
198200
"{database_key_index:?}: shallow_verify_memo(memo = {memo:#?})",
199201
memo = memo.tracing_debug()
200202
);
@@ -207,7 +209,7 @@ where
207209
}
208210

209211
let last_changed = zalsa.last_changed_revision(memo.revisions.durability);
210-
tracing::debug!(
212+
crate::tracing::debug!(
211213
"{database_key_index:?}: check_durability(memo = {memo:#?}, last_changed={:?} <= verified_at={:?}) = {:?}",
212214
last_changed,
213215
verified_at,
@@ -263,7 +265,7 @@ where
263265
database_key_index: DatabaseKeyIndex,
264266
memo: &Memo<'_, C>,
265267
) -> bool {
266-
tracing::trace!(
268+
crate::tracing::trace!(
267269
"{database_key_index:?}: validate_provisional(memo = {memo:#?})",
268270
memo = memo.tracing_debug()
269271
);
@@ -324,7 +326,7 @@ where
324326
database_key_index: DatabaseKeyIndex,
325327
memo: &Memo<'_, C>,
326328
) -> bool {
327-
tracing::trace!(
329+
crate::tracing::trace!(
328330
"{database_key_index:?}: validate_same_iteration(memo = {memo:#?})",
329331
memo = memo.tracing_debug()
330332
);
@@ -377,7 +379,7 @@ where
377379
database_key_index: DatabaseKeyIndex,
378380
cycle_heads: &mut CycleHeads,
379381
) -> VerifyResult {
380-
tracing::debug!(
382+
crate::tracing::debug!(
381383
"{database_key_index:?}: deep_verify_memo(old_memo = {old_memo:#?})",
382384
old_memo = old_memo.tracing_debug()
383385
);

‎src/function/memo.rs‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -153,7 +153,7 @@ impl<'db, C: Configuration> Memo<'db, C> {
153153
} else {
154154
// all our cycle heads are complete; re-fetch
155155
// and we should get a non-provisional memo.
156-
tracing::debug!(
156+
crate::tracing::debug!(
157157
"Retrying provisional memo {database_key_index:?} after awaiting cycle heads."
158158
);
159159
true
@@ -180,7 +180,7 @@ impl<'db, C: Configuration> Memo<'db, C> {
180180

181181
#[inline(never)]
182182
fn block_on_heads_cold(zalsa: &Zalsa, heads: &CycleHeads) -> bool {
183-
let _entered = tracing::debug_span!("block_on_heads").entered();
183+
let _entered = crate::tracing::debug_span!("block_on_heads").entered();
184184
let mut cycle_heads = TryClaimCycleHeadsIter::new(zalsa, heads);
185185
let mut all_cycles = true;
186186

@@ -209,7 +209,7 @@ impl<'db, C: Configuration> Memo<'db, C> {
209209
/// Unlike `block_on_heads`, this code does not block on any cycle head. Instead it returns `false` if
210210
/// claiming all cycle heads failed because one of them is running on another thread.
211211
pub(super) fn try_claim_heads(&self, zalsa: &Zalsa, zalsa_local: &ZalsaLocal) -> bool {
212-
let _entered = tracing::debug_span!("try_claim_heads").entered();
212+
let _entered = crate::tracing::debug_span!("try_claim_heads").entered();
213213
if self.all_cycles_on_stack(zalsa_local) {
214214
return true;
215215
}
@@ -419,19 +419,19 @@ impl<'me> Iterator for TryClaimCycleHeadsIter<'me> {
419419
ProvisionalStatus::Final { .. } | ProvisionalStatus::FallbackImmediate => {
420420
// This cycle is already finalized, so we don't need to wait on it;
421421
// keep looping through cycle heads.
422-
tracing::trace!("Dependent cycle head {head:?} has been finalized.");
422+
crate::tracing::trace!("Dependent cycle head {head:?} has been finalized.");
423423
Some(TryClaimHeadsResult::Finalized)
424424
}
425425
ProvisionalStatus::Provisional { .. } => {
426426
match ingredient.wait_for(self.zalsa, head_key_index) {
427427
WaitForResult::Cycle { .. } => {
428428
// We hit a cycle blocking on the cycle head; this means this query actively
429429
// participates in the cycle and some other query is blocked on this thread.
430-
tracing::debug!("Waiting for {head:?} results in a cycle");
430+
crate::tracing::debug!("Waiting for {head:?} results in a cycle");
431431
Some(TryClaimHeadsResult::Cycle)
432432
}
433433
WaitForResult::Running(running) => {
434-
tracing::debug!("Ingredient {head:?} is running: {running:?}");
434+
crate::tracing::debug!("Ingredient {head:?} is running: {running:?}");
435435

436436
Some(TryClaimHeadsResult::Running(RunningCycleHead {
437437
inner: running,

‎src/function/specify.rs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -83,7 +83,7 @@ where
8383
revisions,
8484
};
8585

86-
tracing::debug!(
86+
crate::tracing::debug!(
8787
"specify: about to add memo {:#?} for key {:?}",
8888
memo.tracing_debug(),
8989
key

‎src/lib.rs‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ mod salsa_struct;
2626
mod storage;
2727
mod sync;
2828
mod table;
29+
mod tracing;
2930
mod tracked_struct;
3031
mod update;
3132
mod views;

‎src/runtime.rs‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -86,7 +86,7 @@ impl Running<'_> {
8686
})
8787
});
8888

89-
tracing::debug!(
89+
crate::tracing::debug!(
9090
"block_on: thread {thread_id:?} is blocking on {database_key:?} in thread {other_id:?}",
9191
);
9292

@@ -180,7 +180,7 @@ impl Runtime {
180180
}
181181

182182
pub(crate) fn set_cancellation_flag(&self) {
183-
tracing::trace!("set_cancellation_flag");
183+
crate::tracing::trace!("set_cancellation_flag");
184184
self.revision_canceled.store(true, Ordering::Release);
185185
}
186186

@@ -206,7 +206,7 @@ impl Runtime {
206206
let r_old = self.current_revision();
207207
let r_new = r_old.next();
208208
self.revisions[0] = r_new;
209-
tracing::debug!("new_revision: {r_old:?} -> {r_new:?}");
209+
crate::tracing::debug!("new_revision: {r_old:?} -> {r_new:?}");
210210
r_new
211211
}
212212

@@ -236,7 +236,7 @@ impl Runtime {
236236
let dg = self.dependency_graph.lock();
237237

238238
if dg.depends_on(other_id, thread_id) {
239-
tracing::debug!("block_on: cycle detected for {database_key:?} in thread {thread_id:?} on {other_id:?}");
239+
crate::tracing::debug!("block_on: cycle detected for {database_key:?} in thread {thread_id:?} on {other_id:?}");
240240
return BlockResult::Cycle { same_thread: false };
241241
}
242242

‎src/tracing.rs‎

Lines changed: 54 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,54 @@
1+
//! Wrappers around `tracing` macros that avoid inlining debug machinery into the hot path,
2+
//! as tracing events are typically only enabled for debugging purposes.
3+
4+
macro_rules! trace {
5+
($($x:tt)*) => {
6+
crate::tracing::event!(TRACE, $($x)*)
7+
};
8+
}
9+
10+
macro_rules! info {
11+
($($x:tt)*) => {
12+
crate::tracing::event!(INFO, $($x)*)
13+
};
14+
}
15+
16+
macro_rules! debug {
17+
($($x:tt)*) => {
18+
crate::tracing::event!(DEBUG, $($x)*)
19+
};
20+
}
21+
22+
macro_rules! debug_span {
23+
($($x:tt)*) => {
24+
crate::tracing::span!(DEBUG, $($x)*)
25+
};
26+
}
27+
28+
macro_rules! event {
29+
($level:ident, $($x:tt)*) => {{
30+
let event = {
31+
#[cold] #[inline(never)] || { ::tracing::event!(::tracing::Level::$level, $($x)*) }
32+
};
33+
34+
if ::tracing::enabled!(::tracing::Level::$level) {
35+
event();
36+
}
37+
}};
38+
}
39+
40+
macro_rules! span {
41+
($level:ident, $($x:tt)*) => {{
42+
let span = {
43+
#[cold] #[inline(never)] || { ::tracing::span!(::tracing::Level::$level, $($x)*) }
44+
};
45+
46+
if ::tracing::enabled!(::tracing::Level::$level) {
47+
span()
48+
} else {
49+
::tracing::Span::none()
50+
}
51+
}};
52+
}
53+
54+
pub(crate) use {debug, debug_span, event, info, span, trace};

0 commit comments

Comments
 (0)