diff --git a/crates/ra-salsa/ra-salsa-macros/src/query_group.rs b/crates/ra-salsa/ra-salsa-macros/src/query_group.rs index 88db6093ee..d761a5e798 100644 --- a/crates/ra-salsa/ra-salsa-macros/src/query_group.rs +++ b/crates/ra-salsa/ra-salsa-macros/src/query_group.rs @@ -242,7 +242,7 @@ pub(crate) fn query_group(args: TokenStream, input: TokenStream) -> TokenStream let tracing = if let QueryStorage::Memoized | QueryStorage::LruMemoized = query.storage { let s = format!("{trait_name}::{fn_name}"); Some(quote! { - let _p = tracing::debug_span!(#s, #(#key_names = tracing::field::debug(&#key_names)),*).entered(); + let _p = tracing::trace_span!(#s, #(#key_names = tracing::field::debug(&#key_names)),*).entered(); }) } else { None diff --git a/crates/ra-salsa/src/derived/slot.rs b/crates/ra-salsa/src/derived/slot.rs index 6c5ccba173..cfe2c48f41 100644 --- a/crates/ra-salsa/src/derived/slot.rs +++ b/crates/ra-salsa/src/derived/slot.rs @@ -13,7 +13,7 @@ use crate::{Database, DatabaseKeyIndex, Event, EventKind, QueryDb}; use parking_lot::{RawRwLock, RwLock}; use std::ops::Deref; use std::sync::atomic::{AtomicBool, Ordering}; -use tracing::{debug, info}; +use tracing::trace; pub(super) struct Slot where @@ -126,7 +126,7 @@ where // doing any `set` invocations while the query function runs. let revision_now = runtime.current_revision(); - info!("{:?}: invoked at {:?}", self, revision_now,); + trace!("{:?}: invoked at {:?}", self, revision_now,); // First, do a check with a read-lock. loop { @@ -152,7 +152,7 @@ where ) -> StampedValue { let runtime = db.salsa_runtime(); - debug!("{:?}: read_upgrade(revision_now={:?})", self, revision_now,); + trace!("{:?}: read_upgrade(revision_now={:?})", self, revision_now,); // Check with an upgradable read to see if there is a value // already. (This permits other readers but prevents anyone @@ -184,7 +184,7 @@ where // inputs and check whether they are out of date. if let Some(memo) = &mut old_memo { if let Some(value) = memo.verify_value(db.ops_database(), revision_now, &active_query) { - info!("{:?}: validated old memoized value", self,); + trace!("{:?}: validated old memoized value", self,); db.salsa_event(Event { runtime_id: runtime.id(), @@ -212,7 +212,7 @@ where old_memo: Option>, key: &Q::Key, ) -> StampedValue { - tracing::info!("{:?}: executing query", self.database_key_index().debug(db)); + tracing::trace!("{:?}: executing query", self.database_key_index().debug(db)); db.salsa_event(Event { runtime_id: db.salsa_runtime().id(), @@ -224,7 +224,7 @@ where let value = match Cycle::catch(|| Q::execute(db, key.clone())) { Ok(v) => v, Err(cycle) => { - tracing::debug!( + tracing::trace!( "{:?}: caught cycle {:?}, have strategy {:?}", self.database_key_index().debug(db), cycle, @@ -272,9 +272,10 @@ where // consumers must be aware of. Becoming *more* durable // is not. See the test `constant_to_non_constant`. if revisions.durability >= old_memo.revisions.durability && old_memo.value == value { - debug!( + trace!( "read_upgrade({:?}): value is equal, back-dating to {:?}", - self, old_memo.revisions.changed_at, + self, + old_memo.revisions.changed_at, ); assert!(old_memo.revisions.changed_at <= revisions.changed_at); @@ -290,7 +291,7 @@ where let memo_value = new_value.value.clone(); - debug!("read_upgrade({:?}): result.revisions = {:#?}", self, revisions,); + trace!("read_upgrade({:?}): result.revisions = {:#?}", self, revisions,); panic_guard.proceed(Some(Memo { value: memo_value, verified_at: revision_now, revisions })); @@ -339,9 +340,11 @@ where } QueryState::Memoized(memo) => { - debug!( + trace!( "{:?}: found memoized value, verified_at={:?}, changed_at={:?}", - self, memo.verified_at, memo.revisions.changed_at, + self, + memo.verified_at, + memo.revisions.changed_at, ); if memo.verified_at < revision_now { @@ -355,7 +358,7 @@ where value: value.clone(), }; - info!("{:?}: returning memoized value changed at {:?}", self, value.changed_at); + trace!("{:?}: returning memoized value changed at {:?}", self, value.changed_at); ProbeState::UpToDate(value) } @@ -387,7 +390,7 @@ where } pub(super) fn invalidate(&self, new_revision: Revision) -> Option { - tracing::debug!("Slot::invalidate(new_revision = {:?})", new_revision); + tracing::trace!("Slot::invalidate(new_revision = {:?})", new_revision); match &mut *self.state.write() { QueryState::Memoized(memo) => { memo.revisions.untracked = true; @@ -411,9 +414,11 @@ where db.unwind_if_cancelled(); - debug!( + trace!( "maybe_changed_after({:?}) called with revision={:?}, revision_now={:?}", - self, revision, revision_now, + self, + revision, + revision_now, ); // Do an initial probe with just the read-lock. @@ -680,9 +685,11 @@ where assert!(self.verified_at != revision_now); let verified_at = self.verified_at; - debug!( + trace!( "verify_revisions: verified_at={:?}, revision_now={:?}, inputs={:#?}", - verified_at, revision_now, self.revisions.inputs + verified_at, + revision_now, + self.revisions.inputs ); if self.check_durability(db.salsa_runtime()) { @@ -708,7 +715,7 @@ where let changed_input = inputs.slice.iter().find(|&&input| db.maybe_changed_after(input, verified_at)); if let Some(input) = changed_input { - debug!("validate_memoized_value: `{:?}` may have changed", input); + trace!("validate_memoized_value: `{:?}` may have changed", input); return false; } @@ -721,7 +728,7 @@ where /// True if this memo is known not to have changed based on its durability. fn check_durability(&self, runtime: &Runtime) -> bool { let last_changed = runtime.last_changed_revision(self.revisions.durability); - debug!( + trace!( "check_durability(last_changed={:?} <= verified_at={:?}) = {:?}", last_changed, self.verified_at, diff --git a/crates/ra-salsa/src/derived_lru/slot.rs b/crates/ra-salsa/src/derived_lru/slot.rs index ff9cc4eade..73a5e07aa0 100644 --- a/crates/ra-salsa/src/derived_lru/slot.rs +++ b/crates/ra-salsa/src/derived_lru/slot.rs @@ -17,7 +17,7 @@ use parking_lot::{RawRwLock, RwLock}; use std::marker::PhantomData; use std::ops::Deref; use std::sync::atomic::{AtomicBool, Ordering}; -use tracing::{debug, info}; +use tracing::trace; pub(super) struct Slot where @@ -140,7 +140,7 @@ where // doing any `set` invocations while the query function runs. let revision_now = runtime.current_revision(); - info!("{:?}: invoked at {:?}", self, revision_now,); + trace!("{:?}: invoked at {:?}", self, revision_now,); // First, do a check with a read-lock. loop { @@ -168,7 +168,7 @@ where ) -> StampedValue { let runtime = db.salsa_runtime(); - debug!("{:?}: read_upgrade(revision_now={:?})", self, revision_now,); + trace!("{:?}: read_upgrade(revision_now={:?})", self, revision_now,); // Check with an upgradable read to see if there is a value // already. (This permits other readers but prevents anyone @@ -202,7 +202,7 @@ where // inputs and check whether they are out of date. if let Some(memo) = &mut old_memo { if let Some(value) = memo.verify_value(db.ops_database(), revision_now, &active_query) { - info!("{:?}: validated old memoized value", self,); + trace!("{:?}: validated old memoized value", self,); db.salsa_event(Event { runtime_id: runtime.id(), @@ -230,7 +230,7 @@ where old_memo: Option>, key: &Q::Key, ) -> StampedValue { - tracing::info!("{:?}: executing query", self.database_key_index().debug(db)); + tracing::trace!("{:?}: executing query", self.database_key_index().debug(db)); db.salsa_event(Event { runtime_id: db.salsa_runtime().id(), @@ -242,7 +242,7 @@ where let value = match Cycle::catch(|| Q::execute(db, key.clone())) { Ok(v) => v, Err(cycle) => { - tracing::debug!( + tracing::trace!( "{:?}: caught cycle {:?}, have strategy {:?}", self.database_key_index().debug(db), cycle, @@ -293,9 +293,10 @@ where if revisions.durability >= old_memo.revisions.durability && MP::memoized_value_eq(old_value, &value) { - debug!( + trace!( "read_upgrade({:?}): value is equal, back-dating to {:?}", - self, old_memo.revisions.changed_at, + self, + old_memo.revisions.changed_at, ); assert!(old_memo.revisions.changed_at <= revisions.changed_at); @@ -313,7 +314,7 @@ where let memo_value = if self.should_memoize_value(key) { Some(new_value.value.clone()) } else { None }; - debug!("read_upgrade({:?}): result.revisions = {:#?}", self, revisions,); + trace!("read_upgrade({:?}): result.revisions = {:#?}", self, revisions,); panic_guard.proceed(Some(Memo { value: memo_value, verified_at: revision_now, revisions })); @@ -362,9 +363,11 @@ where } QueryState::Memoized(memo) => { - debug!( + trace!( "{:?}: found memoized value, verified_at={:?}, changed_at={:?}", - self, memo.verified_at, memo.revisions.changed_at, + self, + memo.verified_at, + memo.revisions.changed_at, ); if memo.verified_at < revision_now { @@ -378,7 +381,11 @@ where value: value.clone(), }; - info!("{:?}: returning memoized value changed at {:?}", self, value.changed_at); + trace!( + "{:?}: returning memoized value changed at {:?}", + self, + value.changed_at + ); ProbeState::UpToDate(value) } else { @@ -426,7 +433,7 @@ where } pub(super) fn invalidate(&self, new_revision: Revision) -> Option { - tracing::debug!("Slot::invalidate(new_revision = {:?})", new_revision); + tracing::trace!("Slot::invalidate(new_revision = {:?})", new_revision); match &mut *self.state.write() { QueryState::Memoized(memo) => { memo.revisions.untracked = true; @@ -450,9 +457,11 @@ where db.unwind_if_cancelled(); - debug!( + trace!( "maybe_changed_after({:?}) called with revision={:?}, revision_now={:?}", - self, revision, revision_now, + self, + revision, + revision_now, ); // Do an initial probe with just the read-lock. @@ -734,9 +743,11 @@ where assert!(self.verified_at != revision_now); let verified_at = self.verified_at; - debug!( + trace!( "verify_revisions: verified_at={:?}, revision_now={:?}, inputs={:#?}", - verified_at, revision_now, self.revisions.inputs + verified_at, + revision_now, + self.revisions.inputs ); if self.check_durability(db.salsa_runtime()) { @@ -762,7 +773,7 @@ where let changed_input = inputs.slice.iter().find(|&&input| db.maybe_changed_after(input, verified_at)); if let Some(input) = changed_input { - debug!("validate_memoized_value: `{:?}` may have changed", input); + trace!("validate_memoized_value: `{:?}` may have changed", input); return false; } @@ -775,7 +786,7 @@ where /// True if this memo is known not to have changed based on its durability. fn check_durability(&self, runtime: &Runtime) -> bool { let last_changed = runtime.last_changed_revision(self.revisions.durability); - debug!( + trace!( "check_durability(last_changed={:?} <= verified_at={:?}) = {:?}", last_changed, self.verified_at, diff --git a/crates/ra-salsa/src/input.rs b/crates/ra-salsa/src/input.rs index f04f48e3ba..4992a0c727 100644 --- a/crates/ra-salsa/src/input.rs +++ b/crates/ra-salsa/src/input.rs @@ -14,7 +14,7 @@ use crate::{DatabaseKeyIndex, QueryDb}; use indexmap::map::Entry; use parking_lot::RwLock; use std::iter; -use tracing::debug; +use tracing::trace; /// Input queries store the result plus a list of the other queries /// that they invoked. This means we can avoid recomputing them when @@ -73,11 +73,11 @@ where return true; }; - debug!("maybe_changed_after(slot={:?}, revision={:?})", Q::default(), revision,); + trace!("maybe_changed_after(slot={:?}, revision={:?})", Q::default(), revision,); let changed_at = slot.stamped_value.read().changed_at; - debug!("maybe_changed_after: changed_at = {:?}", changed_at); + trace!("maybe_changed_after: changed_at = {:?}", changed_at); changed_at > revision } @@ -140,7 +140,7 @@ where Q: Query, { fn set(&self, runtime: &mut Runtime, key: &Q::Key, value: Q::Value, durability: Durability) { - tracing::debug!("{:?}({:?}) = {:?} ({:?})", Q::default(), key, value, durability); + tracing::trace!("{:?}({:?}) = {:?} ({:?})", Q::default(), key, value, durability); // The value is changing, so we need a new revision (*). We also // need to update the 'last changed' revision by invoking @@ -234,14 +234,14 @@ where ) -> bool { debug_assert!(revision < db.salsa_runtime().current_revision()); - debug!("maybe_changed_after(slot={:?}, revision={:?})", Q::default(), revision,); + trace!("maybe_changed_after(slot={:?}, revision={:?})", Q::default(), revision,); let Some(value) = &*self.slot.stamped_value.read() else { return true; }; let changed_at = value.changed_at; - debug!("maybe_changed_after: changed_at = {:?}", changed_at); + trace!("maybe_changed_after: changed_at = {:?}", changed_at); changed_at > revision } @@ -298,7 +298,7 @@ where Q: Query, { fn set(&self, runtime: &mut Runtime, (): &Q::Key, value: Q::Value, durability: Durability) { - tracing::debug!("{:?} = {:?} ({:?})", Q::default(), value, durability); + tracing::trace!("{:?} = {:?} ({:?})", Q::default(), value, durability); // The value is changing, so we need a new revision (*). We also // need to update the 'last changed' revision by invoking diff --git a/crates/ra-salsa/src/lib.rs b/crates/ra-salsa/src/lib.rs index 8530521d91..843b6d31f0 100644 --- a/crates/ra-salsa/src/lib.rs +++ b/crates/ra-salsa/src/lib.rs @@ -79,7 +79,7 @@ pub trait Database: plumbing::DatabaseOps { let current_revision = runtime.current_revision(); let pending_revision = runtime.pending_revision(); - tracing::debug!( + tracing::trace!( "unwind_if_cancelled: current_revision={:?}, pending_revision={:?}", current_revision, pending_revision @@ -684,7 +684,7 @@ impl Cycle { } pub(crate) fn throw(self) -> ! { - tracing::debug!("throwing cycle {:?}", self); + tracing::trace!("throwing cycle {:?}", self); std::panic::resume_unwind(Box::new(self)) } diff --git a/crates/ra-salsa/src/lru.rs b/crates/ra-salsa/src/lru.rs index a6f96beeab..7fbd42f926 100644 --- a/crates/ra-salsa/src/lru.rs +++ b/crates/ra-salsa/src/lru.rs @@ -103,11 +103,11 @@ where /// Records that `node` was used. This may displace an old node (if the LRU limits are pub(crate) fn record_use(&self, node: &Arc) -> Option> { - tracing::debug!("record_use(node={:?})", node); + tracing::trace!("record_use(node={:?})", node); // Load green zone length and check if the LRU cache is even enabled. let green_zone = self.green_zone.load(Ordering::Acquire); - tracing::debug!("record_use: green_zone={}", green_zone); + tracing::trace!("record_use: green_zone={}", green_zone); if green_zone == 0 { return None; } @@ -115,7 +115,7 @@ where // Find current index of list (if any) and the current length // of our green zone. let index = node.lru_index().load(); - tracing::debug!("record_use: index={}", index); + tracing::trace!("record_use: index={}", index); // Already a member of the list, and in the green zone -- nothing to do! if index < green_zone { @@ -162,9 +162,9 @@ where let entries = std::mem::replace(&mut self.entries, Vec::with_capacity(self.end_red_zone as usize)); - tracing::debug!("green_zone = {:?}", self.green_zone()); - tracing::debug!("yellow_zone = {:?}", self.yellow_zone()); - tracing::debug!("red_zone = {:?}", self.red_zone()); + tracing::trace!("green_zone = {:?}", self.green_zone()); + tracing::trace!("yellow_zone = {:?}", self.yellow_zone()); + tracing::trace!("red_zone = {:?}", self.red_zone()); // We expect to resize when the LRU cache is basically empty. // So just forget all the old LRU indices to start. @@ -180,7 +180,7 @@ where /// list may displace an old member of the red zone, in which case /// that is returned. fn record_use(&mut self, node: &Arc) -> Option> { - tracing::debug!("record_use(node={:?})", node); + tracing::trace!("record_use(node={:?})", node); // NB: When this is invoked, we have typically already loaded // the LRU index (to check if it is in green zone). But that @@ -212,7 +212,7 @@ where if len < self.end_red_zone { self.entries.push(node.clone()); node.lru_index().store(len); - tracing::debug!("inserted node {:?} at {}", node, len); + tracing::trace!("inserted node {:?} at {}", node, len); return self.record_use(node); } @@ -220,7 +220,7 @@ where // zone and then promoting. let victim_index = self.pick_index(self.red_zone()); let victim_node = std::mem::replace(&mut self.entries[victim_index as usize], node.clone()); - tracing::debug!("evicting red node {:?} from {}", victim_node, victim_index); + tracing::trace!("evicting red node {:?} from {}", victim_node, victim_index); victim_node.lru_index().clear(); self.promote_red_to_green(node, victim_index); Some(victim_node) @@ -241,7 +241,7 @@ where // going to invoke `self.promote_yellow` next, and it will get // updated then. let yellow_index = self.pick_index(self.yellow_zone()); - tracing::debug!( + tracing::trace!( "demoting yellow node {:?} from {} to red at {}", self.entries[yellow_index as usize], yellow_index, @@ -265,7 +265,7 @@ where // Pick a yellow at random and switch places with it. let green_index = self.pick_index(self.green_zone()); - tracing::debug!( + tracing::trace!( "demoting green node {:?} from {} to yellow at {}", self.entries[green_index as usize], green_index, @@ -275,7 +275,7 @@ where self.entries[yellow_index as usize].lru_index().store(yellow_index); node.lru_index().store(green_index); - tracing::debug!("promoted {:?} to green index {}", node, green_index); + tracing::trace!("promoted {:?} to green index {}", node, green_index); } fn pick_index(&mut self, zone: std::ops::Range) -> u16 { diff --git a/crates/ra-salsa/src/runtime.rs b/crates/ra-salsa/src/runtime.rs index 5fe5f4b46d..cb16ba0044 100644 --- a/crates/ra-salsa/src/runtime.rs +++ b/crates/ra-salsa/src/runtime.rs @@ -9,7 +9,7 @@ use parking_lot::{Mutex, RwLock}; use std::hash::Hash; use std::panic::panic_any; use std::sync::atomic::{AtomicU32, Ordering}; -use tracing::debug; +use tracing::trace; use triomphe::{Arc, ThinArc}; mod dependency_graph; @@ -177,7 +177,7 @@ impl Runtime { where F: FnOnce(Revision) -> Option, { - tracing::debug!("increment_revision()"); + tracing::trace!("increment_revision()"); if !self.permits_increment() { panic!("increment_revision invoked during a query computation"); @@ -196,7 +196,7 @@ impl Runtime { let new_revision = current_revision.next(); - debug!("increment_revision: incremented to {:?}", new_revision); + trace!("increment_revision: incremented to {:?}", new_revision); if let Some(d) = op(new_revision) { for rev in &self.shared_state.revisions[1..=d.index()] { @@ -267,7 +267,7 @@ impl Runtime { database_key_index: DatabaseKeyIndex, to_id: RuntimeId, ) { - debug!("unblock_cycle_and_maybe_throw(database_key={:?})", database_key_index); + trace!("unblock_cycle_and_maybe_throw(database_key={:?})", database_key_index); let mut from_stack = self.local_state.take_query_stack(); let from_id = self.id(); @@ -305,7 +305,7 @@ impl Runtime { Cycle::new(Arc::new(v)) }; - debug!("cycle {:?}, cycle_query {:#?}", cycle.debug(db), cycle_query,); + trace!("cycle {:?}, cycle_query {:#?}", cycle.debug(db), cycle_query,); // We can remove the cycle participants from the list of dependencies; // they are a strongly connected component (SCC) and we only care about @@ -323,7 +323,7 @@ impl Runtime { CycleRecoveryStrategy::Fallback => false, }) .for_each(|aq| { - debug!("marking {:?} for fallback", aq.database_key_index.debug(db)); + trace!("marking {:?} for fallback", aq.database_key_index.debug(db)); aq.take_inputs_from(&cycle_query); assert!(aq.cycle.is_none()); aq.cycle = Some(cycle.clone()); diff --git a/crates/ra-salsa/src/runtime/local_state.rs b/crates/ra-salsa/src/runtime/local_state.rs index 7386967188..4ab4bad0cc 100644 --- a/crates/ra-salsa/src/runtime/local_state.rs +++ b/crates/ra-salsa/src/runtime/local_state.rs @@ -1,4 +1,4 @@ -use tracing::debug; +use tracing::trace; use triomphe::ThinArc; use crate::durability::Durability; @@ -78,7 +78,7 @@ impl LocalState { durability: Durability, changed_at: Revision, ) { - debug!( + trace!( "report_query_read_and_unwind_if_cycle_resulted(input={:?}, durability={:?}, changed_at={:?})", input, durability, changed_at );