Auto merge of #89048 - oli-obk:in_tracing_we_trust, r=jackh726

Add more tracing instrumentation

I changed or added all this while working on a branch and pulled it out so we can merge it on its own.

Author: bors

Diff for: compiler/rustc_borrowck/src/diagnostics/bound_region_errors.rs

@@ -327,6 +327,7 @@ impl TypeOpInfo<'tcx> for AscribeUserTypeQuery<'tcx> {
     }
 }
 
+#[instrument(skip(fulfill_cx, infcx), level = "debug")]
 fn try_extract_error_from_fulfill_cx<'tcx>(
     mut fulfill_cx: Box<dyn TraitEngine<'tcx> + 'tcx>,
     infcx: &InferCtxt<'_, 'tcx>,
@@ -341,7 +342,7 @@ fn try_extract_error_from_fulfill_cx<'tcx>(
     let _errors = fulfill_cx.select_all_or_error(infcx).err().unwrap_or_else(Vec::new);
 
     let (sub_region, cause) = infcx.with_region_constraints(|region_constraints| {
-        debug!(?region_constraints);
+        debug!("{:#?}", region_constraints);
         region_constraints.constraints.iter().find_map(|(constraint, cause)| {
             match *constraint {
                 Constraint::RegSubReg(sub, sup) if sup == placeholder_region && sup != sub => {
@@ -356,7 +357,7 @@ fn try_extract_error_from_fulfill_cx<'tcx>(
         })
     })?;
 
-    debug!(?sub_region, ?cause);
+    debug!(?sub_region, "cause = {:#?}", cause);
     let nice_error = match (error_region, sub_region) {
         (Some(error_region), &ty::ReVar(vid)) => NiceRegionError::new(
             infcx,

Diff for: compiler/rustc_borrowck/src/lib.rs

@@ -144,6 +144,7 @@ fn mir_borrowck<'tcx>(
 /// If `return_body_with_facts` is true, then return the body with non-erased
 /// region ids on which the borrow checking was performed together with Polonius
 /// facts.
+#[instrument(skip(infcx, input_body, input_promoted), level = "debug")]
 fn do_mir_borrowck<'a, 'tcx>(
     infcx: &InferCtxt<'a, 'tcx>,
     input_body: &Body<'tcx>,
@@ -152,7 +153,7 @@ fn do_mir_borrowck<'a, 'tcx>(
 ) -> (BorrowCheckResult<'tcx>, Option<Box<BodyWithBorrowckFacts<'tcx>>>) {
     let def = input_body.source.with_opt_param().as_local().unwrap();
 
-    debug!("do_mir_borrowck(def = {:?})", def);
+    debug!(?def);
 
     let tcx = infcx.tcx;
     let param_env = tcx.param_env(def.did);

Diff for: compiler/rustc_borrowck/src/nll.rs

@@ -54,6 +54,7 @@ crate struct NllOutput<'tcx> {
 /// Rewrites the regions in the MIR to use NLL variables, also scraping out the set of universal
 /// regions (e.g., region parameters) declared on the function. That set will need to be given to
 /// `compute_regions`.
+#[instrument(skip(infcx, param_env, body, promoted), level = "debug")]
 pub(crate) fn replace_regions_in_mir<'cx, 'tcx>(
     infcx: &InferCtxt<'cx, 'tcx>,
     param_env: ty::ParamEnv<'tcx>,
@@ -62,7 +63,7 @@ pub(crate) fn replace_regions_in_mir<'cx, 'tcx>(
 ) -> UniversalRegions<'tcx> {
     let def = body.source.with_opt_param().as_local().unwrap();
 
-    debug!("replace_regions_in_mir(def={:?})", def);
+    debug!(?def);
 
     // Compute named region information. This also renumbers the inputs/outputs.
     let universal_regions = UniversalRegions::new(infcx, def, param_env);

Diff for: compiler/rustc_borrowck/src/region_infer/mod.rs

@@ -552,6 +552,7 @@ impl<'tcx> RegionInferenceContext<'tcx> {
     /// Performs region inference and report errors if we see any
     /// unsatisfiable constraints. If this is a closure, returns the
     /// region requirements to propagate to our creator, if any.
+    #[instrument(skip(self, infcx, body, polonius_output), level = "debug")]
     pub(super) fn solve(
         &mut self,
         infcx: &InferCtxt<'_, 'tcx>,
@@ -607,10 +608,9 @@ impl<'tcx> RegionInferenceContext<'tcx> {
     /// for each region variable until all the constraints are
     /// satisfied. Note that some values may grow **too** large to be
     /// feasible, but we check this later.
+    #[instrument(skip(self, _body), level = "debug")]
     fn propagate_constraints(&mut self, _body: &Body<'tcx>) {
-        debug!("propagate_constraints()");
-
-        debug!("propagate_constraints: constraints={:#?}", {
+        debug!("constraints={:#?}", {
             let mut constraints: Vec<_> = self.constraints.outlives().iter().collect();
             constraints.sort();
             constraints
@@ -637,12 +637,13 @@ impl<'tcx> RegionInferenceContext<'tcx> {
     /// computed, by unioning the values of its successors.
     /// Assumes that all successors have been computed already
     /// (which is assured by iterating over SCCs in dependency order).
+    #[instrument(skip(self), level = "debug")]
     fn compute_value_for_scc(&mut self, scc_a: ConstraintSccIndex) {
         let constraint_sccs = self.constraint_sccs.clone();
 
         // Walk each SCC `B` such that `A: B`...
         for &scc_b in constraint_sccs.successors(scc_a) {
-            debug!("propagate_constraint_sccs: scc_a = {:?} scc_b = {:?}", scc_a, scc_b);
+            debug!(?scc_b);
 
             // ...and add elements from `B` into `A`. One complication
             // arises because of universes: If `B` contains something
@@ -663,11 +664,7 @@ impl<'tcx> RegionInferenceContext<'tcx> {
             self.apply_member_constraint(scc_a, m_c_i, member_constraints.choice_regions(m_c_i));
         }
 
-        debug!(
-            "propagate_constraint_sccs: scc_a = {:?} has value {:?}",
-            scc_a,
-            self.scc_values.region_value_str(scc_a),
-        );
+        debug!(value = ?self.scc_values.region_value_str(scc_a));
     }
 
     /// Invoked for each `R0 member of [R1..Rn]` constraint.
@@ -681,14 +678,13 @@ impl<'tcx> RegionInferenceContext<'tcx> {
     /// is considered a *lower bound*.  If possible, we will modify
     /// the constraint to set it equal to one of the option regions.
     /// If we make any changes, returns true, else false.
+    #[instrument(skip(self, member_constraint_index), level = "debug")]
     fn apply_member_constraint(
         &mut self,
         scc: ConstraintSccIndex,
         member_constraint_index: NllMemberConstraintIndex,
         choice_regions: &[ty::RegionVid],
     ) -> bool {
-        debug!("apply_member_constraint(scc={:?}, choice_regions={:#?})", scc, choice_regions,);
-
         // Create a mutable vector of the options. We'll try to winnow
         // them down.
         let mut choice_regions: Vec<ty::RegionVid> = choice_regions.to_vec();
@@ -714,7 +710,7 @@ impl<'tcx> RegionInferenceContext<'tcx> {
                 .universal_regions_outlived_by(scc)
                 .all(|lb| self.universal_region_relations.outlives(o_r, lb))
         });
-        debug!("apply_member_constraint: after lb, choice_regions={:?}", choice_regions);
+        debug!(?choice_regions, "after lb");
 
         // Now find all the *upper bounds* -- that is, each UB is a
         // free region that must outlive the member region `R0` (`UB:
@@ -723,10 +719,10 @@ impl<'tcx> RegionInferenceContext<'tcx> {
         let rev_scc_graph = self.reverse_scc_graph();
         let universal_region_relations = &self.universal_region_relations;
         for ub in rev_scc_graph.upper_bounds(scc) {
-            debug!("apply_member_constraint: ub={:?}", ub);
+            debug!(?ub);
             choice_regions.retain(|&o_r| universal_region_relations.outlives(ub, o_r));
         }
-        debug!("apply_member_constraint: after ub, choice_regions={:?}", choice_regions);
+        debug!(?choice_regions, "after ub");
 
         // If we ruled everything out, we're done.
         if choice_regions.is_empty() {
@@ -735,7 +731,7 @@ impl<'tcx> RegionInferenceContext<'tcx> {
 
         // Otherwise, we need to find the minimum remaining choice, if
         // any, and take that.
-        debug!("apply_member_constraint: choice_regions remaining are {:#?}", choice_regions);
+        debug!("choice_regions remaining are {:#?}", choice_regions);
         let min = |r1: ty::RegionVid, r2: ty::RegionVid| -> Option<ty::RegionVid> {
             let r1_outlives_r2 = self.universal_region_relations.outlives(r1, r2);
             let r2_outlives_r1 = self.universal_region_relations.outlives(r2, r1);
@@ -748,27 +744,18 @@ impl<'tcx> RegionInferenceContext<'tcx> {
         };
         let mut min_choice = choice_regions[0];
         for &other_option in &choice_regions[1..] {
-            debug!(
-                "apply_member_constraint: min_choice={:?} other_option={:?}",
-                min_choice, other_option,
-            );
+            debug!(?min_choice, ?other_option,);
             match min(min_choice, other_option) {
                 Some(m) => min_choice = m,
                 None => {
-                    debug!(
-                        "apply_member_constraint: {:?} and {:?} are incomparable; no min choice",
-                        min_choice, other_option,
-                    );
+                    debug!(?min_choice, ?other_option, "incomparable; no min choice",);
                     return false;
                 }
             }
         }
 
         let min_choice_scc = self.constraint_sccs.scc(min_choice);
-        debug!(
-            "apply_member_constraint: min_choice={:?} best_choice_scc={:?}",
-            min_choice, min_choice_scc,
-        );
+        debug!(?min_choice, ?min_choice_scc);
         if self.scc_values.add_region(scc, min_choice_scc) {
             self.member_constraints_applied.push(AppliedMemberConstraint {
                 member_region_scc: scc,
@@ -1091,8 +1078,9 @@ impl<'tcx> RegionInferenceContext<'tcx> {
     ///   include the CFG anyhow.
     /// - For each `end('x)` element in `'r`, compute the mutual LUB, yielding
     ///   a result `'y`.
+    #[instrument(skip(self), level = "debug")]
     pub(crate) fn universal_upper_bound(&self, r: RegionVid) -> RegionVid {
-        debug!("universal_upper_bound(r={:?}={})", r, self.region_value_str(r));
+        debug!(r = %self.region_value_str(r));
 
         // Find the smallest universal region that contains all other
         // universal regions within `region`.
@@ -1102,7 +1090,7 @@ impl<'tcx> RegionInferenceContext<'tcx> {
             lub = self.universal_region_relations.postdom_upper_bound(lub, ur);
         }
 
-        debug!("universal_upper_bound: r={:?} lub={:?}", r, lub);
+        debug!(?lub);
 
         lub
     }
@@ -1262,9 +1250,8 @@ impl<'tcx> RegionInferenceContext<'tcx> {
     }
 
     // Evaluate whether `sup_region: sub_region`.
+    #[instrument(skip(self), level = "debug")]
     fn eval_outlives(&self, sup_region: RegionVid, sub_region: RegionVid) -> bool {
-        debug!("eval_outlives({:?}: {:?})", sup_region, sub_region);
-
         debug!(
             "eval_outlives: sup_region's value = {:?} universal={:?}",
             self.region_value_str(sup_region),
@@ -1467,15 +1454,17 @@ impl<'tcx> RegionInferenceContext<'tcx> {
     ///
     /// Things that are to be propagated are accumulated into the
     /// `outlives_requirements` vector.
+    #[instrument(
+        skip(self, body, propagated_outlives_requirements, errors_buffer),
+        level = "debug"
+    )]
     fn check_universal_region(
         &self,
         body: &Body<'tcx>,
         longer_fr: RegionVid,
         propagated_outlives_requirements: &mut Option<&mut Vec<ClosureOutlivesRequirement<'tcx>>>,
         errors_buffer: &mut RegionErrors<'tcx>,
     ) {
-        debug!("check_universal_region(fr={:?})", longer_fr);
-
         let longer_fr_scc = self.constraint_sccs.scc(longer_fr);
 
         // Because this free region must be in the ROOT universe, we
@@ -1880,21 +1869,13 @@ impl<'tcx> RegionInferenceContext<'tcx> {
     }
 
     /// Finds some region R such that `fr1: R` and `R` is live at `elem`.
+    #[instrument(skip(self), level = "trace")]
     crate fn find_sub_region_live_at(&self, fr1: RegionVid, elem: Location) -> RegionVid {
-        debug!("find_sub_region_live_at(fr1={:?}, elem={:?})", fr1, elem);
-        debug!("find_sub_region_live_at: {:?} is in scc {:?}", fr1, self.constraint_sccs.scc(fr1));
-        debug!(
-            "find_sub_region_live_at: {:?} is in universe {:?}",
-            fr1,
-            self.scc_universes[self.constraint_sccs.scc(fr1)]
-        );
+        trace!(scc = ?self.constraint_sccs.scc(fr1));
+        trace!(universe = ?self.scc_universes[self.constraint_sccs.scc(fr1)]);
         self.find_constraint_paths_between_regions(fr1, |r| {
             // First look for some `r` such that `fr1: r` and `r` is live at `elem`
-            debug!(
-                "find_sub_region_live_at: liveness_constraints for {:?} are {:?}",
-                r,
-                self.liveness_constraints.region_value_str(r),
-            );
+            trace!(?r, liveness_constraints=?self.liveness_constraints.region_value_str(r));
             self.liveness_constraints.contains(r, elem)
         })
         .or_else(|| {

Diff for: compiler/rustc_borrowck/src/renumber.rs

@@ -7,13 +7,13 @@ use rustc_middle::ty::{self, Ty, TyCtxt, TypeFoldable};
 
 /// Replaces all free regions appearing in the MIR with fresh
 /// inference variables, returning the number of variables created.
+#[instrument(skip(infcx, body, promoted), level = "debug")]
 pub fn renumber_mir<'tcx>(
     infcx: &InferCtxt<'_, 'tcx>,
     body: &mut Body<'tcx>,
     promoted: &mut IndexVec<Promoted, Body<'tcx>>,
 ) {
-    debug!("renumber_mir()");
-    debug!("renumber_mir: body.arg_count={:?}", body.arg_count);
+    debug!(?body.arg_count);
 
     let mut visitor = NllVisitor { infcx };
 
@@ -26,12 +26,11 @@ pub fn renumber_mir<'tcx>(
 
 /// Replaces all regions appearing in `value` with fresh inference
 /// variables.
+#[instrument(skip(infcx), level = "debug")]
 pub fn renumber_regions<'tcx, T>(infcx: &InferCtxt<'_, 'tcx>, value: T) -> T
 where
     T: TypeFoldable<'tcx>,
 {
-    debug!("renumber_regions(value={:?})", value);
-
     infcx.tcx.fold_regions(value, &mut false, |_region, _depth| {
         let origin = NllRegionVariableOrigin::Existential { from_forall: false };
         infcx.next_nll_region_var(origin)
@@ -56,12 +55,11 @@ impl<'a, 'tcx> MutVisitor<'tcx> for NllVisitor<'a, 'tcx> {
         self.infcx.tcx
     }
 
+    #[instrument(skip(self), level = "debug")]
     fn visit_ty(&mut self, ty: &mut Ty<'tcx>, ty_context: TyContext) {
-        debug!("visit_ty(ty={:?}, ty_context={:?})", ty, ty_context);
-
         *ty = self.renumber_regions(ty);
 
-        debug!("visit_ty: ty={:?}", ty);
+        debug!(?ty);
     }
 
     fn process_projection_elem(
@@ -80,21 +78,19 @@ impl<'a, 'tcx> MutVisitor<'tcx> for NllVisitor<'a, 'tcx> {
         None
     }
 
+    #[instrument(skip(self), level = "debug")]
     fn visit_substs(&mut self, substs: &mut SubstsRef<'tcx>, location: Location) {
-        debug!("visit_substs(substs={:?}, location={:?})", substs, location);
-
         *substs = self.renumber_regions(*substs);
 
-        debug!("visit_substs: substs={:?}", substs);
+        debug!(?substs);
     }
 
+    #[instrument(skip(self), level = "debug")]
     fn visit_region(&mut self, region: &mut ty::Region<'tcx>, location: Location) {
-        debug!("visit_region(region={:?}, location={:?})", region, location);
-
         let old_region = *region;
         *region = self.renumber_regions(&old_region);
 
-        debug!("visit_region: region={:?}", region);
+        debug!(?region);
     }
 
     fn visit_const(&mut self, constant: &mut &'tcx ty::Const<'tcx>, _location: Location) {

Diff for: compiler/rustc_borrowck/src/type_check/canonical.rs

@@ -24,6 +24,7 @@ impl<'a, 'tcx> TypeChecker<'a, 'tcx> {
     /// **Any `rustc_infer::infer` operations that might generate region
     /// constraints should occur within this method so that those
     /// constraints can be properly localized!**
+    #[instrument(skip(self, category, op), level = "trace")]
     pub(super) fn fully_perform_op<R, Op>(
         &mut self,
         locations: Locations,
@@ -131,14 +132,13 @@ impl<'a, 'tcx> TypeChecker<'a, 'tcx> {
         }
     }
 
+    #[instrument(skip(self), level = "debug")]
     pub(super) fn prove_predicate(
         &mut self,
         predicate: ty::Predicate<'tcx>,
         locations: Locations,
         category: ConstraintCategory,
     ) {
-        debug!("prove_predicate(predicate={:?}, location={:?})", predicate, locations,);
-
         let param_env = self.param_env;
         self.fully_perform_op(
             locations,
@@ -150,11 +150,11 @@ impl<'a, 'tcx> TypeChecker<'a, 'tcx> {
         })
     }
 
+    #[instrument(skip(self), level = "debug")]
     pub(super) fn normalize<T>(&mut self, value: T, location: impl NormalizeLocation) -> T
     where
         T: type_op::normalize::Normalizable<'tcx> + fmt::Display + Copy + 'tcx,
     {
-        debug!("normalize(value={:?}, location={:?})", value, location);
         let param_env = self.param_env;
         self.fully_perform_op(
             location.to_locations(),

Diff for: compiler/rustc_borrowck/src/type_check/constraint_conversion.rs

@@ -53,9 +53,8 @@ impl<'a, 'tcx> ConstraintConversion<'a, 'tcx> {
         }
     }
 
+    #[instrument(skip(self), level = "debug")]
     pub(super) fn convert_all(&mut self, query_constraints: &QueryRegionConstraints<'tcx>) {
-        debug!("convert_all(query_constraints={:#?})", query_constraints);
-
         let QueryRegionConstraints { outlives, member_constraints } = query_constraints;
 
         // Annoying: to invoke `self.to_region_vid`, we need access to