Merge pull request #63 from nikomatsakis/logging

Simple logging methods

src/derived.rs

@@ -10,8 +10,7 @@ use crate::runtime::Revision;
 use crate::runtime::Runtime;
 use crate::runtime::RuntimeId;
 use crate::runtime::StampedValue;
-use crate::Database;
-use crate::SweepStrategy;
+use crate::{Database, Event, EventKind, SweepStrategy};
 use log::{debug, info};
 use parking_lot::Mutex;
 use parking_lot::{RwLock, RwLockUpgradableReadGuard};
@@ -258,7 +257,7 @@ where
         );
 
         // First, do a check with a read-lock.
-        match self.probe(self.map.read(), runtime, revision_now, descriptor, key) {
+        match self.probe(db, self.map.read(), runtime, revision_now, descriptor, key) {
             ProbeState::UpToDate(v) => return v,
             ProbeState::StaleOrAbsent(_guard) => (),
         }
@@ -283,6 +282,7 @@ where
         // already. (This permits other readers but prevents anyone
         // else from running `read_upgrade` at the same time.)
         let mut old_memo = match self.probe(
+            db,
             self.map.upgradable_read(),
             runtime,
             revision_now,
@@ -314,6 +314,13 @@ where
                     key
                 );
 
+                db.salsa_event(|| Event {
+                    runtime_id: runtime.id(),
+                    kind: EventKind::DidValidateMemoizedValue {
+                        descriptor: descriptor.clone(),
+                    },
+                });
+
                 self.overwrite_placeholder(
                     runtime,
                     descriptor,
@@ -322,13 +329,14 @@ where
                     &value,
                     panic_guard,
                 );
+
                 return Ok(value);
             }
         }
 
         // Query was not previously executed, or value is potentially
         // stale, or value is absent. Let's execute!
