internal: switch salsa over to tracing from log

Cargo.toml

@@ -13,7 +13,7 @@ name = "salsa"
 [dependencies]
 indexmap = "2.1.0"
 lock_api = "0.4"
-log = "0.4.5"
+tracing = "0.1"
 parking_lot = "0.12.1"
 rustc-hash = "1.0"
 smallvec = "1.0.0"
@@ -24,7 +24,6 @@ rust-analyzer-salsa-macros = { version = "0.17.0-pre.5", path = "components/sals
 
 [dev-dependencies]
 diff = "0.1.0"
-env_logger = "0.7"
 linked-hash-map = "0.5.2"
 rand = "0.7"
 rand_distr = "0.2.1"

src/derived/slot.rs

@@ -14,11 +14,11 @@ use crate::runtime::StampedValue;
 use crate::runtime::WaitResult;
 use crate::Cycle;
 use crate::{Database, DatabaseKeyIndex, Event, EventKind, QueryDb};
-use log::{debug, info};
 use parking_lot::{RawRwLock, RwLock};
 use std::marker::PhantomData;
 use std::ops::Deref;
 use std::sync::atomic::{AtomicBool, Ordering};
+use tracing::{debug, info};
 
 pub(super) struct Slot<Q, MP>
 where
@@ -228,7 +228,7 @@ where
         panic_guard: PanicGuard<'_, Q, MP>,
         old_memo: Option<Memo<Q::Value>>,
     ) -> StampedValue<Q::Value> {
-        log::info!("{:?}: executing query", self.database_key_index.debug(db));
+        tracing::info!("{:?}: 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, self.key.clone())) {
             Ok(v) => v,
             Err(cycle) => {
-                log::debug!(
+                tracing::debug!(
                     "{:?}: caught cycle {:?}, have strategy {:?}",
                     self.database_key_index.debug(db),
                     cycle,
@@ -441,7 +441,7 @@ where
     }
 
     pub(super) fn invalidate(&self, new_revision: Revision) -> Option<Durability> {
-        log::debug!("Slot::invalidate(new_revision = {:?})", new_revision);
+        tracing::debug!("Slot::invalidate(new_revision = {:?})", new_revision);
         match &mut *self.state.write() {
             QueryState::Memoized(memo) => {
                 memo.revisions.inputs = QueryInputs::Untracked;

src/input.rs

@@ -12,9 +12,9 @@ use crate::Query;
 use crate::Runtime;
 use crate::{DatabaseKeyIndex, QueryDb};
 use indexmap::map::Entry;
-use log::debug;
 use parking_lot::RwLock;
 use std::convert::TryFrom;
+use tracing::debug;
 
 /// Input queries store the result plus a list of the other queries
 /// that they invoked. This means we can avoid recomputing them when
@@ -160,7 +160,7 @@ where
     Q: Query,
 {
     fn set(&self, runtime: &mut Runtime, key: &Q::Key, value: Q::Value, durability: Durability) {
-        log::debug!(
+        tracing::debug!(
             "{:?}({:?}) = {:?} ({:?})",
             Q::default(),
             key,

src/lib.rs

@@ -79,7 +79,7 @@ pub trait Database: plumbing::DatabaseOps {
 
         let current_revision = runtime.current_revision();
         let pending_revision = runtime.pending_revision();
-        log::debug!(
+        tracing::debug!(
             "unwind_if_cancelled: current_revision={:?}, pending_revision={:?}",
             current_revision,
             pending_revision
@@ -682,7 +682,7 @@ impl Cycle {
     }
 
     pub(crate) fn throw(self) -> ! {
-        log::debug!("throwing cycle {:?}", self);
+        tracing::debug!("throwing cycle {:?}", self);
         std::panic::resume_unwind(Box::new(self))
     }
 

src/lru.rs

@@ -106,19 +106,19 @@ where
 
     /// Records that `node` was used. This may displace an old node (if the LRU limits are
     pub fn record_use(&self, node: &Arc<Node>) -> Option<Arc<Node>> {
-        log::debug!("record_use(node={:?})", node);
+        tracing::debug!("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);
-        log::debug!("record_use: green_zone={}", green_zone);
+        tracing::debug!("record_use: green_zone={}", green_zone);
         if green_zone == 0 {
             return None;
         }
 
         // Find current index of list (if any) and the current length
         // of our green zone.
         let index = node.lru_index().load();
-        log::debug!("record_use: index={}", index);
+        tracing::debug!("record_use: index={}", index);
 
         // Already a member of the list, and in the green zone -- nothing to do!
         if index < green_zone {
@@ -170,9 +170,9 @@ where
         self.end_red_zone = self.end_yellow_zone + len_red_zone;
         let entries = std::mem::replace(&mut self.entries, Vec::with_capacity(self.end_red_zone));
 
-        log::debug!("green_zone = {:?}", self.green_zone());
-        log::debug!("yellow_zone = {:?}", self.yellow_zone());
-        log::debug!("red_zone = {:?}", self.red_zone());
+        tracing::debug!("green_zone = {:?}", self.green_zone());
+        tracing::debug!("yellow_zone = {:?}", self.yellow_zone());
+        tracing::debug!("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.
@@ -188,7 +188,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<Node>) -> Option<Arc<Node>> {
-        log::debug!("record_use(node={:?})", node);
+        tracing::debug!("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
@@ -220,15 +220,15 @@ where
         if len < self.end_red_zone {
             self.entries.push(node.clone());
             node.lru_index().store(len);
-            log::debug!("inserted node {:?} at {}", node, len);
+            tracing::debug!("inserted node {:?} at {}", node, len);
             return self.record_use(node);
         }
 
         // Harder case: no capacity. Create some by evicting somebody from red
         // zone and then promoting.
         let victim_index = self.pick_index(self.red_zone());
         let victim_node = std::mem::replace(&mut self.entries[victim_index], node.clone());
-        log::debug!("evicting red node {:?} from {}", victim_node, victim_index);
+        tracing::debug!("evicting red node {:?} from {}", victim_node, victim_index);
         victim_node.lru_index().clear();
         self.promote_red_to_green(node, victim_index);
         Some(victim_node)
@@ -249,7 +249,7 @@ where
         // going to invoke `self.promote_yellow` next, and it will get
         // updated then.
         let yellow_index = self.pick_index(self.yellow_zone());
-        log::debug!(
+        tracing::debug!(
             "demoting yellow node {:?} from {} to red at {}",
             self.entries[yellow_index],
             yellow_index,
@@ -273,7 +273,7 @@ where
 
         // Pick a yellow at random and switch places with it.
         let green_index = self.pick_index(self.green_zone());
-        log::debug!(
+        tracing::debug!(
             "demoting green node {:?} from {} to yellow at {}",
             self.entries[green_index],
             green_index,
@@ -283,7 +283,7 @@ where
         self.entries[yellow_index].lru_index().store(yellow_index);
         node.lru_index().store(green_index);
 
-        log::debug!("promoted {:?} to green index {}", node, green_index);
+        tracing::debug!("promoted {:?} to green index {}", node, green_index);
     }
 
     fn pick_index(&mut self, zone: std::ops::Range<usize>) -> usize {

src/runtime.rs

@@ -3,12 +3,12 @@ use crate::hash::FxIndexSet;
 use crate::plumbing::CycleRecoveryStrategy;
 use crate::revision::{AtomicRevision, Revision};
 use crate::{Cancelled, Cycle, Database, DatabaseKeyIndex, Event, EventKind};
-use log::debug;
 use parking_lot::lock_api::{RawRwLock, RawRwLockRecursive};
 use parking_lot::{Mutex, RwLock};
 use std::hash::Hash;
 use std::panic::panic_any;
 use std::sync::atomic::{AtomicUsize, Ordering};
+use tracing::debug;
 use triomphe::Arc;
 
 mod dependency_graph;
@@ -178,7 +178,7 @@ impl Runtime {
     where
         F: FnOnce(Revision) -> Option<Durability>,
     {
-        log::debug!("increment_revision()");
+        tracing::debug!("increment_revision()");
 
         if !self.permits_increment() {
             panic!("increment_revision invoked during a query computation");

src/runtime/local_state.rs

@@ -1,4 +1,4 @@
-use log::debug;
+use tracing::debug;
 
 use crate::durability::Durability;
 use crate::runtime::ActiveQuery;

tests/cycles.rs

@@ -298,7 +298,7 @@ fn cycle_appears() {
     //     ^     |
     //     +-----+
     db.set_b_invokes(CycleQuery::A);
-    log::debug!("Set Cycle Leaf");
+    tracing::debug!("Set Cycle Leaf");
     assert!(db.cycle_a().is_err());
 }
 

tests/parallel/parallel_cycle_all_recover.rs

@@ -63,22 +63,22 @@ pub(crate) trait TestDatabase: Knobs {
 }
 
 fn recover_a1(_db: &dyn TestDatabase, _cycle: &salsa::Cycle, key: &i32) -> i32 {
-    log::debug!("recover_a1");
+    tracing::debug!("recover_a1");
     key * 10 + 1
 }
 
 fn recover_a2(_db: &dyn TestDatabase, _cycle: &salsa::Cycle, key: &i32) -> i32 {
-    log::debug!("recover_a2");
+    tracing::debug!("recover_a2");
     key * 10 + 2
 }
 
 fn recover_b1(_db: &dyn TestDatabase, _cycle: &salsa::Cycle, key: &i32) -> i32 {
-    log::debug!("recover_b1");
+    tracing::debug!("recover_b1");
     key * 20 + 1
 }
 
 fn recover_b2(_db: &dyn TestDatabase, _cycle: &salsa::Cycle, key: &i32) -> i32 {
-    log::debug!("recover_b2");
+    tracing::debug!("recover_b2");
     key * 20 + 2
 }
 

tests/parallel/parallel_cycle_mid_recover.rs

@@ -64,12 +64,12 @@ pub(crate) trait TestDatabase: Knobs {
 }
 
 fn recover_b1(_db: &dyn TestDatabase, _cycle: &salsa::Cycle, key: &i32) -> i32 {
-    log::debug!("recover_b1");
+    tracing::debug!("recover_b1");
     key * 20 + 2
 }
 
 fn recover_b3(_db: &dyn TestDatabase, _cycle: &salsa::Cycle, key: &i32) -> i32 {
-    log::debug!("recover_b1");
+    tracing::debug!("recover_b1");
     key * 200 + 2
 }
 

tests/parallel/parallel_cycle_one_recovers.rs

@@ -63,7 +63,7 @@ pub(crate) trait TestDatabase: Knobs {
 }
 
 fn recover(_db: &dyn TestDatabase, _cycle: &salsa::Cycle, key: &i32) -> i32 {
-    log::debug!("recover");
+    tracing::debug!("recover");
     key * 20 + 2
 }
 

tests/parallel/setup.rs

@@ -122,7 +122,7 @@ fn sum(db: &dyn ParDatabase, key: &'static str) -> usize {
     match db.knobs().sum_wait_for_cancellation.get() {
         CancellationFlag::Down => (),
         CancellationFlag::Panic => {
-            log::debug!("waiting for cancellation");
+            tracing::debug!("waiting for cancellation");
             loop {
                 db.unwind_if_cancelled();
                 std::thread::yield_now();

tests/parallel/signal.rs

@@ -8,7 +8,7 @@ pub(crate) struct Signal {
 
 impl Signal {
     pub(crate) fn signal(&self, stage: usize) {
-        log::debug!("signal({})", stage);
+        tracing::debug!("signal({})", stage);
 
         // This check avoids acquiring the lock for things that will
         // clearly be a no-op. Not *necessary* but helps to ensure we
@@ -27,7 +27,7 @@ impl Signal {
     /// Waits until the given condition is true; the fn is invoked
     /// with the current stage.
     pub(crate) fn wait_for(&self, stage: usize) {
-        log::debug!("wait_for({})", stage);
+        tracing::debug!("wait_for({})", stage);
 
         // As above, avoid lock if clearly a no-op.
         if stage > 0 {