tracing_core::dispatcher is repeatedly monomorphised in the downstream crate

[matklad]

(meta: sorry for ignoring the template, I just want to quickly pen down an observation, feel free to ignore the issue!)

In rust-analyzer, I've noticed that tracing is pretty "hot" in terms of cargo llvm-lines. For our type-checking code I get:

  Lines           Copies        Function name
  -----           ------        -------------
  1687176 (100%)  52708 (100%)  (TOTAL)
    59685 (3.5%)    115 (0.2%)  alloc::raw_vec::RawVec<T,A>::grow
    55452 (3.3%)    474 (0.9%)  tracing_core::dispatcher::get_default::{{closure}}
    41932 (2.5%)    333 (0.6%)  core::iter::traits::iterator::Iterator::try_fold
    40152 (2.4%)   3972 (7.5%)  core::ptr::drop_in_place
    38954 (2.3%)    553 (1.0%)  core::option::Option<T>::map
    33309 (2.0%)    483 (0.9%)  core::result::Result<T,E>::map_err

Three points of interest here:

• tracing is hot in absolute terms
• there's substantiational amount of monomorphisation happening (474 instances)
• monomorphisation happens in the downstream crate, that is, there's no separate compilation.

Note that rust-analyzer doesn't use tracing directly itself, it comes from chalk I believe (but impacts our compile times, and not chalk compile times, due to the last bullet).

[davidbarsky]

Thanks for bringing this to our attention! I did some preliminary digging, I fully expect that @hawkw will correct me :)

I suspect that the get_default monomorphizations are coming from one of two places:

• in the macros that determine whether a span/event is enabled/disabled:

  tracing/tracing/src/macros.rs

  Line 1863 in 971a46b

  $crate::dispatcher::get_default(|current| current.enabled(meta))

• in tracing-log's compatibility layer:

  tracing/tracing-log/src/lib.rs

  Line 159 in a138748

  if !dispatcher::get_default(|dispatch| dispatch.enabled(&filter_meta)) {

If the monomorphized code is coming from the macros, I'm not entirely sure how to change that at the moment; I think Eliza will be able to say with greater confidence as to what's up.

In the meantime, I'm going to try to swap out env-logger in rust-analzyer with tracing-subscriber to see if the LLVM line count goes down.

[davidbarsky]

Over Zulip, @matklad told me:

For salsa, the percentage for the top function was also low (5 or something like this), but the knock-down effect added up to 5x [compilation speed slowdowns]. This probably won't be the case for tracing (as fewer code should be called inside monorphised stuff)

[hawkw]

• monomorphisation happens in the downstream crate, that is, there's no separate compilation.

Ah, yup, this is because all the invocations are inside a macro.

It seems like a potential solution to this would be to have a function like

fn is_enabled(meta: &Metadata<_>) -> bool {
    dispatcher::get_default(|current| current.enabled(meta)
}

for the most common monomorphizations that occur inside the macros. That way, the same closure is only monomorphized once inside of tracing rather than in every downstream crate.

This should actually be a pretty simple fix, so we can try it out and see if it has a significant impact on compile times.

[davidbarsky]

@matklad I've opened an PR that attempts to address this issue: #787.