add tracing

4 files changed, 96 insertions, 17 deletions

diff --git a/incria/Cargo.lock b/incria/Cargo.lock
index 9a19675..3bd4965 100644
--- a/incria/Cargo.lock
+++ b/incria/Cargo.lock
@@ -298,6 +298,7 @@ dependencies = [
  "blink-alloc",
  "criterion",
  "tokio",
+ "tracing",
 ]
 
 [[package]]
@@ -645,6 +646,38 @@ dependencies = [
 ]
 
 [[package]]
+name = "tracing"
+version = "0.1.37"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8ce8c33a8d48bd45d624a6e523445fd21ec13d3653cd51f681abf67418f54eb8"
+dependencies = [
+ "cfg-if",
+ "pin-project-lite",
+ "tracing-attributes",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-attributes"
+version = "0.1.24"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "0f57e3ca2a01450b1a921183a9c9cbfda207fd822cef4ccb00a65402cbba7a74"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
+[[package]]
+name = "tracing-core"
+version = "0.1.31"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "0955b8137a1df6f1a2e9a37d8a6656291ff0297c1a97c24e0d8425fe2312f79a"
+dependencies = [
+ "once_cell",
+]
+
+[[package]]
 name = "unicode-ident"
 version = "1.0.8"
 source = "registry+https://github.com/rust-lang/crates.io-index"
diff --git a/incria/Cargo.toml b/incria/Cargo.toml
index 55e6cdf..db0df01 100644
--- a/incria/Cargo.toml
+++ b/incria/Cargo.toml
@@ -6,6 +6,7 @@ edition = "2021"
 [dependencies]
 blink-alloc = { version = "0.3.0", features = ["sync"] }
 tokio = { version = "1.28.1", features = ["sync", "rt"] }
+tracing = { version = "0.1" }
 
 [dev-dependencies]
 tokio = { version = "1.28.1", features = ["macros", "sync", "rt-multi-thread"] }
diff --git a/incria/src/deps.rs b/incria/src/deps.rs
index 924eb3f..f2fd8f8 100644
--- a/incria/src/deps.rs
+++ b/incria/src/deps.rs
@@ -18,6 +18,8 @@ use std::{
     thread,
 };
 
+use tracing::instrument;
+
 /// Identifier of a node, unique across a program run.
 pub type NodeId = u64;
 
@@ -40,6 +42,7 @@ struct DepTracker {
 
 impl DepTracker {
     /// See [`self::add_dep`]
+    #[instrument(level = "trace", skip(self))]
     fn add_dep(&self, dep: NodeId) {
         self.deps
             .lock()
@@ -65,6 +68,7 @@ impl DepTracker {
     }
 
     /// See [`self::mark_dirty`]
+    #[instrument(level = "trace", skip(self))]
     fn mark_dirty(&self, node: NodeId) {
         let mut lock = self.deps.lock().unwrap();
         let mut frontier = VecDeque::new();
@@ -87,6 +91,7 @@ impl DepTracker {
     }
 
     /// See [`self::is_dirty`]
+    #[instrument(level = "trace", skip(self))]
     fn is_dirty(&self, node: NodeId) -> bool {
         self.deps
             .lock()
@@ -97,6 +102,7 @@ impl DepTracker {
     }
 
     /// See [`self::clear`]
+    #[instrument(level = "trace", skip(self))]
     fn clear(&self, node: NodeId) {
         let mut lock = self.deps.lock().unwrap();
         let node = match lock.get_mut(&node) {
diff --git a/incria/src/lazy_mapping.rs b/incria/src/lazy_mapping.rs
index 27bd76e..f206bdd 100644
--- a/incria/src/lazy_mapping.rs
+++ b/incria/src/lazy_mapping.rs
@@ -1,9 +1,11 @@
 use std::{
-    collections::HashMap, fmt::Debug, future::Future, hash::Hash, mem::transmute, sync::Arc,
+    any::type_name, collections::HashMap, fmt::Debug, future::Future, hash::Hash, mem::transmute,
+    sync::Arc,
 };
 
 use blink_alloc::{Blink, SyncBlinkAlloc};
 use tokio::sync::{Mutex, Notify, RwLock, RwLockReadGuard};
+use tracing::{debug_span, instrument, trace_span, Instrument};
 
 use crate::{
     deps::{self, NodeId},
@@ -56,7 +58,7 @@ impl<K: Clone + Eq + Hash + Send + Sync, V: Send + Sync, B: LazyMappingBackend<K
 
 impl<K, V, B> Mapper for LazyMapper<K, V, B>
 where
-    K: Clone + Eq + Hash + Send + Sync + Debug,
+    K: Clone + Eq + Hash + Send + Sync,
     V: Send + Sync + 'static,
     B: LazyMappingBackend<K, V>,
 {
@@ -64,35 +66,64 @@ where
     type Value = V;
     type Wrapper<'a> = &'a V where V: 'a;
 
+    #[instrument(level = "debug", skip_all, fields(key_type = type_name::<K>(), value_type = type_name::<V>()))]
     async fn get<'a>(&'a self, key: &Self::Key) -> Self::Wrapper<'a> {
         // Attempt to reuse or evict the existing value
         let mut reuse_dep_id = None;
         {
-            let finished = self.calculated.read().await;
-            if let Some((val, node)) = finished.get(key) {
-                let dirty = deps::is_dirty(*node) || self.backend.is_dirty(key).await;
+            let finished = self
+                .calculated
+                .read()
+                .instrument(trace_span!("calculated.read"))
+                .await;
+            if let Some((val, node)) = finished.get(key).copied() {
+                drop(finished);
+
+                let dirty = deps::is_dirty(node)
+                    || self
+                        .backend
+                        .is_dirty(key)
+                        .instrument(trace_span!("backend.is_dirty"))
+                        .await;
                 if !dirty {
-                    deps::add_dep(*node);
+                    deps::add_dep(node);
                     return val;
                 } else {
-                    reuse_dep_id = Some(*node);
-                    drop(finished);
+                    reuse_dep_id = Some(node);
                     // Dirty, so we'll recompute below but we should remove it now
-                    if self.calculated.write().await.remove(key).is_none() {
+                    let removed = async { self.calculated.write().await.remove(key).is_none() }
+                        .instrument(trace_span!("remove dirty value"))
+                        .await;
+                    if removed {
                         // Someone else already noticed it was dirty and removed it before us, so we need to deal with that
                         todo!("dirty value removed between us noticing and us doing something")
                     }
                 }
             }
-        }
+        };
+
+        let barrier = self
+            .waiting
+            .lock()
+            .instrument(trace_span!("waiting.lock"))
+            .await
+            .get(key)
+            .cloned();
 
-        let barrier = self.waiting.lock().await.get(key).cloned();
         if let Some(barrier) = barrier {
             // Waiting for completion
-            barrier.notified().await;
-
-            let (value, node_id) =
-                *RwLockReadGuard::map(self.calculated.read().await, |hm| hm.get(key).unwrap());
+            barrier
+                .notified()
+                .instrument(trace_span!("completion_wait"))
+                .await;
+
+            let (value, node_id) = *RwLockReadGuard::map(
+                self.calculated
+                    .read()
+                    .instrument(trace_span!("calculated.read"))
+                    .await,
+                |hm| hm.get(key).unwrap(),
+            );
 
             deps::add_dep(node_id);
 
@@ -102,6 +133,7 @@ where
             let notify = Arc::new(Notify::new());
             self.waiting
                 .lock()
+                .instrument(trace_span!("waiting.insert"))
                 .await
                 .insert(key.clone(), notify.clone());
 
@@ -112,15 +144,22 @@ where
                 deps::next_node_id()
             };
 
-            let val = deps::with_node_id(dep, self.backend.compute(key.clone())).await;
+            let val = deps::with_node_id(dep, self.backend.compute(key.clone()))
+                .instrument(debug_span!("backend.compute"))
+                .await;
             let val_ref: &'static V = unsafe { transmute(Blink::new_in(&self.values).put(val)) };
             deps::add_dep(dep);
 
             self.calculated
                 .write()
+                .instrument(trace_span!("calculated.insert"))
                 .await
                 .insert(key.clone(), (val_ref, dep));
-            self.waiting.lock().await.remove(key);
+            self.waiting
+                .lock()
+                .instrument(trace_span!("waiting.remove"))
+                .await
+                .remove(key);
 
             notify.notify_waiters();