Some perf optimizations and logging

Author: jackh726

Diff for: compiler/rustc_data_structures/src/obligation_forest/mod.rs

@@ -418,6 +418,7 @@ impl<O: ForestObligation> ObligationForest<O> {
     /// be called in a loop until `outcome.stalled` is false.
     ///
     /// This _cannot_ be unrolled (presently, at least).
+    #[inline(never)]
     pub fn process_obligations<P, OUT>(&mut self, processor: &mut P) -> OUT
     where
         P: ObligationProcessor<Obligation = O>,
@@ -671,6 +672,7 @@ impl<O: ForestObligation> ObligationForest<O> {
         self.reused_node_vec = node_rewrites;
     }
 
+    #[inline(never)]
     fn apply_rewrites(&mut self, node_rewrites: &[usize]) {
         let orig_nodes_len = node_rewrites.len();
 

Diff for: compiler/rustc_infer/src/infer/type_variable.rs

@@ -400,6 +400,7 @@ impl<'tcx> From<ty::TyVid> for TyVidEqKey<'tcx> {
 
 impl<'tcx> ut::UnifyKey for TyVidEqKey<'tcx> {
     type Value = TypeVariableValue<'tcx>;
+    #[inline(always)]
     fn index(&self) -> u32 {
         self.vid.index
     }

Diff for: compiler/rustc_trait_selection/src/traits/fulfill.rs

@@ -167,15 +167,14 @@ impl<'tcx> TraitEngine<'tcx> for FulfillmentContext<'tcx> {
     /// `SomeTrait` or a where-clause that lets us unify `$0` with
     /// something concrete. If this fails, we'll unify `$0` with
     /// `projection_ty` again.
+    #[tracing::instrument(level = "debug", skip(self, infcx, param_env, cause))]
     fn normalize_projection_type(
         &mut self,
         infcx: &InferCtxt<'_, 'tcx>,
         param_env: ty::ParamEnv<'tcx>,
         projection_ty: ty::ProjectionTy<'tcx>,
         cause: ObligationCause<'tcx>,
     ) -> Ty<'tcx> {
-        debug!(?projection_ty, "normalize_projection_type");
-
         debug_assert!(!projection_ty.has_escaping_bound_vars());
 
         // FIXME(#20304) -- cache

Diff for: compiler/rustc_trait_selection/src/traits/project.rs

@@ -273,7 +273,7 @@ where
     Normalized { value, obligations }
 }
 
-#[instrument(level = "debug", skip(selcx, param_env, cause, obligations))]
+#[instrument(level = "info", skip(selcx, param_env, cause, obligations))]
 pub fn normalize_with_depth_to<'a, 'b, 'tcx, T>(
     selcx: &'a mut SelectionContext<'b, 'tcx>,
     param_env: ty::ParamEnv<'tcx>,
@@ -285,6 +285,7 @@ pub fn normalize_with_depth_to<'a, 'b, 'tcx, T>(
 where
     T: TypeFoldable<'tcx>,
 {
+    debug!(obligations.len = obligations.len());
     let mut normalizer = AssocTypeNormalizer::new(selcx, param_env, cause, depth, obligations);
     let result = ensure_sufficient_stack(|| normalizer.fold(value));
     debug!(?result, obligations.len = normalizer.obligations.len());
@@ -314,6 +315,7 @@ impl<'a, 'b, 'tcx> AssocTypeNormalizer<'a, 'b, 'tcx> {
 
     fn fold<T: TypeFoldable<'tcx>>(&mut self, value: T) -> T {
         let value = self.selcx.infcx().resolve_vars_if_possible(value);
+        debug!(?value);
 
         assert!(
             !value.has_escaping_bound_vars(),
@@ -825,7 +827,7 @@ fn opt_normalize_projection_type<'a, 'b, 'tcx>(
 
     let cache_result = infcx.inner.borrow_mut().projection_cache().try_start(cache_key);
     match cache_result {
-        Ok(()) => {}
+        Ok(()) => debug!("no cache"),
         Err(ProjectionCacheEntry::Ambiguous) => {
             // If we found ambiguity the last time, that means we will continue
             // to do so until some type in the key changes (and we know it
@@ -852,6 +854,7 @@ fn opt_normalize_projection_type<'a, 'b, 'tcx>(
             return Err(InProgress);
         }
         Err(ProjectionCacheEntry::Recur) => {
+            debug!("recur cache");
             return Err(InProgress);
         }
         Err(ProjectionCacheEntry::NormalizedTy(ty)) => {
@@ -1058,12 +1061,11 @@ impl<'tcx> Progress<'tcx> {
 ///
 /// IMPORTANT:
 /// - `obligation` must be fully normalized
+#[tracing::instrument(level = "info", skip(selcx))]
 fn project_type<'cx, 'tcx>(
     selcx: &mut SelectionContext<'cx, 'tcx>,
     obligation: &ProjectionTyObligation<'tcx>,
 ) -> Result<ProjectedTy<'tcx>, ProjectionTyError<'tcx>> {
-    debug!(?obligation, "project_type");
-
     if !selcx.tcx().recursion_limit().value_within_limit(obligation.recursion_depth) {
         debug!("project: overflow!");
         // This should really be an immediate error, but some existing code

Diff for: compiler/rustc_trait_selection/src/traits/query/normalize.rs

@@ -65,7 +65,7 @@ impl<'cx, 'tcx> AtExt<'tcx> for At<'cx, 'tcx> {
         };
 
         let result = value.fold_with(&mut normalizer);
-        debug!(
+        info!(
             "normalize::<{}>: result={:?} with {} obligations",
             std::any::type_name::<T>(),
             result,

Diff for: compiler/rustc_trait_selection/src/traits/select/mod.rs

@@ -1865,12 +1865,12 @@ impl<'cx, 'tcx> SelectionContext<'cx, 'tcx> {
         }
     }
 
+    #[tracing::instrument(level = "debug", skip(self))]
     fn match_impl(
         &mut self,
         impl_def_id: DefId,
         obligation: &TraitObligation<'tcx>,
     ) -> Result<Normalized<'tcx, SubstsRef<'tcx>>, ()> {
-        debug!(?impl_def_id, ?obligation, "match_impl");
         let impl_trait_ref = self.tcx().impl_trait_ref(impl_def_id).unwrap();
 
         // Before we create the substitutions and everything, first
@@ -1888,6 +1888,8 @@ impl<'cx, 'tcx> SelectionContext<'cx, 'tcx> {
 
         let impl_trait_ref = impl_trait_ref.subst(self.tcx(), impl_substs);
 
+        debug!(?impl_trait_ref);
+
         let Normalized { value: impl_trait_ref, obligations: mut nested_obligations } =
             ensure_sufficient_stack(|| {
                 project::normalize_with_depth(
@@ -1915,7 +1917,7 @@ impl<'cx, 'tcx> SelectionContext<'cx, 'tcx> {
             return Err(());
         }
 
-        debug!(?impl_substs, "match_impl: success");
+        debug!(?impl_substs, ?nested_obligations, "match_impl: success");
         Ok(Normalized { value: impl_substs, obligations: nested_obligations })
     }
 
@@ -2068,6 +2070,7 @@ impl<'cx, 'tcx> SelectionContext<'cx, 'tcx> {
     /// impl or trait. The obligations are substituted and fully
     /// normalized. This is used when confirming an impl or default
     /// impl.
+    #[tracing::instrument(level = "debug", skip(self, cause, param_env))]
     fn impl_or_trait_obligations(
         &mut self,
         cause: ObligationCause<'tcx>,
@@ -2076,7 +2079,6 @@ impl<'cx, 'tcx> SelectionContext<'cx, 'tcx> {
         def_id: DefId,           // of impl or trait
         substs: SubstsRef<'tcx>, // for impl or trait
     ) -> Vec<PredicateObligation<'tcx>> {
-        debug!(?def_id, "impl_or_trait_obligations");
         let tcx = self.tcx();
 
         // To allow for one-pass evaluation of the nested obligation,
@@ -2094,9 +2096,11 @@ impl<'cx, 'tcx> SelectionContext<'cx, 'tcx> {
         // `$1: Copy`, so we must ensure the obligations are emitted in
         // that order.
         let predicates = tcx.predicates_of(def_id);
+        debug!(?predicates);
         assert_eq!(predicates.parent, None);
         let mut obligations = Vec::with_capacity(predicates.predicates.len());
         for (predicate, _) in predicates.predicates {
+            debug!(?predicate);
             let predicate = normalize_with_depth_to(
                 self,
                 param_env,

Diff for: compiler/rustc_trait_selection/src/traits/wf.rs

@@ -85,6 +85,7 @@ pub fn trait_obligations<'a, 'tcx>(
     let mut wf =
         WfPredicates { infcx, param_env, body_id, span, out: vec![], recursion_depth: 0, item };
     wf.compute_trait_ref(trait_ref, Elaborate::All);
+    debug!(obligations = ?wf.out);
     wf.normalize()
 }
 

Diff for: compiler/rustc_typeck/src/check/fn_ctxt/_impl.rs

@@ -1578,6 +1578,7 @@ impl<'a, 'tcx> FnCtxt<'a, 'tcx> {
     }
 
     /// Add all the obligations that are required, substituting and normalized appropriately.
+    #[tracing::instrument(level = "debug", skip(self, span, def_id, substs))]
     fn add_required_obligations(&self, span: Span, def_id: DefId, substs: &SubstsRef<'tcx>) {
         let (bounds, spans) = self.instantiate_bounds(span, def_id, &substs);
 

Diff for: compiler/rustc_typeck/src/check/inherited.rs

@@ -179,6 +179,7 @@ impl Inherited<'a, 'tcx> {
         T: TypeFoldable<'tcx>,
     {
         let ok = self.partially_normalize_associated_types_in(cause, param_env, value);
+        debug!(?ok);
         self.register_infer_ok_obligations(ok)
     }
 }

Diff for: compiler/rustc_typeck/src/check/wfcheck.rs

@@ -379,14 +379,13 @@ fn check_param_wf(tcx: TyCtxt<'_>, param: &hir::GenericParam<'_>) {
     }
 }
 
+#[tracing::instrument(level = "debug", skip(tcx, span, sig_if_method))]
 fn check_associated_item(
     tcx: TyCtxt<'_>,
     item_id: hir::HirId,
     span: Span,
     sig_if_method: Option<&hir::FnSig<'_>>,
 ) {
-    debug!("check_associated_item: {:?}", item_id);
-
     let code = ObligationCauseCode::WellFormed(Some(item_id));
     for_id(tcx, item_id, span).with_fcx(|fcx| {
         let item = fcx.tcx.associated_item(fcx.tcx.hir().local_def_id(item_id));
@@ -650,14 +649,13 @@ fn check_item_type(tcx: TyCtxt<'_>, item_id: hir::HirId, ty_span: Span, allow_fo
     });
 }
 
+#[tracing::instrument(level = "debug", skip(tcx, ast_self_ty, ast_trait_ref))]
 fn check_impl<'tcx>(
     tcx: TyCtxt<'tcx>,
     item: &'tcx hir::Item<'tcx>,
     ast_self_ty: &hir::Ty<'_>,
     ast_trait_ref: &Option<hir::TraitRef<'_>>,
 ) {
-    debug!("check_impl: {:?}", item);
-
     for_item(tcx, item).with_fcx(|fcx| {
         match *ast_trait_ref {
             Some(ref ast_trait_ref) => {
@@ -675,6 +673,7 @@ fn check_impl<'tcx>(
                     ast_trait_ref.path.span,
                     Some(item),
                 );
+                debug!(?obligations);
                 for obligation in obligations {
                     fcx.register_predicate(obligation);
                 }