Merge pull request #525 from nathanwhit/tracing

Introduce Tracing into Chalk (Third Time's the Charm)

Author: jackh726

Cargo.lock

@@ -20,6 +20,7 @@ rustyline = "6.0.0"
 salsa = "0.10.0"
 serde = "1.0"
 serde_derive = "1.0"
+tracing-subscriber = "0.2"
 
 chalk-derive = { version = "0.14.0-dev.0", path = "chalk-derive" }
 chalk-engine = { version = "0.14.0-dev.0", path = "chalk-engine" }
@@ -32,3 +33,4 @@ chalk-integration = { version = "0.14.0-dev.0", path = "chalk-integration" }
 
 [dev-dependencies]
 pretty_assertions = "0.6.1"
+tracing = "0.1"

Cargo.toml

@@ -48,7 +48,27 @@ $ cargo run
 Unique; substitution [], lifetime constraints []
 ```
 
-More logging can be enabled by setting the `CHALK_DEBUG` environment variable. Set `CHALK_DEBUG=1` to see `info!(...)` output, and `CHALK_DEBUG=2` to see `debug!(...)` output as well.
+More logging can be enabled by setting the `CHALK_DEBUG` environment variable. Set `CHALK_DEBUG=3` or `CHALK_DEBUG=info` to see `info!(...)` output, and `CHALK_DEBUG=4` or `CHALK_DEBUG=debug` to see `debug!(...)` output as well. In addition, logs may be filtered in a number of ways. The syntax for filtering logs is:
+
+```notrust
+ target[span{field=value}]=level
+```
+
+(Note: all parts of the filter are optional )
+
+In more detail, the filter may consist of:
+
+- A target (location of origin)
+  - For example setting `CHALK_DEBUG='chalk_solve::infer::unify'` will filter logs to show only output originating from `chalk_solve::infer::unify`.
+- A span (name provided to the logging macros, for instance `unify_var_ty` in `debug_span!("unify_var_ty")`)
+  - For example setting `CHALK_DEBUG='[unify_ty_ty]'` will show only logs where the span contains `unify_ty_ty`.
+- A list of fields (variables recorded in the logs), for instance `ty` in `debug!("unify_var_ty", ?ty)` with values optionally specified
+  - For example setting `CHALK_DEBUG='[{ty}]'` will show only logs which contain a variable `ty`
+  - Setting `CHALK_DEBUG='[{ty=Bar}]'` will show only logs which contain a variable `ty` with the value `Bar`
+- A maximum log level (one of `info`, `debug`, `trace`) which shows logs at or below the given level
+
+More documentation on the syntax and options can be found [here](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html#Directives).
+
 
 ## Pull Requests
 [pull-requests]: #pull-requests

book/src/contribution_guide.md

@@ -14,6 +14,7 @@ default = []
 
 [dependencies]
 rustc-hash = { version = "1.1.0" }
+tracing = "0.1"
 
 chalk-derive = { version = "0.14.0-dev.0", path = "../chalk-derive" }
 chalk-ir = { version = "0.14.0-dev.0", path = "../chalk-ir" }

chalk-engine/Cargo.toml

@@ -4,9 +4,9 @@ use crate::table::AnswerIndex;
 use crate::tables::Tables;
 use crate::{TableIndex, TimeStamp};
 
-use chalk_ir::debug;
 use chalk_ir::interner::Interner;
 use chalk_ir::{Goal, InEnvironment, Substitution, UCanonical};
+use tracing::debug;
 
 pub struct Forest<I: Interner, C: Context<I>> {
     pub(crate) tables: Tables<I>,

chalk-engine/src/forest.rs

@@ -11,11 +11,11 @@ use crate::{
 };
 
 use chalk_ir::interner::Interner;
-use chalk_ir::{debug, debug_heading, info, info_heading};
 use chalk_ir::{
     Canonical, ConstrainedSubst, DomainGoal, Floundered, Goal, GoalData, InEnvironment, NoSolution,
     Substitution, UCanonical, UniverseMap, WhereClause,
 };
+use tracing::{debug, debug_span, info, instrument};
 
 type RootSearchResult<T> = Result<T, RootSearchFail>;
 
@@ -179,14 +179,13 @@ impl<I: Interner, C: Context<I>> Forest<I, C> {
     /// In terms of the NFTD paper, creating a new table corresponds
     /// to the *New Subgoal* step as well as the *Program Clause
     /// Resolution* steps.
+    #[instrument(level = "debug", skip(self, context, infer))]
     fn get_or_create_table_for_subgoal(
         &mut self,
         context: &impl ContextOps<I, C>,
         infer: &mut dyn InferenceTable<I, C>,
         subgoal: &Literal<I>,
     ) -> Option<(TableIndex, UniverseMap)> {
-        debug_heading!("get_or_create_table_for_subgoal(subgoal={:?})", subgoal);
-
         // Subgoal abstraction:
         let (ucanonical_subgoal, universe_map) = match subgoal {
             Literal::Positive(subgoal) => {
@@ -212,19 +211,18 @@ impl<I: Interner, C: Context<I>> Forest<I, C> {
     /// In terms of the NFTD paper, creating a new table corresponds
     /// to the *New Subgoal* step as well as the *Program Clause
     /// Resolution* steps.
+    #[instrument(level = "debug", skip(self, context))]
     pub(crate) fn get_or_create_table_for_ucanonical_goal(
         &mut self,
         context: &impl ContextOps<I, C>,
         goal: UCanonical<InEnvironment<Goal<I>>>,
     ) -> TableIndex {
-        debug_heading!("get_or_create_table_for_ucanonical_goal({:?})", goal);
-
         if let Some(table) = self.tables.index_of(&goal) {
             debug!("found existing table {:?}", table);
             return table;
         }
 
-        info_heading!(
+        info!(
             "creating new table {:?} and goal {:#?}",
             self.tables.next_index(),
             goal
@@ -436,16 +434,12 @@ impl<'forest, I: Interner, C: Context<I> + 'forest, CO: ContextOps<I, C> + 'fore
     /// This function first attempts to fetch answer that is cached in
     /// the table. If none is found, then it will recursively search
     /// to find an answer.
+    #[instrument(level = "info", skip(self))]
     fn ensure_root_answer(
         &mut self,
         initial_table: TableIndex,
         initial_answer: AnswerIndex,
     ) -> RootSearchResult<()> {
-        info_heading!(
-            "ensure_answer(table={:?}, answer={:?})",
-            initial_table,
-            initial_answer
-        );
         info!(
             "table goal = {:#?}",
             self.forest.tables[initial_table].table_goal
@@ -1529,11 +1523,13 @@ impl<'forest, I: Interner, C: Context<I> + 'forest, CO: ContextOps<I, C> + 'fore
     /// subgoal list and adds it to the strand's floundered subgoal
     /// list.
     fn flounder_subgoal(&self, ex_clause: &mut ExClause<I>, subgoal_index: usize) {
-        info_heading!(
-            "flounder_subgoal(answer_time={:?}, subgoal={:?})",
-            ex_clause.answer_time,
-            ex_clause.subgoals[subgoal_index],
+        let _s = debug_span!(
+            "flounder_subgoal",
+            answer_time = ?ex_clause.answer_time,
+            subgoal = ?ex_clause.subgoals[subgoal_index],
         );
+        let _s = _s.enter();
+
         let floundered_time = ex_clause.answer_time;
         let floundered_literal = ex_clause.subgoals.remove(subgoal_index);
         ex_clause.floundered_subgoals.push(FlounderedSubgoal {

chalk-engine/src/logic.rs

@@ -2,12 +2,12 @@ use crate::context::{Context, ContextOps, InferenceTable};
 use crate::forest::Forest;
 use crate::{ExClause, Literal, TimeStamp};
 
-use chalk_ir::debug;
 use chalk_ir::interner::Interner;
 use chalk_ir::{
     Constraint, DomainGoal, Environment, Fallible, Goal, GoalData, InEnvironment, LifetimeOutlives,
     QuantifierKind, Substitution, WhereClause,
 };
+use tracing::debug;
 
 impl<I: Interner, C: Context<I>> Forest<I, C> {
     /// Simplifies a goal into a series of positive domain goals

chalk-engine/src/simplify.rs

@@ -7,8 +7,8 @@ use std::collections::VecDeque;
 use std::mem;
 
 use chalk_ir::interner::Interner;
-use chalk_ir::{debug, debug_heading, info};
 use chalk_ir::{AnswerSubst, Canonical, Goal, InEnvironment, UCanonical};
+use tracing::{debug, info, instrument};
 
 pub(crate) struct Table<I: Interner> {
     /// The goal this table is trying to solve (also the key to look
@@ -133,10 +133,9 @@ impl<I: Interner> Table<I> {
     /// tests trigger this case, and assumptions upstream assume that when
     /// `true` is returned here, that a *new* answer was added (instead of an)
     /// existing answer replaced.
+    #[instrument(level = "debug", skip(self))]
     pub(super) fn push_answer(&mut self, answer: Answer<I>) -> Option<AnswerIndex> {
         assert!(!self.floundered);
-
-        debug_heading!("push_answer(answer={:?})", answer);
         debug!(
             "pre-existing entry: {:?}",
             self.answers_hash.get(&answer.subst)

chalk-engine/src/table.rs

@@ -12,6 +12,7 @@ publish = false
 [dependencies]
 string_cache = "0.8.0"
 salsa = "0.10.0"
+tracing = "0.1"
 
 chalk-derive = { version = "0.14.0-dev.0", path = "../chalk-derive" }
 chalk-engine = { version = "0.14.0-dev.0", path = "../chalk-engine" }

chalk-integration/Cargo.toml

@@ -5,14 +5,14 @@ use chalk_ir::{
     self, AdtId, AssocTypeId, BoundVar, ClausePriority, DebruijnIndex, FnDefId, ImplId, OpaqueTyId,
     QuantifiedWhereClauses, Substitution, ToGenericArg, TraitId, TyKind,
 };
-use chalk_ir::{debug, debug_heading};
 use chalk_parse::ast::*;
 use chalk_solve::rust_ir::{
     self, Anonymize, AssociatedTyValueId, IntoWhereClauses, OpaqueTyDatum, OpaqueTyDatumBound,
 };
 use std::collections::{BTreeMap, HashSet};
 use std::sync::Arc;
 use string_cache::DefaultAtom as Atom;
+use tracing::{debug, instrument};
 
 use crate::error::RustIrError;
 use crate::program::Program as LoweredProgram;
@@ -1591,14 +1591,13 @@ trait LowerImpl {
 }
 
 impl LowerImpl for Impl {
+    #[instrument(level = "debug", skip(self, empty_env, associated_ty_value_ids))]
     fn lower_impl(
         &self,
         empty_env: &Env,
         impl_id: ImplId<ChalkIr>,
         associated_ty_value_ids: &AssociatedTyValueIds,
     ) -> LowerResult<rust_ir::ImplDatum<ChalkIr>> {
-        debug_heading!("LowerImpl::lower_impl(impl_id={:?})", impl_id);
-
         let polarity = self.polarity.lower();
         let binders = empty_env.in_binders(self.all_parameters(), |env| {
             let trait_ref = self.trait_ref.lower(env)?;

chalk-integration/src/lowering.rs

@@ -12,4 +12,3 @@ edition = "2018"
 [dependencies]
 lazy_static = "1.4.0"
 chalk-derive = { version = "0.14.0-dev.0", path = "../chalk-derive" }
-

chalk-ir/Cargo.toml

@@ -51,9 +51,6 @@ pub mod fold;
 #[macro_use]
 pub mod visit;
 
-#[macro_use]
-pub mod debug_macros;
-
 pub mod cast;
 
 pub mod interner;

chalk-ir/src/debug_macros.rs

@@ -13,6 +13,7 @@ edition = "2018"
 ena = "0.14.0"
 itertools = "0.9.0"
 petgraph = "0.5.0"
+tracing = "0.1"
 rustc-hash = { version = "1.0.0" }
 
 chalk-derive = { version = "0.14.0-dev.0", path = "../chalk-derive" }