Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reduce verbosity of tracing output of RUSTC_LOG #87903

Merged
merged 1 commit into from
Aug 12, 2021

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
Contributor

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