Rollup merge of #109956 - compiler-errors:tweak-debug-outputs, r=oli-obk

Tweak debug outputs to make debugging new solver easier

1. Move the fields that are "most important" (I know this is subjective) to the beginning of the structs.

For goals, I typically care more about the predicate than the param-env (which is significantly longer in debug output).
For canonicalized things, I typically care more about what is *being* canonicalized.
For a canonical response, I typically care about the response -- or at least, it's typically useful to put it first since it's short and affects the whether the solver recurses or not...

2. Add some more debug and instrument calls to functions to add more structure to tracing lines.

r? `@oli-obk` or `@BoxyUwU` (since I think `@lcnr` is on holiday)

compiler/rustc_trait_selection/src/solve/assembly.rs

@@ -270,6 +270,7 @@ impl<'tcx> EvalCtxt<'_, 'tcx> {
     /// To deal with this, we first try to normalize the self type and add the candidates for the normalized
     /// self type to the list of candidates in case that succeeds. We also have to consider candidates with the
     /// projection as a self type as well
+    #[instrument(level = "debug", skip_all)]
     fn assemble_candidates_after_normalizing_self_ty<G: GoalKind<'tcx>>(
         &mut self,
         goal: Goal<'tcx, G>,
@@ -315,6 +316,7 @@ impl<'tcx> EvalCtxt<'_, 'tcx> {
         }
     }
 
+    #[instrument(level = "debug", skip_all)]
     fn assemble_impl_candidates<G: GoalKind<'tcx>>(
         &mut self,
         goal: Goal<'tcx, G>,
@@ -333,6 +335,7 @@ impl<'tcx> EvalCtxt<'_, 'tcx> {
         );
     }
 
+    #[instrument(level = "debug", skip_all)]
     fn assemble_builtin_impl_candidates<G: GoalKind<'tcx>>(
         &mut self,
         goal: Goal<'tcx, G>,
@@ -390,6 +393,7 @@ impl<'tcx> EvalCtxt<'_, 'tcx> {
         }
     }
 
+    #[instrument(level = "debug", skip_all)]
     fn assemble_param_env_candidates<G: GoalKind<'tcx>>(
         &mut self,
         goal: Goal<'tcx, G>,
@@ -405,6 +409,7 @@ impl<'tcx> EvalCtxt<'_, 'tcx> {
         }
     }
 
+    #[instrument(level = "debug", skip_all)]
     fn assemble_alias_bound_candidates<G: GoalKind<'tcx>>(
         &mut self,
         goal: Goal<'tcx, G>,
@@ -452,6 +457,7 @@ impl<'tcx> EvalCtxt<'_, 'tcx> {
         }
     }
 
+    #[instrument(level = "debug", skip_all)]
     fn assemble_object_bound_candidates<G: GoalKind<'tcx>>(
         &mut self,
         goal: Goal<'tcx, G>,
@@ -514,6 +520,7 @@ impl<'tcx> EvalCtxt<'_, 'tcx> {
         }
     }
 
+    #[instrument(level = "debug", skip_all)]
     fn assemble_coherence_unknowable_candidates<G: GoalKind<'tcx>>(
         &mut self,
         goal: Goal<'tcx, G>,

compiler/rustc_trait_selection/src/solve/eval_ctxt.rs

@@ -106,7 +106,7 @@ pub trait InferCtxtEvalExt<'tcx> {
 }
 
 impl<'tcx> InferCtxtEvalExt<'tcx> for InferCtxt<'tcx> {
