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

tracing: attempt to monomorphize is_enabled call #787

Merged
merged 3 commits into from
Jul 8, 2020

Conversation

davidbarsky
Copy link
Member

@davidbarsky davidbarsky commented Jul 7, 2020

Resolves #783.

Copy link
Member

@hawkw hawkw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This looks correct to me.

It looks like there are now a couple of dispatcher imports in the macros that can be removed, if you like:

use $crate::{callsite, dispatcher, Event, field::{Value, ValueSet}};

and
use $crate::{callsite, dispatcher, Event, field::{Value, ValueSet}};

We have to allow unused imports in the macros because some imports are only needed if the span/event has fields and may sometimes be unused depending on user input, so the compiler can't warn about these.

tracing/src/lib.rs Show resolved Hide resolved
@davidbarsky
Copy link
Member Author

davidbarsky commented Jul 8, 2020

Good news, this worked!


Longer: I followed @matklad's steps to reproduce this issue:

$ cargo install cargo-llvm-lines
$ git clone rust-analyzer/rust-analyzer
$ cd rust-analyzer
[patching the tracing and tracing-core dependencies to this branch]
$ cd crates/ra_hir_ty
$ cargo llvm-lines

tracing_core::dispatcher::get_default is now significantly less hot, according to cargo llvm-lines:

  Lines           Copies        Function name
  -----           ------        -------------
  1202887 (100%)  46615 (100%)  (TOTAL)
    41106 (3.4%)    102 (0.2%)  alloc::raw_vec::RawVec<T,A>::grow
    31151 (2.6%)   3544 (7.6%)  core::ptr::drop_in_place
    31076 (2.6%)    539 (1.2%)  core::option::Option<T>::map
    30687 (2.6%)    317 (0.7%)  core::iter::traits::iterator::Iterator::try_fold
    27867 (2.3%)    429 (0.9%)  core::result::Result<T,E>::map_err
    25488 (2.1%)     22 (0.0%)  salsa::derived::slot::Slot<Q,MP>::read_upgrade
    24456 (2.0%)     44 (0.1%)  salsa::derived::slot::Slot<Q,MP>::probe
    17258 (1.4%)    409 (0.9%)  core::ptr::swap_nonoverlapping_one
    16742 (1.4%)     22 (0.0%)  salsa::derived::slot::Slot<Q,MP>::maybe_changed_since
    15634 (1.3%)    202 (0.4%)  alloc::vec::Vec<T>::extend_desugared

davidbarsky and others added 2 commits July 7, 2020 20:03
Co-authored-by: Eliza Weisman <eliza@buoyant.io>
@davidbarsky
Copy link
Member Author

I've removed the unneeded dispatcher imports.

Copy link
Member

@hawkw hawkw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Excellent, lgtm!

I'd love to hear from @matklad if this has a meaningful impact on rust-analyzer compile times, but I think the change is probably a good call regardless.

@@ -869,6 +869,14 @@ pub mod __macro_support {
pub type Once = tracing_core::Once;
}

#[doc(hidden)]
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We may want to consider making this public API, but I think that should be considered separately from fixing the monomorphization issue, so let's save that for another PR.

@matklad
Copy link
Contributor

matklad commented Jul 8, 2020

I observe meaningful change in cargo-llvm lines:

1687120 (100%) 52706 (100%) (TOTAL)
>>>
1587714 (100%) 51297 (100%) (TOTAL)

wall-clock time compilation impact is harder to estimate -- variance within single setup is stupidly high, and each run takes about a minute, so using proper statistic will require too much time. So, "it didn't make compilation 50% faster or slower" is all I can say.

Another thing I've noticed is that there's a bunch of calls to 14632 (0.9%) 236 (0.5%) std::sync::once::Once::call_once. (presumably from here). This shouldn't be too bad (as Once dynamizes the cold path anyway), but still I am wondering if Once is an overkill. If I am reading the code correctly, there's a mutex inside anyway, so we incur double synchronisation. It seems that Once is replaceable with Acquire/Release AtomicBool, at the cost of calling the same register more than once, which should be OK, as we lock a mutex there anyway.

@davidbarsky davidbarsky changed the title tracing: attempt to monomorphization is_enabled call tracing: attempt to monomorphize is_enabled call Jul 8, 2020
@davidbarsky
Copy link
Member Author

@matklad I'm glad you're able to observe a meaningful change in cargo-llvm lines! No worries about the compile times on your end. I've personally observed a (relatively) consistent 1-2 second change on my beefy MacBook Pro when compiling ra_hir_ty.

Another thing I've noticed is that there's a bunch of calls to 14632 (0.9%) 236 (0.5%) std::sync::once::Once::call_once. (presumably from here). This shouldn't be too bad (as Once dynamizes the cold path anyway), but still I am wondering if Once is an overkill. If I am reading the code correctly, there's a mutex inside anyway, so we incur double synchronisation. It seems that Once is replaceable with Acquire/Release AtomicBool, at the cost of calling the same register more than once, which should be OK, as we lock a mutex there anyway.

That's interesting! Since Eliza wrote that code, I'll let her comment on it, but if you're correct, I'll open another issue + PR to fix that.

@davidbarsky davidbarsky merged commit 7f60c92 into master Jul 8, 2020
@hawkw
Copy link
Member

hawkw commented Jul 8, 2020

Yeah, the Once can probably be removed with a second atomic. That path hasn't been a major focus for optimization, since it only happens once per callsite, so there's definitely room for improvement. I think this may also let us remove the vendored Once dependency for no-std targets, which would probably be the biggest benefit in my book.

hawkw added a commit that referenced this pull request Jul 8, 2020
Added

- **attributes**: Support for arbitrary expressions as fields in
  `#[instrument]` (#672)
- **attributes**: `#[instrument]` now emits a compiler warning when
  ignoring unrecognized input (#672, #786)
- Improved documentation on using `tracing` in async code (#769)

Changed

- Updated `tracing-core` dependency to 0.1.11

Fixed

- **macros**: Excessive monomorphization in macros, which could lead to
  longer compilation times (#787)
- **log**: Compiler warnings in macros when `log` or `log-always` features
  are enabled (#753)
- Compiler error when `tracing-core/std` feature is enabled but
  `tracing/std` is not (#760)

Thanks to @nagisa for contributing to this release!
hawkw added a commit that referenced this pull request Jul 8, 2020
### Added

- **attributes**: Support for arbitrary expressions as fields in
  `#[instrument]` (#672)
- **attributes**: `#[instrument]` now emits a compiler warning when
  ignoring unrecognized input (#672, #786)
- Improved documentation on using `tracing` in async code (#769)

### Changed

- Updated `tracing-core` dependency to 0.1.11

### Fixed

- **macros**: Excessive monomorphization in macros, which could lead to
  longer compilation times (#787)
- **log**: Compiler warnings in macros when `log` or `log-always` features
  are enabled (#753)
- Compiler error when `tracing-core/std` feature is enabled but
  `tracing/std` is not (#760)

Thanks to @nagisa, and everyone who contributed to the new `tracing-core`
and `tracing-attributes` versions, for contributing to this release!
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

tracing_core::dispatcher is repeatedly monomorphised in the downstream crate
3 participants