Add more tracing instrumentation #89048

oli-obk · 2021-09-17T16:27:38Z

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

rust-highfive · 2021-09-17T16:27:41Z

r? @matthewjasper

(rust-highfive has picked a reviewer for you, use r? to override)

jackh726 · 2021-09-17T19:12:15Z

r=me with CI green

r? @jackh726

oli-obk · 2021-09-18T08:42:35Z

@bors r=jackh726

bors · 2021-09-18T08:42:36Z

📌 Commit 731d7797b90a37da2a02c9e9d58b17904bd272d6 has been approved by jackh726

bors · 2021-09-18T09:30:06Z

☔ The latest upstream changes (presumably #88980) made this pull request unmergeable. Please resolve the merge conflicts.

oli-obk · 2021-09-20T17:28:19Z

@bors r=jackh726 rollup

bors · 2021-09-20T17:28:21Z

📌 Commit a1b308d12a93a19d46579cc7603279da93e26c58 has been approved by jackh726

oli-obk · 2021-09-20T18:09:25Z

@bors r-

oli-obk · 2021-09-23T12:55:30Z

@bors r=jackh726 rollup

bors · 2021-09-23T12:55:31Z

📌 Commit 1443de7 has been approved by jackh726

…h726 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.

bors · 2021-09-23T23:20:37Z

☔ The latest upstream changes (presumably #89024) made this pull request unmergeable. Please resolve the merge conflicts.

jackh726 · 2021-09-24T00:21:01Z

@bors p=1

This is prone to bitrot.

jackh726 · 2021-09-24T00:21:23Z

@bors rollup=never

Same reason

bors · 2021-09-27T11:10:27Z

🔒 Merge conflict

This pull request and the master branch diverged in a way that cannot be automatically merged. Please rebase on top of the latest master branch, and let the reviewer approve again.

How do I rebase?

Assuming self is your fork and upstream is this repository, you can resolve the conflict following these steps:

git checkout in_tracing_we_trust (switch to your branch)
git fetch upstream master (retrieve the latest master)
git rebase upstream/master -p (rebase on top of it)
Follow the on-screen instruction to resolve conflicts (check git status if you got lost).
git push self in_tracing_we_trust --force-with-lease (update this PR)

You may also read Git Rebasing to Resolve Conflicts by Drew Blessing for a short tutorial.

Please avoid the "Resolve conflicts" button on GitHub. It uses git merge instead of git rebase which makes the PR commit history more difficult to read.

Sometimes step 4 will complete without asking for resolution. This is usually due to difference between how Cargo.lock conflict is handled during merge and rebase. This is normal, and you should still perform step 5 to update this PR.

Error message

Auto-merging compiler/rustc_typeck/src/check/upvar.rs
Auto-merging compiler/rustc_typeck/src/check/fn_ctxt/_impl.rs
Auto-merging compiler/rustc_typeck/src/check/expr.rs
Auto-merging compiler/rustc_typeck/src/check/coercion.rs
Auto-merging compiler/rustc_typeck/src/check/check.rs
Auto-merging compiler/rustc_trait_selection/src/traits/select/mod.rs
Auto-merging compiler/rustc_trait_selection/src/traits/select/confirmation.rs
Auto-merging compiler/rustc_trait_selection/src/opaque_types.rs
Auto-merging compiler/rustc_resolve/src/lib.rs
Auto-merging compiler/rustc_resolve/src/late/lifetimes.rs
Auto-merging compiler/rustc_middle/src/ty/print/pretty.rs
Auto-merging compiler/rustc_infer/src/infer/nll_relate/mod.rs
Auto-merging compiler/rustc_infer/src/infer/mod.rs
Auto-merging compiler/rustc_infer/src/infer/canonical/query_response.rs
Auto-merging compiler/rustc_data_structures/src/graph/scc/mod.rs
Auto-merging compiler/rustc_borrowck/src/type_check/mod.rs
CONFLICT (content): Merge conflict in compiler/rustc_borrowck/src/type_check/mod.rs
Auto-merging compiler/rustc_borrowck/src/type_check/canonical.rs
Auto-merging compiler/rustc_borrowck/src/lib.rs
Automatic merge failed; fix conflicts and then commit the result.

oli-obk · 2021-09-28T12:28:46Z

@bors r=jackh726

bors · 2021-09-28T12:28:47Z

📌 Commit 9b5aa06 has been approved by jackh726

bors · 2021-09-28T14:55:40Z

⌛ Testing commit 9b5aa06 with merge 8f8092c...

bors · 2021-09-28T18:03:57Z

☀️ Test successful - checks-actions
Approved by: jackh726
Pushing 8f8092c to master...

rust-timer · 2021-09-28T19:40:13Z

Finished benchmarking commit (8f8092c): comparison url.

Summary: This change led to very large relevant mixed results 🤷 in compiler performance.

Large improvement in instruction counts (up to -1.6% on full builds of keccak)
Very large regression in instruction counts (up to 12.0% on full builds of ctfe-stress-4)

If you disagree with this performance assessment, please file an issue in rust-lang/rustc-perf.

Next Steps: If you can justify the regressions found in this perf run, please indicate this with @rustbot label: +perf-regression-triaged along with sufficient written justification. If you cannot justify the regressions please open an issue or create a new PR that fixes the regressions, add a comment linking to the newly created issue or PR, and then add the perf-regression-triaged label to this PR.

@rustbot label: +perf-regression

oli-obk · 2021-09-28T20:00:16Z

Uhhhh... why does instrumentation affect release builds?? I'll go through all attributes in this PR and check them again

oli-obk · 2021-09-29T12:27:30Z

Ok found it. The instrument attribute will still generate a wrapper function, even if the level is statically rejected. LLVM will then not optimize this as well. I will open a PR to tracing.

oli-obk · 2021-09-30T12:59:35Z

#89363 shows a path to fix this regression.

@rustbot label: +perf-regression-triaged

…o anything (#1600) ## Motivation Adding `#[instrument(level = "debug")]` attributes to functions in rustc caused a performance regression (in release, where `debug!` is fully optimized out) across all crates: rust-lang/rust#89048 (comment) While trying to debug this, I noticed that spans don't have the same advantage that events have wrt to how LLVM sees them. Spans (or more precisely, the enter-guard), will get dropped at the end of the scope, which throws a spanner into the LLVM optimization pipeline. I am not entirely sure where the problem is, but I am moderately certain that the issue is that even entering a dummy span is too much code for LLVM to reliably (or at all) optimize out. ## Solution My hope is that in trusting the Rust compiler to generate cool code when using drop flags, we can essentially generate a drop flag that depends on something we know (due to events working as expected) to be optimizable. So instead of doing ```rust let _x = span!(); let _y = _x.enter(); // lotsa code drop(_y) ``` we do ```rust let _x; let _y; let must_drop = false; if level_enabled!(DEBUG) { must_drop = true; _x = span!(); _y = _x.enter(); } // lotsa code if must_drop { drop(_y) } ``` I believe this will allow LLVM to properly optimize this again. Testing that right now, but I wanted to open this PR immediately for review.

…o anything (#1600) (#1605) ## Motivation Adding `#[instrument(level = "debug")]` attributes to functions in rustc caused a performance regression (in release, where `debug!` is fully optimized out) across all crates: rust-lang/rust#89048 (comment) While trying to debug this, I noticed that spans don't have the same advantage that events have wrt to how LLVM sees them. Spans (or more precisely, the enter-guard), will get dropped at the end of the scope, which throws a spanner into the LLVM optimization pipeline. I am not entirely sure where the problem is, but I am moderately certain that the issue is that even entering a dummy span is too much code for LLVM to reliably (or at all) optimize out. ## Solution My hope is that in trusting the Rust compiler to generate cool code when using drop flags, we can essentially generate a drop flag that depends on something we know (due to events working as expected) to be optimizable. So instead of doing ```rust let _x = span!(); let _y = _x.enter(); // lotsa code drop(_y) ``` we do ```rust let _x; let _y; let must_drop = false; if level_enabled!(DEBUG) { must_drop = true; _x = span!(); _y = _x.enter(); } // lotsa code if must_drop { drop(_y) } ``` I believe this will allow LLVM to properly optimize this again. Testing that right now, but I wanted to open this PR immediately for review.

…imulacrum Fix performance regression with #[instrument] linked tracing PR: tokio-rs/tracing#1600 regression introduced by rust-lang#89048

rust-highfive assigned matthewjasper Sep 17, 2021

rust-highfive added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Sep 17, 2021

This comment has been minimized.

Sign in to view

rust-highfive assigned jackh726 and unassigned matthewjasper Sep 17, 2021

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 Sep 18, 2021

bors added S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. and removed S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. labels Sep 18, 2021

oli-obk force-pushed the in_tracing_we_trust branch from 731d779 to a1b308d Compare September 20, 2021 17:28

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-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Sep 20, 2021

This comment has been minimized.

Sign in to view

bors added S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. and removed S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. labels Sep 20, 2021

oli-obk force-pushed the in_tracing_we_trust branch 2 times, most recently from 804c1ac to 1443de7 Compare September 21, 2021 14:27

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-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Sep 23, 2021

workingjubilee mentioned this pull request Sep 23, 2021

Rollup of 7 pull requests #89207

Closed

bors added S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. and removed S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. labels Sep 23, 2021

More tracing instrumentation

9b5aa06

oli-obk force-pushed the in_tracing_we_trust branch from 1443de7 to 9b5aa06 Compare September 28, 2021 12:28

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-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Sep 28, 2021

bors added the merged-by-bors This PR was explicitly merged by bors. label Sep 28, 2021

bors merged commit 8f8092c into rust-lang:master Sep 28, 2021

rustbot added this to the 1.57.0 milestone Sep 28, 2021

rustbot added the perf-regression Performance regression. label Sep 28, 2021

oli-obk deleted the in_tracing_we_trust branch September 29, 2021 12:24

oli-obk mentioned this pull request Sep 29, 2021

Help LLVM understand that some spans are never going to do anything tokio-rs/tracing#1600

Merged

rustbot added the perf-regression-triaged The performance regression has been triaged. label Sep 30, 2021

oli-obk mentioned this pull request Oct 2, 2021

Fix performance regression with #[instrument] #89363

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add more tracing instrumentation #89048

Add more tracing instrumentation #89048

oli-obk commented Sep 17, 2021

rust-highfive commented Sep 17, 2021

This comment has been minimized.

jackh726 commented Sep 17, 2021

oli-obk commented Sep 18, 2021

bors commented Sep 18, 2021

bors commented Sep 18, 2021

oli-obk commented Sep 20, 2021

bors commented Sep 20, 2021

This comment has been minimized.

oli-obk commented Sep 20, 2021

oli-obk commented Sep 23, 2021

bors commented Sep 23, 2021

bors commented Sep 23, 2021

jackh726 commented Sep 24, 2021

jackh726 commented Sep 24, 2021

bors commented Sep 27, 2021

oli-obk commented Sep 28, 2021

bors commented Sep 28, 2021

bors commented Sep 28, 2021

bors commented Sep 28, 2021

rust-timer commented Sep 28, 2021

oli-obk commented Sep 28, 2021

oli-obk commented Sep 29, 2021 •

edited

Loading

oli-obk commented Sep 30, 2021

Add more tracing instrumentation #89048

Add more tracing instrumentation #89048

Conversation

oli-obk commented Sep 17, 2021

rust-highfive commented Sep 17, 2021

This comment has been minimized.

jackh726 commented Sep 17, 2021

oli-obk commented Sep 18, 2021

bors commented Sep 18, 2021

bors commented Sep 18, 2021

oli-obk commented Sep 20, 2021

bors commented Sep 20, 2021

This comment has been minimized.

oli-obk commented Sep 20, 2021

oli-obk commented Sep 23, 2021

bors commented Sep 23, 2021

bors commented Sep 23, 2021

jackh726 commented Sep 24, 2021

jackh726 commented Sep 24, 2021

bors commented Sep 27, 2021

oli-obk commented Sep 28, 2021

bors commented Sep 28, 2021

bors commented Sep 28, 2021

bors commented Sep 28, 2021

rust-timer commented Sep 28, 2021

oli-obk commented Sep 28, 2021

oli-obk commented Sep 29, 2021 • edited Loading

oli-obk commented Sep 30, 2021

oli-obk commented Sep 29, 2021 •

edited

Loading