-        let mut result = runtime.execute_query_implementation(descriptor, || {
+        let mut result = runtime.execute_query_implementation(db, descriptor, || {
             info!("{:?}({:?}): executing query", Q::default(), key);
 
             if !self.should_track_inputs(key) {
@@ -434,6 +442,7 @@ where
     /// `map` will have been released.
     fn probe<MapGuard>(
         &self,
+        db: &DB,
         map: MapGuard,
         runtime: &Runtime<DB>,
         revision_now: Revision,
@@ -454,6 +463,14 @@ where
                         // can complete.
                         std::mem::drop(map);
 
+                        db.salsa_event(|| Event {
+                            runtime_id: db.salsa_runtime().id(),
+                            kind: EventKind::WillBlockOn {
+                                other_runtime_id: other_id,
+                                descriptor: descriptor.clone(),
+                            },
+                        });
+
                         let value = rx.recv().unwrap();
                         ProbeState::UpToDate(Ok(value))
                     }

src/input.rs

@@ -7,6 +7,8 @@ use crate::runtime::ChangedAt;
 use crate::runtime::Revision;
 use crate::runtime::StampedValue;
 use crate::Database;
+use crate::Event;
+use crate::EventKind;
 use crate::Query;
 use crate::SweepStrategy;
 use log::debug;
@@ -60,7 +62,14 @@ where
         panic!("no value set for {:?}({:?})", Q::default(), key)
     }
 
-    fn set_common(&self, db: &DB, key: &Q::Key, value: Q::Value, is_constant: IsConstant) {
+    fn set_common(
+        &self,
+        db: &DB,
+        key: &Q::Key,
+        descriptor: &DB::QueryDescriptor,
+        value: Q::Value,
+        is_constant: IsConstant,
+    ) {
         let key = key.clone();
 
         // The value is changing, so even if we are setting this to a
@@ -74,6 +83,13 @@ where
         db.salsa_runtime().with_incremented_revision(|next_revision| {
             let mut map = self.map.write();
 
+            db.salsa_event(|| Event {
+                runtime_id: db.salsa_runtime().id(),
+                kind: EventKind::WillChangeInputValue {
+                    descriptor: descriptor.clone(),
+                },
+            });
+
             // Do this *after* we acquire the lock, so that we are not
             // racing with somebody else to modify this same cell.
             // (Otherwise, someone else might write a *newer* revision
@@ -190,16 +206,22 @@ where
     Q: Query<DB>,
     DB: Database,
 {
-    fn set(&self, db: &DB, key: &Q::Key, value: Q::Value) {
+    fn set(&self, db: &DB, key: &Q::Key, descriptor: &DB::QueryDescriptor, value: Q::Value) {
         log::debug!("{:?}({:?}) = {:?}", Q::default(), key, value);
 
-        self.set_common(db, key, value, IsConstant(false))
+        self.set_common(db, key, descriptor, value, IsConstant(false))
     }
 
-    fn set_constant(&self, db: &DB, key: &Q::Key, value: Q::Value) {
+    fn set_constant(
+        &self,
+        db: &DB,
+        key: &Q::Key,
+        descriptor: &DB::QueryDescriptor,
+        value: Q::Value,
+    ) {
         log::debug!("{:?}({:?}) = {:?}", Q::default(), key, value);
 
-        self.set_common(db, key, value, IsConstant(true))
+        self.set_common(db, key, descriptor, value, IsConstant(true))
     }
 }
 

src/lib.rs

@@ -17,11 +17,12 @@ use crate::plumbing::QueryStorageMassOps;
 use crate::plumbing::QueryStorageOps;
 use crate::plumbing::UncheckedMutQueryStorageOps;
 use derive_new::new;
-use std::fmt::Debug;
+use std::fmt::{self, Debug};
 use std::hash::Hash;
 
-pub use crate::runtime::Runtime;
 pub use crate::runtime::RevisionGuard;
+pub use crate::runtime::Runtime;
+pub use crate::runtime::RuntimeId;
 
 /// The base trait which your "query context" must implement. Gives
 /// access to the salsa runtime, which you must embed into your query
@@ -62,6 +63,86 @@ pub trait Database: plumbing::DatabaseStorageTypes + plumbing::DatabaseOps {
     {
         <Self as plumbing::GetQueryTable<Q>>::get_query_table(self)
     }
+
+    /// This function is invoked at key points in the salsa
+    /// runtime. It permits the database to be customized and to
+    /// inject logging or other custom behavior.
+    fn salsa_event(&self, event_fn: impl Fn() -> Event<Self>) {
+        #![allow(unused_variables)]
+    }
+}
+
+pub struct Event<DB: Database> {
+    pub runtime_id: RuntimeId,
+    pub kind: EventKind<DB>,
+}
+
+impl<DB: Database> fmt::Debug for Event<DB> {
+    fn fmt(&self, fmt: &mut fmt::Formatter<'_>) -> fmt::Result {
+        fmt.debug_struct("Event")
+            .field("runtime_id", &self.runtime_id)
+            .field("kind", &self.kind)
+            .finish()
+    }
+}
+
+pub enum EventKind<DB: Database> {
+    /// Occurs when we found that all inputs to a memoized value are
+    /// up-to-date and hence the value can be re-used without
+    /// executing the closure.
+    ///
+    /// Executes before the "re-used" value is returned.
+    DidValidateMemoizedValue { descriptor: DB::QueryDescriptor },
+
+    /// Indicates that another thread (with id `other_runtime_id`) is processing the
+    /// given query (`descriptor`), so we will block until they
+    /// finish.
+    ///
+    /// Executes after we have registered with the other thread but
+    /// before they have answered us.
+    ///
+    /// (NB: you can find the `id` of the current thread via the
+    /// `salsa_runtime`)
+    WillBlockOn {
+        other_runtime_id: RuntimeId,
+        descriptor: DB::QueryDescriptor,
+    },
+
+    /// Indicates that the input value will change after this
+    /// callback, e.g. due to a call to `set`.
+    WillChangeInputValue { descriptor: DB::QueryDescriptor },
+
+    /// Indicates that the function for this query will be executed.
+    /// This is either because it has never executed before or because
+    /// its inputs may be out of date.
+    WillExecute { descriptor: DB::QueryDescriptor },
+}
+
+impl<DB: Database> fmt::Debug for EventKind<DB> {
+    fn fmt(&self, fmt: &mut fmt::Formatter<'_>) -> fmt::Result {
+        match self {
+            EventKind::DidValidateMemoizedValue { descriptor } => fmt
+                .debug_struct("DidValidateMemoizedValue")
+                .field("descriptor", descriptor)
+                .finish(),
+            EventKind::WillBlockOn {
+                other_runtime_id,
+                descriptor,
+            } => fmt
+                .debug_struct("WillBlockOn")
+                .field("other_runtime_id", other_runtime_id)
+                .field("descriptor", descriptor)
+                .finish(),
+            EventKind::WillChangeInputValue { descriptor } => fmt
+                .debug_struct("WillChangeInputValue")
+                .field("descriptor", descriptor)
+                .finish(),
+            EventKind::WillExecute { descriptor } => fmt
+                .debug_struct("WillExecute")
+                .field("descriptor", descriptor)
+                .finish(),
+        }
+    }
 }
 
 /// The sweep strategy controls what data we will keep/discard when we
@@ -149,7 +230,8 @@ where
     where
         Q::Storage: plumbing::InputQueryStorageOps<DB, Q>,
     {
-        self.storage.set(self.db, &key, value);
+        self.storage
+            .set(self.db, &key, &self.descriptor(&key), value);
     }
 
     /// Assign a value to an "input query", with the additional
@@ -159,7 +241,8 @@ where
     where
         Q::Storage: plumbing::InputQueryStorageOps<DB, Q>,
     {
-        self.storage.set_constant(self.db, &key, value);
+        self.storage
+            .set_constant(self.db, &key, &self.descriptor(&key), value);
     }
 
     /// Assigns a value to the query **bypassing the normal

src/plumbing.rs

@@ -121,9 +121,15 @@ where
     DB: Database,
     Q: Query<DB>,
 {
-    fn set(&self, db: &DB, key: &Q::Key, new_value: Q::Value);
+    fn set(&self, db: &DB, key: &Q::Key, descriptor: &DB::QueryDescriptor, new_value: Q::Value);
 
-    fn set_constant(&self, db: &DB, key: &Q::Key, new_value: Q::Value);
+    fn set_constant(
+        &self,
+        db: &DB,
+        key: &Q::Key,
+        descriptor: &DB::QueryDescriptor,
+        new_value: Q::Value,
+    );
 }
 
 /// An optional trait that is implemented for "user mutable" storage:

src/runtime.rs

@@ -1,4 +1,4 @@
-use crate::{Database, SweepStrategy};
+use crate::{Database, Event, EventKind, SweepStrategy};
 use lock_api::RawRwLock;
 use log::debug;
 use parking_lot::{Mutex, RwLock, RwLockReadGuard};
@@ -147,11 +147,23 @@ where
         RevisionGuard::new(&self.shared_state)
     }
 
+    /// The unique identifier attached to this `SalsaRuntime`. Each
+    /// forked runtime has a distinct identifier.
     #[inline]
-    pub(crate) fn id(&self) -> RuntimeId {
+    pub fn id(&self) -> RuntimeId {
         self.id
     }
 
+    /// Returns the descriptor for the query that this thread is
+    /// actively executing (if any).
+    pub fn active_query(&self) -> Option<DB::QueryDescriptor> {
+        self.local_state
+            .borrow()
+            .query_stack
+            .last()
+            .map(|active_query| active_query.descriptor.clone())
+    }
+
     /// Read current value of the revision counter.
     #[inline]
     pub(crate) fn current_revision(&self) -> Revision {
@@ -239,11 +251,19 @@ where
 
     pub(crate) fn execute_query_implementation<V>(
         &self,
+        db: &DB,
         descriptor: &DB::QueryDescriptor,
         execute: impl FnOnce() -> V,
     ) -> ComputedQueryResult<DB, V> {
         debug!("{:?}: execute_query_implementation invoked", descriptor);
 
+        db.salsa_event(|| Event {
+            runtime_id: db.salsa_runtime().id(),
+            kind: EventKind::WillExecute {
+                descriptor: descriptor.clone(),
+            },
+        });
+
         // Push the active query onto the stack.
         let push_len = {
             let mut local_state = self.local_state.borrow_mut();
@@ -524,7 +544,7 @@ impl<DB: Database> ActiveQuery<DB> {
 }
 
 #[derive(Copy, Clone, Debug, PartialEq, Eq, Hash, PartialOrd, Ord)]
-pub(crate) struct RuntimeId {
+pub struct RuntimeId {
     counter: usize,
 }
 

tests/parallel/setup.rs

@@ -56,6 +56,9 @@ pub(crate) struct KnobsStruct {
     /// threads to ensure we reach various weird states.
     pub(crate) signal: Arc<Signal>,
 
+    /// When this database is about to block, send a signal.
+    pub(crate) signal_on_will_block: Cell<usize>,
+
     /// Invocations of `sum` will signal this stage on entry.
     pub(crate) sum_signal_on_entry: Cell<usize>,
 
@@ -114,6 +117,17 @@ impl Database for ParDatabaseImpl {
     fn salsa_runtime(&self) -> &salsa::Runtime<ParDatabaseImpl> {
         &self.runtime
     }
+
+    fn salsa_event(&self, event_fn: impl Fn() -> salsa::Event<Self>) {
+        let event = event_fn();
+        match event.kind {
+            salsa::EventKind::WillBlockOn { .. } => {
+                self.signal(self.knobs().signal_on_will_block.get());
+            }
+
+            _ => {}
+        }
+    }
 }
 
 impl ParallelDatabase for ParDatabaseImpl {

tests/parallel/true_parallel.rs

@@ -66,13 +66,15 @@ fn true_parallel_same_keys() {
         }
     });
 
-    // Thread 2 will sync barrier *just* before calling `sum`. Doesn't
-    // guarantee the race we want but makes it highly likely.
+    // Thread 2 will wait until Thread 1 has entered sum and then --
+    // once it has set itself to block -- signal Thread 1 to
+    // continue. This way, we test out the mechanism of one thread
+    // blocking on another.
     let thread2 = std::thread::spawn({
         let db = db.fork();
         move || {
             db.knobs().signal.wait_for(1);
-            db.knobs().signal.signal(2);
+            db.knobs().signal_on_will_block.set(2);
             db.sum("abc")
         }
     });