Improve tracing logging

Author: Noratrieb

compiler/rustc_query_system/src/dep_graph/graph.rs

@@ -598,6 +598,7 @@ impl<K: DepKind> DepGraph<K> {
         }
     }
 
+    #[instrument(skip(self, tcx, data, parent_dep_node_index), level = "debug")]
     fn try_mark_parent_green<Ctxt: QueryContext<DepKind = K>>(
         &self,
         tcx: Ctxt,
@@ -613,22 +614,15 @@ impl<K: DepKind> DepGraph<K> {
                 // This dependency has been marked as green before, we are
                 // still fine and can continue with checking the other
                 // dependencies.
-                debug!(
-                    "try_mark_previous_green({:?}) --- found dependency {:?} to \
-                            be immediately green",
-                    dep_node, dep_dep_node,
-                );
+                debug!("dependency {dep_dep_node:?} was immediately green");
                 return Some(());
             }
             Some(DepNodeColor::Red) => {
                 // We found a dependency the value of which has changed
                 // compared to the previous compilation session. We cannot
                 // mark the DepNode as green and also don't need to bother
                 // with checking any of the other dependencies.
-                debug!(
-                    "try_mark_previous_green({:?}) - END - dependency {:?} was immediately red",
-                    dep_node, dep_dep_node,
-                );
+                debug!("dependency {dep_dep_node:?} was immediately red");
                 return None;
             }
             None => {}
@@ -638,51 +632,36 @@ impl<K: DepKind> DepGraph<K> {
         // an eval_always node, let's try to mark it green recursively.
         if !tcx.dep_context().is_eval_always(dep_dep_node.kind) {
             debug!(
-                "try_mark_previous_green({:?}) --- state of dependency {:?} ({}) \
-                                 is unknown, trying to mark it green",
-                dep_node, dep_dep_node, dep_dep_node.hash,
+                "state of dependency {:?} ({}) is unknown, trying to mark it green",
+                dep_dep_node, dep_dep_node.hash,
             );
 
             let node_index =
                 self.try_mark_previous_green(tcx, data, parent_dep_node_index, dep_dep_node);
+
             if node_index.is_some() {
-                debug!(
-                    "try_mark_previous_green({:?}) --- managed to MARK dependency {:?} as green",
-                    dep_node, dep_dep_node
-                );
+                debug!("managed to MARK dependency {dep_dep_node:?} as green",);
                 return Some(());
             }
         }
 
         // We failed to mark it green, so we try to force the query.
-        debug!(
-            "try_mark_previous_green({:?}) --- trying to force dependency {:?}",
-            dep_node, dep_dep_node
-        );
+        debug!("trying to force dependency {dep_dep_node:?}");
         if !tcx.dep_context().try_force_from_dep_node(*dep_dep_node) {
             // The DepNode could not be forced.
-            debug!(
-                "try_mark_previous_green({:?}) - END - dependency {:?} could not be forced",
-                dep_node, dep_dep_node
-            );
+            debug!("dependency {dep_dep_node:?} could not be forced");
             return None;
         }
 
         let dep_dep_node_color = data.colors.get(parent_dep_node_index);
 
         match dep_dep_node_color {
             Some(DepNodeColor::Green(_)) => {
-                debug!(
-                    "try_mark_previous_green({:?}) --- managed to FORCE dependency {:?} to green",
-                    dep_node, dep_dep_node
-                );
+                debug!("managed to FORCE dependency {dep_dep_node:?} to green");
                 return Some(());
             }
             Some(DepNodeColor::Red) => {
-                debug!(
-                    "try_mark_previous_green({:?}) - END - dependency {:?} was red after forcing",
-                    dep_node, dep_dep_node
-                );
+                debug!("dependency {dep_dep_node:?} was red after forcing",);
                 return None;
             }
             None => {}
@@ -702,23 +681,19 @@ impl<K: DepKind> DepGraph<K> {
         // invalid state will not be persisted to the
         // incremental compilation cache because of
         // compilation errors being present.
-        debug!(
-            "try_mark_previous_green({:?}) - END - dependency {:?} resulted in compilation error",
-            dep_node, dep_dep_node
-        );
+        debug!("dependency {dep_dep_node:?} resulted in compilation error",);
         return None;
     }
 
     /// Try to mark a dep-node which existed in the previous compilation session as green.
+    #[instrument(skip(self, tcx, data, prev_dep_node_index), level = "debug")]
     fn try_mark_previous_green<Ctxt: QueryContext<DepKind = K>>(
         &self,
         tcx: Ctxt,
         data: &DepGraphData<K>,
         prev_dep_node_index: SerializedDepNodeIndex,
         dep_node: &DepNode<K>,
     ) -> Option<DepNodeIndex> {
-        debug!("try_mark_previous_green({:?}) - BEGIN", dep_node);
-
         #[cfg(not(parallel_compiler))]
         {
             debug_assert!(!self.dep_node_exists(dep_node));
@@ -772,7 +747,7 @@ impl<K: DepKind> DepGraph<K> {
         // Multiple threads can all write the same color here
         data.colors.insert(prev_dep_node_index, DepNodeColor::Green(dep_node_index));
 
-        debug!("try_mark_previous_green({:?}) - END - successfully marked as green", dep_node);
+        debug!("successfully marked {dep_node:?} as green");
         Some(dep_node_index)
     }
 

compiler/rustc_query_system/src/dep_graph/mod.rs

@@ -52,9 +52,8 @@ pub trait DepContext: Copy {
     }
 
     /// Try to force a dep node to execute and see if it's green.
+    #[instrument(skip(self), level = "debug")]
     fn try_force_from_dep_node(self, dep_node: DepNode<Self::DepKind>) -> bool {
-        debug!("try_force_from_dep_node({:?}) --- trying to force", dep_node);
-
         let cb = self.dep_kind_info(dep_node.kind);
         if let Some(f) = cb.force_from_dep_node {
             f(self, dep_node);

compiler/rustc_query_system/src/query/plumbing.rs

@@ -563,6 +563,7 @@ where
     Some((result, dep_node_index))
 }
 
+#[instrument(skip(tcx, result, query), level = "debug")]
 fn incremental_verify_ich<CTX, K, V: Debug>(
     tcx: CTX::DepContext,
     result: &V,
@@ -577,12 +578,11 @@ fn incremental_verify_ich<CTX, K, V: Debug>(
         dep_node,
     );
 
-    debug!("BEGIN verify_ich({:?})", dep_node);
     let new_hash = query.hash_result.map_or(Fingerprint::ZERO, |f| {
         tcx.with_stable_hashing_context(|mut hcx| f(&mut hcx, result))
     });
+
     let old_hash = tcx.dep_graph().prev_fingerprint_of(dep_node);
-    debug!("END verify_ich({:?})", dep_node);
 
     if Some(new_hash) != old_hash {
         incremental_verify_ich_failed(