-    #[instrument(level = "debug", skip(self))]
+    #[instrument(level = "debug", skip(self), ret)]
     fn evaluate_root_goal(
         &self,
         goal: Goal<'tcx, ty::Predicate<'tcx>>,
@@ -552,7 +552,7 @@ impl<'tcx> EvalCtxt<'_, 'tcx> {
     ///
     /// If possible, try using `eq` instead which automatically handles nested
     /// goals correctly.
-    #[instrument(level = "debug", skip(self, param_env), ret)]
+    #[instrument(level = "trace", skip(self, param_env), ret)]
     pub(super) fn eq_and_get_goals<T: ToTrace<'tcx>>(
         &self,
         param_env: ty::ParamEnv<'tcx>,

compiler/rustc_trait_selection/src/solve/mod.rs

@@ -153,13 +153,22 @@ impl<'a, 'tcx> EvalCtxt<'a, 'tcx> {
     ) -> QueryResult<'tcx> {
         let tcx = self.tcx();
         // We may need to invert the alias relation direction if dealing an alias on the RHS.
+        #[derive(Debug)]
         enum Invert {
             No,
             Yes,
         }
         let evaluate_normalizes_to =
             |ecx: &mut EvalCtxt<'_, 'tcx>, alias, other, direction, invert| {
-                debug!("evaluate_normalizes_to(alias={:?}, other={:?})", alias, other);
+                let span = tracing::span!(
+                    tracing::Level::DEBUG,
+                    "compute_alias_relate_goal(evaluate_normalizes_to)",
+                    ?alias,
+                    ?other,
+                    ?direction,
+                    ?invert
+                );
+                let _enter = span.enter();
                 let result = ecx.probe(|ecx| {
                     let other = match direction {
                         // This is purely an optimization.
@@ -184,7 +193,7 @@ impl<'a, 'tcx> EvalCtxt<'a, 'tcx> {
                     ));
                     ecx.evaluate_added_goals_and_make_canonical_response(Certainty::Yes)
                 });
-                debug!("evaluate_normalizes_to({alias}, {other}, {direction:?}) -> {result:?}");
+                debug!(?result);
                 result
             };
 
@@ -210,7 +219,7 @@ impl<'a, 'tcx> EvalCtxt<'a, 'tcx> {
             }
 
             (Some(alias_lhs), Some(alias_rhs)) => {
-                debug!("compute_alias_relate_goal: both sides are aliases");
+                debug!("both sides are aliases");
 
                 let candidates = vec![
                     // LHS normalizes-to RHS
@@ -219,9 +228,14 @@ impl<'a, 'tcx> EvalCtxt<'a, 'tcx> {
                     evaluate_normalizes_to(self, alias_rhs, lhs, direction, Invert::Yes),
                     // Relate via substs
                     self.probe(|ecx| {
-                        debug!(
-                            "compute_alias_relate_goal: alias defids are equal, equating substs"
+                        let span = tracing::span!(
+                            tracing::Level::DEBUG,
+                            "compute_alias_relate_goal(relate_via_substs)",
+                            ?alias_lhs,
+                            ?alias_rhs,
+                            ?direction
                         );
+                        let _enter = span.enter();
 
                         match direction {
                             ty::AliasRelationDirection::Equate => {
@@ -275,6 +289,7 @@ impl<'tcx> EvalCtxt<'_, 'tcx> {
         debug!("added_goals={:?}", &self.nested_goals.goals[current_len..]);
     }
 
+    #[instrument(level = "debug", skip(self, responses))]
     fn try_merge_responses(
         &mut self,
         responses: impl Iterator<Item = QueryResult<'tcx>>,
@@ -304,6 +319,7 @@ impl<'tcx> EvalCtxt<'_, 'tcx> {
         });
         // FIXME(-Ztrait-solver=next): We should take the intersection of the constraints on all the
         // responses and use that for the constraints of this ambiguous response.
+        debug!(">1 response, bailing with {certainty:?}");
         let response = self.evaluate_added_goals_and_make_canonical_response(certainty);
         if let Ok(response) = &response {
             assert!(response.has_no_inference_or_external_constraints());

compiler/rustc_trait_selection/src/solve/search_graph/mod.rs

@@ -209,6 +209,7 @@ impl<'tcx> SearchGraph<'tcx> {
     ) -> QueryResult<'tcx> {
         if self.should_use_global_cache() {
             if let Some(result) = tcx.new_solver_evaluation_cache.get(&canonical_goal, tcx) {
+                debug!(?canonical_goal, ?result, "cache hit");
                 return result;
             }
         }