Skip to content

Conversation

jackh726
Copy link
Member

The current output is really hard to read, I find, for things like trait selection. I nearly always end up removing these calls locally.

r? @oli-obk since you originally authored this

@rust-highfive rust-highfive added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Aug 10, 2021
@oli-obk
Copy link
Contributor

oli-obk commented Aug 10, 2021

What part is unreadable to you? The duplication when you enter and immediately enter a nested one?

In longer chains it can sometimes be helpful to see which function you came from, but I get your point. We should make this configurable, as I implemented it for miri, which already had this behavior before we used tracing-tree

WRT the wraparound, I personally would also prefer no wraparound, so 👍 from me, may get a lot of rightwards drift though.

@jackh726
Copy link
Member Author

Here's a decent example of how the verbose entry is difficult to read:
with:

│ │ │ ├─0ms DEBUG rustc_infer::infer::region_constraints RegionConstraintCollector: start_snapshot
│ │ │ ├┐rustc_trait_selection::traits::project::project_type obligation=Obligation(predicate=ProjectionTy { substs: [IdScanner, ReEarlyBound(0, 'a)], item_def_id: DefId(0:6 ~ issue_87803[87c4]::Scanner::Token) }, cause=ObligationCauseData { span: src/test/ui/generic-associated-types/issue-87803.rs:14:5: 14:30 (#0), body_id: HirId { owner: DefId(0:15 ~ issue_87803[87c4]::{impl#0}::Token), local_id: 0 }, code: MiscObligation }, param_env=ParamEnv { caller_bounds: [Binder(ProjectionPredicate(ProjectionTy { substs: [IdScanner, ReLateBound(DebruijnIndex(0), BoundRegion { var: 0, kind: BrNamed(DefId(0:16 ~ issue_87803[87c4]::{impl#0}::Token::'a), 'a) })], item_def_id: DefId(0:6 ~ issue_87803[87c4]::Scanner::Token) }, &ReEarlyBound(0, 'a) str), [Region(BrNamed(DefId(0:16 ~ issue_87803[87c4]::{impl#0}::Token::'a), 'a))])], reveal: UserFacing }, depth=0)
│ │ │ │└┐rustc_trait_selection::traits::select::select obligation=Obligation(predicate=Binder(TraitPredicate(<IdScanner as Scanner>), []), cause=ObligationCauseData { span: src/test/ui/generic-associated-types/issue-87803.rs:14:5: 14:30 (#0), body_id: HirId { owner: DefId(0:15 ~ issue_87803[87c4]::{impl#0}::Token), local_id: 0 }, code: MiscObligation }, param_env=ParamEnv { caller_bounds: [Binder(ProjectionPredicate(ProjectionTy { substs: [IdScanner, ReLateBound(DebruijnIndex(0), BoundRegion { var: 0, kind: BrNamed(DefId(0:16 ~ issue_87803[87c4]::{impl#0}::Token::'a), 'a) })], item_def_id: DefId(0:6 ~ issue_87803[87c4]::Scanner::Token) }, &ReEarlyBound(0, 'a) str), [Region(BrNamed(DefId(0:16 ~ issue_87803[87c4]::{impl#0}::Token::'a), 'a))])], reveal: UserFacing }, depth=0)
│ │ │ │ ├┐rustc_trait_selection::traits::select::select obligation=Obligation(predicate=Binder(TraitPredicate(<IdScanner as Scanner>), []), cause=ObligationCauseData { span: src/test/ui/generic-associated-types/issue-87803.rs:14:5: 14:30 (#0), body_id: HirId { owner: DefId(0:15 ~ issue_87803[87c4]::{impl#0}::Token), local_id: 0 }, code: MiscObligation }, param_env=ParamEnv { caller_bounds: [Binder(ProjectionPredicate(ProjectionTy { substs: [IdScanner, ReLateBound(DebruijnIndex(0), BoundRegion { var: 0, kind: BrNamed(DefId(0:16 ~ issue_87803[87c4]::{impl#0}::Token::'a), 'a) })], item_def_id: DefId(0:6 ~ issue_87803[87c4]::Scanner::Token) }, &ReEarlyBound(0, 'a) str), [Region(BrNamed(DefId(0:16 ~ issue_87803[87c4]::{impl#0}::Token::'a), 'a))])], reveal: UserFacing }, depth=0)
│ │ │ │ │└┐rustc_trait_selection::traits::select::candidate_assembly::candidate_from_obligation stack=TraitObligationStack(Obligation(predicate=Binder(TraitPredicate(<IdScanner as Scanner>), []), cause=ObligationCauseData { span: src/test/ui/generic-associated-types/issue-87803.rs:14:5: 14:30 (#0), body_id: HirId { owner: DefId(0:15 ~ issue_87803[87c4]::{impl#0}::Token), local_id: 0 }, code: MiscObligation }, param_env=ParamEnv { caller_bounds: [Binder(ProjectionPredicate(ProjectionTy { substs: [IdScanner, ReLateBound(DebruijnIndex(0), BoundRegion { var: 0, kind: BrNamed(DefId(0:16 ~ issue_87803[87c4]::{impl#0}::Token::'a), 'a) })], item_def_id: DefId(0:6 ~ issue_87803[87c4]::Scanner::Token) }, &ReEarlyBound(0, 'a) str), [Region(BrNamed(DefId(0:16 ~ issue_87803[87c4]::{impl#0}::Token::'a), 'a))])], reveal: UserFacing }, depth=0))
│ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::select::candidate_assembly cache_fresh_trait_pred=Binder(TraitPredicate(<IdScanner as Scanner>), [])

without:

│ │ │ ├─0ms DEBUG rustc_infer::infer::region_constraints RegionConstraintCollector: start_snapshot
│ │ │ ├─┐rustc_trait_selection::traits::select::select obligation=Obligation(predicate=Binder(TraitPredicate(<IdScanner as Scanner>), []), cause=ObligationCauseData { span: src/test/ui/generic-associated-types/issue-87803.rs:14:5: 14:30 (#0), body_id: HirId { owner: DefId(0:15 ~ issue_87803[87c4]::{impl#0}::Token), local_id: 0 }, code: MiscObligation }, param_env=ParamEnv { caller_bounds: [Binder(ProjectionPredicate(ProjectionTy { substs: [IdScanner, ReLateBound(DebruijnIndex(0), BoundRegion { var: 0, kind: BrNamed(DefId(0:16 ~ issue_87803[87c4]::{impl#0}::Token::'a), 'a) })], item_def_id: DefId(0:6 ~ issue_87803[87c4]::Scanner::Token) }, &ReEarlyBound(0, 'a) str), [Region(BrNamed(DefId(0:16 ~ issue_87803[87c4]::{impl#0}::Token::'a), 'a))])], reveal: UserFacing }, depth=0)
│ │ │ │ ├─┐rustc_trait_selection::traits::select::candidate_assembly::candidate_from_obligation stack=TraitObligationStack(Obligation(predicate=Binder(TraitPredicate(<IdScanner as Scanner>), []), cause=ObligationCauseData { span: src/test/ui/generic-associated-types/issue-87803.rs:14:5: 14:30 (#0), body_id: HirId { owner: DefId(0:15 ~ issue_87803[87c4]::{impl#0}::Token), local_id: 0 }, code: MiscObligation }, param_env=ParamEnv { caller_bounds: [Binder(ProjectionPredicate(ProjectionTy { substs: [IdScanner, ReLateBound(DebruijnIndex(0), BoundRegion { var: 0, kind: BrNamed(DefId(0:16 ~ issue_87803[87c4]::{impl#0}::Token::'a), 'a) })], item_def_id: DefId(0:6 ~ issue_87803[87c4]::Scanner::Token) }, &ReEarlyBound(0, 'a) str), [Region(BrNamed(DefId(0:16 ~ issue_87803[87c4]::{impl#0}::Token::'a), 'a))])], reveal: UserFacing }, depth=0))
│ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::select::candidate_assembly cache_fresh_trait_pred=Binder(TraitPredicate(<IdScanner as Scanner>), [])

This shows a couple things:

  • Verbose is longer, which just means more to mentally parse through (here is 6vs4, but in a local comparison of logging a test, it's 5709 vs 5159)
  • There are (lots of) cases where we enter, then immediately enter again (select here)
  • That extra project_type log really doesn't help (at least me). When I go through the logs, if I see that, my mind thinks "oh, there's a call to project_type here. Sure, it could be useful to see the context, but when you have multiple small nested calls, it's really not.

Verbose exit, I suppose, can go either way. But it doesn't really work without the verbose entry (example below, without entry, with/without exit). I find the extra space at the end of the block helpful for mentally parsing the control flow, which you don't get with verbose entry/exit.
with:

│ │ │ │ │ ├─┐rustc_trait_selection::traits::select::match_impl impl_def_id=DefId(0:12 ~ issue_87803[87c4]::{impl#0}), obligation=Obligation(predicate=Binder(TraitPredicate(<IdScanner as Scanner>), []), cause=ObligationCauseData { span: no-location (#0), body_id: HirId { owner: DefId(0:0 ~ issue_87803[87c4]), local_id: 0 }, code: MiscObligation }, param_env=ParamEnv { caller_bounds: [], reveal: UserFacing }, depth=0)
│ │ │ │ │ │ ├─0ms DEBUG rustc_infer::infer::higher_ranked replace_bound_vars_with_placeholders(next_universe=U1, result=TraitPredicate(<IdScanner as Scanner>), map={})
│ │ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::select impl_trait_ref=<IdScanner as Scanner>
│ │ │ │ │ │ ├┐
│ │ │ │ │ │ ├─┐rustc_trait_selection::traits::project::normalize_with_depth_to depth=1, value=<IdScanner as Scanner>
│ │ │ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::project obligations.len=0
│ │ │ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::project value=<IdScanner as Scanner>
│ │ │ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::project result=<IdScanner as Scanner>, obligations.len=0
│ │ │ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::project normalizer.obligations=[]
│ │ │ │ │ │ │┌┘
│ │ │ │ │ │ ├┘
│ │ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::select impl_trait_ref=<IdScanner as Scanner>, placeholder_obligation_trait_ref=<IdScanner as Scanner>

vs without

│ │ │ │ ├─┐rustc_trait_selection::traits::select::match_impl impl_def_id=DefId(0:12 ~ issue_87803[87c4]::{impl#0}), obligation=Obligation(predicate=Binder(TraitPredicate(<IdScanner as Scanner>), []), cause=ObligationCauseData { span: no-location (#0), body_id: HirId { owner: DefId(0:0 ~ issue_87803[87c4]), local_id: 0 }, code: MiscObligation }, param_env=ParamEnv { caller_bounds: [], reveal: UserFacing }, depth=0)
│ │ │ │ │ ├─0ms DEBUG rustc_infer::infer::higher_ranked replace_bound_vars_with_placeholders(next_universe=U1, result=TraitPredicate(<IdScanner as Scanner>), map={})
│ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::select impl_trait_ref=<IdScanner as Scanner>
│ │ │ │ │ ├─┐rustc_trait_selection::traits::project::normalize_with_depth_to depth=1, value=<IdScanner as Scanner>
│ │ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::project obligations.len=0
│ │ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::project value=<IdScanner as Scanner>
│ │ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::project result=<IdScanner as Scanner>, obligations.len=0
│ │ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::project normalizer.obligations=[]
│ │ │ │ │ ├─┘
│ │ │ │ │ ├─0ms DEBUG rustc_trait_selection::traits::select impl_trait_ref=<IdScanner as Scanner>, placeholder_obligation_trait_ref=<IdScanner as Scanner>

One other (big) downside of repeating spans: if you're grepping for a call and you have repeated spans you may now have multiple matches whereas before you had one. The match_impl call above is a good example. If I grep for it, I get 2 matches without verbose entry/exit; with, I get 8.

@oli-obk
Copy link
Contributor

oli-obk commented Aug 10, 2021

@bors r+

@oli-obk
Copy link
Contributor

oli-obk commented Aug 10, 2021

@bors rollup

@jackh726
Copy link
Member Author

@bors r=oli-obk

@bors
Copy link
Collaborator

bors commented Aug 10, 2021

📌 Commit 62b8a5e has been approved by oli-obk

@bors bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Aug 10, 2021
JohnTitor added a commit to JohnTitor/rust that referenced this pull request Aug 11, 2021
Reduce verbosity of tracing output of  RUSTC_LOG

The current output is really hard to read, I find, for things like trait selection. I nearly always end up removing these calls locally.

r? `@oli-obk` since you originally authored this
JohnTitor added a commit to JohnTitor/rust that referenced this pull request Aug 11, 2021
Reduce verbosity of tracing output of  RUSTC_LOG

The current output is really hard to read, I find, for things like trait selection. I nearly always end up removing these calls locally.

r? ``@oli-obk`` since you originally authored this
bors added a commit to rust-lang-ci/rust that referenced this pull request Aug 12, 2021
Rollup of 7 pull requests

Successful merges:

 - rust-lang#85835 (Implement Extend<(A, B)> for (Extend<A>, Extend<B>))
 - rust-lang#87671 (Warn when an escaped newline skips multiple lines)
 - rust-lang#87878 (:arrow_up: rust-analyzer)
 - rust-lang#87903 (Reduce verbosity of tracing output of  RUSTC_LOG)
 - rust-lang#87925 (Update books)
 - rust-lang#87928 (Update cargo)
 - rust-lang#87942 (set the executable bit on pre-commit.sh)

Failed merges:

r? `@ghost`
`@rustbot` modify labels: rollup
@bors bors merged commit 4c632d9 into rust-lang:master Aug 12, 2021
@rustbot rustbot added this to the 1.56.0 milestone Aug 12, 2021
@jackh726 jackh726 deleted the logging-cleanup branch March 12, 2022 18:08
@jackh726 jackh726 restored the logging-cleanup branch March 12, 2022 18:30
@jackh726 jackh726 deleted the logging-cleanup branch March 12, 2022 18:35
@jackh726 jackh726 restored the logging-cleanup branch March 12, 2022 18:42
@jackh726 jackh726 deleted the logging-cleanup branch March 12, 2022 18:52
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants